2007-01-14 22:44:15

by Björn Steinbrink

Subject: SATA exceptions with 2.6.20-rc5

Hi,

with 2.6.20-rc{2,4,5} (no other tested yet) I see SATA exceptions quite
often, with 2.6.19 there are no such exceptions. dmesg and lspci -v
output follows. In the meantime, I'll start bisecting.

Thanks
Bj?rn


Linux version 2.6.20-rc2 (doener@atjola) (gcc version 4.1.2 20061115 (prerelease) (Debian 4.1.1-21)) #4 SMP Sun Dec 31 12:54:22 CET 2006
Command line: root=/dev/md0 ro quiet
BIOS-provided physical RAM map:
BIOS-e820: 0000000000000000 - 000000000009f000 (usable)
BIOS-e820: 000000000009f000 - 00000000000a0000 (reserved)
BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
BIOS-e820: 0000000000100000 - 000000007fee0000 (usable)
BIOS-e820: 000000007fee0000 - 000000007fee3000 (ACPI NVS)
BIOS-e820: 000000007fee3000 - 000000007fef0000 (ACPI data)
BIOS-e820: 000000007fef0000 - 000000007ff00000 (reserved)
BIOS-e820: 00000000e0000000 - 00000000f0000000 (reserved)
BIOS-e820: 00000000fec00000 - 0000000100000000 (reserved)
Entering add_active_range(0, 0, 159) 0 entries of 256 used
Entering add_active_range(0, 256, 524000) 1 entries of 256 used
end_pfn_map = 1048576
DMI 2.2 present.
ACPI: RSDP (v000 Nvidia ) @ 0x00000000000f7a70
ACPI: RSDT (v001 Nvidia AWRDACPI 0x42302e31 AWRD 0x00000000) @ 0x000000007fee3040
ACPI: FADT (v001 Nvidia AWRDACPI 0x42302e31 AWRD 0x00000000) @ 0x000000007fee30c0
ACPI: SSDT (v001 PTLTD POWERNOW 0x00000001 LTP 0x00000001) @ 0x000000007fee9540
ACPI: SRAT (v001 AMD HAMMER 0x00000001 AMD 0x00000001) @ 0x000000007fee9780
ACPI: MADT (v001 Nvidia AWRDACPI 0x42302e31 AWRD 0x00000000) @ 0x000000007fee9480
ACPI: DSDT (v001 NVIDIA AWRDACPI 0x00001000 MSFT 0x0100000e) @ 0x0000000000000000
Entering add_active_range(0, 0, 159) 0 entries of 256 used
Entering add_active_range(0, 256, 524000) 1 entries of 256 used
Zone PFN ranges:
DMA 0 -> 4096
DMA32 4096 -> 1048576
Normal 1048576 -> 1048576
early_node_map[2] active PFN ranges
0: 0 -> 159
0: 256 -> 524000
On node 0 totalpages: 523903
DMA zone: 56 pages used for memmap
DMA zone: 1122 pages reserved
DMA zone: 2821 pages, LIFO batch:0
DMA32 zone: 7108 pages used for memmap
DMA32 zone: 512796 pages, LIFO batch:31
Normal zone: 0 pages used for memmap
Nvidia board detected. Ignoring ACPI timer override.
If you got timer trouble try acpi_use_timer_override
ACPI: PM-Timer IO Port: 0x1008
ACPI: Local APIC address 0xfee00000
ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
Processor #0 (Bootup-CPU)
ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled)
Processor #1
ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
ACPI: IOAPIC (id[0x02] address[0xfec00000] gsi_base[0])
IOAPIC[0]: apic_id 2, address 0xfec00000, GSI 0-23
ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
ACPI: INT_SRC_OVR (bus 0 bus_irq 14 global_irq 14 high edge)
ACPI: INT_SRC_OVR (bus 0 bus_irq 15 global_irq 15 high edge)
ACPI: IRQ9 used by override.
ACPI: IRQ14 used by override.
ACPI: IRQ15 used by override.
Setting APIC routing to flat
Using ACPI (MADT) for SMP configuration information
Nosave address range: 000000000009f000 - 00000000000a0000
Nosave address range: 00000000000a0000 - 00000000000f0000
Nosave address range: 00000000000f0000 - 0000000000100000
Allocating PCI resources starting at 80000000 (gap: 7ff00000:60100000)
PERCPU: Allocating 32000 bytes of per cpu data
Built 1 zonelists. Total pages: 515617
Kernel command line: root=/dev/md0 ro quiet
Initializing CPU#0
PID hash table entries: 4096 (order: 12, 32768 bytes)
Console: colour VGA+ 80x25
Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes)
Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes)
Checking aperture...
CPU 0: aperture @ 5a74000000 size 32 MB
Aperture too small (32 MB)
No AGP bridge found
Memory: 2059000k/2096000k available (2795k kernel code, 36392k reserved, 1089k data, 224k init)
Calibrating delay using timer specific routine.. 4422.42 BogoMIPS (lpj=22112114)
Mount-cache hash table entries: 256
CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
CPU: L2 Cache: 1024K (64 bytes/line)
CPU: Physical Processor ID: 0
CPU: Processor Core ID: 0
Freeing SMP alternatives: 28k freed
ACPI: Core revision 20060707
Using local APIC timer interrupts.
result 12558084
Detected 12.558 MHz APIC timer.
Booting processor 1/2 APIC 0x1
Initializing CPU#1
Calibrating delay using timer specific routine.. 4420.44 BogoMIPS (lpj=22102213)
CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
CPU: L2 Cache: 1024K (64 bytes/line)
CPU: Physical Processor ID: 0
CPU: Processor Core ID: 1
AMD Athlon(tm) 64 X2 Dual Core Processor 4400+ stepping 02
CPU 1: Syncing TSC to CPU 0.
CPU 1: synchronized TSC with CPU 0 (last diff 89 cycles, maxerr 393 cycles)
Brought up 2 CPUs
testing NMI watchdog ... OK.
Disabling vsyscall due to use of PM timer
time.c: Using 3.579545 MHz WALL PM GTOD PM timer.
time.c: Detected 2210.219 MHz processor.
migration_cost=327
NET: Registered protocol family 16
ACPI: bus type pci registered
PCI: Using configuration type 1
ACPI: Interpreter enabled
ACPI: Using IOAPIC for interrupt routing
ACPI: PCI Root Bridge [PCI0] (0000:00)
PCI: Probing PCI hardware (bus 00)
PCI: Transparent bridge - 0000:00:09.0
Boot video device is 0000:05:00.0
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.HUB0._PRT]
ACPI: PCI Interrupt Link [LNK1] (IRQs 3 5 7 9 10 *11 12 14 15)
ACPI: PCI Interrupt Link [LNK2] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNK3] (IRQs 3 *5 7 9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNK4] (IRQs 3 5 7 9 *10 11 12 14 15)
ACPI: PCI Interrupt Link [LNK5] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LUBA] (IRQs 3 *5 7 9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LUBB] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LMAC] (IRQs 3 5 *7 9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LACI] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LMCI] (IRQs *3 5 7 9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LSMB] (IRQs 3 5 *7 9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LUB2] (IRQs 3 5 7 9 *10 11 12 14 15)
ACPI: PCI Interrupt Link [LIDE] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LSID] (IRQs 3 5 7 9 10 *11 12 14 15)
ACPI: PCI Interrupt Link [LFID] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LPCA] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [APC1] (IRQs 16) *0, disabled.
ACPI: PCI Interrupt Link [APC2] (IRQs 17) *0, disabled.
ACPI: PCI Interrupt Link [APC3] (IRQs 18) *0, disabled.
ACPI: PCI Interrupt Link [APC4] (IRQs 19) *0, disabled.
ACPI: PCI Interrupt Link [APC5] (IRQs *16), disabled.
ACPI: PCI Interrupt Link [APCF] (IRQs 20 21 22 23) *0, disabled.
ACPI: PCI Interrupt Link [APCG] (IRQs 20 21 22 23) *0, disabled.
ACPI: PCI Interrupt Link [APCH] (IRQs 20 21 22 23) *0, disabled.
ACPI: PCI Interrupt Link [APCJ] (IRQs 20 21 22 23) *0, disabled.
ACPI: PCI Interrupt Link [APCK] (IRQs 20 21 22 23) *0, disabled.
ACPI: PCI Interrupt Link [APCS] (IRQs 20 21 22 23) *0, disabled.
ACPI: PCI Interrupt Link [APCL] (IRQs 20 21 22 23) *0, disabled.
ACPI: PCI Interrupt Link [APCZ] (IRQs 20 21 22 23) *0, disabled.
ACPI: PCI Interrupt Link [APSI] (IRQs 20 21 22 23) *0, disabled.
ACPI: PCI Interrupt Link [APSJ] (IRQs 20 21 22 23) *0, disabled.
ACPI: PCI Interrupt Link [APCP] (IRQs 20 21 22 23) *0, disabled.
SCSI subsystem initialized
libata version 2.00 loaded.
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
PCI: Using ACPI for IRQ routing
PCI: If a device doesn't work, try "pci=routeirq". If it helps, post a report
PCI: Bridge: 0000:00:09.0
IO window: c000-cfff
MEM window: fc000000-fdffffff
PREFETCH window: fea00000-feafffff
PCI: Bridge: 0000:00:0b.0
IO window: b000-bfff
MEM window: fe900000-fe9fffff
PREFETCH window: fe800000-fe8fffff
PCI: Bridge: 0000:00:0c.0
IO window: a000-afff
MEM window: fe700000-fe7fffff
PREFETCH window: fe600000-fe6fffff
PCI: Bridge: 0000:00:0d.0
IO window: 9000-9fff
MEM window: fe500000-fe5fffff
PREFETCH window: fe400000-fe4fffff
PCI: Bridge: 0000:00:0e.0
IO window: 8000-8fff
MEM window: f4000000-fbffffff
PREFETCH window: d0000000-dfffffff
PCI: Setting latency timer of device 0000:00:09.0 to 64
PCI: Setting latency timer of device 0000:00:0b.0 to 64
PCI: Setting latency timer of device 0000:00:0c.0 to 64
PCI: Setting latency timer of device 0000:00:0d.0 to 64
PCI: Setting latency timer of device 0000:00:0e.0 to 64
NET: Registered protocol family 2
IP route cache hash table entries: 65536 (order: 7, 524288 bytes)
TCP established hash table entries: 262144 (order: 10, 4194304 bytes)
TCP bind hash table entries: 65536 (order: 8, 1048576 bytes)
TCP: Hash tables configured (established 262144 bind 65536)
TCP reno registered
io scheduler noop registered
io scheduler deadline registered (default)
0000:00:02.1 EHCI: BIOS handoff failed (BIOS bug ?) 01010001
PCI: Found disabled HT MSI Mapping on 0000:00:0b.0
PCI: MSI quirk detected. MSI disabled on chipset 0000:00:0b.0.
PCI: Found disabled HT MSI Mapping on 0000:00:0c.0
PCI: MSI quirk detected. MSI disabled on chipset 0000:00:0c.0.
PCI: Found disabled HT MSI Mapping on 0000:00:0d.0
PCI: MSI quirk detected. MSI disabled on chipset 0000:00:0d.0.
PCI: Found disabled HT MSI Mapping on 0000:00:0e.0
PCI: MSI quirk detected. MSI disabled on chipset 0000:00:0e.0.
PCI: Setting latency timer of device 0000:00:0b.0 to 64
assign_interrupt_mode Found MSI capability
Allocate Port Service[0000:00:0b.0:pcie00]
PCI: Setting latency timer of device 0000:00:0c.0 to 64
assign_interrupt_mode Found MSI capability
Allocate Port Service[0000:00:0c.0:pcie00]
PCI: Setting latency timer of device 0000:00:0d.0 to 64
assign_interrupt_mode Found MSI capability
Allocate Port Service[0000:00:0d.0:pcie00]
PCI: Setting latency timer of device 0000:00:0e.0 to 64
assign_interrupt_mode Found MSI capability
Allocate Port Service[0000:00:0e.0:pcie00]
input: Power Button (FF) as /class/input/input0
ACPI: Power Button (FF) [PWRF]
input: Power Button (CM) as /class/input/input1
ACPI: Power Button (CM) [PWRB]
ACPI: Thermal Zone [THRM] (40 C)
Real Time Clock Driver v1.12ac
Linux agpgart interface v0.101 (c) Dave Jones
Serial: 8250/16550 driver $Revision: 1.90 $ 2 ports, IRQ sharing disabled
tg3.c:v3.71 (December 15, 2006)
ACPI: PCI Interrupt Link [APC4] enabled at IRQ 19
ACPI: PCI Interrupt 0000:04:00.0[A] -> Link [APC4] -> GSI 19 (level, low) -> IRQ 19
PCI: Setting latency timer of device 0000:04:00.0 to 64
eth0: Tigon3 [partno(BCM95721) rev 4101 PHY(5750)] (PCI Express) 10/100/1000Base-T Ethernet 00:e0:81:55:09:b0
eth0: RXcsums[1] LinkChgREG[0] MIirq[0] ASF[0] Split[0] WireSpeed[1] TSOcap[1]
eth0: dma_rwctrl[76180000] dma_mask[64-bit]
tun: Universal TUN/TAP device driver, 1.6
tun: (C) 1999-2004 Max Krasnyansky <[email protected]>
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
NFORCE-CK804: IDE controller at PCI slot 0000:00:06.0
NFORCE-CK804: chipset revision 242
NFORCE-CK804: not 100% native mode: will probe irqs later
NFORCE-CK804: 0000:00:06.0 (rev f2) UDMA133 controller
ide0: BM-DMA at 0xe800-0xe807, BIOS settings: hda:DMA, hdb:DMA
Probing IDE interface ide0...
hda: TOSHIBA DVD-ROM SD-M1502, ATAPI CD/DVD-ROM drive
hdb: AOPEN CD-RW CRW4852 1.00 20030123, ATAPI CD/DVD-ROM drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Probing IDE interface ide1...
hda: ATAPI 48X DVD-ROM drive, 128kB Cache, UDMA(33)
Uniform CD-ROM driver Revision: 3.20
hdb: ATAPI 40X CD-ROM CD-R/RW drive, 2048kB Cache, UDMA(33)
sata_nv 0000:00:07.0: version 3.2
ACPI: PCI Interrupt Link [APSI] enabled at IRQ 23
ACPI: PCI Interrupt 0000:00:07.0[A] -> Link [APSI] -> GSI 23 (level, low) -> IRQ 23
sata_nv 0000:00:07.0: Using ADMA mode
PCI: Setting latency timer of device 0000:00:07.0 to 64
ata1: SATA max UDMA/133 cmd 0xFFFFC20000004480 ctl 0xFFFFC200000044A0 bmdma 0xD400 irq 23
ata2: SATA max UDMA/133 cmd 0xFFFFC20000004580 ctl 0xFFFFC200000045A0 bmdma 0xD408 irq 23
scsi0 : sata_nv
ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata1.00: ATA-7, max UDMA/133, 160086528 sectors: LBA
ata1.00: ata1: dev 0 multi count 16
ata1.00: configured for UDMA/133
scsi1 : sata_nv
ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata2.00: ATA-7, max UDMA/133, 160086528 sectors: LBA
ata2.00: ata2: dev 0 multi count 16
ata2.00: configured for UDMA/133
scsi 0:0:0:0: Direct-Access ATA Maxtor 6Y080M0 YAR5 PQ: 0 ANSI: 5
ata1: bounce limit 0xFFFFFFFFFFFFFFFF, segment boundary 0xFFFFFFFF, hw segs 61
SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
sda: sda1 sda2 sda3
sd 0:0:0:0: Attached scsi disk sda
scsi 1:0:0:0: Direct-Access ATA Maxtor 6Y080M0 YAR5 PQ: 0 ANSI: 5
ata2: bounce limit 0xFFFFFFFFFFFFFFFF, segment boundary 0xFFFFFFFF, hw segs 61
SCSI device sdb: 160086528 512-byte hdwr sectors (81964 MB)
sdb: Write Protect is off
sdb: Mode Sense: 00 3a 00 00
SCSI device sdb: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
SCSI device sdb: 160086528 512-byte hdwr sectors (81964 MB)
sdb: Write Protect is off
sdb: Mode Sense: 00 3a 00 00
SCSI device sdb: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
sdb: sdb1 sdb2 sdb3
sd 1:0:0:0: Attached scsi disk sdb
usbmon: debugfs is not available
ACPI: PCI Interrupt Link [APCL] enabled at IRQ 22
ACPI: PCI Interrupt 0000:00:02.1[B] -> Link [APCL] -> GSI 22 (level, low) -> IRQ 22
PCI: Setting latency timer of device 0000:00:02.1 to 64
ehci_hcd 0000:00:02.1: EHCI Host Controller
ehci_hcd 0000:00:02.1: new USB bus registered, assigned bus number 1
ehci_hcd 0000:00:02.1: debug port 1
PCI: cache line size of 64 is not supported by device 0000:00:02.1
ehci_hcd 0000:00:02.1: irq 22, io mem 0xfeb00000
ehci_hcd 0000:00:02.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
usb usb1: configuration #1 chosen from 1 choice
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 8 ports detected
ohci_hcd: 2006 August 04 USB 1.1 'Open' Host Controller (OHCI) Driver (PCI)
ACPI: PCI Interrupt Link [APCF] enabled at IRQ 21
ACPI: PCI Interrupt 0000:00:02.0[A] -> Link [APCF] -> GSI 21 (level, low) -> IRQ 21
PCI: Setting latency timer of device 0000:00:02.0 to 64
ohci_hcd 0000:00:02.0: OHCI Host Controller
ohci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2
ohci_hcd 0000:00:02.0: irq 21, io mem 0xfebff000
usb usb2: configuration #1 chosen from 1 choice
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 8 ports detected
usb 1-5: new high speed USB device using ehci_hcd and address 2
usb 1-5: configuration #1 chosen from 1 choice
usb 2-6: new full speed USB device using ohci_hcd and address 2
usb 2-6: configuration #1 chosen from 1 choice
hub 2-6:1.0: USB hub found
hub 2-6:1.0: 4 ports detected
drivers/usb/class/usblp.c: usblp0: USB Bidirectional printer dev 2 if 0 alt 0 proto 2 vid 0x04F9 pid 0x0022
usb 2-6.3: new low speed USB device using ohci_hcd and address 3
usb 2-6.3: configuration #1 chosen from 1 choice
usb 2-6.4: new low speed USB device using ohci_hcd and address 4
usb 2-6.4: configuration #1 chosen from 1 choice
usbcore: registered new interface driver usblp
drivers/usb/class/usblp.c: v0.13: USB Printer Device Class driver
Initializing USB Mass Storage driver...
usbcore: registered new interface driver usb-storage
USB Mass Storage support registered.
usbcore: registered new interface driver hiddev
input: Lite-On Tech IBM USB Keyboard with UltraNav as /class/input/input2
input: USB HID v1.10 Keyboard [Lite-On Tech IBM USB Keyboard with UltraNav] on usb-0000:00:02.0-6.3
input: Lite-On Tech IBM USB Keyboard with UltraNav as /class/input/input3
input: USB HID v1.10 Device [Lite-On Tech IBM USB Keyboard with UltraNav] on usb-0000:00:02.0-6.3
input: Synaptics Inc. Composite TouchPad / TrackPoint as /class/input/input4
input: USB HID v1.00 Mouse [Synaptics Inc. Composite TouchPad / TrackPoint] on usb-0000:00:02.0-6.4
input: Synaptics Inc. Composite TouchPad / TrackPoint as /class/input/input5
input: USB HID v1.00 Mouse [Synaptics Inc. Composite TouchPad / TrackPoint] on usb-0000:00:02.0-6.4
usbcore: registered new interface driver usbhid
drivers/usb/input/hid-core.c: v2.6:USB HID core driver
serio: i8042 KBD port at 0x60,0x64 irq 1
gameport: EMU10K1 is pci0000:01:08.1/gameport0, io 0xc400, speed 1205kHz
mice: PS/2 mouse device common for all mice
md: raid1 personality registered for level 1
device-mapper: ioctl: 4.11.0-ioctl (2006-10-12) initialised: [email protected]
Advanced Linux Sound Architecture Driver Version 1.0.14rc1 (Wed Dec 20 08:11:48 2006 UTC).
ACPI: PCI Interrupt 0000:01:08.0[A] -> Link [APC4] -> GSI 19 (level, low) -> IRQ 19
sidewinder.c: unknown joystick device detected on pci0000:01:08.1/gameport0, contact <[email protected]>
sidewinder.c: ID packet, 225 bits. [153952b1b912b1b913b1ab5295a95ab52912b52913b1291a95291ab12]
sidewinder.c: Data packet, 5 bits. [ff]
ALSA device list:
#0: Audigy 1 [SB0090] (rev.3, serial:0x531102) at 0xc800, irq 19
TCP cubic registered
NET: Registered protocol family 1
NET: Registered protocol family 17
NET: Registered protocol family 15
powernow-k8: Found 2 AMD Athlon(tm) 64 X2 Dual Core Processor 4400+ processors (version 2.00.00)
powernow-k8: 0 : fid 0xe (2200 MHz), vid 0x8
powernow-k8: 1 : fid 0xc (2000 MHz), vid 0xa
powernow-k8: 2 : fid 0xa (1800 MHz), vid 0xc
powernow-k8: 3 : fid 0x2 (1000 MHz), vid 0xe
md: Autodetecting RAID arrays.
md: autorun ...
md: considering sdb3 ...
md: adding sdb3 ...
md: sdb1 has different UUID to sdb3
md: adding sda3 ...
md: sda1 has different UUID to sdb3
md: created md1
md: bind<sda3>
md: bind<sdb3>
md: running: <sdb3><sda3>
raid1: raid set md1 active with 2 out of 2 mirrors
md: considering sdb1 ...
md: adding sdb1 ...
md: adding sda1 ...
md: created md0
md: bind<sda1>
md: bind<sdb1>
md: running: <sdb1><sda1>
raid1: raid set md0 active with 2 out of 2 mirrors
md: ... autorun DONE.
kjournald starting. Commit interval 5 seconds
EXT3-fs: mounted filesystem with ordered data mode.
VFS: Mounted root (ext3 filesystem) readonly.
Freeing unused kernel memory: 224k freed
forcedeth.c: Reverse Engineered nForce ethernet driver. Version 0.59.
ACPI: PCI Interrupt Link [APCH] enabled at IRQ 20
ACPI: PCI Interrupt 0000:00:0a.0[A] -> Link [APCH] -> GSI 20 (level, low) -> IRQ 20
PCI: Setting latency timer of device 0000:00:0a.0 to 64
forcedeth: using HIGHDMA
eth1: forcedeth.c: subsystem: 010f1:2865 bound to 0000:00:0a.0
Adding 979956k swap on /dev/sda2. Priority:-1 extents:1 across:979956k
Adding 979956k swap on /dev/sdb2. Priority:-2 extents:1 across:979956k
EXT3 FS on md0, internal journal
kjournald starting. Commit interval 5 seconds
EXT3 FS on dm-4, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting. Commit interval 5 seconds
EXT3 FS on dm-0, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting. Commit interval 5 seconds
EXT3 FS on dm-1, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting. Commit interval 5 seconds
EXT3 FS on dm-3, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
eth1: no link during initialization.
tg3: eth0: Link is up at 100 Mbps, full duplex.
tg3: eth0: Flow control is off for TX and off for RX.
nvidia: module license 'NVIDIA' taints kernel.
ACPI: PCI Interrupt Link [APC3] enabled at IRQ 18
ACPI: PCI Interrupt 0000:05:00.0[A] -> Link [APC3] -> GSI 18 (level, low) -> IRQ 18
PCI: Setting latency timer of device 0000:05:00.0 to 64
NVRM: loading NVIDIA Linux x86_64 Kernel Module 1.0-9631 Thu Nov 9 17:35:27 PST 2006
ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 in
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata1: soft resetting port
ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata1.00: configured for UDMA/133
ata1: EH complete
SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 out
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata1: soft resetting port
ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata1.00: configured for UDMA/133
ata1: EH complete
SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 out
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata1: soft resetting port
ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata1.00: configured for UDMA/133
ata1: EH complete
SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata2.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 out
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata2: soft resetting port
ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata2.00: configured for UDMA/133
ata2: EH complete
SCSI device sdb: 160086528 512-byte hdwr sectors (81964 MB)
sdb: Write Protect is off
sdb: Mode Sense: 00 3a 00 00
SCSI device sdb: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata2.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 out
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata2: soft resetting port
ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata2.00: configured for UDMA/133
ata2: EH complete
SCSI device sdb: 160086528 512-byte hdwr sectors (81964 MB)
sdb: Write Protect is off
sdb: Mode Sense: 00 3a 00 00
SCSI device sdb: write cache: enabled, read cache: enabled, doesn't support DPO or FUA





