Decoding marvel + Sil PMP errors / NCQ disabled due to excessive errors / 1.5G downgrade

Decoding marvel + Sil PMP errors / NCQ disabled due to excessive errors / 1.5G downgrade

[Marc MERLIN]

Hi Mark and Tejun,

Would you have any idea of what I'm seeing here?

This is with kernel 3.0.1,
02:00.0 SCSI storage controller: Marvell Technology Group Ltd. 88SX7042 PCI-e 4-port SATA-II (rev 02)

and a Sil PMP.
FIRMWARE_ID:      0x10953726
FIRMWARE_VER:     0x00010114
FIRMWARE_CSUM:    0x5aee2538

I seem to have the same error at boot under heavy read/write (raid rebuild),
the bus resets to 1.5Gbit with NCQ disabled, and then it's mostly stable
(occasional errors, but no failures).

So it works, but of course performance is not good.

Am I stuck with this, or is there a way to avoid those errors and
stay at 3G?
Is there an issue with NCQ on my drives?
Is there any chance I have a bad cable or a bad sata_nv card?
Anything else you can think of?

Thanks,
Marc


Relevant boot messages:
sata_mv 0000:02:00.0: version 1.28
sata_mv 0000:02:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
sata_mv 0000:02:00.0: Gen-IIE 32 slots 4 ports SCSI mode IRQ via INTx
sata_mv 0000:02:00.0: setting latency timer to 64
scsi8 : sata_mv
scsi9 : sata_mv
scsi10 : sata_mv
scsi11 : sata_mv
ata9: SATA max UDMA/133 mmio m1048576@0xfb800000 port 0xfb822000 irq 16
ata10: SATA max UDMA/133 mmio m1048576@0xfb800000 port 0xfb824000 irq 16
ata11: SATA max UDMA/133 mmio m1048576@0xfb800000 port 0xfb826000 irq 16
ata12: SATA max UDMA/133 mmio m1048576@0xfb800000 port 0xfb828000 irq 16


ata11: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata11.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9
ata11.00: hard resetting link
ata11.01: hard resetting link
ata11.02: hard resetting link
ata11.03: hard resetting link
ata11.04: hard resetting link
ata11.05: hard resetting link
ata11.00: ATA-8: WDC WD20EARS-00MVWB0, 51.0AB51, max UDMA/133
ata11.00: 3907029168 sectors, multi 0: LBA48 NCQ (depth 31/32)
ata11.00: configured for UDMA/133
ata11.01: ATA-8: WDC WD20EADS-00W4B0, 01.00A01, max UDMA/133
ata11.01: 3907029168 sectors, multi 0: LBA48 NCQ (depth 31/32)
ata11.01: configured for UDMA/133
ata11.02: ATA-8: WDC WD20EADS-00S2B0, 01.00A01, max UDMA/133
ata11.02: 3907029168 sectors, multi 0: LBA48 NCQ (depth 31/32)
ata11.02: configured for UDMA/133
ata11.03: ATA-8: WDC WD20EADS-00R6B0, 01.00A01, max UDMA/133
ata11.03: 3907029168 sectors, multi 0: LBA48 NCQ (depth 31/32)
ata11.03: configured for UDMA/133
ata11.04: ATA-8: WDC WD20EADS-00R6B0, 01.00A01, max UDMA/133
ata11.04: 3907029168 sectors, multi 0: LBA48 NCQ (depth 31/32)
ata11.04: configured for UDMA/133
ata11: EH complete


Then, it fails and falls back to 1.5G soon after. Choice lines:
ata11.03: device reported invalid CHS sector 0
ata11.15: exception Emask 0x100 SAct 0x0 SErr 0x400000 action 0x6 frozen
ata11.15: edma_err_cause=42200080 pp_flags=00000007, EDMA self-disable
ata11: EH complete
ata11: illegal qc_active transition (00000ff8->00000f79)
ata11.00: failed to read SCR 1 (Emask=0x40)
ata11.00: NCQ disabled due to excessive errors
ata11.15: SError: { Handshk }


