bad sectors, suspicious behaviour

(sorry for dup, incorrect system clock was set)

Hello!

I'm not sure I chose correct maillist, so point me somewhere in case of mistake :)

I'm trying to emulate OS behaviour when something goes wrong with sata hard drive, for example, unrecoverable "bad blocks". By some reason I do not want to use any sw/hw raid. I took new hard drive, because it should contain (and it contains) unreadable (not reallocated yet) sectros, and did

'dd if=/dev/sda of=/dev/null bs=1M'.

first run dd log (errors1.txt) looks OK, drive recovers, as I suppose, approximately at time

cat /sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/0000:02:02.0/host4/target4:0:0/4:0:0:0/timeout 30

but when running dd second time, log looks strange (errors2.txt)

running
echo 1 > /sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/0000:02:02.0/host4/target4:0:0/4:0:0:0/delete echo "scsi add-single-device 4 0 0 0" > /proc/scsi/scsi

and then running dd solve situation until next dd

It is vanilla 2.6.26.2 kernel and sata_mv (MV88SX6081 8-port SATA II PCI-X)

Aug  8 05:34:30 ubuntu kernel: [75558.554046]          res 41/00:08:a8:a8:36/00:00:01:00:00/40 Emask 0x1 (device error)
Aug  8 05:34:30 ubuntu kernel: [75558.554117]          res 41/00:08:a8:a8:36/00:00:01:00:00/40 Emask 0x1 (device error)
Aug  8 05:34:30 ubuntu kernel: [75558.554187] ata5: hard resetting link
Aug  8 05:34:31 ubuntu kernel: [75559.623869] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:31 ubuntu kernel: [75559.688975] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:31 ubuntu kernel: [75559.763885] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:31 ubuntu kernel: [75559.763888] ata5.00: configured for UDMA/133
Aug  8 05:34:31 ubuntu kernel: [75559.763897] ata5: EH complete
Aug  8 05:34:31 ubuntu kernel: [75559.773847] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:31 ubuntu kernel: [75559.773847] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:31 ubuntu kernel: [75559.773847] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:32 ubuntu kernel: [75561.678986]          res 41/00:08:a8:a7:36/00:00:01:00:00/40 Emask 0x1 (device error)
Aug  8 05:34:32 ubuntu kernel: [75561.679056] ata5: hard resetting link
Aug  8 05:34:33 ubuntu kernel: [75562.387966] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:33 ubuntu kernel: [75562.587985] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:33 ubuntu kernel: [75562.667983] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:33 ubuntu kernel: [75562.667986] ata5.00: configured for UDMA/133
Aug  8 05:34:33 ubuntu kernel: [75562.667993] ata5: EH complete
Aug  8 05:34:33 ubuntu kernel: [75562.668027] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:33 ubuntu kernel: [75562.668039] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:33 ubuntu kernel: [75562.668058] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:35 ubuntu kernel: [75564.468246]          res 51/40:00:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:35 ubuntu kernel: [75564.468339] ata5: hard resetting link
Aug  8 05:34:35 ubuntu kernel: [75565.191441] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:35 ubuntu kernel: [75565.251460] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:35 ubuntu kernel: [75565.515045] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:35 ubuntu kernel: [75565.515048] ata5.00: configured for UDMA/133
Aug  8 05:34:35 ubuntu kernel: [75565.515052] ata5: EH complete
Aug  8 05:34:35 ubuntu kernel: [75565.515085] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:35 ubuntu kernel: [75565.515096] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:35 ubuntu kernel: [75565.515116] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:37 ubuntu kernel: [75567.359209]          res 51/40:00:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:37 ubuntu kernel: [75567.368921] ata5: hard resetting link
Aug  8 05:34:37 ubuntu kernel: [75568.136442] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:37 ubuntu kernel: [75568.376525] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:37 ubuntu kernel: [75568.476521] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:37 ubuntu kernel: [75568.476524] ata5.00: configured for UDMA/133
Aug  8 05:34:37 ubuntu kernel: [75568.476529] ata5: EH complete
Aug  8 05:34:37 ubuntu kernel: [75568.476562] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:37 ubuntu kernel: [75568.476573] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:37 ubuntu kernel: [75568.476593] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:39 ubuntu kernel: [75570.406705]          res 51/40:00:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:39 ubuntu kernel: [75570.406798] ata5: hard resetting link
Aug  8 05:34:40 ubuntu kernel: [75571.043944] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:40 ubuntu kernel: [75571.106461] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:40 ubuntu kernel: [75571.306500] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:40 ubuntu kernel: [75571.306503] ata5.00: configured for UDMA/133
Aug  8 05:34:40 ubuntu kernel: [75571.306507] ata5: EH complete
Aug  8 05:34:40 ubuntu kernel: [75571.306540] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:40 ubuntu kernel: [75571.306552] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:40 ubuntu kernel: [75571.306572] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:41 ubuntu kernel: [75572.914314]          res 51/40:00:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:41 ubuntu kernel: [75572.914408] ata5: hard resetting link
Aug  8 05:34:42 ubuntu kernel: [75573.424052] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:42 ubuntu kernel: [75573.624070] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:42 ubuntu kernel: [75573.704069] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:42 ubuntu kernel: [75573.704072] ata5.00: configured for UDMA/133
Aug  8 05:34:42 ubuntu kernel: [75573.704088] sd 4:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK
Aug  8 05:34:42 ubuntu kernel: [75573.704091] sd 4:0:0:0: [sda] Sense Key : Medium Error [current] [descriptor]
Aug  8 05:34:42 ubuntu kernel: [75573.704095] Descriptor sense data with sense descriptors (in hex):
Aug  8 05:34:42 ubuntu kernel: [75573.704096]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Aug  8 05:34:42 ubuntu kernel: [75573.704102]         01 36 a7 e0
Aug  8 05:34:42 ubuntu kernel: [75573.704105] sd 4:0:0:0: [sda] Add. Sense: Unrecovered read error - auto reallocate failed
Aug  8 05:34:42 ubuntu kernel: [75573.704139] __ratelimit: 22 messages suppressed
Aug  8 05:34:42 ubuntu kernel: [75573.704430] ata5: EH complete
Aug  8 05:34:42 ubuntu kernel: [75573.704393] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:42 ubuntu kernel: [75573.704393] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:42 ubuntu kernel: [75573.704393] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:44 ubuntu kernel: [75575.644677]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:44 ubuntu kernel: [75575.644771] ata5: hard resetting link
Aug  8 05:34:44 ubuntu kernel: [75576.434353] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:44 ubuntu kernel: [75576.494370] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:44 ubuntu kernel: [75576.644369] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:44 ubuntu kernel: [75576.644372] ata5.00: configured for UDMA/133
Aug  8 05:34:44 ubuntu kernel: [75576.644377] ata5: EH complete
Aug  8 05:34:44 ubuntu kernel: [75576.644330] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:44 ubuntu kernel: [75576.644330] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:44 ubuntu kernel: [75576.644330] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:46 ubuntu kernel: [75578.654332]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:46 ubuntu kernel: [75578.654332] ata5: hard resetting link
Aug  8 05:34:46 ubuntu kernel: [75579.552581] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:46 ubuntu kernel: [75579.815101] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:47 ubuntu kernel: [75579.902600] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:47 ubuntu kernel: [75579.902603] ata5.00: configured for UDMA/133
Aug  8 05:34:47 ubuntu kernel: [75579.902608] ata5: EH complete
Aug  8 05:34:47 ubuntu kernel: [75579.902639] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:47 ubuntu kernel: [75579.902650] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:47 ubuntu kernel: [75579.902669] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:48 ubuntu kernel: [75581.630346]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:48 ubuntu kernel: [75581.630439] ata5: hard resetting link
Aug  8 05:34:49 ubuntu kernel: [75582.400019] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:49 ubuntu kernel: [75582.480038] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:49 ubuntu kernel: [75582.580035] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:49 ubuntu kernel: [75582.580038] ata5.00: configured for UDMA/133
Aug  8 05:34:49 ubuntu kernel: [75582.580043] ata5: EH complete
Aug  8 05:34:49 ubuntu kernel: [75582.619935] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:49 ubuntu kernel: [75582.619935] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:49 ubuntu kernel: [75582.619935] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:50 ubuntu kernel: [75584.227719]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:50 ubuntu kernel: [75584.227812] ata5: hard resetting link
Aug  8 05:34:51 ubuntu kernel: [75585.067849] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:51 ubuntu kernel: [75585.160367] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:51 ubuntu kernel: [75585.254889] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:51 ubuntu kernel: [75585.254892] ata5.00: configured for UDMA/133
Aug  8 05:34:51 ubuntu kernel: [75585.254897] ata5: EH complete
Aug  8 05:34:51 ubuntu kernel: [75585.254929] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:51 ubuntu kernel: [75585.254940] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:51 ubuntu kernel: [75585.254959] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:53 ubuntu kernel: [75587.002634]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:53 ubuntu kernel: [75587.002727] ata5: hard resetting link
Aug  8 05:34:53 ubuntu kernel: [75587.682309] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:53 ubuntu kernel: [75587.742327] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:53 ubuntu kernel: [75587.842326] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:53 ubuntu kernel: [75587.842329] ata5.00: configured for UDMA/133
Aug  8 05:34:53 ubuntu kernel: [75587.842334] ata5: EH complete
Aug  8 05:34:53 ubuntu kernel: [75587.842326] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:53 ubuntu kernel: [75587.842326] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:53 ubuntu kernel: [75587.842326] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:55 ubuntu kernel: [75589.954997]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:55 ubuntu kernel: [75589.955090] ata5: hard resetting link
Aug  8 05:34:55 ubuntu kernel: [75590.727173] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:55 ubuntu kernel: [75590.806604] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:56 ubuntu kernel: [75590.914330] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:56 ubuntu kernel: [75590.914333] ata5.00: configured for UDMA/133
Aug  8 05:34:56 ubuntu kernel: [75590.914340] sd 4:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK
Aug  8 05:34:56 ubuntu kernel: [75590.914343] sd 4:0:0:0: [sda] Sense Key : Medium Error [current] [descriptor]
Aug  8 05:34:56 ubuntu kernel: [75590.914346] Descriptor sense data with sense descriptors (in hex):
Aug  8 05:34:56 ubuntu kernel: [75590.914348]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Aug  8 05:34:56 ubuntu kernel: [75590.914353]         01 36 a7 e0
Aug  8 05:34:56 ubuntu kernel: [75590.914356] sd 4:0:0:0: [sda] Add. Sense: Unrecovered read error - auto reallocate failed
Aug  8 05:34:56 ubuntu kernel: [75590.914389] __ratelimit: 15 messages suppressed
Aug  8 05:34:56 ubuntu kernel: [75590.914422] ata5: EH complete
Aug  8 05:34:56 ubuntu kernel: [75590.914463] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:56 ubuntu kernel: [75590.914473] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:56 ubuntu kernel: [75590.914491] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:57 ubuntu kernel: [75593.007075]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:57 ubuntu kernel: [75593.007169] ata5: hard resetting link
Aug  8 05:34:58 ubuntu kernel: [75593.732103] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:34:58 ubuntu kernel: [75593.952104] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:58 ubuntu kernel: [75594.033461] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:34:58 ubuntu kernel: [75594.033464] ata5.00: configured for UDMA/133
Aug  8 05:34:58 ubuntu kernel: [75594.033469] ata5: EH complete
Aug  8 05:34:58 ubuntu kernel: [75594.033500] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:34:58 ubuntu kernel: [75594.033511] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:34:58 ubuntu kernel: [75594.033529] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:34:59 ubuntu kernel: [75595.971250]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:34:59 ubuntu kernel: [75595.971343] ata5: hard resetting link
Aug  8 05:35:00 ubuntu kernel: [75596.573547] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:35:00 ubuntu kernel: [75596.685419] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:35:00 ubuntu kernel: [75596.777239] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:35:00 ubuntu kernel: [75596.777242] ata5.00: configured for UDMA/133
Aug  8 05:35:00 ubuntu kernel: [75596.777246] ata5: EH complete
Aug  8 05:35:00 ubuntu kernel: [75596.777278] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:35:00 ubuntu kernel: [75596.787200] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:35:00 ubuntu kernel: [75596.787200] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:35:02 ubuntu kernel: [75598.425197]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:35:02 ubuntu kernel: [75598.425290] ata5: hard resetting link
Aug  8 05:35:02 ubuntu kernel: [75599.326815] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:35:02 ubuntu kernel: [75599.536897] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:35:02 ubuntu kernel: [75599.616896] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:35:02 ubuntu kernel: [75599.616899] ata5.00: configured for UDMA/133
Aug  8 05:35:02 ubuntu kernel: [75599.616904] ata5: EH complete
Aug  8 05:35:02 ubuntu kernel: [75599.616936] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:35:02 ubuntu kernel: [75599.616946] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:35:02 ubuntu kernel: [75599.616964] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:35:04 ubuntu kernel: [75601.757134]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:35:04 ubuntu kernel: [75601.757227] ata5: hard resetting link
Aug  8 05:35:04 ubuntu kernel: [75602.434677] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:35:05 ubuntu kernel: [75602.621432] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:35:05 ubuntu kernel: [75602.700565] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:35:05 ubuntu kernel: [75602.700568] ata5.00: configured for UDMA/133
Aug  8 05:35:05 ubuntu kernel: [75602.700572] ata5: EH complete
Aug  8 05:35:05 ubuntu kernel: [75602.700604] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:35:05 ubuntu kernel: [75602.700614] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:35:05 ubuntu kernel: [75602.700633] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:35:06 ubuntu kernel: [75605.325872]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:35:06 ubuntu kernel: [75605.325965] ata5: hard resetting link
Aug  8 05:35:07 ubuntu kernel: [75606.221411] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:35:07 ubuntu kernel: [75606.341598] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:35:07 ubuntu kernel: [75606.441597] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:35:07 ubuntu kernel: [75606.441600] ata5.00: configured for UDMA/133
Aug  8 05:35:07 ubuntu kernel: [75606.441605] ata5: EH complete
Aug  8 05:35:07 ubuntu kernel: [75606.441636] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:35:07 ubuntu kernel: [75606.441646] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:35:07 ubuntu kernel: [75606.441664] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:35:08 ubuntu kernel: [75608.223366]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug  8 05:35:08 ubuntu kernel: [75608.223459] ata5: hard resetting link
Aug  8 05:35:09 ubuntu kernel: [75608.760949] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:35:09 ubuntu kernel: [75609.071613] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:35:09 ubuntu kernel: [75609.150759] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:35:09 ubuntu kernel: [75609.150762] ata5.00: configured for UDMA/133
Aug  8 05:35:09 ubuntu kernel: [75609.150768] sd 4:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK
Aug  8 05:35:09 ubuntu kernel: [75609.150771] sd 4:0:0:0: [sda] Sense Key : Medium Error [current] [descriptor]
Aug  8 05:35:09 ubuntu kernel: [75609.150774] Descriptor sense data with sense descriptors (in hex):
Aug  8 05:35:09 ubuntu kernel: [75609.150776]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Aug  8 05:35:09 ubuntu kernel: [75609.150781]         01 36 a7 e0
Aug  8 05:35:09 ubuntu kernel: [75609.150784] sd 4:0:0:0: [sda] Add. Sense: Unrecovered read error - auto reallocate failed
Aug  8 05:35:09 ubuntu kernel: [75609.150850] ata5: EH complete
Aug  8 05:35:09 ubuntu kernel: [75609.161573] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:35:09 ubuntu kernel: [75609.171574] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:35:09 ubuntu kernel: [75609.208690] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA

Aug  8 05:36:35 ubuntu kernel: [75699.107166]          res 41/00:00:00:a8:36/00:08:01:00:00/40 Emask 0x1 (device error)
Aug  8 05:36:35 ubuntu kernel: [75699.107236]          res 41/00:08:01:00:00/00:08:01:00:00/40 Emask 0x1 (device error)
Aug  8 05:36:35 ubuntu kernel: [75699.107307] ata5: hard resetting link
Aug  8 05:36:35 ubuntu kernel: [75699.666039] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:36:35 ubuntu kernel: [75699.846017] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:36 ubuntu kernel: [75699.942982] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:36 ubuntu kernel: [75699.942985] ata5.00: configured for UDMA/133
Aug  8 05:36:36 ubuntu kernel: [75699.942993] ata5: EH complete
Aug  8 05:36:36 ubuntu kernel: [75699.943029] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:36:36 ubuntu kernel: [75699.943040] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:36:36 ubuntu kernel: [75699.943059] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:36:37 ubuntu kernel: [75702.039300] ata5.00: NCQ disabled due to excessive errors
Aug  8 05:36:37 ubuntu kernel: [75702.039382]          res 41/00:08:00:a8:36/00:00:01:00:00/40 Emask 0x1 (device error)
Aug  8 05:36:37 ubuntu kernel: [75702.039452]          res 41/00:00:01:00:00/00:00:01:00:00/40 Emask 0x1 (device error)
Aug  8 05:36:37 ubuntu kernel: [75702.039522] ata5: hard resetting link
Aug  8 05:36:38 ubuntu kernel: [75702.936061] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:36:38 ubuntu kernel: [75702.996080] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:38 ubuntu kernel: [75703.296058] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:38 ubuntu kernel: [75703.296061] ata5.00: configured for UDMA/133
Aug  8 05:36:38 ubuntu kernel: [75703.296069] ata5: EH complete
Aug  8 05:36:38 ubuntu kernel: [75703.296098] ------------[ cut here ]------------
Aug  8 05:36:38 ubuntu kernel: [75703.296100] WARNING: at drivers/ata/libata-core.c:4732 ata_qc_issue+0x1ca/0x230 [libata]()
Aug  8 05:36:38 ubuntu kernel: [75703.296102] Modules linked in: dm_mod autofs4 ipv6 iptable_filter ip_tables x_tables lp loop af_packet sr_mod cdrom container e1000e button parport_pc parport iTCO_wdt iTCO_vendor_support pcspkr shpchp pci_hotplug psmouse evdev ext3 jbd mbcache sg sd_mod pata_it8213 ata_piix pata_acpi floppy ata_generic sata_mv libata scsi_mod dock ehci_hcd uhci_hcd usbcore thermal processor fan thermal_sys fuse
Aug  8 05:36:38 ubuntu kernel: [75703.296131] Pid: 2235, comm: scsi_eh_4 Tainted: G        W 2.6.26.2.030320 #1
Aug  8 05:36:38 ubuntu kernel: [75703.296133]
Aug  8 05:36:38 ubuntu kernel: [75703.296133] Call Trace:
Aug  8 05:36:38 ubuntu kernel: [75703.296140]  [ext3:warn_on_slowpath+0x64/0x320] warn_on_slowpath+0x64/0xa0
Aug  8 05:36:38 ubuntu kernel: [75703.296145]  [sched_clock_cpu+0xc1/0x150] sched_clock_cpu+0xc1/0x150
Aug  8 05:36:38 ubuntu kernel: [75703.296148]  [usbcore:up+0x16/0xc0] up+0x16/0x50
Aug  8 05:36:38 ubuntu kernel: [75703.296150]  [release_console_sem+0x19d/0x1e0] release_console_sem+0x19d/0x1e0
Aug  8 05:36:38 ubuntu kernel: [75703.296156]  [sata_mv:mv_qc_issue+0x3c0/0x500] :sata_mv:mv_qc_issue+0x3c0/0x500
Aug  8 05:36:38 ubuntu kernel: [75703.296159]  [nommu_map_sg+0x6b/0xe0] nommu_map_sg+0x6b/0xe0
Aug  8 05:36:38 ubuntu kernel: [75703.296170]  [libata:ata_build_rw_tf+0xc1/0x290] :libata:ata_build_rw_tf+0xc1/0x290
Aug  8 05:36:38 ubuntu kernel: [75703.296181]  [libata:ata_qc_issue+0x1ca/0x230] :libata:ata_qc_issue+0x1ca/0x230
Aug  8 05:36:38 ubuntu kernel: [75703.296193]  [scsi_mod:scsi_done+0x0/0x20] :scsi_mod:scsi_done+0x0/0x20
Aug  8 05:36:38 ubuntu kernel: [75703.296203]  [libata:ata_scsi_translate+0xf8/0x190] :libata:ata_scsi_translate+0xf8/0x190
Aug  8 05:36:38 ubuntu kernel: [75703.296213]  [scsi_mod:scsi_done+0x0/0x20] :scsi_mod:scsi_done+0x0/0x20
Aug  8 05:36:38 ubuntu kernel: [75703.296224]  [sata_mv:ata_scsi_queuecmd+0xbb/0x240] :libata:ata_scsi_queuecmd+0xbb/0x240
Aug  8 05:36:38 ubuntu kernel: [75703.296235]  [scsi_mod:scsi_dispatch_cmd+0x11e/0x2e0] :scsi_mod:scsi_dispatch_cmd+0x11e/0x2e0
Aug  8 05:36:38 ubuntu kernel: [75703.296246]  [scsi_mod:scsi_request_fn+0x213/0x3c0] :scsi_mod:scsi_request_fn+0x213/0x3c0
Aug  8 05:36:38 ubuntu kernel: [75703.296251]  [scsi_mod:__blk_run_queue+0x43/0xd0] __blk_run_queue+0x43/0xd0
Aug  8 05:36:38 ubuntu kernel: [75703.296253]  [scsi_mod:blk_run_queue+0x28/0x50] blk_run_queue+0x28/0x50
Aug  8 05:36:38 ubuntu kernel: [75703.296264]  [scsi_mod:scsi_error_handler+0x0/0x570] :scsi_mod:scsi_error_handler+0x0/0x570
Aug  8 05:36:38 ubuntu kernel: [75703.296274]  [scsi_mod:scsi_run_host_queues+0x19/0x40] :scsi_mod:scsi_run_host_queues+0x19/0x40
Aug  8 05:36:38 ubuntu kernel: [75703.296284]  [scsi_mod:scsi_error_handler+0x1d9/0x570] :scsi_mod:scsi_error_handler+0x1d9/0x570
Aug  8 05:36:38 ubuntu kernel: [75703.296296]  [scsi_mod:scsi_error_handler+0x0/0x570] :scsi_mod:scsi_error_handler+0x0/0x570
Aug  8 05:36:38 ubuntu kernel: [75703.296299]  [kthread+0x4b/0x80] kthread+0x4b/0x80
Aug  8 05:36:38 ubuntu kernel: [75703.296303]  [child_rip+0xa/0x12] child_rip+0xa/0x12
Aug  8 05:36:38 ubuntu kernel: [75703.296307]  [kthread+0x0/0x80] kthread+0x0/0x80
Aug  8 05:36:38 ubuntu kernel: [75703.296309]  [child_rip+0x0/0x12] child_rip+0x0/0x12
Aug  8 05:36:38 ubuntu kernel: [75703.296311]
Aug  8 05:36:38 ubuntu kernel: [75703.296312] ---[ end trace 98cca564749c28e3 ]---
Aug  8 05:36:38 ubuntu kernel: [75703.307281] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:36:38 ubuntu kernel: [75703.307281] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:36:38 ubuntu kernel: [75703.307281] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:36:40 ubuntu kernel: [75705.198509]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:36:40 ubuntu kernel: [75705.198509] ata5: hard resetting link
Aug  8 05:36:40 ubuntu kernel: [75706.235177] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:36:40 ubuntu kernel: [75706.315195] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:41 ubuntu kernel: [75706.396627] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:41 ubuntu kernel: [75706.396630] ata5.00: configured for UDMA/133
Aug  8 05:36:41 ubuntu kernel: [75706.396635] ata5: EH complete
Aug  8 05:36:41 ubuntu kernel: [75706.396667] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:36:41 ubuntu kernel: [75706.396677] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:36:41 ubuntu kernel: [75706.396695] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:36:42 ubuntu kernel: [75709.569567]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:36:42 ubuntu kernel: [75709.569567] ata5: hard resetting link
Aug  8 05:36:43 ubuntu kernel: [75710.486591] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:36:43 ubuntu kernel: [75710.726059] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:43 ubuntu kernel: [75710.843664] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:43 ubuntu kernel: [75710.843667] ata5.00: configured for UDMA/133
Aug  8 05:36:43 ubuntu kernel: [75710.843672] ata5: EH complete
Aug  8 05:36:43 ubuntu kernel: [75710.843705] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:36:43 ubuntu kernel: [75710.843715] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:36:43 ubuntu kernel: [75710.843733] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:36:45 ubuntu kernel: [75713.273625]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:36:45 ubuntu kernel: [75713.313701] ata5: hard resetting link
Aug  8 05:36:46 ubuntu kernel: [75713.899348] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:36:46 ubuntu kernel: [75713.979366] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:46 ubuntu kernel: [75714.059365] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:46 ubuntu kernel: [75714.059368] ata5.00: configured for UDMA/133
Aug  8 05:36:46 ubuntu kernel: [75714.059373] ata5: EH complete
Aug  8 05:36:46 ubuntu kernel: [75714.219264] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:36:46 ubuntu kernel: [75714.219264] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:36:46 ubuntu kernel: [75714.219264] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:36:48 ubuntu kernel: [75716.392820]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:36:48 ubuntu kernel: [75716.392820] ata5: hard resetting link
Aug  8 05:36:48 ubuntu kernel: [75717.322050] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:36:48 ubuntu kernel: [75717.580181] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:48 ubuntu kernel: [75717.660179] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:48 ubuntu kernel: [75717.660182] ata5.00: configured for UDMA/133
Aug  8 05:36:48 ubuntu kernel: [75717.660209] sd 4:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK
Aug  8 05:36:48 ubuntu kernel: [75717.660212] sd 4:0:0:0: [sda] Sense Key : Medium Error [current] [descriptor]
Aug  8 05:36:48 ubuntu kernel: [75717.660216] Descriptor sense data with sense descriptors (in hex):
Aug  8 05:36:48 ubuntu kernel: [75717.660217]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Aug  8 05:36:48 ubuntu kernel: [75717.660223]         01 36 a7 e0
Aug  8 05:36:48 ubuntu kernel: [75717.660226] sd 4:0:0:0: [sda] Add. Sense: Unrecovered read error - auto reallocate failed
Aug  8 05:36:48 ubuntu kernel: [75717.660375] ata5: EH complete
Aug  8 05:36:48 ubuntu kernel: [75717.671137] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:36:48 ubuntu kernel: [75717.671137] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:36:48 ubuntu kernel: [75717.671137] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:36:50 ubuntu kernel: [75719.782578]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:36:50 ubuntu kernel: [75719.782578] ata5: hard resetting link
Aug  8 05:36:51 ubuntu kernel: [75720.479530] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:36:51 ubuntu kernel: [75720.649548] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:51 ubuntu kernel: [75720.739608] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:51 ubuntu kernel: [75720.739611] ata5.00: configured for UDMA/133
Aug  8 05:36:51 ubuntu kernel: [75720.739616] ata5: EH complete
Aug  8 05:36:51 ubuntu kernel: [75720.739648] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:36:51 ubuntu kernel: [75720.739658] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:36:51 ubuntu kernel: [75720.739677] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:36:53 ubuntu kernel: [75723.202008]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:36:53 ubuntu kernel: [75723.202008] ata5: hard resetting link
Aug  8 05:36:53 ubuntu kernel: [75723.762090] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:36:54 ubuntu kernel: [75724.042130] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:54 ubuntu kernel: [75724.139630] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:54 ubuntu kernel: [75724.139633] ata5.00: configured for UDMA/133
Aug  8 05:36:54 ubuntu kernel: [75724.139637] ata5: EH complete
Aug  8 05:36:54 ubuntu kernel: [75724.139668] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:36:54 ubuntu kernel: [75724.139678] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:36:54 ubuntu kernel: [75724.139696] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:36:56 ubuntu kernel: [75726.492091]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:36:56 ubuntu kernel: [75726.492091] ata5: hard resetting link
Aug  8 05:36:56 ubuntu kernel: [75727.426773] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:36:56 ubuntu kernel: [75727.506792] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:56 ubuntu kernel: [75727.586792] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:56 ubuntu kernel: [75727.586795] ata5.00: configured for UDMA/133
Aug  8 05:36:56 ubuntu kernel: [75727.586800] ata5: EH complete
Aug  8 05:36:56 ubuntu kernel: [75727.746685] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:36:56 ubuntu kernel: [75727.746685] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:36:56 ubuntu kernel: [75727.746685] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:36:58 ubuntu kernel: [75730.090040]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:36:58 ubuntu kernel: [75730.090040] ata5: hard resetting link
Aug  8 05:36:59 ubuntu kernel: [75730.871583] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:36:59 ubuntu kernel: [75730.951513] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:59 ubuntu kernel: [75731.063768] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:36:59 ubuntu kernel: [75731.063768] ata5.00: configured for UDMA/133
Aug  8 05:36:59 ubuntu kernel: [75731.063768] ata5: EH complete
Aug  8 05:36:59 ubuntu kernel: [75731.063768] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:36:59 ubuntu kernel: [75731.063768] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:36:59 ubuntu kernel: [75731.063768] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:37:01 ubuntu kernel: [75733.503947]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:37:01 ubuntu kernel: [75733.503947] ata5: hard resetting link
Aug  8 05:37:01 ubuntu kernel: [75734.640474] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:37:01 ubuntu kernel: [75734.722993] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:02 ubuntu kernel: [75734.982993] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:02 ubuntu kernel: [75734.982993] ata5.00: configured for UDMA/133
Aug  8 05:37:02 ubuntu kernel: [75734.982993] ata5: EH complete
Aug  8 05:37:02 ubuntu kernel: [75734.982993] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:37:02 ubuntu kernel: [75734.982993] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:37:02 ubuntu kernel: [75734.982993] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:37:03 ubuntu kernel: [75737.420115]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:37:03 ubuntu kernel: [75737.420115] ata5: hard resetting link
Aug  8 05:37:04 ubuntu kernel: [75738.137382] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:37:04 ubuntu kernel: [75738.243825] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:04 ubuntu kernel: [75738.320964] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:04 ubuntu kernel: [75738.320967] ata5.00: configured for UDMA/133
Aug  8 05:37:04 ubuntu kernel: [75738.320973] sd 4:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK
Aug  8 05:37:04 ubuntu kernel: [75738.320976] sd 4:0:0:0: [sda] Sense Key : Medium Error [current] [descriptor]
Aug  8 05:37:04 ubuntu kernel: [75738.320980] Descriptor sense data with sense descriptors (in hex):
Aug  8 05:37:04 ubuntu kernel: [75738.320981]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Aug  8 05:37:04 ubuntu kernel: [75738.320987]         01 36 a7 e0
Aug  8 05:37:04 ubuntu kernel: [75738.320990] sd 4:0:0:0: [sda] Add. Sense: Unrecovered read error - auto reallocate failed
Aug  8 05:37:04 ubuntu kernel: [75738.321053] ata5: EH complete
Aug  8 05:37:04 ubuntu kernel: [75738.321095] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:37:04 ubuntu kernel: [75738.321105] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:37:04 ubuntu kernel: [75738.321123] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:37:06 ubuntu kernel: [75740.548554]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:37:06 ubuntu kernel: [75740.548554] ata5: hard resetting link
Aug  8 05:37:07 ubuntu kernel: [75741.318513] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:37:07 ubuntu kernel: [75741.398531] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:07 ubuntu kernel: [75741.478530] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:07 ubuntu kernel: [75741.478533] ata5.00: configured for UDMA/133
Aug  8 05:37:07 ubuntu kernel: [75741.478538] ata5: EH complete
Aug  8 05:37:07 ubuntu kernel: [75741.528399] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:37:07 ubuntu kernel: [75741.528399] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:37:07 ubuntu kernel: [75741.528399] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:37:09 ubuntu kernel: [75743.460929]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:37:09 ubuntu kernel: [75743.460929] ata5: hard resetting link
Aug  8 05:37:09 ubuntu kernel: [75744.338647] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:37:09 ubuntu kernel: [75744.401164] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:09 ubuntu kernel: [75744.507991] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:09 ubuntu kernel: [75744.507994] ata5.00: configured for UDMA/133
Aug  8 05:37:09 ubuntu kernel: [75744.507999] ata5: EH complete
Aug  8 05:37:09 ubuntu kernel: [75744.508030] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:37:09 ubuntu kernel: [75744.508041] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:37:09 ubuntu kernel: [75744.508059] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:37:11 ubuntu kernel: [75746.360494]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:37:11 ubuntu kernel: [75746.360494] ata5: hard resetting link
Aug  8 05:37:12 ubuntu kernel: [75747.471458] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:37:12 ubuntu kernel: [75747.531477] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:12 ubuntu kernel: [75747.612969] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:12 ubuntu kernel: [75747.612972] ata5.00: configured for UDMA/133
Aug  8 05:37:12 ubuntu kernel: [75747.612977] ata5: EH complete
Aug  8 05:37:12 ubuntu kernel: [75747.613008] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:37:12 ubuntu kernel: [75747.613019] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:37:12 ubuntu kernel: [75747.613037] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:37:14 ubuntu kernel: [75749.506557]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:37:14 ubuntu kernel: [75749.506557] ata5: hard resetting link
Aug  8 05:37:14 ubuntu kernel: [75750.568741] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:37:15 ubuntu kernel: [75750.838698] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:15 ubuntu kernel: [75750.928696] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:15 ubuntu kernel: [75750.928699] ata5.00: configured for UDMA/133
Aug  8 05:37:15 ubuntu kernel: [75750.928705] ata5: EH complete
Aug  8 05:37:15 ubuntu kernel: [75750.928696] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:37:15 ubuntu kernel: [75750.928696] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:37:15 ubuntu kernel: [75750.928696] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:37:17 ubuntu kernel: [75753.133354]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:37:17 ubuntu kernel: [75753.133354] ata5: hard resetting link
Aug  8 05:37:17 ubuntu kernel: [75753.700876] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:37:17 ubuntu kernel: [75753.920834] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:17 ubuntu kernel: [75754.020331] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:17 ubuntu kernel: [75754.020333] ata5.00: configured for UDMA/133
Aug  8 05:37:17 ubuntu kernel: [75754.020338] ata5: EH complete
Aug  8 05:37:17 ubuntu kernel: [75754.020370] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:37:17 ubuntu kernel: [75754.020381] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:37:17 ubuntu kernel: [75754.020400] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug  8 05:37:19 ubuntu kernel: [75756.348504]          res 51/40:00:e0:a7:36/00:00:01:00:00/e1 Emask 0x9 (media error)
Aug  8 05:37:19 ubuntu kernel: [75756.348504] ata5: hard resetting link
Aug  8 05:37:20 ubuntu kernel: [75757.090698] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug  8 05:37:20 ubuntu kernel: [75757.290812] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:20 ubuntu kernel: [75757.400812] ata5.00: max_sectors limited to 256 for NCQ
Aug  8 05:37:20 ubuntu kernel: [75757.400815] ata5.00: configured for UDMA/133
Aug  8 05:37:20 ubuntu kernel: [75757.400822] sd 4:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK
Aug  8 05:37:20 ubuntu kernel: [75757.400825] sd 4:0:0:0: [sda] Sense Key : Medium Error [current] [descriptor]
Aug  8 05:37:20 ubuntu kernel: [75757.400828] Descriptor sense data with sense descriptors (in hex):
Aug  8 05:37:20 ubuntu kernel: [75757.400830]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Aug  8 05:37:20 ubuntu kernel: [75757.400836]         01 36 a7 e0
Aug  8 05:37:20 ubuntu kernel: [75757.400838] sd 4:0:0:0: [sda] Add. Sense: Unrecovered read error - auto reallocate failed
Aug  8 05:37:20 ubuntu kernel: [75757.400902] ata5: EH complete
Aug  8 05:37:20 ubuntu kernel: [75757.414241] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug  8 05:37:20 ubuntu kernel: [75757.414241] sd 4:0:0:0: [sda] Write Protect is off
Aug  8 05:37:20 ubuntu kernel: [75757.414241] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA

Aug  8 05:54:29 ubuntu kernel: [76898.778051] ------------[ cut here ]------------
Aug  8 05:54:29 ubuntu kernel: [76898.778051] WARNING: at drivers/ata/libata-core.c:4732 ata_qc_issue+0x1ca/0x230 [libata]()
Aug  8 05:54:29 ubuntu kernel: [76898.778051] Modules linked in: dm_mod autofs4 ipv6 iptable_filter ip_tables x_tables lp loop af_packet sr_mod cdrom container e1000e button parport_pc parport iTCO_wdt iTCO_vendor_support pcspkr shpchp pci_hotplug psmouse evdev ext3 jbd mbcache sg sd_mod pata_it8213 ata_piix pata_acpi floppy ata_generic sata_mv libata scsi_mod dock ehci_hcd uhci_hcd usbcore thermal processor fan thermal_sys fuse
Aug  8 05:54:29 ubuntu kernel: [76898.778051] Pid: 4150, comm: dd Tainted: G        W 2.6.26.2.030320 #1
Aug  8 05:54:29 ubuntu kernel: [76898.778051]
Aug  8 05:54:29 ubuntu kernel: [76898.778051] Call Trace:
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [ext3:warn_on_slowpath+0x64/0x320] warn_on_slowpath+0x64/0xa0
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [sg:sg_init_table+0x20/0x663e0] sg_init_table+0x20/0x50
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [scsi_mod:blk_rq_map_sg+0x7c/0x25e0] blk_rq_map_sg+0x7c/0x2b0
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [scsi_mod:scsi_sg_alloc+0x0/0x50] :scsi_mod:scsi_sg_alloc+0x0/0x50
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [scsi_mod:scsi_init_sgtable+0x54/0xb0] :scsi_mod:scsi_init_sgtable+0x54/0xb0
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [libata:ata_build_rw_tf+0xc1/0x290] :libata:ata_build_rw_tf+0xc1/0x290
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [libata:ata_qc_issue+0x1ca/0x230] :libata:ata_qc_issue+0x1ca/0x230
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [scsi_mod:scsi_done+0x0/0x20] :scsi_mod:scsi_done+0x0/0x20
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [libata:ata_scsi_translate+0xf8/0x190] :libata:ata_scsi_translate+0xf8/0x190
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [scsi_mod:scsi_done+0x0/0x20] :scsi_mod:scsi_done+0x0/0x20
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [sata_mv:ata_scsi_queuecmd+0xbb/0x240] :libata:ata_scsi_queuecmd+0xbb/0x240
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [scsi_mod:scsi_dispatch_cmd+0x11e/0x2e0] :scsi_mod:scsi_dispatch_cmd+0x11e/0x2e0
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [scsi_mod:scsi_request_fn+0x213/0x3c0] :scsi_mod:scsi_request_fn+0x213/0x3c0
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [sync_page_killable+0x0/0x40] sync_page_killable+0x0/0x40
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [floppy:generic_unplug_device+0x24/0xa0] generic_unplug_device+0x24/0x30
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [blk_unplug+0x35/0x70] blk_unplug+0x35/0x70
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [sync_page+0x2e/0x50] sync_page+0x2e/0x50
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [sync_page_killable+0x9/0x40] sync_page_killable+0x9/0x40
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [__wait_on_bit_lock+0x4a/0x80] __wait_on_bit_lock+0x4a/0x80
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [__lock_page_killable+0x5f/0x70] __lock_page_killable+0x5f/0x70
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [<ffffffff8024ac30>] wake_bit_function+0x0/0x30
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [fuse:generic_file_aio_read+0x36a/0x710] generic_file_aio_read+0x36a/0x570
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [ext3:do_sync_read+0xd9/0xbc0] do_sync_read+0xd9/0x120
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [<ffffffff8024ac00>] autoremove_wake_function+0x0/0x30
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [handle_mm_fault+0x575/0x810] handle_mm_fault+0x575/0x810
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [block_ioctl+0x1b/0x30] block_ioctl+0x1b/0x30
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [vfs_read+0xc5/0x180] vfs_read+0xc5/0x180
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [sys_read+0x53/0x90] sys_read+0x53/0x90
Aug  8 05:54:29 ubuntu kernel: [76898.778051]  [system_call_after_swapgs+0x7b/0x80] system_call_after_swapgs+0x7b/0x80
Aug  8 05:54:29 ubuntu kernel: [76898.778051]
Aug  8 05:54:29 ubuntu kernel: [76898.778051] ---[ end trace 98cca564749c28e3 ]---