00:00.0 Memory controller: nVidia Corporation CK804 Memory Controller (rev a3)
Subsystem: Tyan Computer Unknown device 2865
Flags: bus master, 66MHz, fast devsel, latency 0
Capabilities: <access denied>

00:01.0 ISA bridge: nVidia Corporation CK804 ISA Bridge (rev a3)
Subsystem: Tyan Computer Unknown device 2865
Flags: bus master, 66MHz, fast devsel, latency 0

00:01.1 SMBus: nVidia Corporation CK804 SMBus (rev a2)
Subsystem: Tyan Computer Unknown device 2865
Flags: 66MHz, fast devsel, IRQ 7
I/O ports at fc00 [size=32]
I/O ports at 1c00 [size=64]
I/O ports at 1c40 [size=64]
Capabilities: <access denied>

00:02.0 USB Controller: nVidia Corporation CK804 USB Controller (rev a2) (prog-if 10 [OHCI])
Subsystem: Tyan Computer Unknown device 2865
Flags: bus master, 66MHz, fast devsel, latency 0, IRQ 21
Memory at febff000 (32-bit, non-prefetchable) [size=4K]
Capabilities: <access denied>

00:02.1 USB Controller: nVidia Corporation CK804 USB Controller (rev a3) (prog-if 20 [EHCI])
Subsystem: Tyan Computer Unknown device 2865
Flags: bus master, 66MHz, fast devsel, latency 0, IRQ 22
Memory at feb00000 (32-bit, non-prefetchable) [size=256]
Capabilities: <access denied>

00:06.0 IDE interface: nVidia Corporation CK804 IDE (rev f2) (prog-if 8a [Master SecP PriP])
Subsystem: Tyan Computer Unknown device 2865
Flags: bus master, 66MHz, fast devsel, latency 0
[virtual] Memory at 000001f0 (32-bit, non-prefetchable) [disabled] [size=8]
[virtual] Memory at 000003f0 (type 3, non-prefetchable) [disabled] [size=1]
[virtual] Memory at 00000170 (32-bit, non-prefetchable) [disabled] [size=8]
[virtual] Memory at 00000370 (type 3, non-prefetchable) [disabled] [size=1]
I/O ports at e800 [size=16]
Capabilities: <access denied>

00:07.0 IDE interface: nVidia Corporation CK804 Serial ATA Controller (rev f3) (prog-if 85 [Master SecO PriO])
Subsystem: Tyan Computer Unknown device 2865
Flags: bus master, 66MHz, fast devsel, latency 0, IRQ 23
I/O ports at 09f0 [size=8]
I/O ports at 0bf0 [size=4]
I/O ports at 0970 [size=8]
I/O ports at 0b70 [size=4]
I/O ports at d400 [size=16]
Memory at febfc000 (32-bit, non-prefetchable) [size=4K]
Capabilities: <access denied>

00:09.0 PCI bridge: nVidia Corporation CK804 PCI Bridge (rev a2) (prog-if 01 [Subtractive decode])
Flags: bus master, 66MHz, fast devsel, latency 0
Bus: primary=00, secondary=01, subordinate=01, sec-latency=32
I/O behind bridge: 0000c000-0000cfff
Memory behind bridge: fc000000-fdffffff
Prefetchable memory behind bridge: fea00000-feafffff

00:0a.0 Bridge: nVidia Corporation CK804 Ethernet Controller (rev a3)
Subsystem: Tyan Computer Unknown device 2865
Flags: bus master, 66MHz, fast devsel, latency 0, IRQ 20
Memory at febfb000 (32-bit, non-prefetchable) [size=4K]
I/O ports at d000 [size=8]
Capabilities: <access denied>

00:0b.0 PCI bridge: nVidia Corporation CK804 PCIE Bridge (rev a3) (prog-if 00 [Normal decode])
Flags: bus master, fast devsel, latency 0
Bus: primary=00, secondary=02, subordinate=02, sec-latency=0
I/O behind bridge: 0000b000-0000bfff
Memory behind bridge: fe900000-fe9fffff
Prefetchable memory behind bridge: 00000000fe800000-00000000fe8fffff
Capabilities: <access denied>

00:0c.0 PCI bridge: nVidia Corporation CK804 PCIE Bridge (rev a3) (prog-if 00 [Normal decode])
Flags: bus master, fast devsel, latency 0
Bus: primary=00, secondary=03, subordinate=03, sec-latency=0
I/O behind bridge: 0000a000-0000afff
Memory behind bridge: fe700000-fe7fffff
Prefetchable memory behind bridge: 00000000fe600000-00000000fe6fffff
Capabilities: <access denied>

00:0d.0 PCI bridge: nVidia Corporation CK804 PCIE Bridge (rev a3) (prog-if 00 [Normal decode])
Flags: bus master, fast devsel, latency 0
Bus: primary=00, secondary=04, subordinate=04, sec-latency=0
I/O behind bridge: 00009000-00009fff
Memory behind bridge: fe500000-fe5fffff
Prefetchable memory behind bridge: 00000000fe400000-00000000fe4fffff
Capabilities: <access denied>

00:0e.0 PCI bridge: nVidia Corporation CK804 PCIE Bridge (rev a3) (prog-if 00 [Normal decode])
Flags: bus master, fast devsel, latency 0
Bus: primary=00, secondary=05, subordinate=05, sec-latency=0
I/O behind bridge: 00008000-00008fff
Memory behind bridge: f4000000-fbffffff
Prefetchable memory behind bridge: 00000000d0000000-00000000dfffffff
Capabilities: <access denied>

00:18.0 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] HyperTransport Technology Configuration
Flags: fast devsel
Capabilities: <access denied>

00:18.1 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] Address Map
Flags: fast devsel

00:18.2 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] DRAM Controller
Flags: fast devsel

00:18.3 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] Miscellaneous Control
Flags: fast devsel

01:05.0 Display controller: ATI Technologies Inc Rage XL (rev 27)
Flags: stepping, medium devsel, IRQ 10
Memory at fc000000 (32-bit, non-prefetchable) [disabled] [size=16M]
I/O ports at cc00 [disabled] [size=256]
Memory at fdfff000 (32-bit, non-prefetchable) [disabled] [size=4K]
[virtual] Expansion ROM at fea00000 [disabled] [size=128K]
Capabilities: <access denied>

01:08.0 Multimedia audio controller: Creative Labs SB Audigy (rev 03)
Subsystem: Creative Labs SB0090 Audigy Player/OEM
Flags: bus master, medium devsel, latency 32, IRQ 19
I/O ports at c800 [size=32]
Capabilities: <access denied>

01:08.1 Input device controller: Creative Labs SB Audigy Game Port (rev 03)
Subsystem: Creative Labs SB Audigy MIDI/Game Port
Flags: bus master, medium devsel, latency 32
I/O ports at c400 [size=8]
Capabilities: <access denied>

01:08.2 FireWire (IEEE 1394): Creative Labs SB Audigy FireWire Port (prog-if 10 [OHCI])
Subsystem: Creative Labs SB Audigy FireWire Port
Flags: bus master, medium devsel, latency 32, IRQ 11
Memory at fdffe000 (32-bit, non-prefetchable) [size=2K]
Memory at fdff8000 (32-bit, non-prefetchable) [size=16K]
Capabilities: <access denied>

04:00.0 Ethernet controller: Broadcom Corporation NetXtreme BCM5721 Gigabit Ethernet PCI Express (rev 11)
Subsystem: Broadcom Corporation NetXtreme BCM5721 Gigabit Ethernet PCI Express
Flags: bus master, fast devsel, latency 0, IRQ 19
Memory at fe5f0000 (64-bit, non-prefetchable) [size=64K]
Capabilities: <access denied>

05:00.0 VGA compatible controller: nVidia Corporation NV43 [GeForce 6600] (rev a2) (prog-if 00 [VGA])
Flags: bus master, fast devsel, latency 0, IRQ 18
Memory at f4000000 (32-bit, non-prefetchable) [size=64M]
Memory at d0000000 (64-bit, prefetchable) [size=256M]
Memory at fa000000 (64-bit, non-prefetchable) [size=16M]
[virtual] Expansion ROM at f8000000 [disabled] [size=128K]
Capabilities: <access denied>

2007-01-14 23:44:21

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Bj?rn Steinbrink wrote:
> Hi,
>
> with 2.6.20-rc{2,4,5} (no other tested yet) I see SATA exceptions quite
> often, with 2.6.19 there are no such exceptions. dmesg and lspci -v
> output follows. In the meantime, I'll start bisecting.

...

> ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 in
> res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> ata1: soft resetting port
> ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> ata1.00: configured for UDMA/133
> ata1: EH complete
> SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
> sda: Write Protect is off
> sda: Mode Sense: 00 3a 00 00
> SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA

Looks like all of these errors are from a FLUSH CACHE command and the
drive is indicating that it is no longer busy, so presumably done.
That's not a DMA-mapped command, so it wouldn't go through the ADMA
machinery and I wouldn't have expected this to be handled any
differently from before. Curious..

--
Robert Hancock Saskatoon, SK, Canada
To email, remove "nospam" from [email protected]
Home Page: http://www.roberthancock.com/

2007-01-15 00:22:56

by Jeff Garzik

Subject: Re: SATA exceptions with 2.6.20-rc5

Robert Hancock wrote:
> Bj?rn Steinbrink wrote:
>> Hi,
>>
>> with 2.6.20-rc{2,4,5} (no other tested yet) I see SATA exceptions quite
>> often, with 2.6.19 there are no such exceptions. dmesg and lspci -v
>> output follows. In the meantime, I'll start bisecting.
>
> ...
>
>> ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
>> ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 in
>> res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
>> ata1: soft resetting port
>> ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>> ata1.00: configured for UDMA/133
>> ata1: EH complete
>> SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
>> sda: Write Protect is off
>> sda: Mode Sense: 00 3a 00 00
>> SCSI device sda: write cache: enabled, read cache: enabled, doesn't
>> support DPO or FUA
>
> Looks like all of these errors are from a FLUSH CACHE command and the
> drive is indicating that it is no longer busy, so presumably done.
> That's not a DMA-mapped command, so it wouldn't go through the ADMA
> machinery and I wouldn't have expected this to be handled any
> differently from before. Curious..

It's possible the flush-cache command takes longer than 30 seconds, if
the cache is large, contents are discontiguous, etc. It's a
pathological case, but possible.

Or maybe flush-cache doesn't get a 30 second timeout, and it should...?
(thinking out loud)

Jeff

2007-01-15 00:34:52

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.14 19:22:51 -0500, Jeff Garzik wrote:
> Robert Hancock wrote:
> >Bj?rn Steinbrink wrote:
> >>Hi,
> >>
> >>with 2.6.20-rc{2,4,5} (no other tested yet) I see SATA exceptions quite
> >>often, with 2.6.19 there are no such exceptions. dmesg and lspci -v
> >>output follows. In the meantime, I'll start bisecting.
> >
> >...
> >
> >>ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> >>ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 in
> >> res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> >>ata1: soft resetting port
> >>ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> >>ata1.00: configured for UDMA/133
> >>ata1: EH complete
> >>SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
> >>sda: Write Protect is off
> >>sda: Mode Sense: 00 3a 00 00
> >>SCSI device sda: write cache: enabled, read cache: enabled, doesn't
> >>support DPO or FUA
> >
> >Looks like all of these errors are from a FLUSH CACHE command and the
> >drive is indicating that it is no longer busy, so presumably done.
> >That's not a DMA-mapped command, so it wouldn't go through the ADMA
> >machinery and I wouldn't have expected this to be handled any
> >differently from before. Curious..
>
> It's possible the flush-cache command takes longer than 30 seconds, if
> the cache is large, contents are discontiguous, etc. It's a
> pathological case, but possible.
>
> Or maybe flush-cache doesn't get a 30 second timeout, and it should...?
> (thinking out loud)

Bi-section led to commit 249e83fe839 which makes absolutely no sense to
me, just in case that anyone sees any problem with that commit.
I'll go and re-check a few of those commits that I marked as good.

Bj?rn

2007-01-15 02:27:09

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Jeff Garzik wrote:
>> Looks like all of these errors are from a FLUSH CACHE command and the
>> drive is indicating that it is no longer busy, so presumably done.
>> That's not a DMA-mapped command, so it wouldn't go through the ADMA
>> machinery and I wouldn't have expected this to be handled any
>> differently from before. Curious..
>
> It's possible the flush-cache command takes longer than 30 seconds, if
> the cache is large, contents are discontiguous, etc. It's a
> pathological case, but possible.
>
> Or maybe flush-cache doesn't get a 30 second timeout, and it should...?
> (thinking out loud)
>
> Jeff

If the flush was still in progress I would expect Busy to still be set,
however..

--
Robert Hancock Saskatoon, SK, Canada
To email, remove "nospam" from [email protected]
Home Page: http://www.roberthancock.com/

2007-01-15 02:47:22

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.15 01:34:48 +0100, Bj?rn Steinbrink wrote:
> On 2007.01.14 19:22:51 -0500, Jeff Garzik wrote:
> > Robert Hancock wrote:
> > >Bj?rn Steinbrink wrote:
> > >>Hi,
> > >>
> > >>with 2.6.20-rc{2,4,5} (no other tested yet) I see SATA exceptions quite
> > >>often, with 2.6.19 there are no such exceptions. dmesg and lspci -v
> > >>output follows. In the meantime, I'll start bisecting.
> > >
> > >...
> > >
> > >>ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> > >>ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 in
> > >> res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> > >>ata1: soft resetting port
> > >>ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> > >>ata1.00: configured for UDMA/133
> > >>ata1: EH complete
> > >>SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
> > >>sda: Write Protect is off
> > >>sda: Mode Sense: 00 3a 00 00
> > >>SCSI device sda: write cache: enabled, read cache: enabled, doesn't
> > >>support DPO or FUA
> > >
> > >Looks like all of these errors are from a FLUSH CACHE command and the
> > >drive is indicating that it is no longer busy, so presumably done.
> > >That's not a DMA-mapped command, so it wouldn't go through the ADMA
> > >machinery and I wouldn't have expected this to be handled any
> > >differently from before. Curious..
> >
> > It's possible the flush-cache command takes longer than 30 seconds, if
> > the cache is large, contents are discontiguous, etc. It's a
> > pathological case, but possible.
> >
> > Or maybe flush-cache doesn't get a 30 second timeout, and it should...?
> > (thinking out loud)
>
> Bi-section led to commit 249e83fe839 which makes absolutely no sense to
> me, just in case that anyone sees any problem with that commit.
> I'll go and re-check a few of those commits that I marked as good.

Next round of bisecting led to another useless result, a) it was an
unrelated driver, b) the kernel I just marked as good after 20 minutes
of testing decided to fail when I hit reply... Guess that it was pure
luck that the kernel I marked as bad failed within 1-2 minutes.
I send the git bisect log with this mail, maybe at least the early good
kernel are really good and someone can make some sense out of it. At
least I ended up somewhere in a series of libata changes.

Thanks,
Bj?rn

git-bisect start
# bad: [8a2d17a56a71c5c796b0a5378ee76a105f21fdd9] Linux 2.6.20-rc2
git-bisect bad 8a2d17a56a71c5c796b0a5378ee76a105f21fdd9
# good: [c3fe6924620fd733ffe8bc8a9da1e9cde08402b3] Linux 2.6.19
git-bisect good c3fe6924620fd733ffe8bc8a9da1e9cde08402b3
# bad: [2685b267bce34c9b66626cb11664509c32a761a5] Merge master.kernel.org:/pub/scm/linux/kernel/git/davem/net-2.6
git-bisect bad 2685b267bce34c9b66626cb11664509c32a761a5
# good: [a985239bdf017e00e985c3a31149d6ae128fdc5f] [POWERPC] cell: spu management xmon routines
git-bisect good a985239bdf017e00e985c3a31149d6ae128fdc5f
# bad: [33f2ef89f8e181486b63fdbdc97c6afa6ca9f34b] mm: make compound page destructor handling explicit
git-bisect bad 33f2ef89f8e181486b63fdbdc97c6afa6ca9f34b
# bad: [651857a1ecaf97a8ad9d324dd2a61675c53e541e] Merge branch 'upstream-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/mfasheh/ocfs2
git-bisect bad 651857a1ecaf97a8ad9d324dd2a61675c53e541e
# bad: [ff51a98799931256b555446b2f5675db08de6229] Merge branch 'upstream-linus' of master.kernel.org:/pub/scm/linux/kernel/git/jgarzik/libata-dev
git-bisect bad ff51a98799931256b555446b2f5675db08de6229
# bad: [3ac551a6a63dcbc707348772a27bd7090b081524] [libata] pata_cs5535: fix build
git-bisect bad 3ac551a6a63dcbc707348772a27bd7090b081524
# good: [750426aa1ad1ddd1fa8bb4ed531a7956f3b9a27c] libata: cosmetic changes to sense generation functions
git-bisect good 750426aa1ad1ddd1fa8bb4ed531a7956f3b9a27c
# good: [62d64ae0ec76360736c9dc4ca2067ae8de0ba9f2] pata : more drivers that need only standard suspend and resume
git-bisect good 62d64ae0ec76360736c9dc4ca2067ae8de0ba9f2
# good: [6a36261e63770ab61422550b774fe949ccca5fa9] libata: fix READ CAPACITY simulation
git-bisect good 6a36261e63770ab61422550b774fe949ccca5fa9
# good: [2432697ba0ce312d60be5009ffe1fa054a761bb9] libata: implement ata_exec_internal_sg()
git-bisect good 2432697ba0ce312d60be5009ffe1fa054a761bb9
# good: [70e6ad0c6d1e6cb9ee3c036a85ca2561eb1fd766] libata: prepare ata_sg_clean() for invocation from EH
git-bisect good 70e6ad0c6d1e6cb9ee3c036a85ca2561eb1fd766
# good: [8e16f941226f15622fbbc416a1f3d8705001a191] ahci: do not powerdown during initialization
git-bisect good 8e16f941226f15622fbbc416a1f3d8705001a191

2007-01-15 02:53:18

by Jens Axboe

Subject: Re: SATA exceptions with 2.6.20-rc5

On Sun, Jan 14 2007, Robert Hancock wrote:
> Jeff Garzik wrote:
> >>Looks like all of these errors are from a FLUSH CACHE command and the
> >>drive is indicating that it is no longer busy, so presumably done.
> >>That's not a DMA-mapped command, so it wouldn't go through the ADMA
> >>machinery and I wouldn't have expected this to be handled any
> >>differently from before. Curious..
> >
> >It's possible the flush-cache command takes longer than 30 seconds, if
> >the cache is large, contents are discontiguous, etc. It's a
> >pathological case, but possible.
> >
> >Or maybe flush-cache doesn't get a 30 second timeout, and it should...?
> > (thinking out loud)
> >
> > Jeff
>
> If the flush was still in progress I would expect Busy to still be set,
> however..

I'd be surprised if the device would not obey the 7 second timeout rule
that seems to be set in stone and not allow more dirty in-drive cache
than it could flush out in approximately that time.

And BUSY should also be set for that case, as Robert indicates.

--
Jens Axboe

2007-01-15 07:15:42

by Mikael Pettersson

Subject: Re: SATA exceptions with 2.6.20-rc5

Bj?rn Steinbrink writes:
> Hi,
>
> with 2.6.20-rc{2,4,5} (no other tested yet) I see SATA exceptions quite
> often, with 2.6.19 there are no such exceptions. dmesg and lspci -v
> output follows. In the meantime, I'll start bisecting.
>
> Thanks
> Bj?rn
>
>
> Linux version 2.6.20-rc2 (doener@atjola) (gcc version 4.1.2 20061115 (prerelease) (Debian 4.1.1-21)) #4 SMP Sun Dec 31 12:54:22 CET 2006

[uneventful kernel log omitted]