Fulll log below:
ata11.00: failed to read SCR 1 (Emask=0x40)
ata11.01: failed to read SCR 1 (Emask=0x40)
ata11.02: failed to read SCR 1 (Emask=0x40)
ata11.03: failed to read SCR 1 (Emask=0x40)
ata11.04: failed to read SCR 1 (Emask=0x40)
ata11.05: failed to read SCR 1 (Emask=0x40)
ata11.15: exception Emask 0x100 SAct 0x0 SErr 0x400000 action 0x6 frozen
ata11.15: edma_err_cause=42200000 pp_flags=00000007
ata11.15: SError: { Handshk }
ata11.00: exception Emask 0x100 SAct 0x20d SErr 0x0 action 0x6 frozen
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/08:00:2f:09:fb/00:00:1a:00:00/40 tag 0 ncq 4096 out
         res c0/00:48:27:09:fb/00:00:1a:00:00/40 Emask 0x2 (HSM violation)
ata11.00: status: { Busy }
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/e0:10:3f:05:fb/03:00:1a:00:00/40 tag 2 ncq 507904 out
         res c0/00:48:27:09:fb/00:00:1a:00:00/40 Emask 0x2 (HSM violation)
ata11.00: status: { Busy }
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/08:18:1f:09:fb/00:00:1a:00:00/40 tag 3 ncq 4096 out
         res c0/00:48:27:09:fb/00:00:1a:00:00/40 Emask 0x2 (HSM violation)
ata11.00: status: { Busy }
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/08:48:27:09:fb/00:00:1a:00:00/40 tag 9 ncq 4096 out
         res c0/00:48:27:09:fb/00:00:1a:00:00/40 Emask 0x2 (HSM violation)
ata11.00: status: { Busy }
ata11.01: exception Emask 0x100 SAct 0x80 SErr 0x0 action 0x6 frozen
ata11.01: failed command: READ FPDMA QUEUED
ata11.01: cmd 60/f8:38:3f:09:fb/03:00:1a:00:00/40 tag 7 ncq 520192 in
         res c0/00:48:27:09:fb/00:00:1a:00:00/40 Emask 0x2 (HSM violation)
ata11.01: status: { Busy }
ata11.02: exception Emask 0x100 SAct 0x40 SErr 0x0 action 0x6 frozen
ata11.02: failed command: READ FPDMA QUEUED
ata11.02: cmd 60/f8:30:3f:09:fb/03:00:1a:00:00/40 tag 6 ncq 520192 in
         res c0/00:48:27:09:fb/00:00:1a:00:00/40 Emask 0x2 (HSM violation)
ata11.02: status: { Busy }
ata11.03: exception Emask 0x100 SAct 0x400 SErr 0x0 action 0x6 frozen
ata11.03: failed command: READ FPDMA QUEUED
ata11.03: cmd 60/f8:50:3f:09:fb/03:00:1a:00:00/40 tag 10 ncq 520192 in
         res c0/00:48:27:09:fb/00:00:1a:00:00/40 Emask 0x2 (HSM violation)
ata11.03: status: { Busy }
ata11.04: exception Emask 0x100 SAct 0x20 SErr 0x0 action 0x6 frozen
ata11.04: failed command: READ FPDMA QUEUED
ata11.04: cmd 60/00:28:37:09:fb/04:00:1a:00:00/40 tag 5 ncq 524288 in
         res c0/00:48:27:09:fb/00:00:1a:00:00/40 Emask 0x2 (HSM violation)