Artem Bokhan wrote:
..

..

Note that you can create/remove *real* bad sectors on most drives by using "hdparm --make-bad-sector" and "hdparm --repair-sector".

..

Mmmm.. something bad there, and also here:

..
That line is this one (linux-2.6.26.2):

       WARN_ON(ap->ops->error_handler && ata_tag_valid(link->active_tag));

So this should trigger only when link->active_tag is valid, which doesn't normally happen. But the convoluted traceback shows that this code path came from the EH,
so something in libata EH is likely neglecting to clear link->active_tag before issuing a new command.

Tejun?

Mark Lord wrote:
..

..

Mmm.. since it happens only once in a while, and not on every EH action, one might assume that it's a race of some kind.

One possibility, might be due to .qc_defer.

The stock ata_qc_defer relies heavily on ata_tag_valid(), which matches what the above WARN_ON uses.

But sata_mv doesn't use ata_tag_valid, because it wants to know about the entire port and not just a single individual link on the port. So instead, it uses ap->nr_active_links for the test.

My guess is that these two items are not kept in sync during EH.

Tejun?

So, is there any chance to test patch from someone on this issue?

ps. I'm very far from kernel development.

Mark Lord пишет:

Hello, Mark, Artem.

The culprit is mv_qc_defer(). If the controller is in host queueing mode, it allows multiple non-NCQ commands to be queued, which currently isn't allowed by the current libata core. Allowing it shouldn't be too difficult but it would incur some core layer changes. For the time being, can you please test whether the following patch fixes the problem?