> sata_nv 0000:00:07.0: Using ADMA mode
> PCI: Setting latency timer of device 0000:00:07.0 to 64
> ata1: SATA max UDMA/133 cmd 0xFFFFC20000004480 ctl 0xFFFFC200000044A0 bmdma 0xD400 irq 23
> ata2: SATA max UDMA/133 cmd 0xFFFFC20000004580 ctl 0xFFFFC200000045A0 bmdma 0xD408 irq 23
> scsi0 : sata_nv
> ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> ata1.00: ATA-7, max UDMA/133, 160086528 sectors: LBA
> ata1.00: ata1: dev 0 multi count 16
> ata1.00: configured for UDMA/133
> scsi1 : sata_nv
> ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> ata2.00: ATA-7, max UDMA/133, 160086528 sectors: LBA
> ata2.00: ata2: dev 0 multi count 16
> ata2.00: configured for UDMA/133
> scsi 0:0:0:0: Direct-Access ATA Maxtor 6Y080M0 YAR5 PQ: 0 ANSI: 5
> ata1: bounce limit 0xFFFFFFFFFFFFFFFF, segment boundary 0xFFFFFFFF, hw segs 61
> SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
> sda: Write Protect is off
> sda: Mode Sense: 00 3a 00 00
> SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
> sda: Write Protect is off
> sda: Mode Sense: 00 3a 00 00
> SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> sda: sda1 sda2 sda3
> sd 0:0:0:0: Attached scsi disk sda
> scsi 1:0:0:0: Direct-Access ATA Maxtor 6Y080M0 YAR5 PQ: 0 ANSI: 5
> ata2: bounce limit 0xFFFFFFFFFFFFFFFF, segment boundary 0xFFFFFFFF, hw segs 61
> SCSI device sdb: 160086528 512-byte hdwr sectors (81964 MB)
> sdb: Write Protect is off
> sdb: Mode Sense: 00 3a 00 00
> SCSI device sdb: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> SCSI device sdb: 160086528 512-byte hdwr sectors (81964 MB)
> sdb: Write Protect is off
> sdb: Mode Sense: 00 3a 00 00
> SCSI device sdb: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> sdb: sdb1 sdb2 sdb3
> sd 1:0:0:0: Attached scsi disk sdb

Things are fine so far.

[more uneventful kernel log omitted]

> NVRM: loading NVIDIA Linux x86_64 Kernel Module 1.0-9631 Thu Nov 9 17:35:27 PST 2006
> ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 in
> res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> ata1: soft resetting port
> ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> ata1.00: configured for UDMA/133
> ata1: EH complete
> SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
> sda: Write Protect is off
> sda: Mode Sense: 00 3a 00 00
> SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 out
> res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)

and then things start to break.

Notice how the problems started exactly at the point the
"NVRM" NVIDIA module (whatever it is) was loaded ...

2007-01-15 13:43:01

by Jeff Garzik

Subject: Re: SATA exceptions with 2.6.20-rc5

Jens Axboe wrote:
> I'd be surprised if the device would not obey the 7 second timeout rule
> that seems to be set in stone and not allow more dirty in-drive cache
> than it could flush out in approximately that time.

AFAIK Windows flush-cache timeout is 30 seconds, not 7 as with other
commands...


> And BUSY should also be set for that case, as Robert indicates.

Agreed.

Jeff

2007-01-15 13:43:25

by Jeff Garzik

Subject: Re: SATA exceptions with 2.6.20-rc5

Mikael Pettersson wrote:
> Notice how the problems started exactly at the point the
> "NVRM" NVIDIA module (whatever it is) was loaded ...


Yes, that's a bit suspicious...

Jeff

2007-01-15 13:47:44

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.15 07:48:23 +0100, Mikael Pettersson wrote:
> Notice how the problems started exactly at the point the
> "NVRM" NVIDIA module (whatever it is) was loaded ...

That's not the reason. Yeah, I should not have sent a log of a run with
the nvidia module loaded, but the same thing happens without it. For the
bisection kernels I did not even build the nvidia module and did the
testing at the console.

Bj?rn

2007-01-15 21:17:33

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.14 17:43:53 -0600, Robert Hancock wrote:
> Bj?rn Steinbrink wrote:
> >Hi,
> >
> >with 2.6.20-rc{2,4,5} (no other tested yet) I see SATA exceptions quite
> >often, with 2.6.19 there are no such exceptions. dmesg and lspci -v
> >output follows. In the meantime, I'll start bisecting.
>
> ...
>
> >ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> >ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 in
> > res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> >ata1: soft resetting port
> >ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> >ata1.00: configured for UDMA/133
> >ata1: EH complete
> >SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
> >sda: Write Protect is off
> >sda: Mode Sense: 00 3a 00 00
> >SCSI device sda: write cache: enabled, read cache: enabled, doesn't
> >support DPO or FUA
>
> Looks like all of these errors are from a FLUSH CACHE command and the
> drive is indicating that it is no longer busy, so presumably done.
> That's not a DMA-mapped command, so it wouldn't go through the ADMA
> machinery and I wouldn't have expected this to be handled any
> differently from before. Curious..

My latest bisection attempt actually led to your sata_nv ADMA commit. [1]
I've now backed out that patch from 2.6.20-rc5 and have my stress test
running for 20 minutes now ("record" for a bad kernel surviving that
test is about 40 minutes IIRC). I'll keep it running for at least 2 more
hours.

The test is pretty simple:
while /bin/true; do ls -lR > /dev/null; done
while /bin/true; do echo 255 > /proc/sys/vm/drop_caches; sleep 1; done

running in parallel.

Bj?rn

[1] 2dec7555e6bf2772749113ea0ad454fcdb8cf861

2007-01-15 23:46:56

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.15 22:17:24 +0100, Bj?rn Steinbrink wrote:
> On 2007.01.14 17:43:53 -0600, Robert Hancock wrote:
> > Bj?rn Steinbrink wrote:
> > >Hi,
> > >
> > >with 2.6.20-rc{2,4,5} (no other tested yet) I see SATA exceptions quite
> > >often, with 2.6.19 there are no such exceptions. dmesg and lspci -v
> > >output follows. In the meantime, I'll start bisecting.
> >
> > ...
> >
> > >ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> > >ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 in
> > > res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> > >ata1: soft resetting port
> > >ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> > >ata1.00: configured for UDMA/133
> > >ata1: EH complete
> > >SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
> > >sda: Write Protect is off
> > >sda: Mode Sense: 00 3a 00 00
> > >SCSI device sda: write cache: enabled, read cache: enabled, doesn't
> > >support DPO or FUA
> >
> > Looks like all of these errors are from a FLUSH CACHE command and the
> > drive is indicating that it is no longer busy, so presumably done.
> > That's not a DMA-mapped command, so it wouldn't go through the ADMA
> > machinery and I wouldn't have expected this to be handled any
> > differently from before. Curious..
>
> My latest bisection attempt actually led to your sata_nv ADMA commit. [1]
> I've now backed out that patch from 2.6.20-rc5 and have my stress test
> running for 20 minutes now ("record" for a bad kernel surviving that
> test is about 40 minutes IIRC). I'll keep it running for at least 2 more
> hours.

Yep, that one seems to be guilty. 2.6.20-rc5 with that commit backed out
survived about 3 hours of testing, while the average was around 5
minutes for a failure, sometimes even before I could log in.
I took a look at the patch, but I can't really tell anything.
nv_adma_check_atapi_dma somehow looks like it should not negate its
return value, so that it returns 0 (atapi dma available) when
adma_enable was 1. But I'm not exactly confident about that either ;)
Will it hurt if I try to remove the negation?

Thanks,
Bj?rn

2007-01-16 00:23:11

by Jens Axboe

Subject: Re: SATA exceptions with 2.6.20-rc5

On Mon, Jan 15 2007, Jeff Garzik wrote:
> Jens Axboe wrote:
> >I'd be surprised if the device would not obey the 7 second timeout rule
> >that seems to be set in stone and not allow more dirty in-drive cache
> >than it could flush out in approximately that time.
>
> AFAIK Windows flush-cache timeout is 30 seconds, not 7 as with other
> commands...

Ok, 7 seconds for FLUSH_CACHE would have been nice for us too though, as
it would pretty much guarentee lower latencies for random writes and
write back caching. The concern is the barrier code, of course. I guess
I should do some timings on potential worst case patterns some day. Alan
may have done that sometime in the past, iirc.

--
Jens Axboe

2007-01-16 00:35:57

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Bj?rn Steinbrink wrote:
>> My latest bisection attempt actually led to your sata_nv ADMA commit. [1]
>> I've now backed out that patch from 2.6.20-rc5 and have my stress test
>> running for 20 minutes now ("record" for a bad kernel surviving that
>> test is about 40 minutes IIRC). I'll keep it running for at least 2 more
>> hours.
>
> Yep, that one seems to be guilty. 2.6.20-rc5 with that commit backed out
> survived about 3 hours of testing, while the average was around 5
> minutes for a failure, sometimes even before I could log in.
> I took a look at the patch, but I can't really tell anything.
> nv_adma_check_atapi_dma somehow looks like it should not negate its
> return value, so that it returns 0 (atapi dma available) when
> adma_enable was 1. But I'm not exactly confident about that either ;)
> Will it hurt if I try to remove the negation?

It should be correct the way it is - that check is trying to prevent
ATAPI commands from using DMA until the slave_config function has been
called to set up the DMA parameters properly. When the
NV_ADMA_ATAPI_SETUP_COMPLETE flag is not set, this returns 1 which
disallows DMA transfers. Unless you were using an ATAPI (i.e. CD/DVD)
device on the channel this wouldn't affect you anyway.

I'll try your stress test when I get a chance, but I doubt I'll run into
the same problem and I haven't seen any similar reports. Perhaps it's
some kind of wierd timing issue or incompatibility between the
controller and that drive when running in ADMA mode? I seem to remember
various reports of issues with certain Maxtor drives and some nForce
SATA controllers under Windows at least..

--
Robert Hancock Saskatoon, SK, Canada
To email, remove "nospam" from [email protected]
Home Page: http://www.roberthancock.com/

2007-01-16 00:37:42

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Jens Axboe wrote:
> On Mon, Jan 15 2007, Jeff Garzik wrote:
>> Jens Axboe wrote:
>>> I'd be surprised if the device would not obey the 7 second timeout rule
>>> that seems to be set in stone and not allow more dirty in-drive cache
>>> than it could flush out in approximately that time.
>> AFAIK Windows flush-cache timeout is 30 seconds, not 7 as with other
>> commands...
>
> Ok, 7 seconds for FLUSH_CACHE would have been nice for us too though, as
> it would pretty much guarentee lower latencies for random writes and
> write back caching. The concern is the barrier code, of course. I guess
> I should do some timings on potential worst case patterns some day. Alan
> may have done that sometime in the past, iirc.
>

Note that the ATA-7 spec for FLUSH CACHE says that "This command may
take longer than 30 s to complete."

--
Robert Hancock Saskatoon, SK, Canada
To email, remove "nospam" from [email protected]
Home Page: http://www.roberthancock.com/

2007-01-16 01:35:11

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.15 18:34:43 -0600, Robert Hancock wrote:
> Bj?rn Steinbrink wrote:
> >>My latest bisection attempt actually led to your sata_nv ADMA commit. [1]
> >>I've now backed out that patch from 2.6.20-rc5 and have my stress test
> >>running for 20 minutes now ("record" for a bad kernel surviving that
> >>test is about 40 minutes IIRC). I'll keep it running for at least 2 more
> >>hours.
> >
> >Yep, that one seems to be guilty. 2.6.20-rc5 with that commit backed out
> >survived about 3 hours of testing, while the average was around 5
> >minutes for a failure, sometimes even before I could log in.
> >I took a look at the patch, but I can't really tell anything.
> >nv_adma_check_atapi_dma somehow looks like it should not negate its
> >return value, so that it returns 0 (atapi dma available) when
> >adma_enable was 1. But I'm not exactly confident about that either ;)
> >Will it hurt if I try to remove the negation?
>
> It should be correct the way it is - that check is trying to prevent
> ATAPI commands from using DMA until the slave_config function has been
> called to set up the DMA parameters properly. When the
> NV_ADMA_ATAPI_SETUP_COMPLETE flag is not set, this returns 1 which
> disallows DMA transfers. Unless you were using an ATAPI (i.e. CD/DVD)
> device on the channel this wouldn't affect you anyway.

I wondered about it, because the flag is cleared when adma_enabled is 1,
which seems to be consistent with everything but nv_adma_check_atapi_dma.
Thus I thought that nv_adma_check_atapi_dma might be wrong, but maybe
setting/clearing the flag is wrong instead? *feels lost*

> I'll try your stress test when I get a chance, but I doubt I'll run into
> the same problem and I haven't seen any similar reports. Perhaps it's
> some kind of wierd timing issue or incompatibility between the
> controller and that drive when running in ADMA mode? I seem to remember
> various reports of issues with certain Maxtor drives and some nForce
> SATA controllers under Windows at least..

I just checked Maxtor's knowledge base, that incompatibility does not
affect my drive.

Thanks,
Bj?rn

2007-01-16 01:51:27

by Jeff Garzik

Subject: Re: SATA exceptions with 2.6.20-rc5

Jens Axboe wrote:
> On Mon, Jan 15 2007, Jeff Garzik wrote:
>> Jens Axboe wrote:
>>> I'd be surprised if the device would not obey the 7 second timeout rule
>>> that seems to be set in stone and not allow more dirty in-drive cache
>>> than it could flush out in approximately that time.
>> AFAIK Windows flush-cache timeout is 30 seconds, not 7 as with other
>> commands...
>
> Ok, 7 seconds for FLUSH_CACHE would have been nice for us too though, as
> it would pretty much guarentee lower latencies for random writes and
> write back caching. The concern is the barrier code, of course. I guess
> I should do some timings on potential worst case patterns some day. Alan
> may have done that sometime in the past, iirc.

FWIW: According to the drive guys (Eric M, among others), FLUSH CACHE
will "probably" be under 30 seconds, but pathological cases might even
extend beyond that.

Definitely more than 7 seconds in less-than-pathological cases,
unfortunately...

The SCSI layer /should/ already take this (30 second timeout) into
account, for SYNCHRONIZE CACHE (and thus FLUSH CACHE for libata) but I'm
too slack to check at the moment.

Jeff

2007-01-16 01:51:49

by Jeff Garzik

Subject: Re: SATA exceptions with 2.6.20-rc5

Robert Hancock wrote:
> Note that the ATA-7 spec for FLUSH CACHE says that "This command may
> take longer than 30 s to complete."

Yep...

Jeff

2007-01-16 01:53:14

by Jeff Garzik

Subject: Re: SATA exceptions with 2.6.20-rc5

Robert Hancock wrote:
> I'll try your stress test when I get a chance, but I doubt I'll run into
> the same problem and I haven't seen any similar reports. Perhaps it's
> some kind of wierd timing issue or incompatibility between the
> controller and that drive when running in ADMA mode? I seem to remember
> various reports of issues with certain Maxtor drives and some nForce
> SATA controllers under Windows at least..


Just to eliminate things, has disabling ADMA been attempted?

It can be disabled using the sata_nv.adma module parameter.

Jeff

2007-01-16 03:00:34

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Bj?rn Steinbrink wrote:
>> It should be correct the way it is - that check is trying to prevent
>> ATAPI commands from using DMA until the slave_config function has been
>> called to set up the DMA parameters properly. When the
>> NV_ADMA_ATAPI_SETUP_COMPLETE flag is not set, this returns 1 which
>> disallows DMA transfers. Unless you were using an ATAPI (i.e. CD/DVD)
>> device on the channel this wouldn't affect you anyway.
>
> I wondered about it, because the flag is cleared when adma_enabled is 1,
> which seems to be consistent with everything but nv_adma_check_atapi_dma.

When ADMA is enabled we can't use ATAPI at all (or so says NVidia
anyway), so it has to be disabled when an ATAPI device is detected in
slave_config. Since doing that implies using the legacy BMDMA engine
with its greater restrictions, this is why we need to prevent DMA
transfers from being attempted until those restrictions have been set
properly. (Otherwise, the libata core will try to use PACKET commands on
an ATAPI device with DMA enabled before slave_config is even called.)

> Thus I thought that nv_adma_check_atapi_dma might be wrong, but maybe
> setting/clearing the flag is wrong instead? *feels lost*

--
Robert Hancock Saskatoon, SK, Canada
To email, remove "nospam" from [email protected]
Home Page: http://www.roberthancock.com/

2007-01-19 00:11:41

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

I heard from Larry Walton who was apparently seeing this problem as
well. He tried my recent "sata_nv: cleanup ADMA error handling v2" patch
and originally thought it fixed the problem, but it turned out to only
make it happen less often.

I wouldn't expect that patch to have an effect on this problem. If it
seems to reduce the frequency that would tend to be further evidence of
some kind of timing-related issue where the code change just happens
to make a difference.

I'll see if I can come up with a debug patch for people having this
problem to try, which prints out when a flush command is issued and what
interrupts happen when a flush is pending.

There is one important difference between ADMA and non-ADMA mode for
non-DMA commands like flushes, which didn't come to mind before: ADMA
mode uses MMIO registers on the controller whereas non-ADMA mode uses
legacy IO registers. Posted write flushing is a concern with MMIO
registers but not with PIO, the libata core is supposed to handle this
but maybe it doesn't in some case(s). In fact, just looking at
libata-sff.c there's this comment on the ata_exec_command_mmio function:

* FIXME: missing write posting for 400nS delay enforcement

That seems a bit suspicious..

--
Robert Hancock Saskatoon, SK, Canada
To email, remove "nospam" from [email protected]
Home Page: http://www.roberthancock.com/

2007-01-19 00:52:55

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.18 18:09:50 -0600, Robert Hancock wrote:
> I heard from Larry Walton who was apparently seeing this problem as
> well. He tried my recent "sata_nv: cleanup ADMA error handling v2" patch
> and originally thought it fixed the problem, but it turned out to only
> make it happen less often.
>
> I wouldn't expect that patch to have an effect on this problem. If it
> seems to reduce the frequency that would tend to be further evidence of
> some kind of timing-related issue where the code change just happens
> to make a difference.
>
> I'll see if I can come up with a debug patch for people having this
> problem to try, which prints out when a flush command is issued and what
> interrupts happen when a flush is pending.
>
> There is one important difference between ADMA and non-ADMA mode for
> non-DMA commands like flushes, which didn't come to mind before: ADMA
> mode uses MMIO registers on the controller whereas non-ADMA mode uses
> legacy IO registers. Posted write flushing is a concern with MMIO
> registers but not with PIO, the libata core is supposed to handle this
> but maybe it doesn't in some case(s). In fact, just looking at
> libata-sff.c there's this comment on the ata_exec_command_mmio function:
>
> * FIXME: missing write posting for 400nS delay enforcement
>
> That seems a bit suspicious..

That would imply that disabling adma via a module parameter should make
the issue go away, right? I'll try to have a test run with adma disabled
over night then.

Thanks,
Bj?rn

2007-01-19 14:53:18

by Alistair John Strachan

Subject: Re: SATA exceptions with 2.6.20-rc5

On Tuesday 16 January 2007 00:34, Robert Hancock wrote:
> I'll try your stress test when I get a chance, but I doubt I'll run into
> the same problem and I haven't seen any similar reports. Perhaps it's
> some kind of wierd timing issue or incompatibility between the
> controller and that drive when running in ADMA mode? I seem to remember
> various reports of issues with certain Maxtor drives and some nForce
> SATA controllers under Windows at least..

I have exactly the same problem on -rc5 and it causes all I/O to stall
periodically if I do _anything_ I/O intensive.

On my box, I have 4 sata_nv handled SATA ports, with two pairs of different
drives (two Maxtor, two WD) and it happens randomly on both. So it's
absolutely nothing to do with the drive make/model.

I'll try Jeff's suggestion of disabling ADMA now, but I think something more
radical than this workaround should make it into 2.6.20 final, otherwise a
lot of people are going to have broken boxes.

--
Cheers,
Alistair.

Final year Computer Science undergraduate.
1F2 55 South Clerk Street, Edinburgh, UK.

2007-01-19 15:05:38

by Alistair John Strachan

Subject: Re: SATA exceptions with 2.6.20-rc5

On Tuesday 16 January 2007 01:53, Jeff Garzik wrote:
> Robert Hancock wrote:
> > I'll try your stress test when I get a chance, but I doubt I'll run into
> > the same problem and I haven't seen any similar reports. Perhaps it's
> > some kind of wierd timing issue or incompatibility between the
> > controller and that drive when running in ADMA mode? I seem to remember
> > various reports of issues with certain Maxtor drives and some nForce
> > SATA controllers under Windows at least..
>
> Just to eliminate things, has disabling ADMA been attempted?
>
> It can be disabled using the sata_nv.adma module parameter.

Setting this option fixes the problem for me. I suggest that ADMA defaults off
in 2.6.20, if there's still time to do that.

--
Cheers,
Alistair.

Final year Computer Science undergraduate.
1F2 55 South Clerk Street, Edinburgh, UK.

2007-01-19 20:17:34

by Christian Lamparter

Subject: Re: SATA exceptions with 2.6.20-rc5

On Friday, 19. January 2007 16:05, Alistair John Strachan wrote:
> On Tuesday 16 January 2007 01:53, Jeff Garzik wrote:
> > Robert Hancock wrote:
> > > I'll try your stress test when I get a chance, but I doubt I'll run
> > > into the same problem and I haven't seen any similar reports. Perhaps
> > > it's some kind of wierd timing issue or incompatibility between the
> > > controller and that drive when running in ADMA mode? I seem to remember
> > > various reports of issues with certain Maxtor drives and some nForce
> > > SATA controllers under Windows at least..
> >
> > Just to eliminate things, has disabling ADMA been attempted?
> >
> > It can be disabled using the sata_nv.adma module parameter.
>
> Setting this option fixes the problem for me. I suggest that ADMA defaults
> off in 2.6.20, if there's still time to do that.

Not for me.
I'm still have the same trouble, but less (maybe about every hour, instead of
every 5 minutes). futhermore, I found a patch
cocktail-2.6.20-rc3.patch: http://tinyurl.com/2gza8q, which improves the
situation too!

Now, the funny thing is that I've two SATA HDDs, but only 1 causes all the
headaches.

The affected drive is a:
sda - @ata3.0 - WDC WD2500KS-00M 02.0
ATA-7, max UDMA/133, 488395055 sectors: LBA48

"ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata3.00: cmd ea/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 out
res 40/00:ff:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata3: soft resetting port
ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata3.00: configured for UDMA/133:PIO0
ata3: EH complete
SCSI device sda: 488395055 512-byte hdwr sectors (250058 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00"

the "good" HDD is a:
sdb - @ata4.0 - WDC WD2500YD-01N 10.0
ATA-7, max UDMA/133, 490234752 sectors: LBA48 NCQ (depth 0/1)

System:
AMD64 4200+
nForce 4 SLI
2 GB
SMP PREEMPT kernel

2007-01-20 02:41:53

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

--- linux-2.6.20-rc5/drivers/ata/sata_nv.c 2007-01-19 19:18:53.000000000 -0600
+++ linux-2.6.20-rc5debug/drivers/ata/sata_nv.c 2007-01-19 20:25:31.000000000 -0600
@@ -245,6 +245,7 @@ static void nv_adma_bmdma_setup(struct a
static void nv_adma_bmdma_start(struct ata_queued_cmd *qc);
static void nv_adma_bmdma_stop(struct ata_queued_cmd *qc);
static u8 nv_adma_bmdma_status(struct ata_port *ap);
+static void nv_adma_exec_command(struct ata_port *ap, const struct ata_taskfile *tf);

enum nv_host_type
{
@@ -409,7 +410,7 @@ static const struct ata_port_operations
.tf_load = ata_tf_load,
.tf_read = ata_tf_read,
.check_atapi_dma = nv_adma_check_atapi_dma,
- .exec_command = ata_exec_command,
+ .exec_command = nv_adma_exec_command,
.check_status = ata_check_status,
.dev_select = ata_std_dev_select,
.bmdma_setup = nv_adma_bmdma_setup,
@@ -617,6 +618,14 @@ static int nv_adma_check_atapi_dma(struc
return !(pp->flags & NV_ADMA_ATAPI_SETUP_COMPLETE);
}

+static void nv_adma_exec_command(struct ata_port *ap, const struct ata_taskfile *tf)
+{
+ void __iomem* mmio = nv_adma_ctl_block(ap);
+ writeb(tf->command, (void __iomem *) ap->ioaddr.command_addr);
+ readw(mmio + NV_ADMA_CTL); /* flush */
+ ndelay(400);
+}
+
static unsigned int nv_adma_tf_to_cpb(struct ata_taskfile *tf, __le16 *cpb)
{
unsigned int idx = 0;
@@ -701,6 +710,9 @@ static int nv_host_intr(struct ata_port
{
struct ata_queued_cmd *qc = ata_qc_from_tag(ap, ap->active_tag);
int handled;
+ u8 cmd = 0;
+ if(qc)
+ cmd = qc->tf.command;

/* freeze if hotplugged */
if (unlikely(irq_stat & (NV_INT_ADDED | NV_INT_REMOVED))) {
@@ -709,8 +721,11 @@ static int nv_host_intr(struct ata_port
}

/* bail out if not our interrupt */
- if (!(irq_stat & NV_INT_DEV))
+ if (!(irq_stat & NV_INT_DEV)) {
+ if( cmd == ATA_CMD_FLUSH || cmd == ATA_CMD_FLUSH_EXT )
+ ata_port_printk(ap, KERN_NOTICE, "cmd 0x%x active but stat 0x%x\n", cmd, irq_stat);
return 0;
+ }

/* DEV interrupt w/ no active qc? */
if (unlikely(!qc || (qc->tf.flags & ATA_TFLAG_POLLING))) {
@@ -720,6 +735,8 @@ static int nv_host_intr(struct ata_port

/* handle interrupt */
handled = ata_host_intr(ap, qc);
+ if( cmd == ATA_CMD_FLUSH || cmd == ATA_CMD_FLUSH_EXT )
+ ata_port_printk(ap, KERN_NOTICE, "cmd 0x%x active, stat = 0x%x, handled = 0x%x\n", cmd, irq_stat, handled);
if (unlikely(!handled)) {
/* spurious, clear it */
ata_check_status(ap);
@@ -870,7 +887,7 @@ static void nv_adma_bmdma_setup(struct a
outb(dmactl, ap->ioaddr.bmdma_addr + ATA_DMA_CMD);

/* issue r/w command */
- ata_exec_command(ap, &qc->tf);
+ nv_adma_exec_command(ap, &qc->tf);
}

static void nv_adma_bmdma_start(struct ata_queued_cmd *qc)
@@ -1161,6 +1178,9 @@ static unsigned int nv_adma_qc_issue(str
/* use ATA register mode */
VPRINTK("no dmamap or ATAPI, using ATA register mode: 0x%lx\n", qc->flags);
nv_adma_register_mode(qc->ap);
+ if(qc->tf.command == ATA_CMD_FLUSH ||
+ qc->tf.command == ATA_CMD_FLUSH_EXT )
+ ata_port_printk(qc->ap, KERN_NOTICE, "issue flush cmd 0x%x\n", qc->tf.command);
return ata_qc_issue_prot(qc);
} else
nv_adma_mode(qc->ap);

Attachments:

2007-01-20 02:47:50

by Alistair John Strachan

Subject: Re: SATA exceptions with 2.6.20-rc5

On Saturday 20 January 2007 02:41, Robert Hancock wrote:
> By the way, I assume that you guys are using reiserfs or xfs, as it
> appears no other file systems issue flush commands automatically. I had
> to test this by "echo 1 > delete" on the SCSI disk in sysfs, as I am
> using ext3.

I'll give it a spin now, and yes I'm using several large XFS partitions on
this machine, layered on top of md RAID5. That's why this particular defect
is so catastrophic (literally _everything_ is stalled).

--
Cheers,
Alistair.

Final year Computer Science undergraduate.
1F2 55 South Clerk Street, Edinburgh, UK.

2007-01-20 04:15:43

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.19 20:41:36 -0600, Robert Hancock wrote:
> Alistair John Strachan wrote:
> >On Tuesday 16 January 2007 01:53, Jeff Garzik wrote:
> >>Robert Hancock wrote:
> >>>I'll try your stress test when I get a chance, but I doubt I'll run into
> >>>the same problem and I haven't seen any similar reports. Perhaps it's
> >>>some kind of wierd timing issue or incompatibility between the
> >>>controller and that drive when running in ADMA mode? I seem to remember
> >>>various reports of issues with certain Maxtor drives and some nForce
> >>>SATA controllers under Windows at least..
> >>Just to eliminate things, has disabling ADMA been attempted?
> >>
> >>It can be disabled using the sata_nv.adma module parameter.
> >
> >Setting this option fixes the problem for me. I suggest that ADMA defaults
> >off in 2.6.20, if there's still time to do that.
> >
>
> Can you guys that are having this problem try the attached debug patch?
> It's possible it will fix the problem, as I'm trying a private
> exec_command implementation that flushes the write by reading a
> controller register instead of reading altstatus from the drive like the
> libata core code does.

Will give it a spin in about an hour.

> If the problem still happens, I also added some more debugging in to
> help figure out what is going on, so please post full dmesg.
>
> By the way, I assume that you guys are using reiserfs or xfs, as it
> appears no other file systems issue flush commands automatically. I had
> to test this by "echo 1 > delete" on the SCSI disk in sysfs, as I am
> using ext3.

No, ext3 here, on top of md RAID1 and LVM. Oh, and one ext2, I wonder
where that comes from...

Bj?rn

2007-01-20 07:50:12

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

Darn, didn't remove enough stuff (hit the 100K limit), next try. Sorry
if anyone gets this duplicated for whatever reason.

On 2007.01.20 08:27:55 +0100, Bj?rn Steinbrink wrote:
> On 2007.01.19 20:41:36 -0600, Robert Hancock wrote:
> > Alistair John Strachan wrote:
> > >On Tuesday 16 January 2007 01:53, Jeff Garzik wrote:
> > >>Robert Hancock wrote:
> > >>>I'll try your stress test when I get a chance, but I doubt I'll run into
> > >>>the same problem and I haven't seen any similar reports. Perhaps it's
> > >>>some kind of wierd timing issue or incompatibility between the
> > >>>controller and that drive when running in ADMA mode? I seem to remember
> > >>>various reports of issues with certain Maxtor drives and some nForce
> > >>>SATA controllers under Windows at least..
> > >>Just to eliminate things, has disabling ADMA been attempted?
> > >>
> > >>It can be disabled using the sata_nv.adma module parameter.
> > >
> > >Setting this option fixes the problem for me. I suggest that ADMA defaults
> > >off in 2.6.20, if there's still time to do that.
> > >
> >
> > Can you guys that are having this problem try the attached debug patch?
> > It's possible it will fix the problem, as I'm trying a private
> > exec_command implementation that flushes the write by reading a
> > controller register instead of reading altstatus from the drive like the
> > libata core code does.
> >
> > If the problem still happens, I also added some more debugging in to
> > help figure out what is going on, so please post full dmesg.
>
> Running it with my little test case produced almost 1MB of dmesg before
> it hit an exception. I'm not exactly sure, but the delay caused by that
> exception seemed to be about twice as long as without the patch, could
> be my imagination though...
>
> As the messages seem to be the same all the time, I snipped a good bunch
> out of the log, if you really want to see the whole thing, let me know.
>
> Thanks,
> Bj?rn
>
>
>
> Jan 20 07:14:55 atjola syslog-ng[1592]: syslog-ng starting up; version='2.0.0'
> Jan 20 07:14:55 atjola kernel: Linux version 2.6.20-rc5-sata (doener@atjola) (gcc version 4.1.2 20061115 (prerelease) (Debian 4.1.1-21)) #7 SMP Sat Jan 20 07:11:46 CET 2007
> Jan 20 07:14:55 atjola kernel: Command line: root=/dev/md0 ro quiet
> Jan 20 07:14:55 atjola kernel: BIOS-provided physical RAM map:
> Jan 20 07:14:55 atjola kernel: BIOS-e820: 0000000000000000 - 000000000009f000 (usable)
> Jan 20 07:14:55 atjola kernel: BIOS-e820: 000000000009f000 - 00000000000a0000 (reserved)
> Jan 20 07:14:55 atjola kernel: BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
> Jan 20 07:14:55 atjola kernel: BIOS-e820: 0000000000100000 - 000000007fee0000 (usable)
> Jan 20 07:14:55 atjola kernel: BIOS-e820: 000000007fee0000 - 000000007fee3000 (ACPI NVS)
> Jan 20 07:14:55 atjola kernel: BIOS-e820: 000000007fee3000 - 000000007fef0000 (ACPI data)
> Jan 20 07:14:55 atjola kernel: BIOS-e820: 000000007fef0000 - 000000007ff00000 (reserved)
> Jan 20 07:14:55 atjola kernel: BIOS-e820: 00000000e0000000 - 00000000f0000000 (reserved)
> Jan 20 07:14:55 atjola kernel: BIOS-e820: 00000000fec00000 - 0000000100000000 (reserved)
> Jan 20 07:14:55 atjola kernel: Entering add_active_range(0, 0, 159) 0 entries of 256 used
> Jan 20 07:14:55 atjola kernel: Entering add_active_range(0, 256, 524000) 1 entries of 256 used
> Jan 20 07:14:55 atjola kernel: end_pfn_map = 1048576
> Jan 20 07:14:55 atjola kernel: DMI 2.2 present.
> Jan 20 07:14:55 atjola kernel: ACPI: RSDP (v000 Nvidia ) @ 0x00000000000f7a70
> Jan 20 07:14:55 atjola kernel: ACPI: RSDT (v001 Nvidia AWRDACPI 0x42302e31 AWRD 0x00000000) @ 0x000000007fee3040
> Jan 20 07:14:55 atjola kernel: ACPI: FADT (v001 Nvidia AWRDACPI 0x42302e31 AWRD 0x00000000) @ 0x000000007fee30c0
> Jan 20 07:14:55 atjola kernel: ACPI: SSDT (v001 PTLTD POWERNOW 0x00000001 LTP 0x00000001) @ 0x000000007fee9540
> Jan 20 07:14:55 atjola kernel: ACPI: SRAT (v001 AMD HAMMER 0x00000001 AMD 0x00000001) @ 0x000000007fee9780
> Jan 20 07:14:55 atjola kernel: ACPI: MADT (v001 Nvidia AWRDACPI 0x42302e31 AWRD 0x00000000) @ 0x000000007fee9480
> Jan 20 07:14:55 atjola kernel: ACPI: DSDT (v001 NVIDIA AWRDACPI 0x00001000 MSFT 0x0100000e) @ 0x0000000000000000
> Jan 20 07:14:55 atjola kernel: Entering add_active_range(0, 0, 159) 0 entries of 256 used
> Jan 20 07:14:55 atjola kernel: Entering add_active_range(0, 256, 524000) 1 entries of 256 used
> Jan 20 07:14:55 atjola kernel: Zone PFN ranges:
> Jan 20 07:14:55 atjola kernel: DMA 0 -> 4096
> Jan 20 07:14:55 atjola kernel: DMA32 4096 -> 1048576
> Jan 20 07:14:55 atjola kernel: Normal 1048576 -> 1048576
> Jan 20 07:14:55 atjola kernel: early_node_map[2] active PFN ranges
> Jan 20 07:14:55 atjola kernel: 0: 0 -> 159
> Jan 20 07:14:55 atjola kernel: 0: 256 -> 524000
> Jan 20 07:14:55 atjola kernel: On node 0 totalpages: 523903
> Jan 20 07:14:55 atjola kernel: DMA zone: 56 pages used for memmap
> Jan 20 07:14:55 atjola kernel: DMA zone: 1122 pages reserved
> Jan 20 07:14:55 atjola kernel: DMA zone: 2821 pages, LIFO batch:0
> Jan 20 07:14:55 atjola kernel: DMA32 zone: 7108 pages used for memmap
> Jan 20 07:14:55 atjola kernel: DMA32 zone: 512796 pages, LIFO batch:31
> Jan 20 07:14:55 atjola kernel: Normal zone: 0 pages used for memmap
> Jan 20 07:14:55 atjola kernel: Nvidia board detected. Ignoring ACPI timer override.
> Jan 20 07:14:55 atjola kernel: If you got timer trouble try acpi_use_timer_override
> Jan 20 07:14:55 atjola kernel: ACPI: PM-Timer IO Port: 0x1008
> Jan 20 07:14:55 atjola kernel: ACPI: Local APIC address 0xfee00000
> Jan 20 07:14:55 atjola kernel: ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
> Jan 20 07:14:55 atjola kernel: Processor #0 (Bootup-CPU)
> Jan 20 07:14:55 atjola kernel: ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled)
> Jan 20 07:14:55 atjola kernel: Processor #1
> Jan 20 07:14:55 atjola kernel: ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
> Jan 20 07:14:55 atjola kernel: ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
> Jan 20 07:14:55 atjola kernel: ACPI: IOAPIC (id[0x02] address[0xfec00000] gsi_base[0])
> Jan 20 07:14:55 atjola kernel: IOAPIC[0]: apic_id 2, address 0xfec00000, GSI 0-23
> Jan 20 07:14:55 atjola kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
> Jan 20 07:14:55 atjola kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 14 global_irq 14 high edge)
> Jan 20 07:14:55 atjola kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 15 global_irq 15 high edge)
> Jan 20 07:14:55 atjola kernel: ACPI: IRQ9 used by override.
> Jan 20 07:14:55 atjola kernel: ACPI: IRQ14 used by override.
> Jan 20 07:14:55 atjola kernel: ACPI: IRQ15 used by override.
> Jan 20 07:14:55 atjola kernel: Setting APIC routing to flat
> Jan 20 07:14:55 atjola kernel: Using ACPI (MADT) for SMP configuration information
> Jan 20 07:14:55 atjola kernel: Nosave address range: 000000000009f000 - 00000000000a0000
> Jan 20 07:14:55 atjola kernel: Nosave address range: 00000000000a0000 - 00000000000f0000
> Jan 20 07:14:55 atjola kernel: Nosave address range: 00000000000f0000 - 0000000000100000
> Jan 20 07:14:55 atjola kernel: Allocating PCI resources starting at 80000000 (gap: 7ff00000:60100000)
> Jan 20 07:14:55 atjola kernel: PERCPU: Allocating 32000 bytes of per cpu data
> Jan 20 07:14:55 atjola kernel: Built 1 zonelists. Total pages: 515617
> Jan 20 07:14:55 atjola kernel: Kernel command line: root=/dev/md0 ro quiet
> Jan 20 07:14:55 atjola kernel: Initializing CPU#0
> Jan 20 07:14:55 atjola kernel: PID hash table entries: 4096 (order: 12, 32768 bytes)
> Jan 20 07:14:55 atjola kernel: Console: colour VGA+ 80x25
> Jan 20 07:14:55 atjola kernel: Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes)
> Jan 20 07:14:55 atjola kernel: Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes)
> Jan 20 07:14:55 atjola kernel: Checking aperture...
> Jan 20 07:14:55 atjola kernel: CPU 0: aperture @ 7a74000000 size 32 MB
> Jan 20 07:14:55 atjola kernel: Aperture too small (32 MB)
> Jan 20 07:14:55 atjola kernel: No AGP bridge found
> Jan 20 07:14:55 atjola kernel: Memory: 2059000k/2096000k available (2796k kernel code, 36392k reserved, 1088k data, 224k init)
> Jan 20 07:14:55 atjola kernel: Calibrating delay using timer specific routine.. 2010.39 BogoMIPS (lpj=10051993)
> Jan 20 07:14:55 atjola kernel: Mount-cache hash table entries: 256
> Jan 20 07:14:55 atjola kernel: CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
> Jan 20 07:14:55 atjola kernel: CPU: L2 Cache: 1024K (64 bytes/line)
> Jan 20 07:14:55 atjola kernel: CPU: Physical Processor ID: 0
> Jan 20 07:14:55 atjola kernel: CPU: Processor Core ID: 0
> Jan 20 07:14:55 atjola kernel: Freeing SMP alternatives: 28k freed
> Jan 20 07:14:55 atjola kernel: ACPI: Core revision 20060707
> Jan 20 07:14:55 atjola kernel: Using local APIC timer interrupts.
> Jan 20 07:14:55 atjola kernel: result 12558007
> Jan 20 07:14:55 atjola kernel: Detected 12.558 MHz APIC timer.
> Jan 20 07:14:55 atjola kernel: Booting processor 1/2 APIC 0x1
> Jan 20 07:14:55 atjola kernel: Initializing CPU#1
> Jan 20 07:14:55 atjola kernel: Calibrating delay using timer specific routine.. 2009.30 BogoMIPS (lpj=10046526)
> Jan 20 07:14:55 atjola kernel: CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
> Jan 20 07:14:55 atjola kernel: CPU: L2 Cache: 1024K (64 bytes/line)
> Jan 20 07:14:55 atjola kernel: CPU: Physical Processor ID: 0
> Jan 20 07:14:55 atjola kernel: CPU: Processor Core ID: 1
> Jan 20 07:14:55 atjola kernel: AMD Athlon(tm) 64 X2 Dual Core Processor 4400+ stepping 02
> Jan 20 07:14:55 atjola kernel: CPU 1: Syncing TSC to CPU 0.
> Jan 20 07:14:55 atjola kernel: CPU 1: synchronized TSC with CPU 0 (last diff 22 cycles, maxerr 344 cycles)
> Jan 20 07:14:55 atjola kernel: Brought up 2 CPUs
> Jan 20 07:14:55 atjola kernel: testing NMI watchdog ... OK.
> Jan 20 07:14:55 atjola kernel: Disabling vsyscall due to use of PM timer
> Jan 20 07:14:55 atjola kernel: time.c: Using 3.579545 MHz WALL PM GTOD PM timer.
> Jan 20 07:14:55 atjola kernel: time.c: Detected 1004.639 MHz processor.
> Jan 20 07:14:55 atjola kernel: migration_cost=453
> Jan 20 07:14:55 atjola kernel: NET: Registered protocol family 16
> Jan 20 07:14:55 atjola kernel: ACPI: bus type pci registered
> Jan 20 07:14:55 atjola kernel: PCI: Using configuration type 1
> Jan 20 07:14:55 atjola kernel: ACPI: Interpreter enabled
> Jan 20 07:14:55 atjola kernel: ACPI: Using IOAPIC for interrupt routing
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Root Bridge [PCI0] (0000:00)
> Jan 20 07:14:55 atjola kernel: PCI: Probing PCI hardware (bus 00)
> Jan 20 07:14:55 atjola kernel: PCI: Transparent bridge - 0000:00:09.0
> Jan 20 07:14:55 atjola kernel: Boot video device is 0000:05:00.0
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.HUB0._PRT]
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LNK1] (IRQs 3 5 7 9 10 *11 12 14 15)
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LNK2] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LNK3] (IRQs 3 *5 7 9 10 11 12 14 15)
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LNK4] (IRQs 3 5 7 9 *10 11 12 14 15)
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LNK5] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LUBA] (IRQs 3 *5 7 9 10 11 12 14 15)
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LUBB] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LMAC] (IRQs 3 5 *7 9 10 11 12 14 15)
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LACI] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LMCI] (IRQs *3 5 7 9 10 11 12 14 15)
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LSMB] (IRQs 3 5 *7 9 10 11 12 14 15)
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LUB2] (IRQs 3 5 7 9 *10 11 12 14 15)
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LIDE] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LSID] (IRQs 3 5 7 9 10 *11 12 14 15)
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LFID] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [LPCA] (IRQs 3 5 7 9 10 11 12 14 15) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APC1] (IRQs 16) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APC2] (IRQs 17) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APC3] (IRQs 18) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APC4] (IRQs 19) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APC5] (IRQs *16), disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCF] (IRQs 20 21 22 23) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCG] (IRQs 20 21 22 23) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCH] (IRQs 20 21 22 23) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCJ] (IRQs 20 21 22 23) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCK] (IRQs 20 21 22 23) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCS] (IRQs 20 21 22 23) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCL] (IRQs 20 21 22 23) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCZ] (IRQs 20 21 22 23) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APSI] (IRQs 20 21 22 23) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APSJ] (IRQs 20 21 22 23) *0, disabled.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCP] (IRQs 20 21 22 23) *0, disabled.
> Jan 20 07:14:55 atjola kernel: SCSI subsystem initialized
> Jan 20 07:14:55 atjola kernel: libata version 2.00 loaded.
> Jan 20 07:14:55 atjola kernel: usbcore: registered new interface driver usbfs
> Jan 20 07:14:55 atjola kernel: usbcore: registered new interface driver hub
> Jan 20 07:14:55 atjola kernel: usbcore: registered new device driver usb
> Jan 20 07:14:55 atjola kernel: PCI: Using ACPI for IRQ routing
> Jan 20 07:14:55 atjola kernel: PCI: If a device doesn't work, try "pci=routeirq". If it helps, post a report
> Jan 20 07:14:55 atjola kernel: PCI: Bridge: 0000:00:09.0
> Jan 20 07:14:55 atjola kernel: IO window: c000-cfff
> Jan 20 07:14:55 atjola kernel: MEM window: fc000000-fdffffff
> Jan 20 07:14:55 atjola kernel: PREFETCH window: fea00000-feafffff
> Jan 20 07:14:55 atjola kernel: PCI: Bridge: 0000:00:0b.0
> Jan 20 07:14:55 atjola kernel: IO window: b000-bfff
> Jan 20 07:14:55 atjola kernel: MEM window: fe900000-fe9fffff
> Jan 20 07:14:55 atjola kernel: PREFETCH window: fe800000-fe8fffff
> Jan 20 07:14:55 atjola kernel: PCI: Bridge: 0000:00:0c.0
> Jan 20 07:14:55 atjola kernel: IO window: a000-afff
> Jan 20 07:14:55 atjola kernel: MEM window: fe700000-fe7fffff
> Jan 20 07:14:55 atjola kernel: PREFETCH window: fe600000-fe6fffff
> Jan 20 07:14:55 atjola kernel: PCI: Bridge: 0000:00:0d.0
> Jan 20 07:14:55 atjola kernel: IO window: 9000-9fff
> Jan 20 07:14:55 atjola kernel: MEM window: fe500000-fe5fffff
> Jan 20 07:14:55 atjola kernel: PREFETCH window: fe400000-fe4fffff
> Jan 20 07:14:55 atjola kernel: PCI: Bridge: 0000:00:0e.0
> Jan 20 07:14:55 atjola kernel: IO window: 8000-8fff
> Jan 20 07:14:55 atjola kernel: MEM window: f4000000-fbffffff
> Jan 20 07:14:55 atjola kernel: PREFETCH window: d0000000-dfffffff
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:09.0 to 64
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:0b.0 to 64
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:0c.0 to 64
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:0d.0 to 64
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:0e.0 to 64
> Jan 20 07:14:55 atjola kernel: NET: Registered protocol family 2
> Jan 20 07:14:55 atjola kernel: IP route cache hash table entries: 65536 (order: 7, 524288 bytes)
> Jan 20 07:14:55 atjola kernel: TCP established hash table entries: 262144 (order: 10, 4194304 bytes)
> Jan 20 07:14:55 atjola kernel: TCP bind hash table entries: 65536 (order: 8, 1048576 bytes)
> Jan 20 07:14:55 atjola kernel: TCP: Hash tables configured (established 262144 bind 65536)
> Jan 20 07:14:55 atjola kernel: TCP reno registered
> Jan 20 07:14:55 atjola kernel: io scheduler noop registered
> Jan 20 07:14:55 atjola kernel: io scheduler deadline registered (default)
> Jan 20 07:14:55 atjola kernel: 0000:00:02.1 EHCI: BIOS handoff failed (BIOS bug ?) 01010001
> Jan 20 07:14:55 atjola kernel: PCI: Found disabled HT MSI Mapping on 0000:00:0b.0
> Jan 20 07:14:55 atjola kernel: PCI: Found enabled HT MSI Mapping on 0000:00:00.0
> Jan 20 07:14:55 atjola kernel: PCI: Found disabled HT MSI Mapping on 0000:00:0c.0
> Jan 20 07:14:55 atjola kernel: PCI: Found enabled HT MSI Mapping on 0000:00:00.0
> Jan 20 07:14:55 atjola kernel: PCI: Found disabled HT MSI Mapping on 0000:00:0d.0
> Jan 20 07:14:55 atjola kernel: PCI: Found enabled HT MSI Mapping on 0000:00:00.0
> Jan 20 07:14:55 atjola kernel: PCI: Found disabled HT MSI Mapping on 0000:00:0e.0
> Jan 20 07:14:55 atjola kernel: PCI: Found enabled HT MSI Mapping on 0000:00:00.0
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:0b.0 to 64
> Jan 20 07:14:55 atjola kernel: assign_interrupt_mode Found MSI capability
> Jan 20 07:14:55 atjola kernel: Allocate Port Service[0000:00:0b.0:pcie00]
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:0c.0 to 64
> Jan 20 07:14:55 atjola kernel: assign_interrupt_mode Found MSI capability
> Jan 20 07:14:55 atjola kernel: Allocate Port Service[0000:00:0c.0:pcie00]
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:0d.0 to 64
> Jan 20 07:14:55 atjola kernel: assign_interrupt_mode Found MSI capability
> Jan 20 07:14:55 atjola kernel: Allocate Port Service[0000:00:0d.0:pcie00]
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:0e.0 to 64
> Jan 20 07:14:55 atjola kernel: assign_interrupt_mode Found MSI capability
> Jan 20 07:14:55 atjola kernel: Allocate Port Service[0000:00:0e.0:pcie00]
> Jan 20 07:14:55 atjola kernel: input: Power Button (FF) as /class/input/input0
> Jan 20 07:14:55 atjola kernel: ACPI: Power Button (FF) [PWRF]
> Jan 20 07:14:55 atjola kernel: input: Power Button (CM) as /class/input/input1
> Jan 20 07:14:55 atjola kernel: ACPI: Power Button (CM) [PWRB]
> Jan 20 07:14:55 atjola kernel: ACPI: Thermal Zone [THRM] (40 C)
> Jan 20 07:14:55 atjola kernel: Real Time Clock Driver v1.12ac
> Jan 20 07:14:55 atjola kernel: Linux agpgart interface v0.101 (c) Dave Jones
> Jan 20 07:14:55 atjola kernel: Serial: 8250/16550 driver $Revision: 1.90 $ 2 ports, IRQ sharing disabled
> Jan 20 07:14:55 atjola kernel: tg3.c:v3.72 (January 8, 2007)
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APC4] enabled at IRQ 19
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt 0000:04:00.0[A] -> Link [APC4] -> GSI 19 (level, low) -> IRQ 19
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:04:00.0 to 64
> Jan 20 07:14:55 atjola kernel: eth0: Tigon3 [partno(BCM95721) rev 4101 PHY(5750)] (PCI Express) 10/100/1000Base-T Ethernet 00:e0:81:55:09:b0
> Jan 20 07:14:55 atjola kernel: eth0: RXcsums[1] LinkChgREG[0] MIirq[0] ASF[0] Split[0] WireSpeed[1] TSOcap[1]
> Jan 20 07:14:55 atjola kernel: eth0: dma_rwctrl[76180000] dma_mask[64-bit]
> Jan 20 07:14:55 atjola kernel: tun: Universal TUN/TAP device driver, 1.6
> Jan 20 07:14:55 atjola kernel: tun: (C) 1999-2004 Max Krasnyansky <[email protected]>
> Jan 20 07:14:55 atjola kernel: Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
> Jan 20 07:14:55 atjola kernel: ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
> Jan 20 07:14:55 atjola kernel: NFORCE-CK804: IDE controller at PCI slot 0000:00:06.0
> Jan 20 07:14:55 atjola kernel: NFORCE-CK804: chipset revision 242
> Jan 20 07:14:55 atjola kernel: NFORCE-CK804: not 100% native mode: will probe irqs later
> Jan 20 07:14:55 atjola kernel: NFORCE-CK804: 0000:00:06.0 (rev f2) UDMA133 controller
> Jan 20 07:14:55 atjola kernel: ide0: BM-DMA at 0xe800-0xe807, BIOS settings: hda:DMA, hdb:DMA
> Jan 20 07:14:55 atjola kernel: Probing IDE interface ide0...
> Jan 20 07:14:55 atjola kernel: hda: TOSHIBA DVD-ROM SD-M1502, ATAPI CD/DVD-ROM drive
> Jan 20 07:14:55 atjola kernel: hdb: AOPEN CD-RW CRW4852 1.00 20030123, ATAPI CD/DVD-ROM drive
> Jan 20 07:14:55 atjola kernel: ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
> Jan 20 07:14:55 atjola kernel: Probing IDE interface ide1...
> Jan 20 07:14:55 atjola kernel: hda: ATAPI 48X DVD-ROM drive, 128kB Cache, UDMA(33)
> Jan 20 07:14:55 atjola kernel: Uniform CD-ROM driver Revision: 3.20
> Jan 20 07:14:55 atjola kernel: hdb: ATAPI 40X CD-ROM CD-R/RW drive, 2048kB Cache, UDMA(33)
> Jan 20 07:14:55 atjola kernel: sata_nv 0000:00:07.0: version 3.2
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APSI] enabled at IRQ 23
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt 0000:00:07.0[A] -> Link [APSI] -> GSI 23 (level, low) -> IRQ 23
> Jan 20 07:14:55 atjola kernel: sata_nv 0000:00:07.0: Using ADMA mode
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:07.0 to 64
> Jan 20 07:14:55 atjola kernel: ata1: SATA max UDMA/133 cmd 0xFFFFC20000004480 ctl 0xFFFFC200000044A0 bmdma 0xD400 irq 23
> Jan 20 07:14:55 atjola kernel: ata2: SATA max UDMA/133 cmd 0xFFFFC20000004580 ctl 0xFFFFC200000045A0 bmdma 0xD408 irq 23
> Jan 20 07:14:55 atjola kernel: scsi0 : sata_nv
> Jan 20 07:14:55 atjola kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> Jan 20 07:14:55 atjola kernel: ata1.00: ATA-7, max UDMA/133, 160086528 sectors: LBA
> Jan 20 07:14:55 atjola kernel: ata1.00: ata1: dev 0 multi count 16
> Jan 20 07:14:55 atjola kernel: ata1.00: configured for UDMA/133
> Jan 20 07:14:55 atjola kernel: scsi1 : sata_nv
> Jan 20 07:14:55 atjola kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> Jan 20 07:14:55 atjola kernel: ata2.00: ATA-7, max UDMA/133, 160086528 sectors: LBA
> Jan 20 07:14:55 atjola kernel: ata2.00: ata2: dev 0 multi count 16
> Jan 20 07:14:55 atjola kernel: ata2.00: configured for UDMA/133
> Jan 20 07:14:55 atjola kernel: scsi 0:0:0:0: Direct-Access ATA Maxtor 6Y080M0 YAR5 PQ: 0 ANSI: 5
> Jan 20 07:14:55 atjola kernel: ata1: bounce limit 0xFFFFFFFFFFFFFFFF, segment boundary 0xFFFFFFFF, hw segs 61
> Jan 20 07:14:55 atjola kernel: SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
> Jan 20 07:14:55 atjola kernel: sda: Write Protect is off
> Jan 20 07:14:55 atjola kernel: sda: Mode Sense: 00 3a 00 00
> Jan 20 07:14:55 atjola kernel: SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> Jan 20 07:14:55 atjola kernel: SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
> Jan 20 07:14:55 atjola kernel: sda: Write Protect is off
> Jan 20 07:14:55 atjola kernel: sda: Mode Sense: 00 3a 00 00
> Jan 20 07:14:55 atjola kernel: SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> Jan 20 07:14:55 atjola kernel: sda: sda1 sda2 sda3
> Jan 20 07:14:55 atjola kernel: sd 0:0:0:0: Attached scsi disk sda
> Jan 20 07:14:55 atjola kernel: scsi 1:0:0:0: Direct-Access ATA Maxtor 6Y080M0 YAR5 PQ: 0 ANSI: 5
> Jan 20 07:14:55 atjola kernel: ata2: bounce limit 0xFFFFFFFFFFFFFFFF, segment boundary 0xFFFFFFFF, hw segs 61
> Jan 20 07:14:55 atjola kernel: SCSI device sdb: 160086528 512-byte hdwr sectors (81964 MB)
> Jan 20 07:14:55 atjola kernel: sdb: Write Protect is off
> Jan 20 07:14:55 atjola kernel: sdb: Mode Sense: 00 3a 00 00
> Jan 20 07:14:55 atjola kernel: SCSI device sdb: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> Jan 20 07:14:55 atjola kernel: SCSI device sdb: 160086528 512-byte hdwr sectors (81964 MB)
> Jan 20 07:14:55 atjola kernel: sdb: Write Protect is off
> Jan 20 07:14:55 atjola kernel: sdb: Mode Sense: 00 3a 00 00
> Jan 20 07:14:55 atjola kernel: SCSI device sdb: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> Jan 20 07:14:55 atjola kernel: sdb: sdb1 sdb2 sdb3
> Jan 20 07:14:55 atjola kernel: sd 1:0:0:0: Attached scsi disk sdb
> Jan 20 07:14:55 atjola kernel: usbmon: debugfs is not available
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCL] enabled at IRQ 22
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt 0000:00:02.1[B] -> Link [APCL] -> GSI 22 (level, low) -> IRQ 22
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:02.1 to 64
> Jan 20 07:14:55 atjola kernel: ehci_hcd 0000:00:02.1: EHCI Host Controller
> Jan 20 07:14:55 atjola kernel: ehci_hcd 0000:00:02.1: new USB bus registered, assigned bus number 1
> Jan 20 07:14:55 atjola kernel: ehci_hcd 0000:00:02.1: debug port 1
> Jan 20 07:14:55 atjola kernel: PCI: cache line size of 64 is not supported by device 0000:00:02.1
> Jan 20 07:14:55 atjola kernel: ehci_hcd 0000:00:02.1: irq 22, io mem 0xfeb00000
> Jan 20 07:14:55 atjola kernel: ehci_hcd 0000:00:02.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
> Jan 20 07:14:55 atjola kernel: usb usb1: configuration #1 chosen from 1 choice
> Jan 20 07:14:55 atjola kernel: hub 1-0:1.0: USB hub found
> Jan 20 07:14:55 atjola kernel: hub 1-0:1.0: 8 ports detected
> Jan 20 07:14:55 atjola kernel: ohci_hcd: 2006 August 04 USB 1.1 'Open' Host Controller (OHCI) Driver (PCI)
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCF] enabled at IRQ 21
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt 0000:00:02.0[A] -> Link [APCF] -> GSI 21 (level, low) -> IRQ 21
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:02.0 to 64
> Jan 20 07:14:55 atjola kernel: ohci_hcd 0000:00:02.0: OHCI Host Controller
> Jan 20 07:14:55 atjola kernel: ohci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2
> Jan 20 07:14:55 atjola kernel: ohci_hcd 0000:00:02.0: irq 21, io mem 0xfebff000
> Jan 20 07:14:55 atjola kernel: usb usb2: configuration #1 chosen from 1 choice
> Jan 20 07:14:55 atjola kernel: hub 2-0:1.0: USB hub found
> Jan 20 07:14:55 atjola kernel: hub 2-0:1.0: 8 ports detected
> Jan 20 07:14:55 atjola kernel: usb 1-5: new high speed USB device using ehci_hcd and address 2
> Jan 20 07:14:55 atjola kernel: usb 1-5: configuration #1 chosen from 1 choice
> Jan 20 07:14:55 atjola kernel: usb 2-6: new full speed USB device using ohci_hcd and address 2
> Jan 20 07:14:55 atjola kernel: usb 2-6: configuration #1 chosen from 1 choice
> Jan 20 07:14:55 atjola kernel: hub 2-6:1.0: USB hub found
> Jan 20 07:14:55 atjola kernel: hub 2-6:1.0: 4 ports detected
> Jan 20 07:14:55 atjola kernel: drivers/usb/class/usblp.c: usblp0: USB Bidirectional printer dev 2 if 0 alt 0 proto 2 vid 0x04F9 pid 0x0022
> Jan 20 07:14:55 atjola kernel: usb 2-6.3: new low speed USB device using ohci_hcd and address 3
> Jan 20 07:14:55 atjola kernel: usb 2-6.3: configuration #1 chosen from 1 choice
> Jan 20 07:14:55 atjola kernel: usb 2-6.4: new low speed USB device using ohci_hcd and address 4
> Jan 20 07:14:55 atjola kernel: usb 2-6.4: configuration #1 chosen from 1 choice
> Jan 20 07:14:55 atjola kernel: usbcore: registered new interface driver usblp
> Jan 20 07:14:55 atjola kernel: drivers/usb/class/usblp.c: v0.13: USB Printer Device Class driver
> Jan 20 07:14:55 atjola kernel: Initializing USB Mass Storage driver...
> Jan 20 07:14:55 atjola kernel: usbcore: registered new interface driver usb-storage
> Jan 20 07:14:55 atjola kernel: USB Mass Storage support registered.
> Jan 20 07:14:55 atjola kernel: usbcore: registered new interface driver hiddev
> Jan 20 07:14:55 atjola kernel: input: Lite-On Tech IBM USB Keyboard with UltraNav as /class/input/input2
> Jan 20 07:14:55 atjola kernel: input: USB HID v1.10 Keyboard [Lite-On Tech IBM USB Keyboard with UltraNav] on usb-0000:00:02.0-6.3
> Jan 20 07:14:55 atjola kernel: input: Lite-On Tech IBM USB Keyboard with UltraNav as /class/input/input3
> Jan 20 07:14:55 atjola kernel: input: USB HID v1.10 Device [Lite-On Tech IBM USB Keyboard with UltraNav] on usb-0000:00:02.0-6.3
> Jan 20 07:14:55 atjola kernel: input: Synaptics Inc. Composite TouchPad / TrackPoint as /class/input/input4
> Jan 20 07:14:55 atjola kernel: input: USB HID v1.00 Mouse [Synaptics Inc. Composite TouchPad / TrackPoint] on usb-0000:00:02.0-6.4
> Jan 20 07:14:55 atjola kernel: input: Synaptics Inc. Composite TouchPad / TrackPoint as /class/input/input5
> Jan 20 07:14:55 atjola kernel: input: USB HID v1.00 Mouse [Synaptics Inc. Composite TouchPad / TrackPoint] on usb-0000:00:02.0-6.4
> Jan 20 07:14:55 atjola kernel: usbcore: registered new interface driver usbhid
> Jan 20 07:14:55 atjola kernel: drivers/usb/input/hid-core.c: v2.6:USB HID core driver
> Jan 20 07:14:55 atjola kernel: serio: i8042 KBD port at 0x60,0x64 irq 1
> Jan 20 07:14:55 atjola kernel: mice: PS/2 mouse device common for all mice
> Jan 20 07:14:55 atjola kernel: md: raid1 personality registered for level 1
> Jan 20 07:14:55 atjola kernel: device-mapper: ioctl: 4.11.0-ioctl (2006-10-12) initialised: [email protected]
> Jan 20 07:14:55 atjola kernel: Advanced Linux Sound Architecture Driver Version 1.0.14rc1 (Tue Jan 09 09:56:17 2007 UTC).
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt 0000:01:08.0[A] -> Link [APC4] -> GSI 19 (level, low) -> IRQ 19
> Jan 20 07:14:55 atjola kernel: gameport: EMU10K1 is pci0000:01:08.1/gameport0, io 0xc400, speed 1194kHz
> Jan 20 07:14:55 atjola kernel: input: Microsoft SideWinder GamePad as /class/input/input6
> Jan 20 07:14:55 atjola kernel: ALSA device list:
> Jan 20 07:14:55 atjola kernel: #0: Audigy 1 [SB0090] (rev.3, serial:0x531102) at 0xc800, irq 19
> Jan 20 07:14:55 atjola kernel: TCP cubic registered
> Jan 20 07:14:55 atjola kernel: NET: Registered protocol family 1
> Jan 20 07:14:55 atjola kernel: NET: Registered protocol family 17
> Jan 20 07:14:55 atjola kernel: NET: Registered protocol family 15
> Jan 20 07:14:55 atjola kernel: powernow-k8: Found 2 AMD Athlon(tm) 64 X2 Dual Core Processor 4400+ processors (version 2.00.00)
> Jan 20 07:14:55 atjola kernel: powernow-k8: 0 : fid 0xe (2200 MHz), vid 0x8
> Jan 20 07:14:55 atjola kernel: powernow-k8: 1 : fid 0xc (2000 MHz), vid 0xa
> Jan 20 07:14:55 atjola kernel: powernow-k8: 2 : fid 0xa (1800 MHz), vid 0xc
> Jan 20 07:14:55 atjola kernel: powernow-k8: 3 : fid 0x2 (1000 MHz), vid 0xe
> Jan 20 07:14:55 atjola kernel: md: Autodetecting RAID arrays.
> Jan 20 07:14:55 atjola kernel: md: autorun ...
> Jan 20 07:14:55 atjola kernel: md: considering sdb3 ...
> Jan 20 07:14:55 atjola kernel: md: adding sdb3 ...
> Jan 20 07:14:55 atjola kernel: md: sdb1 has different UUID to sdb3
> Jan 20 07:14:55 atjola kernel: md: adding sda3 ...
> Jan 20 07:14:55 atjola kernel: md: sda1 has different UUID to sdb3
> Jan 20 07:14:55 atjola kernel: md: created md1
> Jan 20 07:14:55 atjola kernel: md: bind<sda3>
> Jan 20 07:14:55 atjola kernel: md: bind<sdb3>
> Jan 20 07:14:55 atjola kernel: md: running: <sdb3><sda3>
> Jan 20 07:14:55 atjola kernel: raid1: raid set md1 active with 2 out of 2 mirrors
> Jan 20 07:14:55 atjola kernel: md: considering sdb1 ...
> Jan 20 07:14:55 atjola kernel: md: adding sdb1 ...
> Jan 20 07:14:55 atjola kernel: md: adding sda1 ...
> Jan 20 07:14:55 atjola kernel: md: created md0
> Jan 20 07:14:55 atjola kernel: md: bind<sda1>
> Jan 20 07:14:55 atjola kernel: md: bind<sdb1>
> Jan 20 07:14:55 atjola kernel: md: running: <sdb1><sda1>
> Jan 20 07:14:55 atjola kernel: raid1: raid set md0 active with 2 out of 2 mirrors
> Jan 20 07:14:55 atjola kernel: md: ... autorun DONE.
> Jan 20 07:14:55 atjola kernel: kjournald starting. Commit interval 5 seconds
> Jan 20 07:14:55 atjola kernel: EXT3-fs: mounted filesystem with ordered data mode.
> Jan 20 07:14:55 atjola kernel: VFS: Mounted root (ext3 filesystem) readonly.
> Jan 20 07:14:55 atjola kernel: Freeing unused kernel memory: 224k freed
> Jan 20 07:14:55 atjola kernel: forcedeth.c: Reverse Engineered nForce ethernet driver. Version 0.59.
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt Link [APCH] enabled at IRQ 20
> Jan 20 07:14:55 atjola kernel: ACPI: PCI Interrupt 0000:00:0a.0[A] -> Link [APCH] -> GSI 20 (level, low) -> IRQ 20
> Jan 20 07:14:55 atjola kernel: PCI: Setting latency timer of device 0000:00:0a.0 to 64
> Jan 20 07:14:55 atjola kernel: forcedeth: using HIGHDMA
> Jan 20 07:14:55 atjola kernel: eth1: forcedeth.c: subsystem: 010f1:2865 bound to 0000:00:0a.0
> Jan 20 07:14:55 atjola kernel: Adding 979956k swap on /dev/sda2. Priority:-1 extents:1 across:979956k
> Jan 20 07:14:55 atjola kernel: Adding 979956k swap on /dev/sdb2. Priority:-2 extents:1 across:979956k
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: EXT3 FS on md0, internal journal
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: kjournald starting. Commit interval 5 seconds
> Jan 20 07:14:55 atjola kernel: EXT3 FS on dm-4, internal journal
> Jan 20 07:14:55 atjola kernel: EXT3-fs: mounted filesystem with ordered data mode.
> Jan 20 07:14:55 atjola kernel: kjournald starting. Commit interval 5 seconds
> Jan 20 07:14:55 atjola kernel: EXT3 FS on dm-0, internal journal
> Jan 20 07:14:55 atjola kernel: EXT3-fs: mounted filesystem with ordered data mode.
> Jan 20 07:14:55 atjola kernel: kjournald starting. Commit interval 5 seconds
> Jan 20 07:14:55 atjola kernel: EXT3 FS on dm-1, internal journal
> Jan 20 07:14:55 atjola kernel: EXT3-fs: mounted filesystem with ordered data mode.
> Jan 20 07:14:55 atjola kernel: kjournald starting. Commit interval 5 seconds
> Jan 20 07:14:55 atjola kernel: EXT3 FS on dm-3, internal journal
> Jan 20 07:14:55 atjola kernel: EXT3-fs: mounted filesystem with ordered data mode.
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: eth1: no link during initialization.
> Jan 20 07:14:55 atjola kernel: tg3: eth0: Link is up at 100 Mbps, full duplex.
> Jan 20 07:14:55 atjola kernel: tg3: eth0: Flow control is off for TX and off for RX.
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:55 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:55 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:55 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:56 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:56 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:56 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:56 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:56 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:56 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:56 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:56 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:56 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:56 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:56 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:57 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:57 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:57 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:58 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:58 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:58 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:58 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:58 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:58 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:58 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:58 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:58 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:58 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:58 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:58 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:58 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:58 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:14:58 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:58 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:14:58 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:14:58 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:14:58 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:14:58 atjola kernel: ata1: cmd 0xe7 active but stat 0x10