ata11.04: status: { Busy }
ata11.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
ata11.15: hard resetting link
ata11.15: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata11.00: hard resetting link
ata11.01: hard resetting link
ata11.02: hard resetting link
ata11.03: hard resetting link
ata11.04: hard resetting link
ata11.05: hard resetting link
ata11.00: configured for UDMA/133
ata11.01: configured for UDMA/133
ata11.02: configured for UDMA/133
ata11.03: configured for UDMA/133
ata11.04: configured for UDMA/133
ata11: EH complete
ata11.00: failed to read SCR 1 (Emask=0x40)
ata11.01: failed to read SCR 1 (Emask=0x40)
ata11.02: failed to read SCR 1 (Emask=0x40)
ata11.03: failed to read SCR 1 (Emask=0x40)
ata11.04: failed to read SCR 1 (Emask=0x40)
ata11.05: failed to read SCR 1 (Emask=0x40)
ata11.15: exception Emask 0x100 SAct 0x0 SErr 0x400000 action 0x6 frozen
ata11.15: edma_err_cause=42200080 pp_flags=00000007, EDMA self-disable
ata11.15: SError: { Handshk }
ata11.00: exception Emask 0x100 SAct 0xa SErr 0x0 action 0x6 frozen
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/08:08:17:bd:04/00:00:1b:00:00/40 tag 1 ncq 4096 out
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x100 (unknown error)
ata11.00: status: { DRDY }
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/e0:18:37:b9:04/03:00:1b:00:00/40 tag 3 ncq 507904 out
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x100 (unknown error)
ata11.00: status: { DRDY }
ata11.01: exception Emask 0x100 SAct 0x1 SErr 0x0 action 0x6 frozen
ata11.01: failed command: READ FPDMA QUEUED
ata11.01: cmd 60/b0:00:37:bd:04/03:00:1b:00:00/40 tag 0 ncq 483328 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x100 (unknown error)
ata11.01: status: { DRDY }
ata11.02: exception Emask 0x100 SAct 0x100 SErr 0x0 action 0x6 frozen
ata11.02: failed command: READ FPDMA QUEUED
ata11.02: cmd 60/b0:40:37:bd:04/03:00:1b:00:00/40 tag 8 ncq 483328 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x100 (unknown error)
ata11.02: status: { DRDY }
ata11.03: exception Emask 0x100 SAct 0x80 SErr 0x0 action 0x6 frozen
ata11.03: failed command: READ FPDMA QUEUED
ata11.03: cmd 60/b8:38:2f:bd:04/03:00:1b:00:00/40 tag 7 ncq 487424 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x100 (unknown error)
ata11.03: status: { DRDY }
ata11.04: exception Emask 0x100 SAct 0x10000420 SErr 0x0 action 0x6 frozen
ata11.04: failed command: READ FPDMA QUEUED
ata11.04: cmd 60/b8:28:2f:bd:04/03:00:1b:00:00/40 tag 5 ncq 487424 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x100 (unknown error)
ata11.04: status: { DRDY }
ata11.04: failed command: READ FPDMA QUEUED
ata11.04: cmd 60/08:50:27:bd:04/00:00:1b:00:00/40 tag 10 ncq 4096 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x100 (unknown error)
ata11.04: status: { DRDY }
ata11.04: failed command: READ FPDMA QUEUED
ata11.04: cmd 60/08:e0:1f:bd:04/00:00:1b:00:00/40 tag 28 ncq 4096 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x100 (unknown error)
ata11.04: status: { DRDY }
ata11.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
ata11.15: hard resetting link
ata11.15: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata11.00: hard resetting link
ata11.01: hard resetting link
ata11.02: hard resetting link
ata11.03: hard resetting link
ata11.04: hard resetting link
ata11.05: hard resetting link
ata11.00: configured for UDMA/133
ata11.01: configured for UDMA/133
ata11.02: configured for UDMA/133
ata11.03: configured for UDMA/133
ata11.04: configured for UDMA/133
ata11: EH complete
ata11: illegal qc_active transition (000000fc->100000dc)
usb 2-1.6.4: 5 byte block, baudrate 6, databits 8, u1 0, u2 1
usb 2-1.6.4: sending SIO Poll request
usb 2-1.6.4: read status 0 0
usb 2-1.6.4: 5 byte block, baudrate 6, databits 8, u1 0, u2 1
usb 2-1.6.4: 5 byte block, baudrate 6, databits 8, u1 0, u2 1
usb 2-1.6.4: 5 byte block, baudrate 6, databits 8, u1 0, u2 1
usb 2-1.6.4: 5 byte block, baudrate 6, databits 8, u1 0, u2 1
usb 2-1.6.4: 5 byte block, baudrate 6, databits 8, u1 0, u2 1
usb 2-1.6.4: 5 byte block, baudrate 6, databits 8, u1 0, u2 1
usb 2-1.6.4: 5 byte block, baudrate 6, databits 8, u1 0, u2 1
usb 2-1.6.4: 5 byte block, baudrate 6, databits 8, u1 0, u2 1
ata11.00: failed to read SCR 1 (Emask=0x40)
ata11.01: failed to read SCR 1 (Emask=0x40)
ata11.02: failed to read SCR 1 (Emask=0x40)
ata11.03: failed to read SCR 1 (Emask=0x40)
ata11.04: failed to read SCR 1 (Emask=0x40)
ata11.05: failed to read SCR 1 (Emask=0x40)
ata11.15: exception Emask 0x4 SAct 0x0 SErr 0x0 action 0x6 frozen
ata11.00: exception Emask 0x100 SAct 0x200 SErr 0x0 action 0x6 frozen
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/08:48:27:bd:04/00:00:1b:00:00/40 tag 9 ncq 4096 out
         res 40/00:48:27:09:fb/00:00:1a:00:00/40 Emask 0x4 (timeout)
