Scary Intel SATA problem: "frozen"

Scary Intel SATA problem: "frozen"

[Linus Torvalds]

[ You may or may not have gotten my previous email. The kernel stayed 
  working, but due to the IO errors the filesystem got re-mounted 
  read-only, and I'm not sure that the email I sent out in that state 
  actually ever made it out. I suspect it didn't. ]

Jeff,
 I just had a scary thing on my nice new Intel i965 box (all Intel 
chipsets apart from some strange Marvell IDE interface that I'm not using 
and that no driver even detected, and a TI firewire thing that I'm 
similarly not using).

The machine basically froze for about a minute or so (well, things worked 
surprisingly well, considering that apparently no disk IO happened - I 
initially thought it was just firefox that had frozen up, since my mail 
session seemed to be fine), and after it came back the filesystem was 
mounted read-only and nothing really worked any more..

I have no idea what status 0xD0 means: it looks like ATA_BUSY + ATA_DRDY + 
"bit#4", but what is bit#4?

And clearly, the soft-reset isn't doing squat.

Ideas?

		Linus

----
Boot-time messages:

	libata version 2.00 loaded.
	..
	Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
	ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
	Probing IDE interface ide0...
	Probing IDE interface ide1...
	ide-floppy driver 0.99.newide
	ata_piix 0000:00:1f.2: version 2.00ac6
	ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
	ACPI: PCI Interrupt 0000:00:1f.2[A] -> GSI 19 (level, low) -> IRQ 19
	PCI: Setting latency timer of device 0000:00:1f.2 to 64
	ata1: SATA max UDMA/133 cmd 0x2148 ctl 0x217E bmdma 0x2110 irq 19
	ata2: SATA max UDMA/133 cmd 0x2140 ctl 0x217A bmdma 0x2118 irq 19
	scsi0 : ata_piix
	ata1.00: ATA-7, max UDMA/133, 976773168 sectors: LBA48 NCQ (depth 0/32)
	ata1.00: ata1: dev 0 multi count 16
	ata1.00: configured for UDMA/133
	scsi1 : ata_piix
	ata2.00: ATAPI, max UDMA/66
	ata2.00: configured for UDMA/66
	scsi 0:0:0:0: Direct-Access     ATA      WDC WD5000YS-01M 07.0 PQ: 0 ANSI: 5
	SCSI device sda: 976773168 512-byte hdwr sectors (500108 MB)
	sda: Write Protect is off
	sda: Mode Sense: 00 3a 00 00
	SCSI device sda: drive cache: write back
	SCSI device sda: 976773168 512-byte hdwr sectors (500108 MB)
	sda: Write Protect is off
	sda: Mode Sense: 00 3a 00 00
	SCSI device sda: drive cache: write back
	 sda: sda1 sda2
	sd 0:0:0:0: Attached scsi disk sda
	sd 0:0:0:0: Attached scsi generic sg0 type 0
	scsi 1:0:0:0: CD-ROM            PLEXTOR  DVDR   PX-755A   1.04 PQ: 0 ANSI: 5
	sr0: scsi3-mmc drive: 40x/40x writer cd/rw xa/form2 cdda tray
	Uniform CD-ROM driver Revision: 3.20
	sr 1:0:0:0: Attached scsi CD-ROM sr0
	sr 1:0:0:0: Attached scsi generic sg1 type 5
	ata_piix 0000:00:1f.5: MAP [ P0 P2 P1 P3 ]
	ACPI: PCI Interrupt 0000:00:1f.5[A] -> GSI 19 (level, low) -> IRQ 19
	PCI: Setting latency timer of device 0000:00:1f.5 to 64
	ata3: SATA max UDMA/133 cmd 0x2138 ctl 0x2176 bmdma 0x20F0 irq 19
	ata4: SATA max UDMA/133 cmd 0x2130 ctl 0x2172 bmdma 0x20F8 irq 19
	scsi2 : ata_piix
	ATA: abnormal status 0x7F on port 0x213F
	scsi3 : ata_piix
	ATA: abnormal status 0x7F on port 0x2137

Problem starts:

	ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
	ata1.00: (BMDMA stat 0x21)
	ata1.00: tag 0 cmd 0xca Emask 0x4 stat 0x40 err 0x0 (timeout)
	ata1: port is slow to respond, please be patient (Status 0xd0)
	ata1: port failed to respond (30 secs, Status 0xd0)
	ata1: soft resetting port
	ATA: abnormal status 0xD0 on port 0x214F
	ATA: abnormal status 0xD0 on port 0x214F
	ATA: abnormal status 0xD0 on port 0x214F
	ATA: abnormal status 0xD0 on port 0x214F
	ata1.00: qc timeout (cmd 0xec)
	ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
	ata1.00: revalidation failed (errno=-5)
	ata1: failed to recover some devices, retrying in 5 secs
	ata1: port is slow to respond, please be patient (Status 0xd0)
	ata1: port failed to respond (30 secs, Status 0xd0)
	ata1: soft resetting port
	ATA: abnormal status 0xD0 on port 0x214F
	ATA: abnormal status 0xD0 on port 0x214F
	ATA: abnormal status 0xD0 on port 0x214F
	ATA: abnormal status 0xD0 on port 0x214F
	ata1.00: qc timeout (cmd 0xec)
	ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
	ata1.00: revalidation failed (errno=-5)
	ata1: failed to recover some devices, retrying in 5 secs
	ata1: port is slow to respond, please be patient (Status 0xd0)
	ata1: port failed to respond (30 secs, Status 0xd0)
	ata1: soft resetting port
	ATA: abnormal status 0xD0 on port 0x214F
	ATA: abnormal status 0xD0 on port 0x214F
	ATA: abnormal status 0xD0 on port 0x214F
	ATA: abnormal status 0xD0 on port 0x214F
	ata1.00: qc timeout (cmd 0xec)
	ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
	ata1.00: revalidation failed (errno=-5)
	ata1.00: disabled
	ata1: EH complete

And then it goes all downhill from there - the machine is toast:

	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 335093
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 896217445
	Buffer I/O error on device dm-0, logical block 112001027
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221400325
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221400325
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221400325
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 421212525
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52625475, block=52625412
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 896217485
	Buffer I/O error on device dm-0, logical block 112001032
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 896217501
	Buffer I/O error on device dm-0, logical block 112001034
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 209229
	Buffer I/O error on device dm-0, logical block 0
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 335117
	Buffer I/O error on device dm-0, logical block 15736
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437255077
	Buffer I/O error on device dm-0, logical block 54630731
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437255085
	Buffer I/O error on device dm-0, logical block 54630732
	lost page write due to I/O error on dm-0
	Buffer I/O error on device dm-0, logical block 54630733
	lost page write due to I/O error on dm-0
	Buffer I/O error on device dm-0, logical block 54630734
	lost page write due to I/O error on dm-0
	Buffer I/O error on device dm-0, logical block 54630735
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437255157
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437255221
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437255381
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437269949
	Aborting journal on device dm-0.
	EXT3-fs error (device dm-0) in ext3_reserve_inode_write: Journal has aborted
	ext3_abort called.
	EXT3-fs error (device dm-0): ext3_journal_start_sb: Detected aborted journal
	Remounting filesystem read-only
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437270109
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437270229
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437270245
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437496517
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438170837
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438170941
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438235885
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438235981
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438236021
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438236045
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438236077
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438236141
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438242893
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438246285
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438249165
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438250517
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438286605
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438286861
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438286885
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438286917
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438286933
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438289381
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438290421
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438290653
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438290685
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438290717
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438290765
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438291717
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438291773
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438291797
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438296973
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438709949
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 640245117
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 209229
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 247935325
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=30965782, block=30965762
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 208613733
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=26050605, block=26050563
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 422785389
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52822081, block=52822020
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 424358245
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=53018686, block=53018627
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 421212525
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52625477, block=52625412
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 247935325
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=30965784, block=30965762
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 208613733
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=26050607, block=26050563
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223968533
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 422785389
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52822083, block=52822020
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 424358245
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=53018688, block=53018627
	EXT3-fs error (device dm-0) in ext3_reserve_inode_write: Journal has aborted
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 435077853
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438236021
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438249165
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438296973
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223968533
	__journal_remove_journal_head: freeing b_committed_data
	__journal_remove_journal_head: freeing b_committed_data
	__journal_remove_journal_head: freeing b_committed_data
	__journal_remove_journal_head: freeing b_committed_data
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223968533
	journal commit I/O error
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 421212525
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52625479, block=52625412
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 208613733
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=26050608, block=26050563
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 422785389
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52822085, block=52822020
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 424358253
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=53018690, block=53018628
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 232730981
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=29065261, block=29065219
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 193409381
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=24150055, block=24150019
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 421212525
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52625481, block=52625412
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 247935325
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=30965785, block=30965762
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 208613733
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=26050610, block=26050563
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 422785389
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52822087, block=52822020
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 424358253
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=53018692, block=53018628
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221082957
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221082957
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221082957
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 421212525
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52625482, block=52625412
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 247935325
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=30965786, block=30965762
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 208613733
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=26050611, block=26050563
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 422785389
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52822088, block=52822020
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 424358253
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=53018693, block=53018628
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 232730981
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=29065262, block=29065219
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 193409381
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=24150056, block=24150019
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 421212525
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52625484, block=52625412
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 247935325
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=30965787, block=30965762
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 208613733
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=26050613, block=26050563
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 422785389
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52822090, block=52822020
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 424358253
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=53018695, block=53018628
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 421212525
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52625485, block=52625412
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 208613733
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=26050614, block=26050563
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 422785389
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=52822091, block=52822020
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 424358253
	EXT3-fs error (device dm-0): ext3_get_inode_loc: unable to read inode block - inode=53018696, block=53018628
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 222476325
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 222476325
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 222476325
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220006069
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220006069
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220006069
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218847341
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218847341
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223939293
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223939293
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223939293
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223968533
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223968533
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223968533
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223968533
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 209229
	printk: 141 messages suppressed.
	Buffer I/O error on device dm-0, logical block 0
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 209341
	Buffer I/O error on device dm-0, logical block 14
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 209429
	Buffer I/O error on device dm-0, logical block 25
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218838829
	Buffer I/O error on device dm-0, logical block 27328700
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218838957
	Buffer I/O error on device dm-0, logical block 27328716
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218839021
	Buffer I/O error on device dm-0, logical block 27328724
	lost page write due to I/O error on dm-0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218839133
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218839173
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218839229
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218839261
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218839317
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218839341
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218839365
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218840301
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218840349
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218840453
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218840501
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218841173
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218842141
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218842877
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218842901
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218843021
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218843045
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218844933
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218844949
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218844965
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218844997
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218845045
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 218845141
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 219624301
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 219624381
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 219625901
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 219625957
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 219626005
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 219626421
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 219626485
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220149909
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220673461
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220673485
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220673525
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220673733
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221196965
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221722813
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221722845
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 222245285
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 222247365
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223818765
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 223818965
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 434844005
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 434844397
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 436680901
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437203277
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437203437
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437203477
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437236053
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437255213
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437270237
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437727581
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 437989709
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438170933
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438235669
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438251925
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 438939997
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 454766925
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 553070941
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 553070973
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 553071005
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 640102773
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 640102965
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 640102997
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 830681421
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 830927181
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 896217437
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 896217597
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 896217645
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 896217885
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220252173
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220252253
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220252277
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220252173
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 220252173
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 830927181
	EXT3-fs error (device dm-0): ext3_find_entry: reading directory #103809025 offset 0
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221816517
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221816589
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221816629
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221816653
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221816677
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221816629
	sd 0:0:0:0: SCSI error: return code = 0x00040000
	end_request: I/O error, dev sda, sector 221816629

Re: Scary Intel SATA problem: "frozen"

[Mark Lord]

Linus Torvalds wrote:
> [ You may or may not have gotten my previous email. The kernel stayed 
>   working, but due to the IO errors the filesystem got re-mounted 
>   read-only, and I'm not sure that the email I sent out in that state 
>   actually ever made it out. I suspect it didn't. ]
> 
> Jeff,
>  I just had a scary thing on my nice new Intel i965 box (all Intel 
> chipsets apart from some strange Marvell IDE interface that I'm not using 
> and that no driver even detected, and a TI firewire thing that I'm 
> similarly not using).
> 
> The machine basically froze for about a minute or so (well, things worked 
> surprisingly well, considering that apparently no disk IO happened - I 
> initially thought it was just firefox that had frozen up, since my mail 
> session seemed to be fine), and after it came back the filesystem was 
> mounted read-only and nothing really worked any more..
> 
> I have no idea what status 0xD0 means: it looks like ATA_BUSY + ATA_DRDY + 
> "bit#4", but what is bit#4?

Bit #4, when actually implemented, is a rotational seek indicator,
which can be used for timing purposes.

But when BUSY (bit #7) is set, the rest are generally nonsense.
 
> And clearly, the soft-reset isn't doing squat.

Tejun ?

Re: Scary Intel SATA problem: "frozen"

[Sergei Shtylyov]

Hello.

Mark Lord wrote:

> Bit #4, when actually implemented, is a rotational seek indicator,
> which can be used for timing purposes.

    Hm, I thought it was DSC (drive seek complete) set by the SEEK command 
completion, and it's always implemented. Didn't you mean IDX (bit 1, IIRC)?

> But when BUSY (bit #7) is set, the rest are generally nonsense.

    Indeed...

WBR, Sergei

Re: Scary Intel SATA problem: "frozen"

[Alan]

On Tue, 28 Nov 2006 09:31:51 -0800 (PST)
Linus Torvalds <torvalds@osdl.org> wrote:

>  I just had a scary thing on my nice new Intel i965 box (all Intel 
> chipsets apart from some strange Marvell IDE interface that I'm not using 
> and that no driver even detected, and a TI firewire thing that I'm 

Mr Morton has the Marvell libata driver in his tree waiting to head your
way.

Re: Scary Intel SATA problem: "frozen"

[Linus Torvalds]

On Tue, 28 Nov 2006, Alan wrote:
>
> On Tue, 28 Nov 2006 09:31:51 -0800 (PST)
> Linus Torvalds <torvalds@osdl.org> wrote:
> 
> >  I just had a scary thing on my nice new Intel i965 box (all Intel 
> > chipsets apart from some strange Marvell IDE interface that I'm not using 
> > and that no driver even detected, and a TI firewire thing that I'm 
> 
> Mr Morton has the Marvell libata driver in his tree waiting to head your
> way.

Well, I don't actually personally want it (I have nothing connected to it, 
nor any intention of connecting anything in the future), I just want my 
bog-standard PIIX driver to not do the scary things to me.

	"Mommy, mommy, the IDE messages/behaviour is scaring me!"

I just mentioned the Marvell chip because apart from those two (unused) 
chips, the box is absolutely and utterly bog-standard Intel-everything. 
The i965 may still be somewhat unusual right now, but that's going to 
change, and if there's something strange going on, we should try to fix it 
asap.

It could be a one-off thing (knock wood), but on the other hand, I've only 
been using this machine for a couple of weeks now, and I can't remember 
seeing anything even remotely similar on my other machines (including the 
earlier-generation i945 SATA setup that I've had a lot longer). So I worry 
that it's something i965-specific, and that will be a _very_ common 
chipset soon enough.

One data-point that may or may not be relevant: the afore-mentioned i945 
machine that I've had longer is otherwise reasonably similar, but the DVD 
drive on that one is in legacy mode. Not that I see why it should matter 
(the problem happened on the harddisk, not the DVD)...

		Linus

Re: Scary Intel SATA problem: "frozen"

[Eric D. Mudama]

On 11/28/06, Sergei Shtylyov <sshtylyov@ru.mvista.com> wrote:
> Hello.
>
> Mark Lord wrote:
>
> > Bit #4, when actually implemented, is a rotational seek indicator,
> > which can be used for timing purposes.
>
>     Hm, I thought it was DSC (drive seek complete) set by the SEEK command
> completion, and it's always implemented. Didn't you mean IDX (bit 1, IIRC)?

0x50 is the standard, non queueing "device is ready" status.  It used
to have those special meanings, but they're pretty obsolete today as I
understand it.

0x40 is used for queueing, because bit 4 was the service bit for PATA TCQ.

> > But when BUSY (bit #7) is set, the rest are generally nonsense.
>
>     Indeed...
>
> WBR, Sergei

Typically, 0x80 as the busy state indicates the device is in POR
reset.  Once the firmware is up and running in the device, it often
switches from 0x80 to 0xD0 during POR.

0xD0 is the busy state you'd get to if you were 0x50 and received a
command, so this is reported typically after the device is up and
running.

0x7F usually is hardware indicating nothing is attached to the port,
and isn't supposed to infer a non-busy state.

You're right, while not meaningful according to spec, you can derive
some information from the reported status even when you're only
supposed to look at one bit.

Re: Scary Intel SATA problem: "frozen"

[Sergei Shtylyov]

Hello.

Eric D. Mudama wrote:
>> > Bit #4, when actually implemented, is a rotational seek indicator,
>> > which can be used for timing purposes.

>>     Hm, I thought it was DSC (drive seek complete) set by the SEEK 
>> command
>> completion, and it's always implemented. Didn't you mean IDX (bit 1, 
>> IIRC)?

> 0x50 is the standard, non queueing "device is ready" status.  It used
> to have those special meanings, but they're pretty obsolete today as I
> understand it.

    Erm, some status bits maybe obsolete but I've never heard that the status 
*values* were specified to mean anything special anywhere...

> 0x40 is used for queueing, because bit 4 was the service bit for PATA TCQ.

   I know. This meaning (SERVICE) actualy came from ATAPI

>> > But when BUSY (bit #7) is set, the rest are generally nonsense.

>>     Indeed...

>> WBR, Sergei

> Typically, 0x80 as the busy state indicates the device is in POR
> reset.  Once the firmware is up and running in the device, it often
> switches from 0x80 to 0xD0 during POR.

    Oh, I guess it's completely up to the disk makers what other status to 
show with BSY=1.

> 0xD0 is the busy state you'd get to if you were 0x50 and received a
> command, so this is reported typically after the device is up and
> running.

> 0x7F usually is hardware indicating nothing is attached to the port,
> and isn't supposed to infer a non-busy state.

    Ha, *never* seen that one. It's has always been 0xFF since PC people 
didn't ever bother themselves with silly pulldowns. :-)

> You're right, while not meaningful according to spec, you can derive
> some information from the reported status even when you're only
> supposed to look at one bit.

   Well, to some extent...

WBR, Sergei

Re: Scary Intel SATA problem: "frozen"

[Jeff Garzik]

Linus Torvalds wrote:
> [ You may or may not have gotten my previous email. The kernel stayed 
>   working, but due to the IO errors the filesystem got re-mounted 
>   read-only, and I'm not sure that the email I sent out in that state 
>   actually ever made it out. I suspect it didn't. ]
> 
> Jeff,
>  I just had a scary thing on my nice new Intel i965 box (all Intel 
> chipsets apart from some strange Marvell IDE interface that I'm not using 
> and that no driver even detected, and a TI firewire thing that I'm 
> similarly not using).

Does jgarzik/libata-dev.git#upstream (don't pull, just test) work for you?

Or -mm, which includes #upstream?

I'm pretty sure this is already fixed, by the polling IDENTIFY for 
ata_piix patchset.

	Jeff

Re: Scary Intel SATA problem: "frozen"

[Linus Torvalds]

On Tue, 28 Nov 2006, Jeff Garzik wrote:
> 
> Does jgarzik/libata-dev.git#upstream (don't pull, just test) work for you?

Well, since I can't really test, I don't know. This problem has happened 
just once in the couple of weeks I've used that machine, and I wasn't even 
doing anything strange when it triggered (no heavy IO, no special 
programs, no nothing - I was literally just reading email and I think 
trying to browse over to news.com or something..)

So I was more hoping that you'd say that it's a known issue, and already 
fixed, or that the status bits would give you some clue and make you say 
"Ahh, we don't handle that case". I have nothing to "test". The thing 
seems to work, and I have no known way to trigger the problem...

> I'm pretty sure this is already fixed, by the polling IDENTIFY for ata_piix
> patchset.

Hmm. That sounds like it should just affect the bootup identification, 
which has always worked fine for me. Would it fix the softreset too?

Anyway, I can certainly try yout current "upstream" branch, but as 
mentioned, the standard kernel works fine for me generally, so I don't 
really know what I can offer (except if "upstream" simply doesn't work at 
all, in which case I'll certainly let you know ;)

		Linus

Re: Scary Intel SATA problem: "frozen"

[Jeff Garzik]

And FWIW, "frozen" in this context means that Tejun's libata error 
handling code has take ownership of the ATA port, after stopping all 
outstanding I/O transactions.

So when you see that, that's libata EH kicking in.

	Jeff

Re: Scary Intel SATA problem: "frozen"

[Jonas Lundgren]

I've been monitoring the linux-ide list to try and find a solution to my
problem with my intel box (i965) and SATA disks.. I sent a mail to the
maintainer of the ata_piix driver and cc'd the linux-ide ML, but go no
responses. I'm not used to mail to ML's, so please excuse me if I did
something wrong with the reply of this mail/CC'ing the wrong persons etc. :)



Here's what I wrote in my last mail to linux-ide:

I've got some big performance related problem with my Abit AB9 pro mobo,
the ICH8 controller and my SATA disks.. I've got 2 64GB WD raptor disks
in a raid0(These are the disks I have used dd/hdparm on in the commands
below), and a 2x250GB WD disk raid0, and I used to get around
130-140mb/sec seq write with them, but now with my new mobo I'm lucky if
I get 10mb/sec. During heavy disk activity the system locks up, until
the write is completed (Ie, no other read or write is being made, it's
like heavy IO completely starves all other processes until it's finished)..

Running 2.6.19-rc5-mm2 atm, but I've tried a few diffrent kernels, same
thing.

Also, it doesn't matter if I enable AHCI in the BIOS (But with AHCI
enabled the disks spin down/power down when I boot, just to power up
again a few seconds after. The boot progress freezes until the disks
have spun up again. (This happens when the kernel probes the sata
controller ports at bootup, the disks spin down at the same time, but
spin up one by one as they're getting probed))

I've tried changing I/O scheduler, only noticable diffrence is when I
use "noop". Then I get like 20mb/sec write instead of 4mb/sec. I have no
idea why this is :P

Example of what I mean with crappy performance:
dd if=/dev/zero of=test232 bs=1M count=100; time sync
100+0 records in
100+0 records out
104857600 bytes (105 MB) copied, 0.130424 s, 804 MB/s
real 0m21.104s
user 0m0.000s
sys 0m0.011s

21 seconds to do a seq write of 100mb.. And during this time ALL other
disk IO gets starved, I can't do anything that uses disk IO for the
duration.. (not even `ls`)

Yet, a hdparm shows a decent read
hdparm -tT /dev/md4
/dev/md4:
Timing cached reads: 8060 MB in 1.99 seconds = 4042.19 MB/sec
Timing buffered disk reads: 400 MB in 3.00 seconds = 133.28 MB/sec

dd if=1GBzeroFile of=/dev/null bs=1M count=1000
1000+0 records in
1000+0 records out
1048576000 bytes (1.0 GB) copied, 11.4335 s, 91.7 MB/s

This is the cpu usage stats I get from top when running the dd write:
Cpu0 : 0.0%us, 0.0%sy, 0.0%ni, 0.0%id, 99.0%wa, 0.5%hi, 0.5%si, 0.0%st
Cpu1 : 0.0%us, 0.0%sy, 0.0%ni,100.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st

Pretty crappy read speeds compared to what I got on my previous mobo
(around 140mb/sec), but still alot better than the 4mb/sec I get when
writing..

I've also googled this for many hours, I've searched the lkml, checked
the gentoo forums, as well as other distro forums, I just don't know
what else to do. I'll appreciate any help or hints I can get.




Dmesg output from the error(s): (sda and sdb are 2 * 74GB raptor SATA
drives in a Linux software raid0)

ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata1.00: (BMDMA stat 0x20)
ata1.00: tag 0 cmd 0xca Emask 0x4 stat 0x40 err 0x0 (timeout)
ata1: port is slow to respond, please be patient
ata1: port failed to respond (30 secs)
ata1: soft resetting port
ATA: abnormal status 0xD0 on port 0xFA07
ATA: abnormal status 0xD0 on port 0xFA07
ATA: abnormal status 0xD0 on port 0xFA07
ATA: abnormal status 0xD0 on port 0xFA07
ATA: abnormal status 0xD0 on port 0xFA07
ATA: abnormal status 0xD0 on port 0xFA07
ata1.00: qc timeout (cmd 0xec)
ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
ata1.00: revalidation failed (errno=-5)
ata1: failed to recover some devices, retrying in 5 secs
ata1: soft resetting port
ata1.00: configured for UDMA/100
ata1: EH complete
SCSI device sda: 145226112 512-byte hdwr sectors (74356 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: drive cache: write back
ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata1.00: (BMDMA stat 0x21)
ata1.00: tag 0 cmd 0xc8 Emask 0x4 stat 0x40 err 0x0 (timeout)
ata1: port is slow to respond, please be patient
ata1: port failed to respond (30 secs)
ata1: soft resetting port
ata1.00: configured for UDMA/100
ata1: EH complete
SCSI device sda: 145226112 512-byte hdwr sectors (74356 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: drive cache: write back
ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata1.00: (BMDMA stat 0x21)
ata1.00: tag 0 cmd 0xc8 Emask 0x4 stat 0x40 err 0x0 (timeout)
ata1: port is slow to respond, please be patient
ata1: port failed to respond (30 secs)
ata1: soft resetting port
ATA: abnormal status 0xD0 on port 0xFA07
ATA: abnormal status 0xD0 on port 0xFA07
ATA: abnormal status 0xD0 on port 0xFA07
ATA: abnormal status 0xD0 on port 0xFA07
ATA: abnormal status 0xD0 on port 0xFA07
ATA: abnormal status 0xD0 on port 0xFA07
ata1.00: failed to IDENTIFY (I/O error, err_mask=0x2)
ata1.00: revalidation failed (errno=-5)
ata1: failed to recover some devices, retrying in 5 secs
ata1: soft resetting port
ata1.00: configured for UDMA/100
ata1: EH complete
SCSI device sda: 145226112 512-byte hdwr sectors (74356 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: drive cache: write back


Most of the time when I get these errors the system will recover after
anything from 10 seconds to 10 minutes of unresponsiveness (no disk
I/O), and sometimes hang. IF the system does recover, I start getting
the extremly low disk write speeds that I reported above, and only a
reboot will get the performance back to regular.

I don't know what causes it, but most of the times when I've gotten it
my system has been under heavy load (compiling, downloading torrents in
11mb/sec etc). Please let me know if you want any additional info, want
me to try something out, or whatever. My recent hardware upgrade for
around $1200 (to a core2duo system, i965 mobo) is just going to waste
because of this problem. :/

I just got so glad when I saw the post of this on linux-ide, I've been
searching like crazy to find another person having the same problem (and
possibly a solution) for the past 2-3 weeks or so.

-- 
-Jonas

Name:   Jonas Lundgren
ICQ#:   52064961
IRC:    neon / neonman @ EFnet, Undernet, Quakenet, freenode

Re: Scary Intel SATA problem: "frozen"

[Linus Torvalds]

On Tue, 28 Nov 2006, Jonas Lundgren wrote:
> 
> Example of what I mean with crappy performance:
> dd if=/dev/zero of=test232 bs=1M count=100; time sync
> 100+0 records in
> 100+0 records out
> 104857600 bytes (105 MB) copied, 0.130424 s, 804 MB/s
> real 0m21.104s

Ok, that's definitely not the same thing I see.

I get

	real    0m2.673s

for the "time sync" part of your example, so the chipset can definitely do 
better than your 4-5 MB/s.

And your read performance seems fine. Strange.

I suspect it's related to your RAID usage. I've only got a single disk in 
my system. Maybe there is something problematic in sending commands to 
alternating SATA ports on the same controller with the i965 thing?

The "switching between SATA ports" thing migt actually be a clue, because 
while I've had this thing for a few weeks, I only used the DVD drive for 
the first time the day before yesterday, and didn't actually even have the 
SCSI CD-ROM support compiled in until then (copied a config from another 
machine that had the DVD-rom on the legacy side, so it used the more 
common IDE-CD thing).

So maybe these _are_ related somehow, and my problem showed up because I 
actually had concurrent access to my DVD drive (some KDE media daemon 
checking to see if I inserted a music CD or something?). Jeff, Tejun, is 
there any reason to believe that the two channels on a PIIX ata controller 
are somehow "tied together" and it could be problematic for concurrent 
accesses?

Jonas definitely has the same error messages:

> Dmesg output from the error(s): (sda and sdb are 2 * 74GB raptor SATA
> drives in a Linux software raid0)
> 
> ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> ata1.00: (BMDMA stat 0x20)
> ata1.00: tag 0 cmd 0xca Emask 0x4 stat 0x40 err 0x0 (timeout)
> ata1: port is slow to respond, please be patient
> ata1: port failed to respond (30 secs)
> ata1: soft resetting port
> ATA: abnormal status 0xD0 on port 0xFA07
> ATA: abnormal status 0xD0 on port 0xFA07
> ATA: abnormal status 0xD0 on port 0xFA07
> ATA: abnormal status 0xD0 on port 0xFA07
> ATA: abnormal status 0xD0 on port 0xFA07
> ATA: abnormal status 0xD0 on port 0xFA07

That all looks exactly like mine did.

Except:

> ata1: EH complete
> SCSI device sda: 145226112 512-byte hdwr sectors (74356 MB)
> sda: Write Protect is off
> sda: Mode Sense: 00 3a 00 00
> SCSI device sda: drive cache: write back

Jonas' disks came back.

So while Jonas' behaviour/problems otherwise don't seem to match mine at 
all, there might be some underlying commonality..

			Linus

Re: Scary Intel SATA problem: "frozen"

[Jeff Garzik]

Linus Torvalds wrote:
> So maybe these _are_ related somehow, and my problem showed up because I 
> actually had concurrent access to my DVD drive (some KDE media daemon 
> checking to see if I inserted a music CD or something?). Jeff, Tejun, is 
> there any reason to believe that the two channels on a PIIX ata controller 
> are somehow "tied together" and it could be problematic for concurrent 
> accesses?


I was sorta wondering in that direction too.  If its in legacy mode 
(PATA and SATA smushed together), that's a possibility.  But native or 
AHCI modes, the channels are pretty independent (which is the nature of 
SATA).

Historical note:  ata_piix is IMO more complicated than ahci, because 
the silicon is emulating the PATA interface using an internal (probably 
huge) state machine, converting PATA behavior to sending/receiving SATA 
packets.  There are classes of problems that just don't exist on ahci, 
simply because we can directly talk to the sata phy, rather than having 
to guess what the emulation state machine is doing.

	Jeff

Re: Scary Intel SATA problem: "frozen"

[Linus Torvalds]

On Tue, 28 Nov 2006, Jeff Garzik wrote:
> 
> I was sorta wondering in that direction too.  If its in legacy mode (PATA and
> SATA smushed together), that's a possibility.  But native or AHCI modes, the
> channels are pretty independent (which is the nature of SATA).

Well, what I was more wondering about is whether perhaps the legacy mode 
emulation - even when it isn't actually used - means that there is simply 
some shared state (read: chipset bug that nobody noticed).

> Historical note:  ata_piix is IMO more complicated than ahci, because the
> silicon is emulating the PATA interface using an internal (probably huge)
> state machine, converting PATA behavior to sending/receiving SATA packets.

Well, there's bound to be the same big state machine working the other 
way, and maybe the chip simply internally gets confused. Or, as you say, 
simply because the emulation state machinery has to be taken into account, 
and _that_ ends up beign shared between the two otherwise independent 
channels..

How hard would it be to just force a shared spinlock between two sata 
channels on the same "controller"? It sounds like Jonas has a very 
repeatable setup, so even if I can't repeat my problem, if the performance 
degradation on writes is related, he can check his thing..

		Linus

Re: Scary Intel SATA problem: "frozen"

[Jeff Garzik]

Linus Torvalds wrote:
> How hard would it be to just force a shared spinlock between two sata 
> channels on the same "controller"? It sounds like Jonas has a very 
> repeatable setup, so even if I can't repeat my problem, if the performance 
> degradation on writes is related, he can check his thing..


ap->host (struct ata_host) already has a spinlock for precisely just 
that...  :)

	Jeff

Re: Scary Intel SATA problem: "frozen"

[Linus Torvalds]

On Tue, 28 Nov 2006, Jeff Garzik wrote:
> 
> ap->host (struct ata_host) already has a spinlock for precisely just that...
> :)

Right, but do we actually take it? I'm not seing any spin_lock's in 
ata_piix.c, but I don't know the SATA layers enough to say whether upper 
layers take it or not..

		Linus

Re: Scary Intel SATA problem: "frozen"

[Tejun Heo]

Jonas Lundgren wrote:
[--snip--]
> Also, it doesn't matter if I enable AHCI in the BIOS (But with AHCI
> enabled the disks spin down/power down when I boot, just to power up
> again a few seconds after. The boot progress freezes until the disks
> have spun up again. (This happens when the kernel probes the sata
> controller ports at bootup, the disks spin down at the same time, but
> spin up one by one as they're getting probed))

Likely fix is pending for this problem.

> I've tried changing I/O scheduler, only noticable diffrence is when I
> use "noop". Then I get like 20mb/sec write instead of 4mb/sec. I have no
> idea why this is :P
> 
> Example of what I mean with crappy performance:
> dd if=/dev/zero of=test232 bs=1M count=100; time sync
> 100+0 records in
> 100+0 records out
> 104857600 bytes (105 MB) copied, 0.130424 s, 804 MB/s
> real 0m21.104s
> user 0m0.000s
> sys 0m0.011s
> 
> 21 seconds to do a seq write of 100mb.. And during this time ALL other
> disk IO gets starved, I can't do anything that uses disk IO for the
> duration.. (not even `ls`)

What does the kernel say during this writing?  Can you post the result 
of the following?

1. reboot
2. dmesg -c
3. time dd if=/dev/zero.. blah
4. dmesg

Also, does 'mount -o remount,barrier=0 /' change anything?

> Yet, a hdparm shows a decent read
> hdparm -tT /dev/md4
> /dev/md4:
> Timing cached reads: 8060 MB in 1.99 seconds = 4042.19 MB/sec
> Timing buffered disk reads: 400 MB in 3.00 seconds = 133.28 MB/sec
> 
> dd if=1GBzeroFile of=/dev/null bs=1M count=1000
> 1000+0 records in
> 1000+0 records out
> 1048576000 bytes (1.0 GB) copied, 11.4335 s, 91.7 MB/s
> 
> This is the cpu usage stats I get from top when running the dd write:
> Cpu0 : 0.0%us, 0.0%sy, 0.0%ni, 0.0%id, 99.0%wa, 0.5%hi, 0.5%si, 0.0%st
> Cpu1 : 0.0%us, 0.0%sy, 0.0%ni,100.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
> 
> Pretty crappy read speeds compared to what I got on my previous mobo
> (around 140mb/sec), but still alot better than the 4mb/sec I get when
> writing..

Which controller did you use on your previous mobo?  If you're using 
ata_piix and hook two hard drives as primary and secondary on the same 
channel, some level of performance degradation is expected.  ata_piix 
can only issue command to only one of the two drives at once.  Is the 
read performance still bad in ahci mode?

[--snip--]
> Dmesg output from the error(s): (sda and sdb are 2 * 74GB raptor SATA
> drives in a Linux software raid0)
> 
> ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> ata1.00: (BMDMA stat 0x20)
> ata1.00: tag 0 cmd 0xca Emask 0x4 stat 0x40 err 0x0 (timeout)

This might be a missed interrupt.  It's a write.  DMA engine is done 
finishing transferring all data.  Device is ready for the next command 
but the interrupt has never arrived.

> ata1: port is slow to respond, please be patient
> ata1: port failed to respond (30 secs)
> ata1: soft resetting port
> ATA: abnormal status 0xD0 on port 0xFA07
> ATA: abnormal status 0xD0 on port 0xFA07
> ATA: abnormal status 0xD0 on port 0xFA07
> ATA: abnormal status 0xD0 on port 0xFA07
> ATA: abnormal status 0xD0 on port 0xFA07
> ATA: abnormal status 0xD0 on port 0xFA07
> ata1.00: qc timeout (cmd 0xec)
> ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
> ata1.00: revalidation failed (errno=-5)
> ata1: failed to recover some devices, retrying in 5 secs

But this is weird.  If it were a missed interrupt, softreset should have 
recovered it instantly.  Something fishy is going on.

[--snip--]
> ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> ata1.00: (BMDMA stat 0x21)
> ata1.00: tag 0 cmd 0xc8 Emask 0x4 stat 0x40 err 0x0 (timeout)

Same thing for read.

> ata1: port is slow to respond, please be patient
> ata1: port failed to respond (30 secs)

Again, pre-reset wait times out.  Weird.

> ata1: soft resetting port
> ata1.00: configured for UDMA/100
> ata1: EH complete
[--snip--]
> ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
> ata1.00: (BMDMA stat 0x21)
> ata1.00: tag 0 cmd 0xc8 Emask 0x4 stat 0x40 err 0x0 (timeout)

Again, for read.

> Most of the time when I get these errors the system will recover after
> anything from 10 seconds to 10 minutes of unresponsiveness (no disk
> I/O), and sometimes hang.

Yeap, libata needs stricter timing constraints for recovery.  That's 
high on to-do list.

> IF the system does recover, I start getting
> the extremly low disk write speeds that I reported above, and only a
> reboot will get the performance back to regular.

Please full dmesg after your computer got really slow.  I suspect libata 
decided to switch to PIO mode.

> I don't know what causes it, but most of the times when I've gotten it
> my system has been under heavy load (compiling, downloading torrents in
> 11mb/sec etc). Please let me know if you want any additional info, want
> me to try something out, or whatever. My recent hardware upgrade for
> around $1200 (to a core2duo system, i965 mobo) is just going to waste
> because of this problem. :/

Heh, nice machine you got there.  When you look at the dmesg, do the 
error messages occur only on one of the two drives?  Or are both 
affected?  If only one is affected,

1. swap the two.  you'll probably have to dance a little bit with boot 
loader but md should handle that fine once the kernel is loaded.  does 
the errors persist?  on which device do they occur?  do they follow the 
drive or stay on the mobo port?

2. try different cable / port.  if you change port, again, you need to 
dance w/ boot loader.  who's carrying the error messages with it?

3. try different power plug from different power lane.

> I just got so glad when I saw the post of this on linux-ide, I've been
> searching like crazy to find another person having the same problem (and
> possibly a solution) for the past 2-3 weeks or so.

My first guess is frequent transmission errors.  Please report the test 
results.  Thanks.

-- 
tejun

Re: Scary Intel SATA problem: "frozen"

[Tejun Heo]

Mark Lord wrote:
> Linus Torvalds wrote:
>> [ You may or may not have gotten my previous email. The kernel stayed 
>>   working, but due to the IO errors the filesystem got re-mounted   
>> read-only, and I'm not sure that the email I sent out in that state   
>> actually ever made it out. I suspect it didn't. ]
>>
>> Jeff,
>>  I just had a scary thing on my nice new Intel i965 box (all Intel 
>> chipsets apart from some strange Marvell IDE interface that I'm not 
>> using and that no driver even detected, and a TI firewire thing that 
>> I'm similarly not using).
>>
>> The machine basically froze for about a minute or so (well, things 
>> worked surprisingly well, considering that apparently no disk IO 
>> happened - I initially thought it was just firefox that had frozen up, 
>> since my mail session seemed to be fine), and after it came back the 
>> filesystem was mounted read-only and nothing really worked any more..
>>
>> I have no idea what status 0xD0 means: it looks like ATA_BUSY + 
>> ATA_DRDY + "bit#4", but what is bit#4?
> 
> Bit #4, when actually implemented, is a rotational seek indicator,
> which can be used for timing purposes.
> 
> But when BUSY (bit #7) is set, the rest are generally nonsense.
> 
>> And clearly, the soft-reset isn't doing squat.

I dunno.  My first suspect is transient transmission error and yeah they 
do occur from time to time even on otherwise stable setup.  For example, 
my machine is nvidia ck804 which has pretty weak error handling (at 
least used to) and stays up 24/7 and I've seen such unrecovered 
transmission error just once during last 6+ months.

My experience is that if something is weird (say, power fluctuation or 
electro-magnetic interference), SATA is the first thing to give out and 
that's why we need good EH w/ SATA much more than we do with PATA.

Drives (controllers too) sometimes fall into weird state after such 
errors and softreset is often not enough, so we need hardreset.  ICH8 
can do hardreset even in ata_piix mode.  I'll work on it.

Linus, I'll follow up with Jonas as his problem seems reproducible but 
I'm a bit skeptical about it being a driver issue.  Even w/ all its 
kinks, ata_piix is just a sff IDE controller and libata has been doing 
it for a long time.  I would be really surprised if the driver or 
controller has any such issue in the usual r/w path.  AHCI should be 
able to recover from most error conditions unless drive firmware is 
completely stuck requiring physical power off.

-- 
tejun

Re: Scary Intel SATA problem: "frozen"

[Mark Lord]

> How hard would it be to just force a shared spinlock between two sata 
> channels on the same "controller"? It sounds like Jonas has a very 
> repeatable setup, so even if I can't repeat my problem, if the performance 
> degradation on writes is related, he can check his thing..

Kinda like the "ide0=serialize" flag for the IDE subsystem, I suppose.

We certainly don't want it to be the default, as millions of ata_piix 
systems already out there seem to be working just fine (not all of them
running Linux, but enough of them to extrapolate to the zillions of
identical models).

It must be something new with ICH8 that we're not doing correctly yet.

???

Re: Scary Intel SATA problem: "frozen"

[Jonas Lundgren]

Tejun Heo wrote:
> Jonas Lundgren wrote:
> [--snip--]
>> Also, it doesn't matter if I enable AHCI in the BIOS (But with AHCI
>> enabled the disks spin down/power down when I boot, just to power up
>> again a few seconds after. The boot progress freezes until the disks
>> have spun up again. (This happens when the kernel probes the sata
>> controller ports at bootup, the disks spin down at the same time, but
>> spin up one by one as they're getting probed))
> 
> Likely fix is pending for this problem.
> 
>> I've tried changing I/O scheduler, only noticable diffrence is when I
>> use "noop". Then I get like 20mb/sec write instead of 4mb/sec. I have no
>> idea why this is :P
>>
>> Example of what I mean with crappy performance:
>> dd if=/dev/zero of=test232 bs=1M count=100; time sync
>> 100+0 records in
>> 100+0 records out
>> 104857600 bytes (105 MB) copied, 0.130424 s, 804 MB/s
>> real 0m21.104s
>> user 0m0.000s
>> sys 0m0.011s
>>
>> 21 seconds to do a seq write of 100mb.. And during this time ALL other
>> disk IO gets starved, I can't do anything that uses disk IO for the
>> duration.. (not even `ls`)
> 
> What does the kernel say during this writing?  Can you post the result
> of the following?
> 
> 1. reboot
> 2. dmesg -c
> 3. time dd if=/dev/zero.. blah
> 4. dmesg
> 
> Also, does 'mount -o remount,barrier=0 /' change anything?

I will post this info as soon as I can "reproduce" the error.

> 
>> Yet, a hdparm shows a decent read
>> hdparm -tT /dev/md4
>> /dev/md4:
>> Timing cached reads: 8060 MB in 1.99 seconds = 4042.19 MB/sec
>> Timing buffered disk reads: 400 MB in 3.00 seconds = 133.28 MB/sec
>>
>> dd if=1GBzeroFile of=/dev/null bs=1M count=1000
>> 1000+0 records in
>> 1000+0 records out
>> 1048576000 bytes (1.0 GB) copied, 11.4335 s, 91.7 MB/s
>>
>> This is the cpu usage stats I get from top when running the dd write:
>> Cpu0 : 0.0%us, 0.0%sy, 0.0%ni, 0.0%id, 99.0%wa, 0.5%hi, 0.5%si, 0.0%st
>> Cpu1 : 0.0%us, 0.0%sy, 0.0%ni,100.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
>>
>> Pretty crappy read speeds compared to what I got on my previous mobo
>> (around 140mb/sec), but still alot better than the 4mb/sec I get when
>> writing..
> 
> Which controller did you use on your previous mobo?  If you're using
> ata_piix and hook two hard drives as primary and secondary on the same
> channel, some level of performance degradation is expected.  ata_piix
> can only issue command to only one of the two drives at once.  Is the
> read performance still bad in ahci mode?

Atm I run the ICH8 SATA ports in AHCI mode with "IDE bus master"(To be
honest I don't really know what this option does, no info about it in
the BIOS nor the mobo manual) turned off in BIOS. The drives are
connected to port 1, 3, 6 and 8 (raptor+raptor on 1+3, and WD 250G + WD
250G (also a raid0) on ports 6+8)

> 
> [--snip--]
>> Dmesg output from the error(s): (sda and sdb are 2 * 74GB raptor SATA
>> drives in a Linux software raid0)
>>
>> ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
>> ata1.00: (BMDMA stat 0x20)
>> ata1.00: tag 0 cmd 0xca Emask 0x4 stat 0x40 err 0x0 (timeout)
> 
> This might be a missed interrupt.  It's a write.  DMA engine is done
> finishing transferring all data.  Device is ready for the next command
> but the interrupt has never arrived.
> 
>> ata1: port is slow to respond, please be patient
>> ata1: port failed to respond (30 secs)
>> ata1: soft resetting port
>> ATA: abnormal status 0xD0 on port 0xFA07
>> ATA: abnormal status 0xD0 on port 0xFA07
>> ATA: abnormal status 0xD0 on port 0xFA07
>> ATA: abnormal status 0xD0 on port 0xFA07
>> ATA: abnormal status 0xD0 on port 0xFA07
>> ATA: abnormal status 0xD0 on port 0xFA07
>> ata1.00: qc timeout (cmd 0xec)
>> ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
>> ata1.00: revalidation failed (errno=-5)
>> ata1: failed to recover some devices, retrying in 5 secs
> 
> But this is weird.  If it were a missed interrupt, softreset should have
> recovered it instantly.  Something fishy is going on.
> 
> [--snip--]
>> ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
>> ata1.00: (BMDMA stat 0x21)
>> ata1.00: tag 0 cmd 0xc8 Emask 0x4 stat 0x40 err 0x0 (timeout)
> 
> Same thing for read.
> 
>> ata1: port is slow to respond, please be patient
>> ata1: port failed to respond (30 secs)
> 
> Again, pre-reset wait times out.  Weird.
> 
>> ata1: soft resetting port
>> ata1.00: configured for UDMA/100
>> ata1: EH complete
> [--snip--]
>> ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
>> ata1.00: (BMDMA stat 0x21)
>> ata1.00: tag 0 cmd 0xc8 Emask 0x4 stat 0x40 err 0x0 (timeout)
> 
> Again, for read.
> 
>> Most of the time when I get these errors the system will recover after
>> anything from 10 seconds to 10 minutes of unresponsiveness (no disk
>> I/O), and sometimes hang.
> 
> Yeap, libata needs stricter timing constraints for recovery.  That's
> high on to-do list.
> 
>> IF the system does recover, I start getting
>> the extremly low disk write speeds that I reported above, and only a
>> reboot will get the performance back to regular.
> 
> Please full dmesg after your computer got really slow.  I suspect libata
> decided to switch to PIO mode.

If that's so, how come I still get good read speeds? o.O

> 
>> I don't know what causes it, but most of the times when I've gotten it
>> my system has been under heavy load (compiling, downloading torrents in
>> 11mb/sec etc). Please let me know if you want any additional info, want
>> me to try something out, or whatever. My recent hardware upgrade for
>> around $1200 (to a core2duo system, i965 mobo) is just going to waste
>> because of this problem. :/
> 
> Heh, nice machine you got there.  When you look at the dmesg, do the
> error messages occur only on one of the two drives?  Or are both
> affected?  If only one is affected,

IIRC only sda is affected, and later today I'm gonna switch back to
non-AHCI mode and try to reproduce this error (This might be my
imagination, but it feels like I get the error more frequently if I
don't run the ports in AHCI mode..) so I can try out the things you've
listed here.. Would suck if there's a hardware problem with one of my
disks, but I guess it's possible.

> 
> 1. swap the two.  you'll probably have to dance a little bit with boot
> loader but md should handle that fine once the kernel is loaded.  does
> the errors persist?  on which device do they occur?  do they follow the
> drive or stay on the mobo port?

(I'm running my /boot on a raid1, so switching drives should require no
reconfiguration at all :)

> 
> 2. try different cable / port.  if you change port, again, you need to
> dance w/ boot loader.  who's carrying the error messages with it?
> 
> 3. try different power plug from different power lane.
> 
>> I just got so glad when I saw the post of this on linux-ide, I've been
>> searching like crazy to find another person having the same problem (and
>> possibly a solution) for the past 2-3 weeks or so.
> 
> My first guess is frequent transmission errors.  Please report the test
> results.  Thanks.
>

I've pushing my system really hard for half an hour or so to reproduce
this problem, and I got something else (no write speed slowdown, but
some page allocation errors, no idea if this has something to do with
anything, but I'll post it anyways)

My dmesg is filled up with this:

swapper: page allocation failure. order:0, mode:0x20
 [<c0143a29>] __alloc_pages+0x2ec/0x308
 [<c03507a7>] tcp_v4_rcv+0x984/0x99d
 [<c0159ef2>] cache_alloc_refill+0x2d0/0x507
 [<c015a1a5>] __kmalloc+0x7c/0x7e
 [<c031c901>] __alloc_skb+0x58/0x108
 [<c026e369>] rtl8169_rx_fill+0x7b/0x140
 [<c026e6ea>] rtl8169_rx_interrupt+0x2bc/0x413
 [<c027069e>] rtl8169_poll+0x3f/0x20a
 [<c0132fa7>] hrtimer_run_queues+0xc0/0x14b
 [<c03226ef>] net_rx_action+0x79/0x106
 [<c01221e4>] __do_softirq+0x73/0xd9
 [<c0122281>] do_softirq+0x37/0x39
 [<c01056b5>] do_IRQ+0x40/0x7b
 [<c01037df>] common_interrupt+0x23/0x28
 [<c01010fe>] mwait_idle_with_hints+0x39/0x3b
 [<c0101118>] mwait_idle+0x18/0x1c
 [<c010123b>] cpu_idle+0x64/0x79
 =======================
Mem-info:
DMA per-cpu:
CPU    0: Hot: hi:    0, btch:   1 usd:   0   Cold: hi:    0, btch:   1
usd:   0
CPU    1: Hot: hi:    0, btch:   1 usd:   0   Cold: hi:    0, btch:   1
usd:   0
Normal per-cpu:
CPU    0: Hot: hi:  186, btch:  31 usd:  30   Cold: hi:   62, btch:  15
usd:  60
CPU    1: Hot: hi:  186, btch:  31 usd:  30   Cold: hi:   62, btch:  15
usd:  13
HighMem per-cpu:
CPU    0: Hot: hi:  186, btch:  31 usd: 147   Cold: hi:   62, btch:  15
usd:  49
CPU    1: Hot: hi:  186, btch:  31 usd: 174   Cold: hi:   62, btch:  15
usd:  14
Active:149205 inactive:322562 dirty:155279 writeback:8923 unstable:0
free:3019 slab:36075 mapped:52151 pagetables:808
DMA free:3520kB min:68kB low:84kB high:100kB active:0kB inactive:6684kB
present:16256kB pages_scanned:64 all_unreclaimable? no
lowmem_reserve[]: 0 873 2015
Normal free:1404kB min:3744kB low:4680kB high:5616kB active:20436kB
inactive:714124kB present:894080kB pages_scanned:45728 all_unreclaimable? no
lowmem_reserve[]: 0 0 9135
HighMem free:7152kB min:512kB low:1736kB high:2960kB active:576384kB
inactive:569440kB present:1169292kB pages_scanned:7 all_unreclaimable? no
lowmem_reserve[]: 0 0 0
DMA: 0*4kB 0*8kB 0*16kB 0*32kB 1*64kB 1*128kB 1*256kB 0*512kB 1*1024kB
1*2048kB 0*4096kB = 3520kB
Normal: 1*4kB 1*8kB 7*16kB 0*32kB 0*64kB 0*128kB 1*256kB 0*512kB
1*1024kB 0*2048kB 0*4096kB = 1404kB
HighMem: 1140*4kB 96*8kB 80*16kB 3*32kB 1*64kB 1*128kB 1*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 7152kB
Swap cache: add 29537, delete 19491, find 7603/9179, race 1+0
Free swap  = 1704516kB
Total swap = 1767128kB
Free swap:       1704516kB
524000 pages of RAM
294624 pages of HIGHMEM
5482 reserved pages
486945 pages shared
10046 pages swap cached
155279 pages dirty
8798 pages writeback
52151 pages mapped
36075 pages slab
808 pages pagetables

printk: 892 messages suppressed.
ent:md4!: page allocation failure. order:0, mode:0x20
 [<c0143a29>] __alloc_pages+0x2ec/0x308
 [<c03507a7>] tcp_v4_rcv+0x984/0x99d
 [<c0159ef2>] cache_alloc_refill+0x2d0/0x507
 [<c015a1a5>] __kmalloc+0x7c/0x7e
 [<c031c901>] __alloc_skb+0x58/0x108
 [<c026e369>] rtl8169_rx_fill+0x7b/0x140
 [<c026e6ea>] rtl8169_rx_interrupt+0x2bc/0x413
 [<c027069e>] rtl8169_poll+0x3f/0x20a
 [<c01168f9>] find_busiest_group+0x124/0x4fd
 [<c0270ed7>] rtl8169_interrupt+0xce/0x22b
 [<c03226ef>] net_rx_action+0x79/0x106
 [<c01221e4>] __do_softirq+0x73/0xd9
 [<c0122281>] do_softirq+0x37/0x39
 [<c01056b5>] do_IRQ+0x40/0x7b
 [<c036fc19>] __sched_text_start+0x309/0x937
 [<c01037df>] common_interrupt+0x23/0x28
 [<c02256ed>] _atomic_dec_and_lock+0x1d/0x80
 [<c0179044>] generic_sync_sb_inodes+0xe2/0x249
 [<c016f8f9>] iput+0x41/0x77
 [<c01b4a8f>] put_wbq+0x13/0x21
 [<c01b4c27>] entd+0x18a/0x2b8
 [<c01b4a9d>] entd+0x0/0x2b8
 [<c0130345>] kthread+0xcc/0xf3
 [<c0130279>] kthread+0x0/0xf3
 [<c01039eb>] kernel_thread_helper+0x7/0x1c
 =======================
Mem-info:
DMA per-cpu:
CPU    0: Hot: hi:    0, btch:   1 usd:   0   Cold: hi:    0, btch:   1
usd:   0
CPU    1: Hot: hi:    0, btch:   1 usd:   0   Cold: hi:    0, btch:   1
usd:   0
Normal per-cpu:
CPU    0: Hot: hi:  186, btch:  31 usd:  31   Cold: hi:   62, btch:  15
usd:  53
CPU    1: Hot: hi:  186, btch:  31 usd:  30   Cold: hi:   62, btch:  15
usd:  51
HighMem per-cpu:
CPU    0: Hot: hi:  186, btch:  31 usd: 131   Cold: hi:   62, btch:  15
usd:  54
CPU    1: Hot: hi:  186, btch:  31 usd:  77   Cold: hi:   62, btch:  15
usd:  15
Active:188954 inactive:272272 dirty:147727 writeback:8547 unstable:0
free:1969 slab:47710 mapped:50495 pagetables:832
DMA free:3520kB min:68kB low:84kB high:100kB active:0kB inactive:5256kB
present:16256kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 873 2015
Normal free:1284kB min:3744kB low:4680kB high:5616kB active:23140kB
inactive:666264kB present:894080kB pages_scanned:19930 all_unreclaimable? no
lowmem_reserve[]: 0 0 9135
HighMem free:3072kB min:512kB low:1736kB high:2960kB active:732676kB
inactive:417568kB present:1169292kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 0 0
DMA: 0*4kB 0*8kB 0*16kB 0*32kB 1*64kB 1*128kB 1*256kB 0*512kB 1*1024kB
1*2048kB 0*4096kB = 3520kB
Normal: 1*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 1*256kB 0*512kB
1*1024kB 0*2048kB 0*4096kB = 1284kB
HighMem: 172*4kB 66*8kB 18*16kB 35*32kB 1*64kB 1*128kB 1*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 3072kB
Swap cache: add 29623, delete 19495, find 7636/9238, race 1+0
Free swap  = 1704512kB
Total swap = 1767128kB
Free swap:       1704512kB
524000 pages of RAM
294624 pages of HIGHMEM
5482 reserved pages
474337 pages shared
10128 pages swap cached
147727 pages dirty
8447 pages writeback
50495 pages mapped
47710 pages slab
832 pages pagetables


This happened after I kicked up a "dd if=/dev/mdX of=/dev/null" and "dd
if=/dev/zero of=tfile1" on both my raid0's (2 dd's per raid (1 read+1
write) per drive), started a recompile of kdelibs, and had a torrent
download running for 11mb/sec, ie pretty heavy load. (done with the
anticipatory scheduler)

I guess it could just be that the kernel couldn't read the swap in a
reasonable amount of time because of all the other disk activity, but
I'm posting it anyways, since you guys will know if it has something to
do with this or not.


ps. The system is back to stable now after those allocation errors.
-- 
-Jonas

Name:   Jonas Lundgren
ICQ#:   52064961
Mail:   jonas@local.se
IRC:    neon / neonman @ EFnet, Undernet, Quakenet, freenode

Re: Scary Intel SATA problem: "frozen"

[Tejun Heo]

Jonas Lundgren wrote:
>> Also, does 'mount -o remount,barrier=0 /' change anything?
> 
> I will post this info as soon as I can "reproduce" the error.

If it doesn't occur as soon as you boot, it's probably irrelevant.

> Atm I run the ICH8 SATA ports in AHCI mode with "IDE bus master"(To be
> honest I don't really know what this option does, no info about it in
> the BIOS nor the mobo manual) turned off in BIOS. The drives are
> connected to port 1, 3, 6 and 8 (raptor+raptor on 1+3, and WD 250G + WD
> 250G (also a raid0) on ports 6+8)

I guess that's just your mobo's way of telling that ahci mode is active.

[--snip--]
>> Please full dmesg after your computer got really slow.  I suspect libata
>> decided to switch to PIO mode.
> 
> If that's so, how come I still get good read speeds? o.O

Yeah, if you're still getting good read speed, PIO mode hasn't kicked in.

>>> I don't know what causes it, but most of the times when I've gotten it
>>> my system has been under heavy load (compiling, downloading torrents in
>>> 11mb/sec etc). Please let me know if you want any additional info, want
>>> me to try something out, or whatever. My recent hardware upgrade for
>>> around $1200 (to a core2duo system, i965 mobo) is just going to waste
>>> because of this problem. :/
>> Heh, nice machine you got there.  When you look at the dmesg, do the
>> error messages occur only on one of the two drives?  Or are both
>> affected?  If only one is affected,
> 
> IIRC only sda is affected, and later today I'm gonna switch back to
> non-AHCI mode and try to reproduce this error (This might be my
> imagination, but it feels like I get the error more frequently if I
> don't run the ports in AHCI mode..) so I can try out the things you've
> listed here.. Would suck if there's a hardware problem with one of my
> disks, but I guess it's possible.

Cabling/power issue is more likely than faulty hard drive, I think. 
Interestingly, you're more likely to encounter insufficient power 
problem if you have multi-lane power supply (most high-powered ones are 
multi-lane these days) because they have less power per lane.

e.g. Single-lane 350w power supply won't have problem powering 5 drives 
no matter how you connect them but if you somehow hook up five drives to 
a single lane in 450w multi-lane power, you're screwed.  Furthermore, 
it's not always clear which cable belongs to which power lane.

>> 1. swap the two.  you'll probably have to dance a little bit with boot
>> loader but md should handle that fine once the kernel is loaded.  does
>> the errors persist?  on which device do they occur?  do they follow the
>> drive or stay on the mobo port?
> 
> (I'm running my /boot on a raid1, so switching drives should require no
> reconfiguration at all :)
> 
>> 2. try different cable / port.  if you change port, again, you need to
>> dance w/ boot loader.  who's carrying the error messages with it?
>>
>> 3. try different power plug from different power lane.
>>
>>> I just got so glad when I saw the post of this on linux-ide, I've been
>>> searching like crazy to find another person having the same problem (and
>>> possibly a solution) for the past 2-3 weeks or so.
>> My first guess is frequent transmission errors.  Please report the test
>> results.  Thanks.
>>
> 
> I've pushing my system really hard for half an hour or so to reproduce
> this problem, and I got something else (no write speed slowdown, but
> some page allocation errors, no idea if this has something to do with
> anything, but I'll post it anyways)

You pushed your box really hard and the kernel can't get the memory it 
wants.  Not really relevant to SATA problem.

-- 
tejun

Re: Scary Intel SATA problem: "frozen"

[Mark Lord]

Tejun Heo wrote:
>
> You pushed your box really hard and the kernel can't get the memory it 
> wants.  Not really relevant to SATA problem.

...unless the slowdown is due to extraordinarily high swap activity,
because of the low-memory situation..

Re: Scary Intel SATA problem: "frozen"

[Linus Torvalds]

On Wed, 29 Nov 2006, Tejun Heo wrote:
> 
> You pushed your box really hard and the kernel can't get the memory it wants.
> Not really relevant to SATA problem.

And it's not even really a bug - the caller is supposed to be ok with it. 
It's a warning message that the kernel spits out just because we've had 
problems in the past with callers that did _not_ handle an allocation 
error gracefully, so the warnign is spit out to (a) let us know something 
happened and (b) if there's a subsequent oops due to dereferencing a NULL 
pointer, it becomes easier to pinpoint what the sequence of events was.

So it's an atomic allocation that happens on the receive path in the 
network when you've run out of pages (because you're getting enough 
network traffic that earlier receives have used up all buffers, and so 
much disk IO that we haven't had time to clean any new pages yet), and 
getting an allocation failure there really is "normal", it's just "very 
unusual".

So that particular dump _looks_ scary, but it happens to be totally a 
non-issue unless something else happens afterwards to imply that the 
caller had trouble with the allocation failure.

It's also a sign of trouble if you can trigger it _easily_. It should be 
something that only triggers under very high load and under unusual 
circumstances.

		Linus

Re: Scary Intel SATA problem: "frozen"

[Jonas Lundgren]

Tejun Heo wrote:
[--snip--]

>> IF the system does recover, I start getting
>> the extremly low disk write speeds that I reported above, and only a
>> reboot will get the performance back to regular.
> 
> Please full dmesg after your computer got really slow.  I suspect libata
> decided to switch to PIO mode.
Here's the relevant part, if you want the whole dmesg look at:
http://pastebin.ca/269581

[--snip--]
[82048.255126] can't create port
[85055.578172] reiser4[unrar(30787)]: disable_write_barrier
(fs/reiser4/wander.c:234)[zam-1055]:
[85055.578174] NOTICE: md5 does not support write barriers, using
synchronous write instead.
[87825.501998] can't create port
[89520.019538] ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2
frozen
[89520.019545] ata2.00: cmd c8/00:08:fe:68:df/00:00:00:00:00/e1 tag 0
data 4096 in
[89520.019547]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[89520.322292] ata2: soft resetting port
[89527.515891] ata2: port is slow to respond, please be patient (Status
0xd0)
[89550.457913] ata2: port failed to respond (30 secs, Status 0xd0)
[89550.457917] ata2: softreset failed (device not ready)
[89550.457921] ata2: softreset failed, retrying in 5 secs
[89555.454103] ata2: hard resetting port
[89562.799693] ata2: port is slow to respond, please be patient (Status
0x80)
[89585.740239] ata2: port failed to respond (30 secs, Status 0x80)
[89585.740242] ata2: COMRESET failed (device not ready)
[89585.740245] ata2: hardreset failed, retrying in 5 secs
[89590.736978] ata2: hard resetting port
[89598.081854] ata2: port is slow to respond, please be patient (Status
0x80)
[89617.604742] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[89617.611034] ata2.00: configured for UDMA/100
[89617.611042] ata2: EH complete
[89617.623426] SCSI device sdb: 145226112 512-byte hdwr sectors (74356 MB)
[89617.633551] sdb: Write Protect is off
[89617.633553] sdb: Mode Sense: 00 3a 00 00
[89617.637765] SCSI device sdb: write cache: enabled, read cache:
enabled, doesn't support DPO or FUA

> 
>> I don't know what causes it, but most of the times when I've gotten it
>> my system has been under heavy load (compiling, downloading torrents in
>> 11mb/sec etc). Please let me know if you want any additional info, want
>> me to try something out, or whatever. My recent hardware upgrade for
>> around $1200 (to a core2duo system, i965 mobo) is just going to waste
>> because of this problem. :/
> 
> Heh, nice machine you got there.  When you look at the dmesg, do the
> error messages occur only on one of the two drives?  Or are both
> affected?  If only one is affected,
> 
> 1. swap the two.  you'll probably have to dance a little bit with boot
> loader but md should handle that fine once the kernel is loaded.  does
> the errors persist?  on which device do they occur?  do they follow the
> drive or stay on the mobo port?
It follows the drive. (Hardware problem?)

> 
> 2. try different cable / port.  if you change port, again, you need to
> dance w/ boot loader.  who's carrying the error messages with it?
Read above.

> 
> 3. try different power plug from different power lane.
I've got a really good power supply, wich can handle max 560W on the +12
/ -12 V rail alone.

> 
>> I just got so glad when I saw the post of this on linux-ide, I've been
>> searching like crazy to find another person having the same problem (and
>> possibly a solution) for the past 2-3 weeks or so.
> 
> My first guess is frequent transmission errors.  Please report the test
> results.  Thanks.
>

I guess it could only be a hardware problem since the error follows the
drive, and both the drives are identical, so it can't be a firmware
problem. Correct me if I'm wrong.

I just checked the smart status, and the drive passes, but it seems like
it's going down though, on the other hand I might misread the results.

smartctl -d ata -A /dev/sdb
smartctl version 5.36 [i686-pc-linux-gnu] Copyright (C) 2002-6 Bruce Allen
Home page is http://smartmontools.sourceforge.net/

=== START OF READ SMART DATA SECTION ===
SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE
UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000b   200   200   051    Pre-fail  Always
      -       0
  3 Spin_Up_Time            0x0007   113   111   021    Pre-fail  Always
    -       4875
  4 Start_Stop_Count        0x0032   100   100   040    Old_age   Always
      -       237
  5 Reallocated_Sector_Ct   0x0033   153   153   140    Pre-fail  Always
      -       747
  7 Seek_Error_Rate         0x000b   100   253   051    Pre-fail  Always
      -       0
  9 Power_On_Hours          0x0032   076   076   000    Old_age   Always
      -       18117
 10 Spin_Retry_Count        0x0013   100   100   051    Pre-fail  Always
      -       0
 11 Calibration_Retry_Count 0x0013   100   100   051    Pre-fail  Always
      -       0
 12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always
      -       228
194 Temperature_Celsius     0x0022   117   108   000    Old_age   Always
      -       33
196 Reallocated_Event_Count 0x0032   001   001   000    Old_age   Always
      -       639
197 Current_Pending_Sector  0x0012   200   200   000    Old_age   Always
      -       0
198 Offline_Uncorrectable   0x0012   200   200   000    Old_age   Always
      -       0
199 UDMA_CRC_Error_Count    0x000a   200   253   000    Old_age   Always
      -       0
200 Multi_Zone_Error_Rate   0x0009   200   179   051    Pre-fail
Offline      -       0


The "Reallocated_Sector_Ct" and "Reallocated_Event_Count" worries me..
Should I be worried?

-- 
-Jonas

Name:   Jonas Lundgren
ICQ#:   52064961
Mail:   jonas@local.se
IRC:    neon / neonman @ EFnet, Undernet, Quakenet, freenode

Re: Scary Intel SATA problem: "frozen"

[Andrew Lyon]

On 12/6/06, Jonas Lundgren <jonas@local.se> wrote:
> Tejun Heo wrote:
> [--snip--]
>
> >> IF the system does recover, I start getting
> >> the extremly low disk write speeds that I reported above, and only a
> >> reboot will get the performance back to regular.
> >
> > Please full dmesg after your computer got really slow.  I suspect libata
> > decided to switch to PIO mode.
> Here's the relevant part, if you want the whole dmesg look at:
> http://pastebin.ca/269581
>
> [--snip--]
> [82048.255126] can't create port
> [85055.578172] reiser4[unrar(30787)]: disable_write_barrier
> (fs/reiser4/wander.c:234)[zam-1055]:
> [85055.578174] NOTICE: md5 does not support write barriers, using
> synchronous write instead.
> [87825.501998] can't create port
> [89520.019538] ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2
> frozen
> [89520.019545] ata2.00: cmd c8/00:08:fe:68:df/00:00:00:00:00/e1 tag 0
> data 4096 in
> [89520.019547]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
> 0x4 (timeout)
> [89520.322292] ata2: soft resetting port
> [89527.515891] ata2: port is slow to respond, please be patient (Status
> 0xd0)
> [89550.457913] ata2: port failed to respond (30 secs, Status 0xd0)
> [89550.457917] ata2: softreset failed (device not ready)
> [89550.457921] ata2: softreset failed, retrying in 5 secs
> [89555.454103] ata2: hard resetting port
> [89562.799693] ata2: port is slow to respond, please be patient (Status
> 0x80)
> [89585.740239] ata2: port failed to respond (30 secs, Status 0x80)
> [89585.740242] ata2: COMRESET failed (device not ready)
> [89585.740245] ata2: hardreset failed, retrying in 5 secs
> [89590.736978] ata2: hard resetting port
> [89598.081854] ata2: port is slow to respond, please be patient (Status
> 0x80)
> [89617.604742] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [89617.611034] ata2.00: configured for UDMA/100
> [89617.611042] ata2: EH complete
> [89617.623426] SCSI device sdb: 145226112 512-byte hdwr sectors (74356 MB)
> [89617.633551] sdb: Write Protect is off
> [89617.633553] sdb: Mode Sense: 00 3a 00 00
> [89617.637765] SCSI device sdb: write cache: enabled, read cache:
> enabled, doesn't support DPO or FUA
>
> >
> >> I don't know what causes it, but most of the times when I've gotten it
> >> my system has been under heavy load (compiling, downloading torrents in
> >> 11mb/sec etc). Please let me know if you want any additional info, want
> >> me to try something out, or whatever. My recent hardware upgrade for
> >> around $1200 (to a core2duo system, i965 mobo) is just going to waste
> >> because of this problem. :/
> >
> > Heh, nice machine you got there.  When you look at the dmesg, do the
> > error messages occur only on one of the two drives?  Or are both
> > affected?  If only one is affected,
> >
> > 1. swap the two.  you'll probably have to dance a little bit with boot
> > loader but md should handle that fine once the kernel is loaded.  does
> > the errors persist?  on which device do they occur?  do they follow the
> > drive or stay on the mobo port?
> It follows the drive. (Hardware problem?)
>
> >
> > 2. try different cable / port.  if you change port, again, you need to
> > dance w/ boot loader.  who's carrying the error messages with it?
> Read above.
>
> >
> > 3. try different power plug from different power lane.
> I've got a really good power supply, wich can handle max 560W on the +12
> / -12 V rail alone.
>
> >
> >> I just got so glad when I saw the post of this on linux-ide, I've been
> >> searching like crazy to find another person having the same problem (and
> >> possibly a solution) for the past 2-3 weeks or so.
> >
> > My first guess is frequent transmission errors.  Please report the test
> > results.  Thanks.
> >
>
> I guess it could only be a hardware problem since the error follows the
> drive, and both the drives are identical, so it can't be a firmware
> problem. Correct me if I'm wrong.
>
> I just checked the smart status, and the drive passes, but it seems like
> it's going down though, on the other hand I might misread the results.
>
> smartctl -d ata -A /dev/sdb
> smartctl version 5.36 [i686-pc-linux-gnu] Copyright (C) 2002-6 Bruce Allen
> Home page is http://smartmontools.sourceforge.net/
>
> === START OF READ SMART DATA SECTION ===
> SMART Attributes Data Structure revision number: 16
> Vendor Specific SMART Attributes with Thresholds:
> ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE
> UPDATED  WHEN_FAILED RAW_VALUE
>   1 Raw_Read_Error_Rate     0x000b   200   200   051    Pre-fail  Always
>       -       0
>   3 Spin_Up_Time            0x0007   113   111   021    Pre-fail  Always
>     -       4875
>   4 Start_Stop_Count        0x0032   100   100   040    Old_age   Always
>       -       237
>   5 Reallocated_Sector_Ct   0x0033   153   153   140    Pre-fail  Always
>       -       747
>   7 Seek_Error_Rate         0x000b   100   253   051    Pre-fail  Always
>       -       0
>   9 Power_On_Hours          0x0032   076   076   000    Old_age   Always
>       -       18117
>  10 Spin_Retry_Count        0x0013   100   100   051    Pre-fail  Always
>       -       0
>  11 Calibration_Retry_Count 0x0013   100   100   051    Pre-fail  Always
>       -       0
>  12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always
>       -       228
> 194 Temperature_Celsius     0x0022   117   108   000    Old_age   Always
>       -       33
> 196 Reallocated_Event_Count 0x0032   001   001   000    Old_age   Always
>       -       639
> 197 Current_Pending_Sector  0x0012   200   200   000    Old_age   Always
>       -       0
> 198 Offline_Uncorrectable   0x0012   200   200   000    Old_age   Always
>       -       0
> 199 UDMA_CRC_Error_Count    0x000a   200   253   000    Old_age   Always
>       -       0
> 200 Multi_Zone_Error_Rate   0x0009   200   179   051    Pre-fail
> Offline      -       0
>
>
> The "Reallocated_Sector_Ct" and "Reallocated_Event_Count" worries me..
> Should I be worried?

Yes, they are a sign that the drive is wearing out!

Andy

> --
> -Jonas
>
> Name:   Jonas Lundgren
> ICQ#:   52064961
> Mail:   jonas@local.se
> IRC:    neon / neonman @ EFnet, Undernet, Quakenet, freenode
> -
> To unsubscribe from this list: send the line "unsubscribe linux-ide" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

Re: Scary Intel SATA problem: "frozen"

[Tejun Heo]

On Wed, Dec 06, 2006 at 06:58:18PM +0100, Jonas Lundgren wrote:
> Here's the relevant part, if you want the whole dmesg look at:
> http://pastebin.ca/269581
> 
[--snip--]
> [89585.740245] ata2: hardreset failed, retrying in 5 secs
> [89590.736978] ata2: hard resetting port
> [89598.081854] ata2: port is slow to respond, please be patient (Status
> 0x80)
> [89617.604742] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [89617.611034] ata2.00: configured for UDMA/100
> [89617.611042] ata2: EH complete
> [89617.623426] SCSI device sdb: 145226112 512-byte hdwr sectors (74356 MB)
> [89617.633551] sdb: Write Protect is off
> [89617.633553] sdb: Mode Sense: 00 3a 00 00
> [89617.637765] SCSI device sdb: write cache: enabled, read cache:
> enabled, doesn't support DPO or FUA

EH went okay although your harddrive is responding sluggishly.

> > 1. swap the two.  you'll probably have to dance a little bit with boot
> > loader but md should handle that fine once the kernel is loaded.  does
> > the errors persist?  on which device do they occur?  do they follow the
> > drive or stay on the mobo port?
>
> It follows the drive. (Hardware problem?)

Yeap, probably.

[--snip--]
> I guess it could only be a hardware problem since the error follows the
> drive, and both the drives are identical, so it can't be a firmware
> problem. Correct me if I'm wrong.

Firmware?  Could be a firmware bug on the drive but not
controller/driver problem.

[--snip--]
>   9 Power_On_Hours          0x0032   076   076   000    Old_age   Always
>       -       18117

That's two year's worth of spinning.  I wouldn't be surprised if the
drive gives out.

> 196 Reallocated_Event_Count 0x0032   001   001   000    Old_age   Always
>       -       639

And quite some number of reallocations.  Reallocation itself doesn't
necessarily indicate critical condition but if you've got 639 of them,
you gotta throw that thing away.

-- 
tejun