[-- SNIP --]

> Jan 20 07:15:09 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:09 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:09 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:09 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:09 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:09 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:09 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:09 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:09 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:09 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:09 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:09 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:09 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:11 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:11 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:11 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:11 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:11 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:11 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:11 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:11 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:11 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:11 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:11 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:11 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:11 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:11 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:11 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:11 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:11 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:11 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:11 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:11 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:11 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:11 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:12 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:12 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:12 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:12 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:12 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:12 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:12 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:12 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:12 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:12 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:12 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:12 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:12 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:12 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:12 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:12 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:13 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:13 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:13 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:13 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:13 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1

[-- SNIP --]

> Jan 20 07:15:22 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:22 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:22 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:22 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:22 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:22 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:22 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:22 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:22 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:22 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:22 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:22 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:22 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:23 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:23 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:23 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:23 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:23 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:23 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:23 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:23 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:23 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:24 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:24 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:24 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:24 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:24 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:24 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:24 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:24 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:24 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:24 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:24 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:24 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:24 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:24 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:24 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:24 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:15:24 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:15:24 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
>
> [-- SNIP --]
>
> Jan 20 07:26:38 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:38 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:38 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:38 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:38 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:38 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:38 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:38 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:38 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:38 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:38 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:38 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:38 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:38 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:41 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:41 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:41 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:41 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:41 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:41 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:41 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:41 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:41 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:41 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:41 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:41 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:41 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:41 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:41 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:41 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:41 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:41 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:41 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:41 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:41 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:41 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:42 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:42 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:46 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:46 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:46 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:46 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:46 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:46 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:46 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:46 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:46 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:46 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:46 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:46 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:46 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:46 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:46 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:46 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:46 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:46 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:46 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:46 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:46 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:46 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:46 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:46 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:47 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:47 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:47 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:47 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:47 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:47 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:47 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1