ata11.00: status: { DRDY }
ata11.01: exception Emask 0x100 SAct 0x3 SErr 0x0 action 0x6 frozen
ata11.01: failed command: READ FPDMA QUEUED
ata11.01: cmd 60/00:00:e7:c0:04/04:00:1b:00:00/40 tag 0 ncq 524288 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.01: status: { DRDY }
ata11.01: failed command: READ FPDMA QUEUED
ata11.01: cmd 60/38:08:e7:c4:04/00:00:1b:00:00/40 tag 1 ncq 28672 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.01: status: { DRDY }
ata11.02: exception Emask 0x100 SAct 0x8 SErr 0x0 action 0x6 frozen
ata11.02: failed command: READ FPDMA QUEUED
ata11.02: cmd 60/b0:18:37:bd:04/03:00:1b:00:00/40 tag 3 ncq 483328 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.02: status: { DRDY }
ata11.03: exception Emask 0x100 SAct 0x14 SErr 0x0 action 0x6 frozen
ata11.03: failed command: READ FPDMA QUEUED
ata11.03: cmd 60/00:10:e7:c0:04/04:00:1b:00:00/40 tag 2 ncq 524288 in
         res 40/00:48:27:09:fb/00:00:1a:00:00/40 Emask 0x4 (timeout)
ata11.03: status: { DRDY }
ata11.03: failed command: READ FPDMA QUEUED
ata11.03: cmd 60/38:20:e7:c4:04/00:00:1b:00:00/40 tag 4 ncq 28672 in
         res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata11.03: status: { DRDY }
ata11.04: exception Emask 0x100 SAct 0x1e0 SErr 0x0 action 0x6 frozen
ata11.04: failed command: READ FPDMA QUEUED
ata11.04: cmd 60/08:28:1f:bd:04/00:00:1b:00:00/40 tag 5 ncq 4096 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.04: status: { DRDY }
ata11.04: failed command: READ FPDMA QUEUED
ata11.04: cmd 60/00:30:e7:c0:04/04:00:1b:00:00/40 tag 6 ncq 524288 in
         res 40/00:48:27:09:fb/00:00:1a:00:00/40 Emask 0x4 (timeout)