index ad169ff..80c655f 100644
@@ -1134,30 +1134,16 @@ static int mv_qc_defer(struct ata_queued_cmd *qc)
 	if (ap->nr_active_links == 0)
 		return 0;
 
-	if (pp->pp_flags & MV_PP_FLAG_EDMA_EN) {
-		/*
-		 * The port is operating in host queuing mode (EDMA).
-		 * It can accomodate a new qc if the qc protocol
-		 * is compatible with the current host queue mode.
-		 */
-		if (pp->pp_flags & MV_PP_FLAG_NCQ_EN) {
-			/*
-			 * The host queue (EDMA) is in NCQ mode.
-			 * If the new qc is also an NCQ command,
-			 * then allow the new qc.
-			 */
-			if (qc->tf.protocol == ATA_PROT_NCQ)
-				return 0;
-		} else {
-			/*
-			 * The host queue (EDMA) is in non-NCQ, DMA mode.
-			 * If the new qc is also a non-NCQ, DMA command,
-			 * then allow the new qc.
-			 */
-			if (qc->tf.protocol == ATA_PROT_DMA)
-				return 0;
-		}
-	}
+	/*
+	 * The port is operating in host queuing mode (EDMA) with NCQ
+	 * enabled, allow multiple NCQ commands.  EDMA also allows
+	 * queueing multiple DMA commands but libata core currently
+	 * doesn't allow it.
+	 */
+	if ((pp->pp_flags & MV_PP_FLAG_EDMA_EN) &&
+	    (pp->pp_flags & MV_PP_FLAG_NCQ_EN) && ata_is_ncq(qc->tf.protocol))
+		return 0;
+
 	return ATA_DEFER_PORT;
 }

patch did not help, but I found additional necessary condition (I didn't take it into account before system reboot):

to reproduce the problem from scratch it is necessary to

echo 1 > /sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/0000:02:02.0/host4/target4:0:0/4:0:0:0/timeout

returning the value to 30 do not help.

With default 30 secs the problem can not be reproduced

Tejun Heo пишет:

Can you please post full kernel log?

tejun

Tejun, I am very sorry, necessary initrd image was not updated. Now I can not reproduce the problem, thx a lot.

Tejun Heo пишет:

sata_mv allowed issuing two DMA commands concurrently which the hardware allows. Unfortunately, libata core layer isn't ready for this yet and spews ugly warning message and malfunctions on this. Don't allow concurrent DMA commands for now.

---
No problem, Artem.

Mark, does this look good to you?

 drivers/ata/sata_mv.c |   34 ++++++++++------------------------
 1 file changed, 10 insertions(+), 24 deletions(-)

index ad169ff..80c655f 100644
@@ -1134,30 +1134,16 @@ static int mv_qc_defer(struct ata_queued_cmd *qc)
 	if (ap->nr_active_links == 0)
 		return 0;
 
-	if (pp->pp_flags & MV_PP_FLAG_EDMA_EN) {
-		/*
-		 * The port is operating in host queuing mode (EDMA).
-		 * It can accomodate a new qc if the qc protocol
-		 * is compatible with the current host queue mode.
-		 */
-		if (pp->pp_flags & MV_PP_FLAG_NCQ_EN) {
-			/*
-			 * The host queue (EDMA) is in NCQ mode.
-			 * If the new qc is also an NCQ command,
-			 * then allow the new qc.
-			 */
-			if (qc->tf.protocol == ATA_PROT_NCQ)
-				return 0;
-		} else {
-			/*
-			 * The host queue (EDMA) is in non-NCQ, DMA mode.
-			 * If the new qc is also a non-NCQ, DMA command,
-			 * then allow the new qc.
-			 */
-			if (qc->tf.protocol == ATA_PROT_DMA)
-				return 0;
-		}
-	}
+	/*
+	 * The port is operating in host queuing mode (EDMA) with NCQ
+	 * enabled, allow multiple NCQ commands.  EDMA also allows
+	 * queueing multiple DMA commands but libata core currently
+	 * doesn't allow it.
+	 */
+	if ((pp->pp_flags & MV_PP_FLAG_EDMA_EN) &&
+	    (pp->pp_flags & MV_PP_FLAG_NCQ_EN) && ata_is_ncq(qc->tf.protocol))
+		return 0;
+
 	return ATA_DEFER_PORT;
 }
 

Now I have about 10 seconds of "disk restart" when hitting bad block (with /sys/...../timeout=1). Can somebody point me, if there any way to reduce it to 1/2/3 secs?

Tejun Heo пишет:

I don't really follow what you're saying. Can you please elaborate?

tejun