[-- SNIP --]

> Jan 20 07:26:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:57 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:26:57 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:26:57 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:57 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:57 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:57 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:57 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:57 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:57 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:26:57 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:26:57 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:26:58 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:00 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:01 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:01 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:01 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:01 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:01 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:01 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:01 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:01 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:01 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:02 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:27 atjola kernel: ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> Jan 20 07:27:27 atjola kernel: ata1.00: cmd e7/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 in
> Jan 20 07:27:27 atjola kernel: res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Jan 20 07:27:28 atjola kernel: ata1: soft resetting port
> Jan 20 07:27:28 atjola kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> Jan 20 07:27:28 atjola kernel: ata1.00: configured for UDMA/133
> Jan 20 07:27:28 atjola kernel: ata1: EH complete
> Jan 20 07:27:28 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: SCSI device sda: 160086528 512-byte hdwr sectors (81964 MB)
> Jan 20 07:27:28 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:27:28 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: sda: Write Protect is off
> Jan 20 07:27:28 atjola kernel: sda: Mode Sense: 00 3a 00 00
> Jan 20 07:27:28 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:27:28 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:27:28 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:27:28 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> Jan 20 07:27:28 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:28 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:28 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:27:28 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:27:28 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:27:28 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: ata1: cmd 0xe7 active but stat 0x10
> Jan 20 07:27:28 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:27:28 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:27:28 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:27:28 atjola kernel: ata1: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: ata1: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:27:28 atjola kernel: ata2: cmd 0xe7 active but stat 0x0
> Jan 20 07:27:28 atjola kernel: ata2: cmd 0xe7 active, stat = 0x1, handled = 0x1
> Jan 20 07:27:28 atjola kernel: ata2: issue flush cmd 0xe7
> Jan 20 07:27:28 atjola kernel: ata1: issue flush cmd 0xe7
>
> [More of the same...]

2007-01-20 15:24:53

by Ian Kumlien

Subject: Re: SATA exceptions with 2.6.20-rc5

Hi,

I went from 2.6.19+sata_nv-adma-ncq-v7.patch, with no problems and adama
enabled, to 2.6.20-rc5, which gave me problems almost instantly.

I just thought that it might be interesting to know that it DID work
nicely.

CC since i'm not on the ml

--
Ian Kumlien <pomac () vapor ! com> -- http://pomac.netswarm.net

Attachments:

2007-01-20 18:50:40

by Christian Lamparter

Subject: Re: SATA exceptions with 2.6.20-rc5

On Saturday, 20. January 2007 03:41, Robert Hancock wrote:
> Alistair John Strachan wrote:
> > On Tuesday 16 January 2007 01:53, Jeff Garzik wrote:
> >> Robert Hancock wrote:
> >>> I'll try your stress test when I get a chance, but I doubt I'll run
> >>> into the same problem and I haven't seen any similar reports. Perhaps
> >>> it's some kind of wierd timing issue or incompatibility between the
> >>> controller and that drive when running in ADMA mode? I seem to remember
> >>> various reports of issues with certain Maxtor drives and some nForce
> >>> SATA controllers under Windows at least..
> >>
> >> Just to eliminate things, has disabling ADMA been attempted?
> >>
> >> It can be disabled using the sata_nv.adma module parameter.
> >
> > Setting this option fixes the problem for me. I suggest that ADMA
> > defaults off in 2.6.20, if there's still time to do that.
>
> Can you guys that are having this problem try the attached debug patch?
> It's possible it will fix the problem, as I'm trying a private
> exec_command implementation that flushes the write by reading a
> controller register instead of reading altstatus from the drive like the
> libata core code does.
>
> If the problem still happens, I also added some more debugging in to
> help figure out what is going on, so please post full dmesg.
>
> By the way, I assume that you guys are using reiserfs or xfs, as it
> appears no other file systems issue flush commands automatically. I had
> to test this by "echo 1 > delete" on the SCSI disk in sysfs, as I am
> using ext3.
Yes, I've some reiserfs partitions, but I don't think it's reiserfs fault ;).
Here is the log. (I cut out some parts, because it was too big.)


BTW: please CC, I'm not on the list!

Attachments:

2007-01-20 19:59:14

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Ian Kumlien wrote:
> Hi,
>
> I went from 2.6.19+sata_nv-adma-ncq-v7.patch, with no problems and adama
> enabled, to 2.6.20-rc5, which gave me problems almost instantly.
>
> I just thought that it might be interesting to know that it DID work
> nicely.
>
> CC since i'm not on the ml
>

(I'm ccing more of the people who reported this)

Well that's interesting.. The only significant change that went into
2.6.20-rc5 in that driver that wasn't in that version you mentioned was
this one:

http://www2.kernel.org/git/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=2dec7555e6bf2772749113ea0ad454fcdb8cf861

Could you (or anyone else) test what happens if you take the 2.6.20-rc5
version of sata_nv.c and try it on 2.6.19? That would tell us whether
it's this change or whether it's something else (i.e. in libata core).

Assuming that still doesn't work, can you then try removing these lines
from nv_host_intr in 2.6.20-rc5 sata_nv.c and see what that does?

/* bail out if not our interrupt */
if (!(irq_stat & NV_INT_DEV))
return 0;

as that's the difference I'm most suspicious of causing the problem.

--
Robert Hancock Saskatoon, SK, Canada
To email, remove "nospam" from [email protected]
Home Page: http://www.roberthancock.com/

2007-01-20 21:43:38

by Alistair John Strachan

Subject: Re: SATA exceptions with 2.6.20-rc5

On Saturday 20 January 2007 19:59, Robert Hancock wrote:
> Ian Kumlien wrote:
> > Hi,
> >
> > I went from 2.6.19+sata_nv-adma-ncq-v7.patch, with no problems and adama
> > enabled, to 2.6.20-rc5, which gave me problems almost instantly.
> >
> > I just thought that it might be interesting to know that it DID work
> > nicely.
> >
> > CC since i'm not on the ml
>
> (I'm ccing more of the people who reported this)
>
> Well that's interesting.. The only significant change that went into
> 2.6.20-rc5 in that driver that wasn't in that version you mentioned was
> this one:
>
> http://www2.kernel.org/git/?p=linux/kernel/git/torvalds/linux-2.6.git;a=com
>mit;h=2dec7555e6bf2772749113ea0ad454fcdb8cf861
>
> Could you (or anyone else) test what happens if you take the 2.6.20-rc5
> version of sata_nv.c and try it on 2.6.19? That would tell us whether
> it's this change or whether it's something else (i.e. in libata core).

I'm still running an -rc5 kernel with ADMA switched off entirely and I can't
reproduce the problem. How is everybody else reproducing this?

I've been successful installing bonnie++, then going to a large XFS partition
and running "bonnie++ -u 1000:1000" and letting it run through, all defaults.

It doesn't cause the problem I was seeing in -rc5 with ADMA on, when I switch
ADMA off, so I think this is sufficient to fix it.

Others have reported differently. Did you guys do:

alistair@damocles:~$ cat /proc/cmdline
root=/dev/sda1 ro sata_nv.adma=0

Or something similar? This is how Jeff suggested disabling ADMA and indeed the
messages about its use disappear from dmesg.

--
Cheers,
Alistair.

Final year Computer Science undergraduate.
1F2 55 South Clerk Street, Edinburgh, UK.

2007-01-20 22:11:49

by Ian Kumlien

Subject: Re: SATA exceptions with 2.6.20-rc5

On lör, 2007-01-20 at 21:43 +0000, Alistair John Strachan wrote:
> On Saturday 20 January 2007 19:59, Robert Hancock wrote:
> > Ian Kumlien wrote:
> > > Hi,
> > >
> > > I went from 2.6.19+sata_nv-adma-ncq-v7.patch, with no problems and adama
> > > enabled, to 2.6.20-rc5, which gave me problems almost instantly.
> > >
> > > I just thought that it might be interesting to know that it DID work
> > > nicely.
> > >
> > > CC since i'm not on the ml
> >
> > (I'm ccing more of the people who reported this)
> >
> > Well that's interesting.. The only significant change that went into
> > 2.6.20-rc5 in that driver that wasn't in that version you mentioned was
> > this one:
> >
> > http://www2.kernel.org/git/?p=linux/kernel/git/torvalds/linux-2.6.git;a=com
> >mit;h=2dec7555e6bf2772749113ea0ad454fcdb8cf861
> >
> > Could you (or anyone else) test what happens if you take the 2.6.20-rc5
> > version of sata_nv.c and try it on 2.6.19? That would tell us whether
> > it's this change or whether it's something else (i.e. in libata core).
>
> I'm still running an -rc5 kernel with ADMA switched off entirely and I can't
> reproduce the problem. How is everybody else reproducing this?
>
> I've been successful installing bonnie++, then going to a large XFS partition
> and running "bonnie++ -u 1000:1000" and letting it run through, all defaults.
>
> It doesn't cause the problem I was seeing in -rc5 with ADMA on, when I switch
> ADMA off, so I think this is sufficient to fix it.

Eh? The whole point with that patch was to ADD ADMA support to sata_nv,
imho that is something we want to have and i have been running with ADMA
on on two computers since sata_nv-adma-ncq-v4 or 5 or so without
problems.

So, something has been introduced or been broken to cause this error,
wouldn't it be better to find the error introduced than to just totally
negate the patch in the first place?

I haven't had the energy to go trough the patch that was found as
causing the problem yet... I don't know if i even have all the info
needed to make any form of educated guess but i'll give it a try when i
have the energy.

I really home someone finds it before then =)

--
Ian Kumlien <pomac () vapor ! com> -- http://pomac.netswarm.net

Attachments:

2007-01-20 22:33:06

by Christian Lamparter

Subject: Re: SATA exceptions with 2.6.20-rc5

On Saturday, 20. January 2007 20:59, you wrote:
> Ian Kumlien wrote:
> > Hi,
> >
> > I went from 2.6.19+sata_nv-adma-ncq-v7.patch, with no problems and adama
> > enabled, to 2.6.20-rc5, which gave me problems almost instantly.
> >
> > I just thought that it might be interesting to know that it DID work
> > nicely.
> >
> > CC since i'm not on the ml
>
> (I'm ccing more of the people who reported this)
>
> Well that's interesting.. The only significant change that went into
> 2.6.20-rc5 in that driver that wasn't in that version you mentioned was
> this one:
>
> http://www2.kernel.org/git/?p=linux/kernel/git/torvalds/linux-2.6.git;a=com
>mit;h=2dec7555e6bf2772749113ea0ad454fcdb8cf861
>
> Could you (or anyone else) test what happens if you take the 2.6.20-rc5
> version of sata_nv.c and try it on 2.6.19? That would tell us whether
> it's this change or whether it's something else (i.e. in libata core).

Ok, did that! (got a fresh 2.6.19 tar ball, and used 2.6.20-rc5' sata_nv.c
with the oneliner in libata_sff.c)

And surprise.................... after one hour uptime, there is not even one
sata exceptions in dmesg! (I'll report back tomorrow...)

>
> Assuming that still doesn't work, can you then try removing these lines
> from nv_host_intr in 2.6.20-rc5 sata_nv.c and see what that does?
>
> /* bail out if not our interrupt */
> if (!(irq_stat & NV_INT_DEV))
> return 0;
>
> as that's the difference I'm most suspicious of causing the problem.

Attachments:

2007-01-21 01:50:38

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Chr wrote:
>> Could you (or anyone else) test what happens if you take the 2.6.20-rc5
>> version of sata_nv.c and try it on 2.6.19? That would tell us whether
>> it's this change or whether it's something else (i.e. in libata core).
>
> Ok, did that! (got a fresh 2.6.19 tar ball, and used 2.6.20-rc5' sata_nv.c
> with the oneliner in libata_sff.c)
>
> And surprise.................... after one hour uptime, there is not even one
> sata exceptions in dmesg! (I'll report back tomorrow...)

That is interesting, indeed.. If that holds up then I assume some other
change in 2.6.20-rc is either causing or triggering this problem. It
would be useful if you could try git bisect between 2.6.19 and
2.6.20-rc5, keeping the latest sata_nv.c each time, and see if that
gives any indication. If not, just trying some of the different
2.6.20-rcX versions may be useful.

Before that, though, can you try making this change I suggested below in
2.6.20-rc5 and see if the problem still shows up?

>
>> Assuming that still doesn't work, can you then try removing these lines
>> from nv_host_intr in 2.6.20-rc5 sata_nv.c and see what that does?
>>
>> /* bail out if not our interrupt */
>> if (!(irq_stat & NV_INT_DEV))
>> return 0;
>>
>> as that's the difference I'm most suspicious of causing the problem.
>

2007-01-21 03:34:35

by Jeff Garzik

Subject: Re: SATA exceptions with 2.6.20-rc5

Robert Hancock wrote:
> change in 2.6.20-rc is either causing or triggering this problem. It
> would be useful if you could try git bisect between 2.6.19 and
> 2.6.20-rc5, keeping the latest sata_nv.c each time, and see if that


Yes, 'git bisect' would be the next step in figuring out this puzzle.

Anybody up for it?

Jeff

2007-01-21 04:54:41

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.20 22:34:27 -0500, Jeff Garzik wrote:
> Robert Hancock wrote:
> >change in 2.6.20-rc is either causing or triggering this problem. It
> >would be useful if you could try git bisect between 2.6.19 and
> >2.6.20-rc5, keeping the latest sata_nv.c each time, and see if that
>
>
> Yes, 'git bisect' would be the next step in figuring out this puzzle.
>
> Anybody up for it?

I'll go for it, but could I get an explanation how that could lead to a
different result than my last bisection? I see the difference of keeping
sata_nv.c but my brain can't wrap around it right now (woke up in the
middle of the night and still not up to speed...).

Thanks,
Bj?rn

2007-01-21 06:39:25

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Bj?rn Steinbrink wrote:
> On 2007.01.20 22:34:27 -0500, Jeff Garzik wrote:
>> Robert Hancock wrote:
>>> change in 2.6.20-rc is either causing or triggering this problem. It
>>> would be useful if you could try git bisect between 2.6.19 and
>>> 2.6.20-rc5, keeping the latest sata_nv.c each time, and see if that
>>
>> Yes, 'git bisect' would be the next step in figuring out this puzzle.
>>
>> Anybody up for it?
>
> I'll go for it, but could I get an explanation how that could lead to a
> different result than my last bisection? I see the difference of keeping
> sata_nv.c but my brain can't wrap around it right now (woke up in the
> middle of the night and still not up to speed...).

Whatever the problem is, only seems to show up when ADMA is enabled, and
so the patch that added ADMA support shows up as the culprit from your
git bisect. However, from what Chr is reporting, 2.6.19 with the ADMA
support added in doesn't seem to have the problem, so presumably
something else that changed in the 2.6.20-rc series is triggering it.
Doing a bisect while keeping the driver code itself the same will
hopefully identify what that change is..

2007-01-21 08:36:25

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.21 00:39:20 -0600, Robert Hancock wrote:
> Bj?rn Steinbrink wrote:
> >On 2007.01.20 22:34:27 -0500, Jeff Garzik wrote:
> >>Robert Hancock wrote:
> >>>change in 2.6.20-rc is either causing or triggering this problem. It
> >>>would be useful if you could try git bisect between 2.6.19 and
> >>>2.6.20-rc5, keeping the latest sata_nv.c each time, and see if that
> >>
> >>Yes, 'git bisect' would be the next step in figuring out this puzzle.
> >>
> >>Anybody up for it?
> >
> >I'll go for it, but could I get an explanation how that could lead to a
> >different result than my last bisection? I see the difference of keeping
> >sata_nv.c but my brain can't wrap around it right now (woke up in the
> >middle of the night and still not up to speed...).
>
> Whatever the problem is, only seems to show up when ADMA is enabled, and
> so the patch that added ADMA support shows up as the culprit from your
> git bisect. However, from what Chr is reporting, 2.6.19 with the ADMA
> support added in doesn't seem to have the problem, so presumably
> something else that changed in the 2.6.20-rc series is triggering it.
> Doing a bisect while keeping the driver code itself the same will
> hopefully identify what that change is..

Ah, right... sata_nv.c of course interacts with the outside world, d'oh!

Up to now, I only got bad kernels, latest tested being:
94fcda1f8ab5e0cacc381c5ca1cc9aa6ad523576

Which, unless I missed a commit in the diff, only USB changes,
continuing anyway.

Just to make sure, here's my little helper for this bisect run, I hope
it does what you expected:

#!/bin/bash
cp ../sata_nv.c.orig drivers/ata/sata_nv.c
git bisect good
cp drivers/ata/sata_nv.c ../sata_nv.c.orig
cp ../sata_nv.c drivers/ata/
make oldconfig
make -j4

Where "../sata_nv.c" is the version from 2.6.20-rc5. The copying is done
to avoid conflicts and keep git happy. Of course there's also a version
for bad kernels ;) No idea, why I didn't make that an argument to the
script...

Thanks,
Bj?rn

2007-01-21 17:36:55

by Christian Lamparter

Subject: Re: SATA exceptions with 2.6.20-rc5

On Sunday, 21. January 2007 09:36, Bj?rn Steinbrink wrote:
> On 2007.01.21 00:39:20 -0600, Robert Hancock wrote:
>
> Ah, right... sata_nv.c of course interacts with the outside world, d'oh!
>
> Up to now, I only got bad kernels, latest tested being:
> 94fcda1f8ab5e0cacc381c5ca1cc9aa6ad523576
>
> Which, unless I missed a commit in the diff, only USB changes,
> continuing anyway.
>
> Just to make sure, here's my little helper for this bisect run, I hope
> it does what you expected:
>
> #!/bin/bash
> cp ../sata_nv.c.orig drivers/ata/sata_nv.c
> git bisect good
> cp drivers/ata/sata_nv.c ../sata_nv.c.orig
> cp ../sata_nv.c drivers/ata/
> make oldconfig
> make -j4
>
> Where "../sata_nv.c" is the version from 2.6.20-rc5. The copying is done
> to avoid conflicts and keep git happy. Of course there's also a version
> for bad kernels ;) No idea, why I didn't make that an argument to the
> script...
>
> Thanks,
> Bj?rn

Argggg, 2.6.19 (with 2.6.20-rc5 adma stuff) is affected too (BTW, what do you
do to trigger the exceptions? Because, it takes hours to "reproduces" this
silly *************).