ata11.04: status: { DRDY }
ata11.04: failed command: READ FPDMA QUEUED
ata11.04: cmd 60/b8:38:2f:bd:04/03:00:1b:00:00/40 tag 7 ncq 487424 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.04: status: { DRDY }
ata11.04: failed command: READ FPDMA QUEUED
ata11.04: cmd 60/38:40:e7:c4:04/00:00:1b:00:00/40 tag 8 ncq 28672 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.04: status: { DRDY }
ata11.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
ata11.15: hard resetting link
ata11.15: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata11.05: limiting SATA link speed to 1.5 Gbps
ata11.00: hard resetting link
ata11.01: hard resetting link
ata11.02: hard resetting link
ata11.03: hard resetting link
ata11.04: hard resetting link
ata11.05: hard resetting link
ata11.00: configured for UDMA/133
ata11.01: configured for UDMA/133
ata11.02: configured for UDMA/133
ata11.03: configured for UDMA/133
ata11.04: configured for UDMA/133
ata11.03: device reported invalid CHS sector 0
ata11: EH complete
ata11.00: failed to read SCR 1 (Emask=0x40)
ata11.01: failed to read SCR 1 (Emask=0x40)
ata11.02: failed to read SCR 1 (Emask=0x40)
ata11.03: failed to read SCR 1 (Emask=0x40)
ata11.04: failed to read SCR 1 (Emask=0x40)
ata11.05: failed to read SCR 1 (Emask=0x40)
ata11.15: exception Emask 0x100 SAct 0x0 SErr 0x400000 action 0x6 frozen
ata11.15: edma_err_cause=42200080 pp_flags=00000007, EDMA self-disable
ata11.15: SError: { Handshk }
ata11.00: exception Emask 0x100 SAct 0x32 SErr 0x0 action 0x6 frozen
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/a8:08:b7:f8:34/03:00:1b:00:00/40 tag 1 ncq 479232 out
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.00: status: { Busy }
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/08:20:5f:fc:34/00:00:1b:00:00/40 tag 4 ncq 4096 out
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.00: status: { Busy }
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/08:28:67:fc:34/00:00:1b:00:00/40 tag 5 ncq 4096 out
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.00: status: { Busy }
ata11.01: exception Emask 0x100 SAct 0x10400 SErr 0x0 action 0x6 frozen
ata11.01: failed command: READ FPDMA QUEUED
ata11.01: cmd 60/00:50:77:fc:34/04:00:1b:00:00/40 tag 10 ncq 524288 in
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.01: status: { Busy }
ata11.01: failed command: READ FPDMA QUEUED
ata11.01: cmd 60/38:80:77:00:35/00:00:1b:00:00/40 tag 16 ncq 28672 in
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.01: status: { Busy }
ata11.02: exception Emask 0x100 SAct 0xd SErr 0x0 action 0x6 frozen
ata11.02: failed command: READ FPDMA QUEUED
ata11.02: cmd 60/08:00:6f:fc:34/00:00:1b:00:00/40 tag 0 ncq 4096 in
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.02: status: { Busy }
ata11.02: failed command: READ FPDMA QUEUED
ata11.02: cmd 60/00:10:77:fc:34/04:00:1b:00:00/40 tag 2 ncq 524288 in
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.02: status: { Busy }
ata11.02: failed command: READ FPDMA QUEUED
ata11.02: cmd 60/38:18:77:00:35/00:00:1b:00:00/40 tag 3 ncq 28672 in
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.02: status: { Busy }
ata11.03: exception Emask 0x100 SAct 0x3000 SErr 0x0 action 0x6 frozen
ata11.03: failed command: READ FPDMA QUEUED
ata11.03: cmd 60/00:60:77:fc:34/04:00:1b:00:00/40 tag 12 ncq 524288 in
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.03: status: { Busy }
ata11.03: failed command: READ FPDMA QUEUED
ata11.03: cmd 60/38:68:77:00:35/00:00:1b:00:00/40 tag 13 ncq 28672 in
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.03: status: { Busy }
ata11.04: exception Emask 0x100 SAct 0x4200 SErr 0x0 action 0x6 frozen
ata11.04: failed command: READ FPDMA QUEUED
ata11.04: cmd 60/40:48:6f:00:35/00:00:1b:00:00/40 tag 9 ncq 32768 in
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.04: status: { Busy }
ata11.04: failed command: READ FPDMA QUEUED
ata11.04: cmd 60/00:70:6f:fc:34/04:00:1b:00:00/40 tag 14 ncq 524288 in
         res c0/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x2 (HSM violation)