When I run 'dd if=/dev/sda of=/dev/null skip=9700 bs=1M' and it meets bad block, it takes about '/sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/0000:02:02.0/host4/target4:0:0/4:0:0:0/timeout + about 10 seconds' to determine I/O error. Until that IO to device is locked, as I understand. I want to reduce the time of lock as much as possible.

dd: reading `/dev/sda': Input/output error 240+1 records in
240+1 records out
252575744 bytes (253 MB) copied, 13.7833 s, 18.3 MB/s

Tejun Heo пишет:

Can you post timestamped dmesg?

tejun

Last part of it with two examples is in attachment.

Tejun Heo пишет:

[ 4199.496484] ata5.00: exception Emask 0x0 SAct 0x3 SErr 0x0 action 0x6 frozen
[ 4199.496520] ata5.00: cmd 60/00:00:00:a8:36/01:00:01:00:00/40 tag 0 ncq 131072 in
[ 4199.496522]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4199.496566] ata5.00: status: { DRDY }
[ 4199.496591] ata5.00: cmd 60/00:08:00:a7:36/01:00:01:00:00/40 tag 1 ncq 131072 in
[ 4199.496592]          res 40/00:00:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4199.496635] ata5.00: status: { DRDY }
[ 4199.496662] ata5: hard resetting link
[ 4200.295533] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 4200.375552] ata5.00: max_sectors limited to 256 for NCQ
[ 4200.455551] ata5.00: max_sectors limited to 256 for NCQ
[ 4200.455553] ata5.00: configured for UDMA/133
[ 4200.455558] ata5: EH complete
[ 4200.455513] sd 4:0:0:0: [sde] 1465149168 512-byte hardware sectors (750156 MB)
[ 4200.455513] sd 4:0:0:0: [sde] Write Protect is off
[ 4200.455513] sd 4:0:0:0: [sde] Mode Sense: 00 3a 00 00
[ 4200.455513] sd 4:0:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 4201.672540] ata5.00: exception Emask 0x0 SAct 0x3 SErr 0x0 action 0x6 frozen
[ 4201.672573] ata5.00: cmd 60/00:00:00:a7:36/01:00:01:00:00/40 tag 0 ncq 131072 in
[ 4201.672574]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4201.672618] ata5.00: status: { DRDY }
[ 4201.672643] ata5.00: cmd 60/00:08:00:a8:36/01:00:01:00:00/40 tag 1 ncq 131072 in
[ 4201.672644]          res 40/00:00:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4201.672687] ata5.00: status: { DRDY }
[ 4201.672713] ata5: hard resetting link
[ 4202.508032] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 4202.588051] ata5.00: max_sectors limited to 256 for NCQ
[ 4202.668051] ata5.00: max_sectors limited to 256 for NCQ
[ 4202.668053] ata5.00: configured for UDMA/133
[ 4202.668057] ata5: EH complete
[ 4202.668013] sd 4:0:0:0: [sde] 1465149168 512-byte hardware sectors (750156 MB)
[ 4202.668013] sd 4:0:0:0: [sde] Write Protect is off
[ 4202.668013] sd 4:0:0:0: [sde] Mode Sense: 00 3a 00 00
[ 4202.668013] sd 4:0:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 4203.760548] ata5.00: exception Emask 0x0 SAct 0x2 SErr 0x0 action 0x6 frozen
[ 4203.760581] ata5.00: cmd 60/00:08:00:a7:36/01:00:01:00:00/40 tag 1 ncq 131072 in
[ 4203.760582]          res 40/00:00:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4203.760626] ata5.00: status: { DRDY }
[ 4203.760651] ata5: hard resetting link
[ 4204.383548] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 4204.463561] ata5.00: max_sectors limited to 256 for NCQ
[ 4204.543561] ata5.00: max_sectors limited to 256 for NCQ
[ 4204.543564] ata5.00: configured for UDMA/133
[ 4204.543567] ata5: EH complete
[ 4204.543524] sd 4:0:0:0: [sde] 1465149168 512-byte hardware sectors (750156 MB)
[ 4204.543524] sd 4:0:0:0: [sde] Write Protect is off
[ 4204.543524] sd 4:0:0:0: [sde] Mode Sense: 00 3a 00 00
[ 4204.543524] sd 4:0:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 4205.628049] ata5.00: NCQ disabled due to excessive errors
[ 4205.628052] ata5.00: exception Emask 0x0 SAct 0x1 SErr 0x0 action 0x6 frozen
[ 4205.628084] ata5.00: cmd 60/00:00:00:a7:36/01:00:01:00:00/40 tag 0 ncq 131072 in
[ 4205.628085]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4205.628129] ata5.00: status: { DRDY }
[ 4205.628154] ata5: hard resetting link
[ 4206.256912] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 4206.511887] ata5.00: max_sectors limited to 256 for NCQ
[ 4206.591747] ata5.00: max_sectors limited to 256 for NCQ
[ 4206.591750] ata5.00: configured for UDMA/133
[ 4206.591753] ata5: EH complete
[ 4206.591710] sd 4:0:0:0: [sde] 1465149168 512-byte hardware sectors (750156 MB)
[ 4206.591710] sd 4:0:0:0: [sde] Write Protect is off
[ 4206.591710] sd 4:0:0:0: [sde] Mode Sense: 00 3a 00 00
[ 4206.591710] sd 4:0:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 4207.608735] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 4207.608768] ata5.00: cmd c8/00:00:00:a7:36/00:00:00:00:00/e1 tag 0 dma 131072 in
[ 4207.608769]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4207.608813] ata5.00: status: { DRDY }
[ 4207.608838] ata5: hard resetting link
[ 4208.175534] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 4208.235553] ata5.00: max_sectors limited to 256 for NCQ
[ 4208.319607] ata5.00: max_sectors limited to 256 for NCQ
[ 4208.319610] ata5.00: configured for UDMA/133
[ 4208.319613] ata5: EH complete
[ 4208.319570] sd 4:0:0:0: [sde] 1465149168 512-byte hardware sectors (750156 MB)
[ 4208.319570] sd 4:0:0:0: [sde] Write Protect is off
[ 4208.319570] sd 4:0:0:0: [sde] Mode Sense: 00 3a 00 00
[ 4208.319570] sd 4:0:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 4209.433738] ata5: limiting SATA link speed to 1.5 Gbps
[ 4209.433741] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 4209.433773] ata5.00: cmd c8/00:00:00:a7:36/00:00:00:00:00/e1 tag 0 dma 131072 in
[ 4209.433774]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4209.433818] ata5.00: status: { DRDY }
[ 4209.433843] ata5: hard resetting link
[ 4210.027860] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4210.158577] ata5.00: max_sectors limited to 256 for NCQ
[ 4210.245289] ata5.00: max_sectors limited to 256 for NCQ
[ 4210.245292] ata5.00: configured for UDMA/133
[ 4210.245297] sd 4:0:0:0: [sde] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK
[ 4210.245301] sd 4:0:0:0: [sde] Sense Key : Aborted Command [current] [descriptor]
[ 4210.245305] Descriptor sense data with sense descriptors (in hex):
[ 4210.245307]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 4210.245314]         01 36 a7 e0
[ 4210.245317] sd 4:0:0:0: [sde] Add. Sense: No additional sense information
[ 4210.245321] end_request: I/O error, dev sde, sector 20358912
[ 4210.245405] Buffer I/O error on device sde, logical block 2544864
[ 4210.245405] Buffer I/O error on device sde, logical block 2544865
[ 4210.245405] Buffer I/O error on device sde, logical block 2544866
[ 4210.245405] Buffer I/O error on device sde, logical block 2544867
[ 4210.245405] Buffer I/O error on device sde, logical block 2544868
[ 4210.245405] Buffer I/O error on device sde, logical block 2544869
[ 4210.245405] Buffer I/O error on device sde, logical block 2544870
[ 4210.245405] Buffer I/O error on device sde, logical block 2544871
[ 4210.245405] Buffer I/O error on device sde, logical block 2544872
[ 4210.245405] Buffer I/O error on device sde, logical block 2544873
[ 4210.245405] ata5: EH complete
[ 4210.245405] sd 4:0:0:0: [sde] 1465149168 512-byte hardware sectors (750156 MB)
[ 4210.245405] sd 4:0:0:0: [sde] Write Protect is off
[ 4210.245405] sd 4:0:0:0: [sde] Mode Sense: 00 3a 00 00
[ 4210.245405] sd 4:0:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA

[ 4375.878665] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 4375.878701] ata5.00: cmd c8/00:00:00:a7:36/00:00:00:00:00/e1 tag 0 dma 131072 in
[ 4375.878702]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4375.878747] ata5.00: status: { DRDY }
[ 4375.878773] ata5: hard resetting link
[ 4376.677474] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4376.781136] ata5.00: max_sectors limited to 256 for NCQ
[ 4376.860960] ata5.00: max_sectors limited to 256 for NCQ
[ 4376.860962] ata5.00: configured for UDMA/133
[ 4376.860967] ata5: EH complete
[ 4377.920091] ata5.00: limiting speed to UDMA/100:PIO4
[ 4377.920094] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 4377.920126] ata5.00: cmd c8/00:00:00:a7:36/00:00:00:00:00/e1 tag 0 dma 131072 in
[ 4377.920128]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4377.920171] ata5.00: status: { DRDY }
[ 4377.920197] ata5: hard resetting link
[ 4378.506765] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4378.566651] ata5.00: max_sectors limited to 256 for NCQ
[ 4378.670698] ata5.00: max_sectors limited to 256 for NCQ
[ 4378.670701] ata5.00: configured for UDMA/100
[ 4378.670705] ata5: EH complete
[ 4378.690792] sd 4:0:0:0: [sde] 1465149168 512-byte hardware sectors (750156 MB)
[ 4379.699935] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 4379.699969] ata5.00: cmd c8/00:00:00:a7:36/00:00:00:00:00/e1 tag 0 dma 131072 in
[ 4379.699970]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4379.700014] ata5.00: status: { DRDY }
[ 4379.700040] ata5: hard resetting link
[ 4380.470704] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4380.550291] ata5.00: max_sectors limited to 256 for NCQ
[ 4380.630116] ata5.00: max_sectors limited to 256 for NCQ
[ 4380.630118] ata5.00: configured for UDMA/100
[ 4380.630122] ata5: EH complete
[ 4380.630253] sd 4:0:0:0: [sde] Write Protect is off
[ 4380.630253] sd 4:0:0:0: [sde] Mode Sense: 00 3a 00 00
[ 4381.641298] ata5.00: limiting speed to UDMA/33:PIO4
[ 4381.641301] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 4381.641333] ata5.00: cmd c8/00:00:00:a7:36/00:00:00:00:00/e1 tag 0 dma 131072 in
[ 4381.641334]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4381.641378] ata5.00: status: { DRDY }
[ 4381.641403] ata5: hard resetting link
[ 4382.227742] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4382.287630] ata5.00: max_sectors limited to 256 for NCQ
[ 4382.387411] ata5.00: max_sectors limited to 256 for NCQ
[ 4382.387413] ata5.00: configured for UDMA/33
[ 4382.387416] ata5: EH complete
[ 4383.405274] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 4383.405307] ata5.00: cmd c8/00:00:00:a7:36/00:00:00:00:00/e1 tag 0 dma 131072 in
[ 4383.405308]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4383.405352] ata5.00: status: { DRDY }
[ 4383.405377] ata5: hard resetting link
[ 4384.118477] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4384.178496] ata5.00: max_sectors limited to 256 for NCQ
[ 4384.278496] ata5.00: max_sectors limited to 256 for NCQ
[ 4384.278499] ata5.00: configured for UDMA/33
[ 4384.278502] ata5: EH complete
[ 4384.285352] sd 4:0:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 4385.295484] ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 4385.295516] ata5.00: cmd c8/00:00:00:a7:36/00:00:00:00:00/e1 tag 0 dma 131072 in
[ 4385.295518]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
[ 4385.295561] ata5.00: status: { DRDY }
[ 4385.295586] ata5: hard resetting link
[ 4385.871406] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4385.951127] ata5.00: max_sectors limited to 256 for NCQ
[ 4386.030952] ata5.00: max_sectors limited to 256 for NCQ
[ 4386.030954] ata5.00: configured for UDMA/33
[ 4386.030961] sd 4:0:0:0: [sde] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK
[ 4386.030964] sd 4:0:0:0: [sde] Sense Key : Aborted Command [current] [descriptor]
[ 4386.030969] Descriptor sense data with sense descriptors (in hex):
[ 4386.030970]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 4386.030978]         01 36 a7 e0
[ 4386.030981] sd 4:0:0:0: [sde] Add. Sense: No additional sense information
[ 4386.030985] end_request: I/O error, dev sde, sector 20358912
[ 4386.031012] __ratelimit: 22 messages suppressed
[ 4386.031014] Buffer I/O error on device sde, logical block 2544864
[ 4386.031043] Buffer I/O error on device sde, logical block 2544865
[ 4386.031071] Buffer I/O error on device sde, logical block 2544866
[ 4386.031099] Buffer I/O error on device sde, logical block 2544867
[ 4386.031126] Buffer I/O error on device sde, logical block 2544868
[ 4386.031154] Buffer I/O error on device sde, logical block 2544869
[ 4386.031182] Buffer I/O error on device sde, logical block 2544870
[ 4386.031209] Buffer I/O error on device sde, logical block 2544871
[ 4386.031237] Buffer I/O error on device sde, logical block 2544872
[ 4386.031265] Buffer I/O error on device sde, logical block 2544873
[ 4386.031305] ata5: EH complete
[ 4386.041090] sd 4:0:0:0: [sde] 1465149168 512-byte hardware sectors (750156 MB)
[ 4386.041090] sd 4:0:0:0: [sde] Write Protect is off
[ 4386.041090] sd 4:0:0:0: [sde] Mode Sense: 00 3a 00 00
[ 4386.086179] sd 4:0:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 4386.101090] sd 4:0:0:0: [sde] 1465149168 512-byte hardware sectors (750156 MB)
[ 4386.101090] sd 4:0:0:0: [sde] Write Protect is off
[ 4386.101090] sd 4:0:0:0: [sde] Mode Sense: 00 3a 00 00
[ 4386.101090] sd 4:0:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA

..

Tell the SCSI layer to stop flogging the drive with unnecessary retries. A quick and dirty way, is this patch below, but it really should be more intelligent than this for some situations:

@@ -23,7 +23,7 @@

/*
* Number of allowed retries
*/
-#define SD_MAX_RETRIES 5
+#define SD_MAX_RETRIES 1
#define SD_PASSTHROUGH_RETRIES 1

/*

It's very strange for me that it is not runtime configurable... OK, thnx.

Also I'm not very close to ata protocols, so :
1. Why there is need to reset link if sector can not be read?
2. Why device is locked until hard reset?

Aug 13 08:45:45 ubuntu kernel: [ 5634.080692] sd 4:0:0:0: [sde] 1465149168 512-byte hardware sectors (750156 MB)
Aug 13 08:45:46 ubuntu kernel: [ 5635.088067]          res 40/00:08:e0:a7:36/01:00:01:00:00/00 Emask 0x4 (timeout)
Aug 13 08:45:46 ubuntu kernel: [ 5635.088136] ata5: hard resetting link

Mark Lord пишет:

As it named RETRY, I set it to 0, "define SD_MAX_RETRIES 0"
But still got two retries. Any suggestions?

dd if=/dev/sda of=/dev/null bs=512 skip=20359137 count=1

Aug 13 15:50:02 ubuntu kernel: [  244.688030]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug 13 15:50:02 ubuntu kernel: [  244.688206] ata5: hard resetting link
Aug 13 15:50:02 ubuntu kernel: [  245.226248] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug 13 15:50:02 ubuntu kernel: [  245.306267] ata5.00: max_sectors limited to 256 for NCQ
Aug 13 15:50:02 ubuntu kernel: [  245.388635] ata5.00: max_sectors limited to 256 for NCQ
Aug 13 15:50:02 ubuntu kernel: [  245.388637] ata5.00: configured for UDMA/133
Aug 13 15:50:02 ubuntu kernel: [  245.388643] sd 4:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK
Aug 13 15:50:02 ubuntu kernel: [  245.388646] sd 4:0:0:0: [sda] Sense Key : Medium Error [current] [descriptor]
Aug 13 15:50:02 ubuntu kernel: [  245.388649] Descriptor sense data with sense descriptors (in hex):
Aug 13 15:50:02 ubuntu kernel: [  245.388651]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Aug 13 15:50:02 ubuntu kernel: [  245.388658]         01 36 a7 e0
Aug 13 15:50:02 ubuntu kernel: [  245.388661] sd 4:0:0:0: [sda] Add. Sense: Unrecovered read error - auto reallocate failed
Aug 13 15:50:02 ubuntu kernel: [  245.388783] ata5: EH complete
Aug 13 15:50:02 ubuntu kernel: [  245.388722] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug 13 15:50:02 ubuntu kernel: [  245.388722] sd 4:0:0:0: [sda] Write Protect is off
Aug 13 15:50:02 ubuntu kernel: [  245.388722] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA

Aug 13 15:50:04 ubuntu kernel: [  247.117648]          res 51/40:08:e0:a7:36/01:00:01:00:00/00 Emask 0x409 (media error) <F>
Aug 13 15:50:04 ubuntu kernel: [  247.117824] ata5: hard resetting link
Aug 13 15:50:04 ubuntu kernel: [  247.659679] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug 13 15:50:04 ubuntu kernel: [  247.747372] ata5.00: max_sectors limited to 256 for NCQ
Aug 13 15:50:04 ubuntu kernel: [  247.825139] ata5.00: max_sectors limited to 256 for NCQ
Aug 13 15:50:04 ubuntu kernel: [  247.825141] ata5.00: configured for UDMA/133
Aug 13 15:50:04 ubuntu kernel: [  247.825145] sd 4:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK
Aug 13 15:50:04 ubuntu kernel: [  247.825148] sd 4:0:0:0: [sda] Sense Key : Medium Error [current] [descriptor]
Aug 13 15:50:04 ubuntu kernel: [  247.825151] Descriptor sense data with sense descriptors (in hex):
Aug 13 15:50:04 ubuntu kernel: [  247.825153]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Aug 13 15:50:04 ubuntu kernel: [  247.825160]         01 36 a7 e0
Aug 13 15:50:04 ubuntu kernel: [  247.825163] sd 4:0:0:0: [sda] Add. Sense: Unrecovered read error - auto reallocate failed
Aug 13 15:50:04 ubuntu kernel: [  247.825281] ata5: EH complete
Aug 13 15:50:04 ubuntu kernel: [  247.825223] sd 4:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
Aug 13 15:50:04 ubuntu kernel: [  247.825223] sd 4:0:0:0: [sda] Write Protect is off
Aug 13 15:50:04 ubuntu kernel: [  247.825223] sd 4:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA

Mark Lord пишет:

..

I only see two failures (eg. one retry) in the log you showed. But it probably was not a retry, but rather a second I/O after the first one. The filesystem layer often does that.

Cheers

Mark Lord пишет:

Yes, I mean 2 tries, so 1 unnecessary rerty.

If kernel tries to read the same sector more then one time, I call that retry :)

I found that it depend on vm someway... First 'dd if=/dev/sdb of=/dev/null skip=300000 count=1' causes 2 failures (1 retry), but next 'dd's only 1failure. After I drop vm cache 'sysctl vm.drop_caches=1', I get two failures again.

running 'dd if=/dev/sdb of=/dev/null skip=300000 count=1 iflag=direct' always causes only 1 failure

IMHO, looks like cavity somewhere... Any ideas?

Artem Bokhan wrote:
..

..

Have you tried to disable fs read-ahead?

Something like "hdparm -a0 /dev/sd*" ?

-ml

That work, thanks, no retries at all now. But is behavior with readahead on and double reads correct?

Mark Lord пишет:

Now I spend ~1.9 seconds to serve one bad sector. That's great.
0.75 of 1.9 seconds is a time spent on hard reset, 1.15 seconds are spent on reallocation try. Is hard reset real necessary to return disk to life after media error?

time dd if=/dev/sda of=/dev/null count=1 skip=300000
dd: reading `/dev/sda': Input/output error 0+0 records in
0+0 records out
0 bytes (0 B) copied, 1.87432 s, 0.0 kB/s