But, this time it looks slightly different:
ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata3.00: tag 0 cmd 0xec Emask 0x4 stat 0x40 err 0x0 (timeout)
ata3: soft resetting port
ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
!!!
ata3.00: failed to IDENTIFY (INIT_DEV_PARAMS failed, err_mask=0x1)
ata3.00: revalidation failed (errno=-5)
ata3: failed to recover some devices, retrying in 5 secs
!!!
ata3: hard resetting port
ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata3.00: configured for UDMA/133
ata3: EH complete
SCSI device sda: 488395055 512-byte hdwr sectors (250058 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: drive cache: write back


Oh, and I got this nice SMART Error:

ID# ATTRIBUTE_NAME FLAG RAW VALUE
199 UDMA_CRC_Error_Count 0x003e ... - 12

SMART Error Log Version: 1
ATA Error Count: 1
CR = Command Register [HEX]
FR = Features Register [HEX]
SC = Sector Count Register [HEX]
SN = Sector Number Register [HEX]
CL = Cylinder Low Register [HEX]
CH = Cylinder High Register [HEX]
DH = Device/Head Register [HEX]
DC = Device Command Register [HEX]
ER = Error register [HEX]
ST = Status register [HEX]
Powered_Up_Time is measured from power on, and printed as
DDd+hh:mm:SS.sss where DD=days, hh=hours, mm=minutes,
SS=sec, and sss=millisec. It "wraps" after 49.710 days.

Error 1 occurred at disk power-on lifetime: 5603 hours (233 days + 11 hours)
When the command that caused the error occurred, the device was in an
unknown state.

After command completion occurred, registers were:
ER ST SC SN CL CH DH
-- -- -- -- -- -- --
04 51 3f 00 00 00 af

Commands leading to the command that caused the error were:
CR FR SC SN CL CH DH DC Powered_Up_Time Command/Feature_Name
-- -- -- -- -- -- -- -- ---------------- --------------------
91 00 3f 00 00 00 0f 00 05:30:59.655 INITIALIZE DEVICE PARAMETERS
[OBS-6]
ec 00 01 01 00 00 00 00 05:30:59.654 IDENTIFY DEVICE
ec 00 00 00 00 00 00 00 05:30:56.191 IDENTIFY DEVICE
ca 00 28 02 ee 9a 0c 00 05:30:56.190 WRITE DMA
ca 00 10 e8 4c 10 0a 00 05:30:56.190 WRITE DMA


Maybe, it's really the HDD!

OT: "http://www.nvidia.com/object/680i_hotfix.html"


Chr.

2007-01-21 18:01:18

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.21 18:34:40 +0100, Chr wrote:
> On Sunday, 21. January 2007 09:36, Bj?rn Steinbrink wrote:
> > On 2007.01.21 00:39:20 -0600, Robert Hancock wrote:
> >
> > Ah, right... sata_nv.c of course interacts with the outside world, d'oh!
> >
> > Up to now, I only got bad kernels, latest tested being:
> > 94fcda1f8ab5e0cacc381c5ca1cc9aa6ad523576
> >
> > Which, unless I missed a commit in the diff, only USB changes,
> > continuing anyway.
> >
> > Just to make sure, here's my little helper for this bisect run, I hope
> > it does what you expected:
> >
> > #!/bin/bash
> > cp ../sata_nv.c.orig drivers/ata/sata_nv.c
> > git bisect good
> > cp drivers/ata/sata_nv.c ../sata_nv.c.orig
> > cp ../sata_nv.c drivers/ata/
> > make oldconfig
> > make -j4
> >
> > Where "../sata_nv.c" is the version from 2.6.20-rc5. The copying is done
> > to avoid conflicts and keep git happy. Of course there's also a version
> > for bad kernels ;) No idea, why I didn't make that an argument to the
> > script...
> >
> > Thanks,
> > Bj?rn
>
> Argggg, 2.6.19 (with 2.6.20-rc5 adma stuff) is affected too (BTW, what do you
> do to trigger the exceptions? Because, it takes hours to "reproduces" this
> silly *************).

I run those two in parallel:
while /bin/true; do ls -lR / > /dev/null 2>&1; done
while /bin/true; do echo 255 > /proc/sys/vm/drop_caches; sleep 1; done

Not sure if running them in parallel is necessary, but I don't want to
change the test setup ;) Takes between 1 and 40 minutes to trigger it.
Most of the time it's around 15 minutes now, doing more random stuff in
addition to that seems to trigger it even easier (like reading mail,
rebuilding the kernel etc.).

I'm down to 2 commits after 2.6.19 now, only bad kernels, so I tend to
say that 2.6.19 with 2.6.20-rc5's sata_nv.c will also fail for me, but I
thought I might finish bisection just to be sure.

> But, this time it looks slightly different:
> ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> ata3.00: tag 0 cmd 0xec Emask 0x4 stat 0x40 err 0x0 (timeout)

> [Rest of the error message + SMART error snipped]

I get the same exception every time, doesn't change for me. And neither
do I get any SMART errors or something.

Thanks,
Bj?rn

2007-01-21 18:40:37

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.21 09:36:18 +0100, Bj?rn Steinbrink wrote:
> On 2007.01.21 00:39:20 -0600, Robert Hancock wrote:
> > Bj?rn Steinbrink wrote:
> > >On 2007.01.20 22:34:27 -0500, Jeff Garzik wrote:
> > >>Robert Hancock wrote:
> > >>>change in 2.6.20-rc is either causing or triggering this problem. It
> > >>>would be useful if you could try git bisect between 2.6.19 and
> > >>>2.6.20-rc5, keeping the latest sata_nv.c each time, and see if that
> > >>
> > >>Yes, 'git bisect' would be the next step in figuring out this puzzle.
> > >>
> > >>Anybody up for it?
> > >
> > >I'll go for it, but could I get an explanation how that could lead to a
> > >different result than my last bisection? I see the difference of keeping
> > >sata_nv.c but my brain can't wrap around it right now (woke up in the
> > >middle of the night and still not up to speed...).
> >
> > Whatever the problem is, only seems to show up when ADMA is enabled, and
> > so the patch that added ADMA support shows up as the culprit from your
> > git bisect. However, from what Chr is reporting, 2.6.19 with the ADMA
> > support added in doesn't seem to have the problem, so presumably
> > something else that changed in the 2.6.20-rc series is triggering it.
> > Doing a bisect while keeping the driver code itself the same will
> > hopefully identify what that change is..
>
> Ah, right... sata_nv.c of course interacts with the outside world, d'oh!
>
> Up to now, I only got bad kernels, latest tested being:
> 94fcda1f8ab5e0cacc381c5ca1cc9aa6ad523576
>
> Which, unless I missed a commit in the diff, only USB changes,
> continuing anyway.

All kernels were bad using that approach. So back to square 1. :/

Bj?rn

2007-01-21 19:59:20

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