ata11.04: status: { Busy }
ata11.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
ata11.15: hard resetting link
ata11.15: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata11.00: hard resetting link
ata11.01: hard resetting link
ata11.02: hard resetting link
ata11.03: hard resetting link
ata11.04: hard resetting link
ata11.05: hard resetting link
ata11.00: configured for UDMA/133
ata11.01: configured for UDMA/133
ata11.02: configured for UDMA/133
ata11.03: configured for UDMA/133
ata11.04: configured for UDMA/133
ata11: EH complete
ata11: illegal qc_active transition (00000ff8->00000f79)
ata11.00: failed to read SCR 1 (Emask=0x40)
ata11.00: NCQ disabled due to excessive errors
ata11.01: failed to read SCR 1 (Emask=0x40)
ata11.02: failed to read SCR 1 (Emask=0x40)
ata11.02: NCQ disabled due to excessive errors
ata11.03: failed to read SCR 1 (Emask=0x40)
ata11.03: NCQ disabled due to excessive errors
ata11.04: failed to read SCR 1 (Emask=0x40)
ata11.04: NCQ disabled due to excessive errors
ata11.05: failed to read SCR 1 (Emask=0x40)
ata11.15: exception Emask 0x4 SAct 0x0 SErr 0x400000 action 0x6 frozen
ata11.15: SError: { Handshk }
ata11.00: exception Emask 0x100 SAct 0x18 SErr 0x0 action 0x6 frozen
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/f8:18:77:fc:34/03:00:1b:00:00/40 tag 3 ncq 520192 out
         res 40/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.00: status: { DRDY }
ata11.00: failed command: WRITE FPDMA QUEUED
ata11.00: cmd 61/40:20:6f:00:35/00:00:1b:00:00/40 tag 4 ncq 32768 out
         res 40/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.00: status: { DRDY }
ata11.01: exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
ata11.02: exception Emask 0x100 SAct 0x82 SErr 0x0 action 0x6 frozen
ata11.02: failed command: READ FPDMA QUEUED
ata11.02: cmd 60/c0:08:af:00:35/03:00:1b:00:00/40 tag 1 ncq 491520 in
         res 40/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.02: status: { DRDY }
ata11.02: failed command: READ FPDMA QUEUED
ata11.02: cmd 60/08:38:6f:fc:34/00:00:1b:00:00/40 tag 7 ncq 4096 in
         res 40/00:04:37:bd:04/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.02: status: { DRDY }
ata11.03: exception Emask 0x100 SAct 0x4 SErr 0x0 action 0x6 frozen
ata11.03: failed command: READ FPDMA QUEUED
ata11.03: cmd 60/c0:10:af:00:35/03:00:1b:00:00/40 tag 2 ncq 491520 in
         res 40/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.03: status: { DRDY }
ata11.04: exception Emask 0x100 SAct 0x1 SErr 0x0 action 0x6 frozen
ata11.04: failed command: READ FPDMA QUEUED
ata11.04: cmd 60/c0:00:af:00:35/03:00:1b:00:00/40 tag 0 ncq 491520 in
         res 40/00:20:5f:fc:34/00:00:1b:00:00/40 Emask 0x4 (timeout)
ata11.04: status: { DRDY }
ata11.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
ata11.15: hard resetting link
ata11.15: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata11.00: hard resetting link
ata11.01: hard resetting link
ata11.02: hard resetting link
ata11.03: hard resetting link
ata11.04: hard resetting link
ata11.05: hard resetting link
ata11.00: configured for UDMA/133
ata11.01: configured for UDMA/133
ata11.02: configured for UDMA/133
ata11.03: configured for UDMA/133
ata11.04: configured for UDMA/133
ata11: EH complete

-- 
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Re: Decoding marvel + Sil PMP errors / NCQ disabled due to excessive errors / 1.5G downgrade

[Mark Lord]

On 11-08-30 10:20 PM, Marc MERLIN wrote:
> Hi Mark and Tejun,
> 
> Would you have any idea of what I'm seeing here?
> 
> This is with kernel 3.0.1,
> 02:00.0 SCSI storage controller: Marvell Technology Group Ltd. 88SX7042 PCI-e 4-port SATA-II (rev 02)
> 
> and a Sil PMP.
...