real 0m1.876s

[63107.038255] ata6.00: exception Emask 0x0 SAct 0x1 SErr 0x0 action 0x6
[63107.038287] ata6.00: edma_err_cause=00000084 pp_flags=00000003, dev error, EDMA self-disable
[63107.038335] ata6.00: cmd 60/08:00:e0:93:04/00:00:00:00:00/40 tag 0 ncq 4096 in
[63107.038336]          res 51/40:08:e0:93:04/01:00:00:00:00/00 Emask 0x409 (media error) <F>
[63107.038380] ata6.00: status: { DRDY ERR }
[63107.038403] ata6.00: error: { UNC }
[63107.038430] ata6: hard resetting link
[63107.608304] ata6: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[63107.692432] ata6.00: max_sectors limited to 256 for NCQ
[63107.772479] ata6.00: max_sectors limited to 256 for NCQ
[63107.772481] ata6.00: configured for UDMA/133
[63107.772488] sd 5:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK
[63107.772491] sd 5:0:0:0: [sda] Sense Key : Medium Error [current] [descriptor]
[63107.772495] Descriptor sense data with sense descriptors (in hex):
[63107.772497]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
[63107.772504]         00 04 93 e0
[63107.772507] sd 5:0:0:0: [sda] Add. Sense: Unrecovered read error - auto reallocate failed
[63107.772512] end_request: I/O error, dev sda, sector 300000
[63107.772540] Buffer I/O error on device sda, logical block 37500
[63107.772572] ata6: EH complete
[63107.790290] sd 5:0:0:0: [sda] 1465149168 512-byte hardware sectors (750156 MB)
[63107.790290] sd 5:0:0:0: [sda] Write Protect is off
[63107.790290] sd 5:0:0:0: [sda] Mode Sense: 00 3a 00 00
[63107.790290] sd 5:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA

Mark Lord пишет:

..

It is necessary in many cases, but not in all. But the observed behaviour (reset) is the safest way to guarantee that things will nearly always work by default.

If the drive is NOT using NCQ, and the host controller does not get confused by the incomplete data transfers (many do), then the reset is not necessary.

You can try hacking it out, if you want to.

Cheers

It uses ncq. Thanks, Mark.

Mark Lord пишет:

..

Okay, so the ATA specs explicitly require a reset there. Not much to do about that.

If you were super-keen, though, you could crawl through libata and try reducing various delays and polling intervals that are associated with a hard reset for that specific (ahci?) driver and the core libata routines.

Might shave that 0.75sec down to perhaps 100ms or so. But again, the optimal numbers in your specific case will not work for the general case. It might be possible to parameterize it all, though, permitting different values for differing hardware.

Cheers

Artem,

I'm not sure what your goal is but you might find it interesting that "Enterprise" versions of some of the drives have fast fail logic built into them. ie. They don't internally retry on medium errors.

As I understand it, the concept is if you have a raid setup, you don't want to waste time retrying a read. It is better to fail the read ASAP and get the data from another source.

Greg

Greg Freemyer
Litigation Triage Solutions Specialist
http://www.linkedin.com/in/gregfreemyer
First 99 Days Litigation White Paper -
http://www.norcrossgroup.com/forms/whitepapers/99%20Days%20whitepaper.pdf

The Norcross Group
The Intersection of Evidence & Technology
http://www.norcrossgroup.com

I have particular fast, simple and cheap controller(s) (MV88SX6081 8-port SATA II PCI-X) with a bunch of disks w/o sw/hw raid. I need to return an error to application ASAP if media error detected.

Greg Freemyer ?????:

My thought was that if speed is more important than reliability in your case, then you could buy a "Enterprise" version hard drive and eliminate the time it takes the drive to internally do retries.

ie. The concept for which Enterprise drives exist is raid, but that does not mean you have to use them that way.

Greg

Greg Freemyer
Litigation Triage Solutions Specialist
http://www.linkedin.com/in/gregfreemyer
First 99 Days Litigation White Paper -
http://www.norcrossgroup.com/forms/whitepapers/99%20Days%20whitepaper.pdf

The Norcross Group
The Intersection of Evidence & Technology
http://www.norcrossgroup.com

But as I understand my problem, all retries and delays are made inside linux kernel, not inside hardware...

Greg Freemyer ?????:

AIUI you have both.

And they multiply, so if the hardware is doing X retries per attempt and the kernel is doing Y retries, then the total retries is close to X*(Y+1).

To get the fastest possible failure mode you need to reduce both X and Y.

Greg

Greg Freemyer
Litigation Triage Solutions Specialist
http://www.linkedin.com/in/gregfreemyer
First 99 Days Litigation White Paper -
http://www.norcrossgroup.com/forms/whitepapers/99%20Days%20whitepaper.pdf

The Norcross Group
The Intersection of Evidence & Technology
http://www.norcrossgroup.com

Tejun Heo пишет:

Does this affect performance/functionality of controller/hdd someway?

When NCQ is disabled, it will probably add tiny bit to inter command latency thus reducing performance a bit but I don't think it will stand out in any way. When you count in the seek time and all, the inter command latency should be negligible in most cases.

tejun

When there is no seek time it does matter (e.g. SSD). To test command perf with a normal HD, excercise the disk cache with this fio command line:
/root/fio --runtime=30 --time_based --bwavgtime=5000 --thread --numjobs=1 --iodepth=1 -rw=randrw --norandommap -overwrite=1 --direct=1 --ioengine=sync --ioscheduler=noop --bs=4k --size=4k --name=hd_sdc --filename=/dev/sdc

and will get output which contains something like:
hd_sdc: (g=0): rw=randrw, bs=4K-4K/4K-4K, ioengine=sync, iodepth=1 Starting 1 thread
Jobs: 1 (f=1): [m] [96.7% done] [ 18381/ 17705 kb/s] [eta 00m:01s]
hd_sdc: (groupid=0, jobs=1): err= 0: pid=17079
read : io=528344KiB, bw=18476KiB/s, iops=4510, runt= 29281msec

    clat (usec): min=82, max=131, avg=93.11, stdev= 1.67
  write: io=527792KiB, bw=18235KiB/s, iops=4452, runt= 29637msec
    clat (usec): min=84, max=209, avg=93.88, stdev= 1.60
...
     lat (usec): 100=99.60%, 250=0.40%

...

The drive/controller config reports almost 9000 iops from a single drive. This compares well with existing SSDs on the market.

And looks like fio needs better granularity in it's latency buckets.

hth,
grant

Yeah, looks fine. For some odd reason, I must have been thinking that libata-{scsi,core} would not even attempt multiple simultaneous non-NCQ. Silly me!

applied

Is this -stable material?

Martin Michlmayr
http://www.cyrius.com/

Absolutely yes.

Adding [email protected]. This is commit 4bdee6c5103696a2729d3db2f235d202191788e4

Martin Michlmayr
http://www.cyrius.com/

What happen if there is a SATA port multiplier behing the marvell controller and NCQ is disabled?

I have the impression that with this patch we are able to only send one DMA command at a time to all the drives behind the PM, which has an impact on performance.

Gwendal.

Yeah, right. :-( The simplest way to implement this would be just calling ata_std_qc_defer() which computes per-link restrictions after ruling out all non-standard restrictions. I wasn't really sure how EDMA/NCQ_EN flags are supposed to work so just sticked to the original condition tests. Mark, can you please help us out here? :-)

Thanks.

tejun

..

The hardware is both tricky and buggy, depending upon the version, and my memory is fading -- I haven't looked at the code since early June, when Marvell stopped paying invoices (administrative "issues").

The only 100% safe scenario is to issue only a single non-NCQ command at a time. But there are many situations where it is safe to allow one command/port, provided that there are no PIO commands anywhere in the mix.

Messy. I'll have another walk through it whenever Marvell gets over their "administrative issues" on this.

Cheers