--- linux-2.6.20-rc5/drivers/ata/sata_nv.c 2007-01-19 19:18:53.000000000 -0600
+++ linux-2.6.20-rc5debug/drivers/ata/sata_nv.c 2007-01-21 13:35:17.000000000 -0600
@@ -509,14 +509,38 @@ static void nv_adma_register_mode(struct
{
void __iomem *mmio = nv_adma_ctl_block(ap);
struct nv_adma_port_priv *pp = ap->private_data;
- u16 tmp;
+ u16 tmp, status;
+ int count = 0;

if (pp->flags & NV_ADMA_PORT_REGISTER_MODE)
return;

+ status = readw(mmio + NV_ADMA_STAT);
+ while(!(status & NV_ADMA_STAT_IDLE) && count < 20) {
+ ndelay(50);
+ status = readw(mmio + NV_ADMA_STAT);
+ count++;
+ }
+ if(count == 20)
+ ata_port_printk(ap, KERN_WARNING,
+ "timeout waiting for ADMA IDLE, stat=0x%hx\n",
+ status);
+
tmp = readw(mmio + NV_ADMA_CTL);
writew(tmp & ~NV_ADMA_CTL_GO, mmio + NV_ADMA_CTL);

+ count = 0;
+ status = readw(mmio + NV_ADMA_STAT);
+ while(!(status & NV_ADMA_STAT_LEGACY) && count < 20) {
+ ndelay(50);
+ status = readw(mmio + NV_ADMA_STAT);
+ count++;
+ }
+ if(count == 20)
+ ata_port_printk(ap, KERN_WARNING,
+ "timeout waiting for ADMA LEGACY, stat=0x%hx\n",
+ status);
+
pp->flags |= NV_ADMA_PORT_REGISTER_MODE;
}

@@ -524,7 +548,8 @@ static void nv_adma_mode(struct ata_port
{
void __iomem *mmio = nv_adma_ctl_block(ap);
struct nv_adma_port_priv *pp = ap->private_data;
- u16 tmp;
+ u16 tmp, status;
+ int count = 0;

if (!(pp->flags & NV_ADMA_PORT_REGISTER_MODE))
return;
@@ -534,6 +559,18 @@ static void nv_adma_mode(struct ata_port
tmp = readw(mmio + NV_ADMA_CTL);
writew(tmp | NV_ADMA_CTL_GO, mmio + NV_ADMA_CTL);

+ status = readw(mmio + NV_ADMA_STAT);
+ while(((status & NV_ADMA_STAT_LEGACY) ||
+ !(status & NV_ADMA_STAT_IDLE)) && count < 20) {
+ ndelay(50);
+ status = readw(mmio + NV_ADMA_STAT);
+ count++;
+ }
+ if(count == 20)
+ ata_port_printk(ap, KERN_WARNING,
+ "timeout waiting for ADMA LEGACY clear and IDLE, stat=0x%hx\n",
+ status);
+
pp->flags &= ~NV_ADMA_PORT_REGISTER_MODE;
}

Attachments:

2007-01-21 20:13:31

by Christian Lamparter

Subject: Re: SATA exceptions with 2.6.20-rc5

On Sunday, 21. January 2007 19:01, Bj?rn Steinbrink wrote:
> On 2007.01.21 18:34:40 +0100, Chr wrote:
>
> I run those two in parallel:
> while /bin/true; do ls -lR / > /dev/null 2>&1; done
> while /bin/true; do echo 255 > /proc/sys/vm/drop_caches; sleep 1; done
>
> Not sure if running them in parallel is necessary, but I don't want to
> change the test setup ;) Takes between 1 and 40 minutes to trigger it.
> Most of the time it's around 15 minutes now, doing more random stuff in
> addition to that seems to trigger it even easier (like reading mail,
> rebuilding the kernel etc.).
>
> I'm down to 2 commits after 2.6.19 now, only bad kernels, so I tend to
> say that 2.6.19 with 2.6.20-rc5's sata_nv.c will also fail for me, but I
> thought I might finish bisection just to be sure.
>
> > But, this time it looks slightly different:
> > ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> > ata3.00: tag 0 cmd 0xec Emask 0x4 stat 0x40 err 0x0 (timeout)
> >
> > [Rest of the error message + SMART error snipped]
>
> I get the same exception every time, doesn't change for me. And neither
> do I get any SMART errors or something.
>
> Thanks,
> Bj?rn

Ok, you won't believe this... I opened my case and rewired my drives...
And guess what, my second (aka the "good") HDD is now failing!
I guess, my mainboard has a (but maybe two, or three :( ) "bad" sata-port(s)!

But, one small question remains: when I opened my case, I saw that my drivers
are pluged in SATA jack 1 and 2... The BIOS also says they're on 1 and 2.
Now, Linux says they're on port 3 & 4!



it's always ata3.00!
"ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata3.00: tag 0 cmd 0xea Emask 0x4 stat 0x40 err 0x0 (timeout)
ata3: soft resetting port
ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata3.00: configured for UDMA/133
ata3: EH complete
SCSI device sda: 490234752 512-byte hdwr sectors (251000 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: drive cache: write back"


Thanks,
Chr.

2007-01-21 22:08:17

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.21 13:58:01 -0600, Robert Hancock wrote:
> Bj?rn Steinbrink wrote:
> >All kernels were bad using that approach. So back to square 1. :/
> >
> >Bj?rn
> >
>
> OK guys, here's a new patch to try against 2.6.20-rc5:
>
> Right now when switching between ADMA mode and legacy mode (i.e. when
> going from doing normal DMA reads/writes to doing a FLUSH CACHE) we just
> set the ADMA GO register bit appropriately and continue with no delay.
> It looks like in some cases the controller doesn't respond to this
> immediately, it takes some nanoseconds for the controller's status
> registers to reflect the change that was made. It's possible that if we
> were trying to issue commands during this time, the controller might not
> react properly. This patch adds some code to wait for the status
> register to change to the state we asked for before continuing.

I went for the "I feel lucky" route and did just add mmio reads after the
mmio writes, posting them. Rationale being that if it is a write posting
issue, the debug patch would/could actually hide it AFAICT.
It's the "I feel lucky" route, because my whole "knowledge" about mmio
and write posting originates from the few things I read up on when you
discovered the comment about write posting in the generic ata code.

Bj?rn

2007-01-21 22:11:31

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.21 23:08:11 +0100, Bj?rn Steinbrink wrote:
> On 2007.01.21 13:58:01 -0600, Robert Hancock wrote:
> > Bj?rn Steinbrink wrote:
> > >All kernels were bad using that approach. So back to square 1. :/
> > >
> > >Bj?rn
> > >
> >
> > OK guys, here's a new patch to try against 2.6.20-rc5:
> >
> > Right now when switching between ADMA mode and legacy mode (i.e. when
> > going from doing normal DMA reads/writes to doing a FLUSH CACHE) we just
> > set the ADMA GO register bit appropriately and continue with no delay.
> > It looks like in some cases the controller doesn't respond to this
> > immediately, it takes some nanoseconds for the controller's status
> > registers to reflect the change that was made. It's possible that if we
> > were trying to issue commands during this time, the controller might not
> > react properly. This patch adds some code to wait for the status
> > register to change to the state we asked for before continuing.
>
> I went for the "I feel lucky" route and did just add mmio reads after the
> mmio writes, posting them. Rationale being that if it is a write posting
> issue, the debug patch would/could actually hide it AFAICT.
> It's the "I feel lucky" route, because my whole "knowledge" about mmio
> and write posting originates from the few things I read up on when you
> discovered the comment about write posting in the generic ata code.

Uhm, yeah, exception occured about the time that I hit "send".

Bj?rn

2007-01-21 22:26:30

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Bj?rn Steinbrink wrote:
> On 2007.01.21 23:08:11 +0100, Bj?rn Steinbrink wrote:
>> On 2007.01.21 13:58:01 -0600, Robert Hancock wrote:
>>> Bj?rn Steinbrink wrote:
>>>> All kernels were bad using that approach. So back to square 1. :/
>>>>
>>>> Bj?rn
>>>>
>>> OK guys, here's a new patch to try against 2.6.20-rc5:
>>>
>>> Right now when switching between ADMA mode and legacy mode (i.e. when
>>> going from doing normal DMA reads/writes to doing a FLUSH CACHE) we just
>>> set the ADMA GO register bit appropriately and continue with no delay.
>>> It looks like in some cases the controller doesn't respond to this
>>> immediately, it takes some nanoseconds for the controller's status
>>> registers to reflect the change that was made. It's possible that if we
>>> were trying to issue commands during this time, the controller might not
>>> react properly. This patch adds some code to wait for the status
>>> register to change to the state we asked for before continuing.
>> I went for the "I feel lucky" route and did just add mmio reads after the
>> mmio writes, posting them. Rationale being that if it is a write posting
>> issue, the debug patch would/could actually hide it AFAICT.
>> It's the "I feel lucky" route, because my whole "knowledge" about mmio
>> and write posting originates from the few things I read up on when you
>> discovered the comment about write posting in the generic ata code.
>
> Uhm, yeah, exception occured about the time that I hit "send".
>
> Bj?rn

Yeah, I don't think just adding reads to flush posted writes is enough
here - it seems to need more delay than that, and it also wasn't always
in the idle state even before we would write the register..

2007-01-21 22:27:19

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.21 13:58:01 -0600, Robert Hancock wrote:
> Bj?rn Steinbrink wrote:
> >All kernels were bad using that approach. So back to square 1. :/
> >
> >Bj?rn
> >
>
> OK guys, here's a new patch to try against 2.6.20-rc5:
>
> Right now when switching between ADMA mode and legacy mode (i.e. when
> going from doing normal DMA reads/writes to doing a FLUSH CACHE) we just
> set the ADMA GO register bit appropriately and continue with no delay.
> It looks like in some cases the controller doesn't respond to this
> immediately, it takes some nanoseconds for the controller's status
> registers to reflect the change that was made. It's possible that if we
> were trying to issue commands during this time, the controller might not
> react properly. This patch adds some code to wait for the status
> register to change to the state we asked for before continuing.

Just got two exceptions with your patch, none of the debug messages were
issued.

Bj?rn

2007-01-22 00:18:27

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Bj?rn Steinbrink wrote:
> On 2007.01.21 13:58:01 -0600, Robert Hancock wrote:
>> Bj?rn Steinbrink wrote:
>>> All kernels were bad using that approach. So back to square 1. :/
>>>
>>> Bj?rn
>>>
>> OK guys, here's a new patch to try against 2.6.20-rc5:
>>
>> Right now when switching between ADMA mode and legacy mode (i.e. when
>> going from doing normal DMA reads/writes to doing a FLUSH CACHE) we just
>> set the ADMA GO register bit appropriately and continue with no delay.
>> It looks like in some cases the controller doesn't respond to this
>> immediately, it takes some nanoseconds for the controller's status
>> registers to reflect the change that was made. It's possible that if we
>> were trying to issue commands during this time, the controller might not
>> react properly. This patch adds some code to wait for the status
>> register to change to the state we asked for before continuing.
>
> Just got two exceptions with your patch, none of the debug messages were
> issued.
>
> Bj?rn

Hmm, another miss, apparently.. Has anyone tried removing these lines
from nv_host_intr in 2.6.20-rc5 sata_nv.c and see what that does?

/* bail out if not our interrupt */
if (!(irq_stat & NV_INT_DEV))
return 0;

--
Robert Hancock Saskatoon, SK, Canada
To email, remove "nospam" from [email protected]
Home Page: http://www.roberthancock.com/

2007-01-22 02:39:45

by Tejun Heo

Subject: Re: SATA exceptions with 2.6.20-rc5

Hello,

Chr wrote:
> Ok, you won't believe this... I opened my case and rewired my drives...
> And guess what, my second (aka the "good") HDD is now failing!
> I guess, my mainboard has a (but maybe two, or three :( ) "bad" sata-port(s)!

Or, you have power related problem. Try to rewire the power lines or
connect harddrives to a separate powersupply. It's often useful to
change one component at a time and watch which change the problem
follows. Anyways, you seem to be suffering transmission failures, not a
driver problem.

Thanks.

--
tejun

2007-01-22 12:32:56

by Christian Lamparter

Subject: Re: SATA exceptions with 2.6.20-rc5

On Monday, 22. January 2007 03:39, Tejun Heo wrote:
> Hello,
>
> Chr wrote:
> > Ok, you won't believe this... I opened my case and rewired my drives...
> > And guess what, my second (aka the "good") HDD is now failing!
> > I guess, my mainboard has a (but maybe two, or three :( ) "bad" sata-port(s)!
>
> Or, you have power related problem. Try to rewire the power lines or
> connect harddrives to a separate powersupply. It's often useful to
> change one component at a time and watch which change the problem
> follows. Anyways, you seem to be suffering transmission failures, not a
> driver problem.
>
> Thanks.
>

Yes and no, it's probably not a power problem, I've tried another
PSU with the same result :( . Futhermore, the RAID0 setup makes
it impossible to try only one drive alone :(.

Anyway,the WD2500KS is known to have some strange bugs in the FW.
e.g.: It reports 255?C right after a cold start.
( http://www.bugtrack.almico.com/view.php?id=468 ).

Thanks,
Chr.

2007-01-22 16:12:46

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.21 18:17:01 -0600, Robert Hancock wrote:
> Bj?rn Steinbrink wrote:
> >On 2007.01.21 13:58:01 -0600, Robert Hancock wrote:
> >>Bj?rn Steinbrink wrote:
> >>>All kernels were bad using that approach. So back to square 1. :/
> >>>
> >>>Bj?rn
> >>>
> >>OK guys, here's a new patch to try against 2.6.20-rc5:
> >>
> >>Right now when switching between ADMA mode and legacy mode (i.e. when
> >>going from doing normal DMA reads/writes to doing a FLUSH CACHE) we just
> >>set the ADMA GO register bit appropriately and continue with no delay.
> >>It looks like in some cases the controller doesn't respond to this
> >>immediately, it takes some nanoseconds for the controller's status
> >>registers to reflect the change that was made. It's possible that if we
> >>were trying to issue commands during this time, the controller might not
> >>react properly. This patch adds some code to wait for the status
> >>register to change to the state we asked for before continuing.
> >
> >Just got two exceptions with your patch, none of the debug messages were
> >issued.
> >
> >Bj?rn
>
> Hmm, another miss, apparently.. Has anyone tried removing these lines
> >from nv_host_intr in 2.6.20-rc5 sata_nv.c and see what that does?
>
> /* bail out if not our interrupt */
> if (!(irq_stat & NV_INT_DEV))
> return 0;

Running a kernel with the return statement replace by a line that prints
the irq_stat instead.

Currently I'm seeing lots of 0x10 on ata1 and 0x0 on ata2.

Bj?rn

2007-01-22 16:57:14

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.22 17:12:40 +0100, Bj?rn Steinbrink wrote:
> On 2007.01.21 18:17:01 -0600, Robert Hancock wrote:
> > Bj?rn Steinbrink wrote:
> > >On 2007.01.21 13:58:01 -0600, Robert Hancock wrote:
> > >>Bj?rn Steinbrink wrote:
> > >>>All kernels were bad using that approach. So back to square 1. :/
> > >>>
> > >>>Bj?rn
> > >>>
> > >>OK guys, here's a new patch to try against 2.6.20-rc5:
> > >>
> > >>Right now when switching between ADMA mode and legacy mode (i.e. when
> > >>going from doing normal DMA reads/writes to doing a FLUSH CACHE) we just
> > >>set the ADMA GO register bit appropriately and continue with no delay.
> > >>It looks like in some cases the controller doesn't respond to this
> > >>immediately, it takes some nanoseconds for the controller's status
> > >>registers to reflect the change that was made. It's possible that if we
> > >>were trying to issue commands during this time, the controller might not
> > >>react properly. This patch adds some code to wait for the status
> > >>register to change to the state we asked for before continuing.
> > >
> > >Just got two exceptions with your patch, none of the debug messages were
> > >issued.
> > >
> > >Bj?rn
> >
> > Hmm, another miss, apparently.. Has anyone tried removing these lines
> > >from nv_host_intr in 2.6.20-rc5 sata_nv.c and see what that does?
> >
> > /* bail out if not our interrupt */
> > if (!(irq_stat & NV_INT_DEV))
> > return 0;
>
> Running a kernel with the return statement replace by a line that prints
> the irq_stat instead.
>
> Currently I'm seeing lots of 0x10 on ata1 and 0x0 on ata2.

40 minutes stress test now and no exception yet. What's interesting is
that ata1 saw exactly one interrupt with irq_stat 0x0, all others that
might have get dropped are as above.
I'll keep it running for some time and will then re-enable the return
statement to see if there's a relation between the irq_stat 0x0 and the
exception.

Bj?rn

2007-01-22 17:53:29

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.22 17:57:08 +0100, Bj?rn Steinbrink wrote:
> On 2007.01.22 17:12:40 +0100, Bj?rn Steinbrink wrote:
> > On 2007.01.21 18:17:01 -0600, Robert Hancock wrote:
> > > Hmm, another miss, apparently.. Has anyone tried removing these lines
> > > >from nv_host_intr in 2.6.20-rc5 sata_nv.c and see what that does?
> > >
> > > /* bail out if not our interrupt */
> > > if (!(irq_stat & NV_INT_DEV))
> > > return 0;
> >
> > Running a kernel with the return statement replace by a line that prints
> > the irq_stat instead.
> >
> > Currently I'm seeing lots of 0x10 on ata1 and 0x0 on ata2.
>
> 40 minutes stress test now and no exception yet. What's interesting is
> that ata1 saw exactly one interrupt with irq_stat 0x0, all others that
> might have get dropped are as above.
> I'll keep it running for some time and will then re-enable the return
> statement to see if there's a relation between the irq_stat 0x0 and the
> exception.

No, doesn't seem to be related, did get 2 exceptions, but no irq_stat
0x0 for ata1. Syslog/dmesg has nothing new either, still the same
pattern of dismissed irq_stats.

Bj?rn

2007-01-22 18:17:58

by Eric D. Mudama

Subject: Re: SATA exceptions with 2.6.20-rc5

On 1/15/07, Jeff Garzik <[email protected]> wrote:
> Jens Axboe wrote:
> > On Mon, Jan 15 2007, Jeff Garzik wrote:
> >> Jens Axboe wrote:
> >>> I'd be surprised if the device would not obey the 7 second timeout rule
> >>> that seems to be set in stone and not allow more dirty in-drive cache
> >>> than it could flush out in approximately that time.
> >> AFAIK Windows flush-cache timeout is 30 seconds, not 7 as with other
> >> commands...
> >
> > Ok, 7 seconds for FLUSH_CACHE would have been nice for us too though, as
> > it would pretty much guarentee lower latencies for random writes and
> > write back caching. The concern is the barrier code, of course. I guess
> > I should do some timings on potential worst case patterns some day. Alan
> > may have done that sometime in the past, iirc.
>
> FWIW: According to the drive guys (Eric M, among others), FLUSH CACHE
> will "probably" be under 30 seconds, but pathological cases might even
> extend beyond that.
>
> Definitely more than 7 seconds in less-than-pathological cases,
> unfortunately...

The mentioned Maxtor model (6Yxxx) isn't susceptible to the
large-buffer long completion times, due to architectural differences
and availability of only small buffers. Any "real" long-completion
flush on this device would, I believe, involve damage to the disk that
hinders the ability to seek, settle, or write. (e.g. 30-second
flushes are easy to hit if you mount the disk on a shaker-table with
sufficient amplitude)

Later in the thread I think people have pretty much isolated it as not
the disk's problem, but just wanted to point this out.

I assume that large enough customers can buy enterprise-type command
completion ("all commands within X seconds") from most any disk
vendor. However, these firmwares require much smarter or more active
drivers or block layers, to handle the higher error rate when the data
on the device is valid, but it will take longer than allowed by the
arbitrary enterprise rules. Most customers who are buying this many
devices have software engineers customizing the drivers or disk
management applications to handle this differing behavior.

--eric

2007-01-23 01:24:49

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

--- linux-2.6.20-rc5/drivers/ata/sata_nv.c 2007-01-19 19:18:53.000000000 -0600
+++ linux-2.6.20-rc5debug/drivers/ata/sata_nv.c 2007-01-22 18:35:09.000000000 -0600
@@ -750,9 +750,9 @@ static irqreturn_t nv_adma_interrupt(int

/* if in ATA register mode, use standard ata interrupt handler */
if (pp->flags & NV_ADMA_PORT_REGISTER_MODE) {
- u8 irq_stat = readb(host->mmio_base + NV_INT_STATUS_CK804)
- >> (NV_INT_PORT_SHIFT * i);
- handled += nv_host_intr(ap, irq_stat);
+ struct ata_queued_cmd *qc = ata_qc_from_tag(ap, ap->active_tag);
+ if(qc && !(qc->tf.flags & ATA_TFLAG_POLLING))
+ handled += ata_host_intr(ap, qc);
continue;
}

Attachments:

2007-01-23 01:35:05

by Alistair John Strachan

Subject: Re: SATA exceptions with 2.6.20-rc5

On Tuesday 23 January 2007 01:24, Robert Hancock wrote:
> As a final aside, this is another case where the hardware docs for this
> controller would really be useful, in order to know whether we are
> actually supposed to be reading that register in ADMA mode or not. I
> sent a query to Allen Martin at NVIDIA asking if there's a way I could
> get access to the documents, but I haven't heard anything yet.

Obviously, NVIDIA's response is disappointing, but thank you for putting the
time in to debug this problem. Definitely sounds like a hardware defect, I'm
just glad there's a workaround.

Will we see this fix in 2.6.20?

--
Cheers,
Alistair.

Final year Computer Science undergraduate.
1F2 55 South Clerk Street, Edinburgh, UK.

2007-01-23 01:43:43

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Alistair John Strachan wrote:
> On Tuesday 23 January 2007 01:24, Robert Hancock wrote:
>> As a final aside, this is another case where the hardware docs for this
>> controller would really be useful, in order to know whether we are
>> actually supposed to be reading that register in ADMA mode or not. I
>> sent a query to Allen Martin at NVIDIA asking if there's a way I could
>> get access to the documents, but I haven't heard anything yet.
>
> Obviously, NVIDIA's response is disappointing, but thank you for putting the
> time in to debug this problem. Definitely sounds like a hardware defect, I'm
> just glad there's a workaround.
>
> Will we see this fix in 2.6.20?

Hopefully, assuming it actually does fix the problem for those that have
been seeing it..

--
Robert Hancock Saskatoon, SK, Canada
To email, remove "nospam" from [email protected]
Home Page: http://www.roberthancock.com/

2007-01-23 02:44:17

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.22 19:24:22 -0600, Robert Hancock wrote:
> Bj?rn Steinbrink wrote:
> >>>Running a kernel with the return statement replace by a line that prints
> >>>the irq_stat instead.
> >>>
> >>>Currently I'm seeing lots of 0x10 on ata1 and 0x0 on ata2.
> >>40 minutes stress test now and no exception yet. What's interesting is
> >>that ata1 saw exactly one interrupt with irq_stat 0x0, all others that
> >>might have get dropped are as above.
> >>I'll keep it running for some time and will then re-enable the return
> >>statement to see if there's a relation between the irq_stat 0x0 and the
> >>exception.
> >
> >No, doesn't seem to be related, did get 2 exceptions, but no irq_stat
> >0x0 for ata1. Syslog/dmesg has nothing new either, still the same
> >pattern of dismissed irq_stats.
>
> I've finally managed to reproduce this problem on my box, by doing:
>
> watch --interval=0.1 /sbin/hdparm -I /dev/sda
>
> on one drive and then running bonnie++ on /dev/sdb connected to the
> other port on the same controller device. Usually within a few minutes
> one of the IDENTIFY commands would time out in the same way you guys
> have been seeing.
>
> Through some various trials and tribulations, the only conclusion I can
> come to is that this controller really doesn't like that
> NV_INT_STATUS_CK804 register being looked at in ADMA mode. I tried
> adding some debug code to the qc_issue function that would check to see
> if the BUSY flag in altstatus went high or that register showed an
> interrupt within a certain time afterwards, however that really seemed
> to hose things, the system wouldn't even boot.

Hm, I don't think it is unhappy about looking at NV_INT_STATUS_CK804.
I'm running 2.6.20-rc5 with the INT_DEV check removed for 8 hours now
without a single problem and that should still look at
NV_INT_STATUS_CK804, right?
I just noticed that my last email might not have been clear enough. The
exceptions happened when I re-enabled the return statement in addition
to the debug message. Without the INT_DEV check, it is completely fine
AFAICT.

> Try out this patch, it just calls the ata_host_intr function where
> appropriate without using nv_host_intr which looks at the
> NV_INT_STATUS_CK804 register. This is what the original ADMA patch from
> Mr. Mysterious NVIDIA Person did, I'm guessing there may be a reason for
> that. With this patch I can get through a whole bonnie++ run with the
> repeated IDENTIFY requests running without seeing the error.

I'll see if I can schedule a test run for tomorrow, I currently need
this box.

Thanks,
Bj?rn

2007-01-23 05:05:43

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

--- linux-2.6.20-rc5/drivers/ata/sata_nv.c 2007-01-19 19:18:53.000000000 -0600
+++ linux-2.6.20-rc5debug/drivers/ata/sata_nv.c 2007-01-22 22:33:43.000000000 -0600
@@ -700,7 +700,6 @@ static void nv_adma_check_cpb(struct ata
static int nv_host_intr(struct ata_port *ap, u8 irq_stat)
{
struct ata_queued_cmd *qc = ata_qc_from_tag(ap, ap->active_tag);
- int handled;

/* freeze if hotplugged */
if (unlikely(irq_stat & (NV_INT_ADDED | NV_INT_REMOVED))) {
@@ -719,13 +718,7 @@ static int nv_host_intr(struct ata_port
}

/* handle interrupt */
- handled = ata_host_intr(ap, qc);
- if (unlikely(!handled)) {
- /* spurious, clear it */
- ata_check_status(ap);
- }
-
- return 1;
+ return ata_host_intr(ap, qc);
}

static irqreturn_t nv_adma_interrupt(int irq, void *dev_instance)
@@ -752,6 +745,11 @@ static irqreturn_t nv_adma_interrupt(int
if (pp->flags & NV_ADMA_PORT_REGISTER_MODE) {
u8 irq_stat = readb(host->mmio_base + NV_INT_STATUS_CK804)
>> (NV_INT_PORT_SHIFT * i);
+ if(ata_tag_valid(ap->active_tag))
+ /** NV_INT_DEV indication seems unreliable at times
+ at least in ADMA mode. Force it on always when a
+ command is active, to prevent losing interrupts. */
+ irq_stat |= NV_INT_DEV;
handled += nv_host_intr(ap, irq_stat);
continue;
}

Attachments:

2007-01-23 15:34:28

by Larry Walton

Subject: Re: SATA exceptions with 2.6.20-rc5

The last patch (sata_nv-force-int-dev-in-interrupt.patch)
seems to have fix the problem. Much appreciated,
thank you. I'd consider it a must have in 2.6.20.


--
*--* Mail: [email protected]
*--* Voice: 206.892.6269
*--* Cell: 206.225.0154
*--* HTTP://real.com
--------------------------------------
- - - - - - - R e a l - - - - - - - -

Attachments:

2007-01-23 23:20:13

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Larry Walton wrote:
> The last patch (sata_nv-force-int-dev-in-interrupt.patch)
> seems to have fix the problem. Much appreciated,
> thank you. I'd consider it a must have in 2.6.20.

Can any of the rest of you that have been seeing this problem also
confirm that this fixes it?

--
Robert Hancock Saskatoon, SK, Canada
To email, remove "nospam" from [email protected]
Home Page: http://www.roberthancock.com/

2007-01-24 00:39:27

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.23 17:18:43 -0600, Robert Hancock wrote:
> Larry Walton wrote:
> >The last patch (sata_nv-force-int-dev-in-interrupt.patch)
> >seems to have fix the problem. Much appreciated,
> >thank you. I'd consider it a must have in 2.6.20.
>
> Can any of the rest of you that have been seeing this problem also
> confirm that this fixes it?

Seems to work for me, uptime is about an hour now and no exception yet.
Had the stress test running for only about 10 minutes, but I usually got
an exception within an hour even during plain irssi usage, so I'm quite
confident that the patch fixes it.

Thanks,
Bj?rn

2007-01-24 02:09:51

by Robert Hancock

Subject: [PATCH 2.6.20] sata_nv: don't rely on NV_INT_DEV indication with ADMA

--- linux-2.6.20-rc5/drivers/ata/sata_nv.c 2007-01-19 19:18:53.000000000 -0600
+++ linux-2.6.20-rc5debug/drivers/ata/sata_nv.c 2007-01-22 22:33:43.000000000 -0600
@@ -700,7 +700,6 @@ static void nv_adma_check_cpb(struct ata
static int nv_host_intr(struct ata_port *ap, u8 irq_stat)
{
struct ata_queued_cmd *qc = ata_qc_from_tag(ap, ap->active_tag);
- int handled;

/* freeze if hotplugged */
if (unlikely(irq_stat & (NV_INT_ADDED | NV_INT_REMOVED))) {
@@ -719,13 +718,7 @@ static int nv_host_intr(struct ata_port
}

/* handle interrupt */
- handled = ata_host_intr(ap, qc);
- if (unlikely(!handled)) {
- /* spurious, clear it */
- ata_check_status(ap);
- }
-
- return 1;
+ return ata_host_intr(ap, qc);
}

static irqreturn_t nv_adma_interrupt(int irq, void *dev_instance)
@@ -752,6 +745,11 @@ static irqreturn_t nv_adma_interrupt(int
if (pp->flags & NV_ADMA_PORT_REGISTER_MODE) {
u8 irq_stat = readb(host->mmio_base + NV_INT_STATUS_CK804)
>> (NV_INT_PORT_SHIFT * i);
+ if(ata_tag_valid(ap->active_tag))
+ /** NV_INT_DEV indication seems unreliable at times
+ at least in ADMA mode. Force it on always when a
+ command is active, to prevent losing interrupts. */
+ irq_stat |= NV_INT_DEV;
handled += nv_host_intr(ap, irq_stat);
continue;
}

Attachments:

2007-01-24 08:24:13

by Ian Kumlien

Subject: Re: SATA exceptions with 2.6.20-rc5

On tis, 2007-01-23 at 17:18 -0600, Robert Hancock wrote:
> Larry Walton wrote:
> > The last patch (sata_nv-force-int-dev-in-interrupt.patch)
> > seems to have fix the problem. Much appreciated,
> > thank you. I'd consider it a must have in 2.6.20.
>
> Can any of the rest of you that have been seeing this problem also
> confirm that this fixes it?

I applied it yesterday and today my dmesg contains three:
BUG: at mm/truncate.c:60 cancel_dirty_page()

Call Trace:
[<ffffffff8029f3e5>] cancel_dirty_page+0x43/0x71
[<ffffffff802ec1ab>] reiserfs_cut_from_item+0x5f8/0x61d
[<ffffffff802074fc>] find_get_page+0x21/0x47
[<ffffffff802ec51d>] reiserfs_do_truncate+0x34d/0x495
[<ffffffff802d9d47>] reiserfs_truncate_file+0x199/0x2aa
[<ffffffff802df9c5>] reiserfs_file_release+0x261/0x281
[<ffffffff80211b02>] __fput+0xb1/0x17d
[<ffffffff802218e0>] filp_close+0x5d/0x65
[<ffffffff8021bef5>] sys_close+0x8c/0xcf
[<ffffffff8025725e>] system_call+0x7e/0x83

Which never happened before... I dunno if they are related though, but
they weren't there before...

(It does fix the timeout problem)

--
Ian Kumlien <pomac () vapor ! com> -- http://pomac.netswarm.net

Attachments:

2007-01-24 14:41:16

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.24 09:24:00 +0100, Ian Kumlien wrote:
> On tis, 2007-01-23 at 17:18 -0600, Robert Hancock wrote:
> > Larry Walton wrote:
> > > The last patch (sata_nv-force-int-dev-in-interrupt.patch)
> > > seems to have fix the problem. Much appreciated,
> > > thank you. I'd consider it a must have in 2.6.20.
> >
> > Can any of the rest of you that have been seeing this problem also
> > confirm that this fixes it?
>
> I applied it yesterday and today my dmesg contains three:
> BUG: at mm/truncate.c:60 cancel_dirty_page()

David Chinner sent two patches regarding that bug yesterday.
http://lkml.org/lkml/2007/1/23/190
http://lkml.org/lkml/2007/1/23/192

Bj?rn

2007-02-03 01:42:20

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.01.24 01:39:23 +0100, Bj?rn Steinbrink wrote:
> On 2007.01.23 17:18:43 -0600, Robert Hancock wrote:
> > Larry Walton wrote:
> > >The last patch (sata_nv-force-int-dev-in-interrupt.patch)
> > >seems to have fix the problem. Much appreciated,
> > >thank you. I'd consider it a must have in 2.6.20.
> >
> > Can any of the rest of you that have been seeing this problem also
> > confirm that this fixes it?
>
> Seems to work for me, uptime is about an hour now and no exception yet.
> Had the stress test running for only about 10 minutes, but I usually got
> an exception within an hour even during plain irssi usage, so I'm quite
> confident that the patch fixes it.

Or maybe not :( Just got an exception on 2.6.20-rc6. Took 4 days of
uptime to trigger, so it's just a lot harder to trigger now.

Bj?rn

2007-02-03 05:48:24

by Robert Hancock

Subject: Re: SATA exceptions with 2.6.20-rc5

Bj?rn Steinbrink wrote:
> On 2007.01.24 01:39:23 +0100, Bj?rn Steinbrink wrote:
>> On 2007.01.23 17:18:43 -0600, Robert Hancock wrote:
>>> Larry Walton wrote:
>>>> The last patch (sata_nv-force-int-dev-in-interrupt.patch)
>>>> seems to have fix the problem. Much appreciated,
>>>> thank you. I'd consider it a must have in 2.6.20.
>>> Can any of the rest of you that have been seeing this problem also
>>> confirm that this fixes it?
>> Seems to work for me, uptime is about an hour now and no exception yet.
>> Had the stress test running for only about 10 minutes, but I usually got
>> an exception within an hour even during plain irssi usage, so I'm quite
>> confident that the patch fixes it.
>
> Or maybe not :( Just got an exception on 2.6.20-rc6. Took 4 days of
> uptime to trigger, so it's just a lot harder to trigger now.

Same exception details as before?

There's a patch in -mm (sata_nv-use-adma-for-nodata-commands.patch)
which should hopefully avoid this problem for the cache flush commands,
at least - can you try that one out? You'll have to apply the other
sata_nv patches in -mm first, i.e. this order:

http://www2.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.20-rc6/2.6.20-rc6-mm3/broken-out/sata_nv-cleanup-adma-error-handling-v2.patch
http://www2.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.20-rc6/2.6.20-rc6-mm3/broken-out/sata_nv-cleanup-adma-error-handling-v2-cleanup.patch
http://www2.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.20-rc6/2.6.20-rc6-mm3/broken-out/sata_nv-use-adma-for-nodata-commands.patch

--
Robert Hancock Saskatoon, SK, Canada
To email, remove "nospam" from [email protected]
Home Page: http://www.roberthancock.com/

2007-02-04 01:13:57

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.02.02 23:48:14 -0600, Robert Hancock wrote:
> Bj?rn Steinbrink wrote:
> >On 2007.01.24 01:39:23 +0100, Bj?rn Steinbrink wrote:
> >>On 2007.01.23 17:18:43 -0600, Robert Hancock wrote:
> >>>Larry Walton wrote:
> >>>>The last patch (sata_nv-force-int-dev-in-interrupt.patch)
> >>>>seems to have fix the problem. Much appreciated,
> >>>>thank you. I'd consider it a must have in 2.6.20.
> >>>Can any of the rest of you that have been seeing this problem also
> >>>confirm that this fixes it?
> >>Seems to work for me, uptime is about an hour now and no exception yet.
> >>Had the stress test running for only about 10 minutes, but I usually got
> >>an exception within an hour even during plain irssi usage, so I'm quite
> >>confident that the patch fixes it.
> >
> >Or maybe not :( Just got an exception on 2.6.20-rc6. Took 4 days of
> >uptime to trigger, so it's just a lot harder to trigger now.
>
> Same exception details as before?

Yes, exactly the same.

> There's a patch in -mm (sata_nv-use-adma-for-nodata-commands.patch)
> which should hopefully avoid this problem for the cache flush commands,
> at least - can you try that one out? You'll have to apply the other
> sata_nv patches in -mm first, i.e. this order:
>
> http://www2.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.20-rc6/2.6.20-rc6-mm3/broken-out/sata_nv-cleanup-adma-error-handling-v2.patch
> http://www2.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.20-rc6/2.6.20-rc6-mm3/broken-out/sata_nv-cleanup-adma-error-handling-v2-cleanup.patch
> http://www2.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.20-rc6/2.6.20-rc6-mm3/broken-out/sata_nv-use-adma-for-nodata-commands.patch

Got 2.6.20-rc7 with them applied now (the rejects seemed trivial enough
for me to fix them). Let's see how that works out...

Bj?rn

2007-02-09 12:03:20

by Björn Steinbrink

Subject: Re: SATA exceptions with 2.6.20-rc5

On 2007.02.04 02:13:51 +0100, Bj?rn Steinbrink wrote:
> On 2007.02.02 23:48:14 -0600, Robert Hancock wrote:
> > There's a patch in -mm (sata_nv-use-adma-for-nodata-commands.patch)
> > which should hopefully avoid this problem for the cache flush commands,
> > at least - can you try that one out? You'll have to apply the other
> > sata_nv patches in -mm first, i.e. this order:
> >
> > http://www2.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.20-rc6/2.6.20-rc6-mm3/broken-out/sata_nv-cleanup-adma-error-handling-v2.patch
> > http://www2.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.20-rc6/2.6.20-rc6-mm3/broken-out/sata_nv-cleanup-adma-error-handling-v2-cleanup.patch
> > http://www2.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.20-rc6/2.6.20-rc6-mm3/broken-out/sata_nv-use-adma-for-nodata-commands.patch
>
> Got 2.6.20-rc7 with them applied now (the rejects seemed trivial enough
> for me to fix them). Let's see how that works out...

After about 1.5 days of uptime, an involuntary reboot and another 3
days of uptime, no sign of an exception. No stress testing was done,
but a few disk intensive actions did happen, at least more than with
that -rc6 that did throw an exception at me.

Bj?rn