At present, I don't think either of my PMPs work with any of my SATA controllers
using recent kernels.  They all used to work back in the 2.6.2x kernels,
and I have not reloaded one of those to retest with (due to lack of ext4 in those).

Something's just not right in PMP land.
The same PMPs work fine on the same hardware in WinXP.

I wonder what we're missing?

I'm also travelling without internet access for the next month.  :)
-- 
Mark Lord
Real-Time Remedies Inc.
mlord@pobox.com

Re: Can reading a raid drive trigger all the other drives in that set?

[Marc MERLIN]

Mark/Tejun et all, my issue may be linked to the fact that I'm using a port
multiplier for my drives. If so, please let me know if that might be the
case.

I'm not quite sure what's going on, but it looks like for 2 sets of 5 drives,
ST drive reads from a drive in sleep mode can happen in // (i.e. all drives spin up
in //) whereas the WDC drives seem to hang the kernel block layer so that the next
drive will not be read and spun up before the previous one was.

Is that possible?
If not, any idea what's going on?

For what it's worth, all the drives are on the same SIL PMP plugged into the
same Marvel SATA card.

On Fri, Sep 02, 2011 at 02:28:21PM -0700, Doug Dumitru wrote:
> On Thu, Sep 1, 2011 at 6:23 PM, Marc MERLIN <marc@merlins.org> wrote:
> > > I have ext4 over lvm2 on a sw raid5 with 2.6.39.1
> > >
> > > In order to save power I have my drives spin down.
> > >
> > > When I access my filesystem mount point, I get hangs of 30sec or a bit more
> > > as each and every drive are woken up serially.
> > >
> > > Is there any chance to put a patch in the block layer so that when it gets a
> > > read on a block after a certain timeout, it just does one dummy read on all
> > > the other droves in parallel so that all the drives have a chance to spin
> > > back up at the same time and not serially?
> >
> > Ok, so the lack of answer probably means 'no' :)
> >
> > Given that, is there a user space way to do this?
> > I'm thinking I might be able to poll drives every second to see if they
> > were spun down and got an IO. If any drive gets an IO, then the other
> > ones all get a dummy read, although I'd have to make sure that read is
> > random so that it can't be in the cache.
>
> What you are looking to do is not really what raid is all about.
> Essentially, the side effect of a drive wakeup is non optimal in that
> the raid layer is not aware of this event.  Then again, the drive does
> this invisibly, so no software is really aware.
> 
> You "could" fix this with a "filter" plug-in.  Basically, you could
> write a device mapper plug-in that watched IO and after some length of
> pause kicked off dummy reads so that all drives would wake up.  In
> terms of code, this would probably be less than 300 lines to implement
> the module.
> 
> Writing a device mapper plug-in is not that hard (see dm-zero.c for a
> hello-world example), but it is kernel code and does require a pretty
> good understanding of the BIO structure and how things flow.  If you
> had such a module, you would load it with a dmsetup command and then
> use the 2nd mapper device instead of /dev/mdX.

I just had a little time to work at what I thought would be the userspace
solution to this.

Please have a quick look at:
http://marc.merlins.org/linux/scripts/swraidwakeup
Basiscally, I use 
iostat -z 1
to detect access to /dev/md5 and then read a random sector from all its
drives in //.

The idea is of course trigger a spinup of all the drive in // as opposed to
waiting for the raid block layer to serially wait for the first drive, and
then the second, and the third, etc...

My script outputs what it does and I can tell that when I access the raid
while the drives are sleeping, those 5 commands are sent at the same time:
dd if=/dev/sdh of=/dev/null bs=1024 ibs=1024 skip=304955122 count=1 2>/dev/null &
dd if=/dev/sdi of=/dev/null bs=1024 ibs=1024 skip=32879776 count=1 2>/dev/null &
dd if=/dev/sdj of=/dev/null bs=1024 ibs=1024 skip=214592398 count=1 2>/dev/null &
dd if=/dev/sdk of=/dev/null bs=1024 ibs=1024 skip=128138452 count=1 2>/dev/null &
dd if=/dev/sdl of=/dev/null bs=1024 ibs=1024 skip=397070851 count=1 2>/dev/null &

I'm working with 2 sets of drives:
/dev/sdc: ST3500630AS: 34°C
/dev/sdd: ST3500630AS: 35°C
/dev/sde: ST3750640AS: 36°C
/dev/sdf: ST3500630AS: 36°C
/dev/sdg: ST3500630AS: 36°C

/dev/sdh: WDC WD20EARS-00MVWB0: 38°C
/dev/sdi: WDC WD20EADS-00W4B0: 38°C
/dev/sdj: WDC WD20EADS-00S2B0: 45°C
/dev/sdk: WDC WD20EADS-00R6B0: 41°C
/dev/sdl: WDC WD20EADS-00R6B0: 41°C

(I use hddtemp since it's a handy way to see if the drive is sleeping or
not without waking it up).

On my raidset with the Seagate drives, the spin up in 7 seconds at the same
time:

Here's an example wakeup with 4 drives sleeping and one awake:
/usr/bin/time -f 'sdc: %E secs' dd if=/dev/sdc of=/dev/null bs=1024 ibs=1024 skip=227835482 count=1 2>&1 | grep -Ev '(records|copied)' &
/usr/bin/time -f 'sdd: %E secs' dd if=/dev/sdd of=/dev/null bs=1024 ibs=1024 skip=158569697 count=1 2>&1 | grep -Ev '(records|copied)' &
/usr/bin/time -f 'sde: %E secs' dd if=/dev/sde of=/dev/null bs=1024 ibs=1024 skip=244180302 count=1 2>&1 | grep -Ev '(records|copied)' &
/usr/bin/time -f 'sdf: %E secs' dd if=/dev/sdf of=/dev/null bs=1024 ibs=1024 skip=257519832 count=1 2>&1 | grep -Ev '(records|copied)' &
/usr/bin/time -f 'sdg: %E secs' dd if=/dev/sdg of=/dev/null bs=1024 ibs=1024 skip=248812549 count=1 2>&1 | grep -Ev '(records|copied)' &
sdg: 0:00.01 secs
sdc: 0:07.56 secs
sdf: 0:07.60 secs
sdd: 0:07.78 secs
sde: 0:07.89 secs


On my other raid, my code still runs the 5 dd commands at the same time, but the block layer
seems to run them sequentially even though they were scheduled at the same time.

1) does that make sense?
2) could that be related to the fact that the drives are on a port multiplier?
3) if so, why is it affecting the WDC drives but not the ST drives? Do the WDC
   drives hang the kernel when issued a command while in sleep mode, but not the ST drives?

/usr/bin/time -f 'sdh: %E secs' dd if=/dev/sdh of=/dev/null bs=1024 ibs=1024 skip=31905054 count=1 2>&1 | grep -Ev '(records|copied)' &
/usr/bin/time -f 'sdi: %E secs' dd if=/dev/sdi of=/dev/null bs=1024 ibs=1024 skip=261665955 count=1 2>&1 | grep -Ev '(records|copied)' &
/usr/bin/time -f 'sdj: %E secs' dd if=/dev/sdj of=/dev/null bs=1024 ibs=1024 skip=244694085 count=1 2>&1 | grep -Ev '(records|copied)' &
/usr/bin/time -f 'sdk: %E secs' dd if=/dev/sdk of=/dev/null bs=1024 ibs=1024 skip=323059576 count=1 2>&1 | grep -Ev '(records|copied)' &
/usr/bin/time -f 'sdl: %E secs' dd if=/dev/sdl of=/dev/null bs=1024 ibs=1024 skip=286720059 count=1 2>&1 | grep -Ev '(records|copied)' &
sdh: 0:06.91 secs
sdi: 0:10.38 secs
sdk: 0:20.82 secs
sdl: 0:31.29 secs
sdj: 0:31.91 secs


Thanks,
Marc
-- 
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/