Dotaz: AHCI kontrolér (ASM1062) přestal fungovat

[Petr Tomášek]

Zdravím!

Dávám dohromady jistý servřík nadoma, nějakou dobu ta věc ležela ladem, teď jsem se k tomu vrátil a nainstaloval nový Devuan (beowulf/ceres) [jádro: 4.19.0-5-amd64 #1 SMP Debian 4.19.37-5 (2019-06-19). Původně tam byl nějaký Debian Wheezy, jádro snad 3.16 nebo 4.0. Ve stroji je pár 2,5" disků v mdraidu, které z nějakých technických důvodu nějaký čas nefungovaly (napájení atd). To je teď vyřešeno, jenže přestaly fungovat dva SATA porty, které visí na miniPCI kartě (od soudruha Číňaňa), kartá má v sobě AHCI kontrolér ASM1062.

Moje otázka: je třeba očekávat, že se jedná o sw problém s novým jádrem nebo že se nějak ten kontrolér poškodil? (Nový kontrolér stojí sice u Číňana pouhých 10 éček, ale putuje 2 měsíce a jiný nemám).

Relevantní část dmegs. Pokud jsou ty samé disky zapojené do jiného kontroléru, fungují bez problémů (včetně identického SATA kabelu):

[    0.913380] pci 0000:03:00.0: [1b21:0612] type 00 class 0x010601
[    0.925636] pci 0000:03:00.0: reg 0x10: [mem 0x00000000-0x00001fff]
[    0.926422] pci 0000:03:00.0: reg 0x14: [io  0x2018-0x201b]
[    0.927205] pci 0000:03:00.0: reg 0x18: [io  0x2000-0x2007]
[    0.927988] pci 0000:03:00.0: reg 0x1c: [io  0x2014-0x2017]
[    0.929821] pci 0000:03:00.0: reg 0x20: [io  0x2000-0x201f]
[    0.930608] pci 0000:03:00.0: reg 0x24: [mem 0xd0500000-0xd05001ff]
[    0.931395] pci 0000:03:00.0: reg 0x30: [mem 0xffff0000-0xffffffff pref]
[    0.945238] pci 0000:03:00.0: 2.000 Gb/s available PCIe bandwidth, limited by 2.5 GT/s x1 link at 0000:00:1c.3 (capable of 4.000 Gb/s with 5 GT/s x1 link)
[    0.951519] pci 0000:03:00.0: can't claim BAR 4 [io  0x2000-0x201f]: address conflict with 0000:03:00.0 [io  0x2000-0x2007]
[    0.993116] pnp 00:07: disabling [mem 0x00000000-0x00000fff] because it overlaps 0000:03:00.0 BAR 0 [mem 0x00000000-0x00001fff]
[    0.993121] pnp 00:07: disabling [mem 0x00000000-0x00000fff] because it overlaps 0000:03:00.0 BAR 0 [mem 0x00000000-0x00001fff]
[    1.004941] pci 0000:03:00.0: can't claim BAR 6 [mem 0xffff0000-0xffffffff pref]: no compatible bridge window
[    1.005132] pci 0000:03:00.0: BAR 6: assigned [mem 0xd0510000-0xd051ffff pref]
[    1.005137] pci 0000:03:00.0: BAR 0: assigned [mem 0xd0502000-0xd0503fff]
[    1.005463] pci 0000:03:00.0: BAR 4: assigned [io  0x2020-0x203f]
[    4.419962] ahci 0000:03:00.0: SSS flag set, parallel bus scan disabled
[    4.422457] ahci 0000:03:00.0: AHCI 0001.0200 32 slots 2 ports 6 Gbps 0x3 impl SATA mode
[    4.422462] ahci 0000:03:00.0: flags: 64bit ncq sntf stag led clo pmp pio slum part ccc sxs 
[    4.426395] ata9: FORCE: PHY spd limit set to 3.0Gbps
[    4.426399] ata9: SATA max UDMA/133 abar m512@0xd0500000 port 0xd0500100 irq 28
[    4.426513] ata10: FORCE: PHY spd limit set to 3.0Gbps
[    4.426515] ata10: SATA max UDMA/133 abar m512@0xd0500000 port 0xd0500180 irq 28
[    4.902598] ata9: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[    5.235694] ata9.00: failed to IDENTIFY (I/O error, err_mask=0x1)
[   10.470645] ata9: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[   10.480359] ata9.00: ATA-8: ST1500LM006 HN-M151RAD, 2BC10001, max UDMA/133
[   10.480364] ata9.00: 2930277168 sectors, multi 0: LBA48 NCQ (depth 32), AA
[   15.625673] ata9.00: qc timeout (cmd 0xec)
[   15.664972] ahci 0000:03:00.0: AHCI controller unavailable!
[   15.704289] ata9.00: failed to IDENTIFY (I/O error, err_mask=0x4)
[   15.704293] ata9.00: revalidation failed (errno=-5)
[   15.723948] ata9: limiting SATA link speed to 1.5 Gbps
[   15.723951] ata9.00: limiting speed to UDMA/133:PIO3
[   15.743610] ahci 0000:03:00.0: AHCI controller unavailable!
[   16.238670] ata9: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[   16.304681] ata9.00: failed to enable AA (error_mask=0x1)
[   16.310279] ata9.00: failed to set xfermode (err_mask=0x40)
[   16.316126] ata9.00: disabled
[   17.247690] ata9: softreset failed (device not ready)
[   17.252918] ata9: reset failed (errno=-19), retrying in 10 secs
[   27.254587] ata9: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[   27.264409] ata9.00: ATA-8: ST1500LM006 HN-M151RAD, 2BC10001, max UDMA/133
[   27.264414] ata9.00: 2930277168 sectors, multi 0: LBA48 NCQ (depth 32), AA
[   27.402477] ahci 0000:03:00.0: AHCI controller unavailable!
[   27.408277] ata9.00: failed to IDENTIFY (I/O error, err_mask=0x1)
[   27.408280] ata9.00: revalidation failed (errno=-5)
[   41.440289] ata9: softreset failed (device not ready)
[   41.445587] ata9: reset failed (errno=-19), retrying in 1 secs
[   42.295557] ahci 0000:03:00.0: AHCI controller unavailable!
[   44.940701] ata9: SATA link up 3.0 Gbps (SStatus 123 SControl 3F0)
[   44.941037] ata9.00: link online but device misclassified
[   50.185694] ata9.00: qc timeout (cmd 0xec)
[   50.186189] ata9.00: failed to IDENTIFY (I/O error, err_mask=0x4)
[   50.186192] ata9.00: revalidation failed (errno=-5)
[   50.191356] ata9: limiting SATA link speed to 1.5 Gbps
[   50.670671] ata9: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[   50.691244] ata9.00: configured for UDMA/133
[   50.692516] sd 8:0:0:0: [sdh] 2930277168 512-byte logical blocks: (1.50 TB/1.36 TiB)
[   50.692521] sd 8:0:0:0: [sdh] 4096-byte physical blocks
[   50.692553] sd 8:0:0:0: [sdh] Write Protect is off
[   50.692557] sd 8:0:0:0: [sdh] Mode Sense: 00 3a 00 00
[   50.692607] sd 8:0:0:0: [sdh] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[   52.057120] ata9: illegal qc_active transition (01000000-gt;ffffffff)
[   52.116130] ata9.00: exception Emask 0x52 SAct 0x1000000 SErr 0xffffffff action 0xe frozen
[   52.124484] ata9: SError: { RecovData RecovComm UnrecovData Persist Proto HostInt PHYRdyChg PHYInt CommWake 10B8B Dispar BadCRC Handshk LinkSeq TrStaTrns UnrecFIS DevExch }
[   52.140182] ata9.00: failed command: READ FPDMA QUEUED
[   52.145408] ata9.00: cmd 60/08:c0:00:00:00/00:00:00:00:00/40 tag 24 ncq dma 4096 in
[   52.161188] ata9.00: status: { DRDY }
[   52.165055] ata9: hard resetting link
[   52.175086] ahci 0000:03:00.0: AHCI controller unavailable!
[   52.922772] ata10: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[   52.991378] ata10.00: ATA-8: ST1500LM006 HN-M151RAD, 2BC10008, max UDMA/133
[   52.991384] ata10.00: 2930277168 sectors, multi 0: LBA48 NCQ (depth 32), AA
[   53.119445] ata10.00: failed to enable AA (error_mask=0x1)
[   53.125360] ata10.00: configured for UDMA/133
[   53.856096] ata9: SATA link down (SStatus 123 SControl FFFFFFFF)
[   53.876152] ata9.00: configured for UDMA/133
[   53.876184] ata9: EH complete
[   54.072364] ata10: softreset failed (device not ready)
[   54.077645] ata10: reset failed (errno=-19), retrying in 10 secs
[   63.253975] ahci 0000:03:00.0: AHCI controller unavailable!
[   64.404131] ata10: failed to resume link (SControl FFFFFFFF)
[   64.561886] ata10: SATA link up 3.0 Gbps (SStatus 123 SControl 3F0)
[   64.562333] ata10.00: link online but device misclassified
[   64.660269] ata10.00: failed to read native max address (err_mask=0x1)
[   64.660273] ata10.00: HPA support seems broken, skipping HPA handling
[   64.660276] ata10.00: revalidation failed (errno=-5)
[   65.710890] udevd[103]: worker [115] /devices/pci0000:00/0000:00:1c.3/0000:03:00.0 is taking a long time
[   69.642675] ata9.00: limiting speed to UDMA/100:PIO4
[   69.642684] ata9.00: exception Emask 0x73 SAct 0x10000000 SErr 0xffffffff action 0xe frozen
[   69.651355] ata9.00: irq_stat 0xffffffff, unknown FIS 00000000 00000000 00000000 00000000, host bus 
[   69.660704] ata9: SError: { RecovData RecovComm UnrecovData Persist Proto HostInt PHYRdyChg PHYInt CommWake 10B8B Dispar BadCRC Handshk LinkSeq TrStaTrns UnrecFIS DevExch }
[   69.676636] ata9.00: failed command: READ FPDMA QUEUED
[   69.682099] ata9.00: cmd 60/08:e0:00:00:00/00:00:00:00:00/40 tag 28 ncq dma 4096 in
[   69.698447] ata9.00: status: { DRDY }
[   69.702321] ata9: hard resetting link
[   70.115854] ata10: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[   70.144370] ata10.00: configured for UDMA/133
[   70.145654] sd 9:0:0:0: [sdi] 2930277168 512-byte logical blocks: (1.50 TB/1.36 TiB)
[   70.145661] sd 9:0:0:0: [sdi] 4096-byte physical blocks
[   70.145697] sd 9:0:0:0: [sdi] Write Protect is off
[   70.145703] sd 9:0:0:0: [sdi] Mode Sense: 00 3a 00 00
[   70.145748] sd 9:0:0:0: [sdi] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[   72.057892] ata9: COMRESET failed (errno=-32)
[   72.101316] ata9: reset failed (errno=-32), retrying in 8 secs
[   79.896843] ata9: hard resetting link
[   79.916492] ahci 0000:03:00.0: AHCI controller unavailable!
[   81.056827] ata9: failed to resume link (SControl FFFFFFFF)
[   81.117199] ata9: SATA link up 1.5 Gbps (SStatus 113 SControl 3F0)
[   81.117822] ata9.00: link online but device misclassified
[   86.281695] ata9.00: qc timeout (cmd 0xec)
[   86.316083] ahci 0000:03:00.0: AHCI controller unavailable!
[   86.355407] ata9.00: failed to IDENTIFY (I/O error, err_mask=0x4)
[   86.355411] ata9.00: revalidation failed (errno=-5)
[   86.360373] ata9: hard resetting link
[   86.375062] ahci 0000:03:00.0: AHCI controller unavailable!
[   87.485914] ata9: failed to resume link (SControl FFFFFFFF)
[   87.643367] ata9: SATA link up lt;unknowngt; (SStatus FFFFFFFF SControl 3F0)
[   87.682502] ata10: illegal qc_active transition (00000001-gt;ffffffff)
[   87.721942] ata9.00: link status unknown, clearing UNKNOWN to NONE
[   87.729780] ata10.00: exception Emask 0x2 SAct 0x1 SErr 0x0 action 0x6 frozen
[   87.737120] ata10.00: failed command: READ FPDMA QUEUED
[   87.742549] ata10.00: cmd 60/08:00:18:00:00/00:00:00:00:00/40 tag 0 ncq dma 4096 in
[   87.758535] ata10.00: status: { DRDY }
[   87.762392] ata10: hard resetting link
[   88.238656] ata10: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[   93.449667] ata10.00: qc timeout (cmd 0xec)
[   93.482443] ahci 0000:03:00.0: AHCI controller unavailable!
[   93.521763] ata10.00: failed to IDENTIFY (I/O error, err_mask=0x4)
[   93.521766] ata10.00: revalidation failed (errno=-5)
[   93.526866] ata10: hard resetting link
[   93.541423] ahci 0000:03:00.0: AHCI controller unavailable!
[   94.022626] ata10: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[   97.801676] ata9.00: qc timeout (cmd 0xec)
[   97.837327] ahci 0000:03:00.0: AHCI controller unavailable!
[   97.843223] ata9.00: failed to IDENTIFY (I/O error, err_mask=0x4)
[   97.843226] ata9.00: revalidation failed (errno=-5)
[   97.848715] ata9: hard resetting link
[   97.860823] ata10.00: configured for UDMA/133
[   97.860858] ata10: EH complete
[   98.937751] ata9: link resume succeeded after 4 retries
[   99.174246] ata10: illegal qc_active transition (00008000-gt;ffffffff)
[   99.252916] ata10.00: exception Emask 0x52 SAct 0x8000 SErr 0xffffffff action 0xe frozen
[   99.261393] ata10: SError: { RecovData RecovComm UnrecovData Persist Proto HostInt PHYRdyChg PHYInt CommWake 10B8B Dispar BadCRC Handshk LinkSeq TrStaTrns UnrecFIS DevExch }
[   99.277442] ata10.00: failed command: READ FPDMA QUEUED
[   99.282760] ata10.00: cmd 60/08:78:18:00:00/00:00:00:00:00/40 tag 15 ncq dma 4096 in
[   99.298917] ata10.00: status: { DRDY }
[   99.302844] ata10: hard resetting link
[  100.178668] ata10: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[  100.327206] ata10.00: configured for UDMA/133
[  100.327237] ata10: EH complete
[  100.540679] ata9: softreset failed (device not ready)
[  100.545980] ata9: reset failed (errno=-19), retrying in 8 secs
[  108.041658] ata9: hard resetting link
[  108.060949] ahci 0000:03:00.0: AHCI controller unavailable!
[  109.201274] ata9: failed to resume link (SControl FFFFFFFF)
[  109.358898] ata9: SATA link up lt;unknowngt; (SStatus FFFFFFFF SControl 3F0)
[  109.359795] ata9.00: link online but device misclassified
[  109.360386] sdi: detected capacity change from 0 to 1500301910016
[  109.360635] sd 9:0:0:0: [sdi] Attached SCSI disk
[  141.065684] ata9.00: qc timeout (cmd 0xec)
[  141.100922] ahci 0000:03:00.0: AHCI controller unavailable!
[  141.140238] ata9.00: failed to IDENTIFY (I/O error, err_mask=0x4)
[  141.140241] ata9.00: revalidation failed (errno=-5)
[  141.145324] ata9.00: disabled
[  141.159904] ata9: hard resetting link
[  141.638626] ata9: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[  141.681835] ata9.00: failed to IDENTIFY (I/O error, err_mask=0x1)
[  146.697680] ata9: hard resetting link
[  147.174635] ata9: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[  147.184309] ata9.00: ATA-8: ST1500LM006 HN-M151RAD, 2BC10001, max UDMA/133
[  147.184314] ata9.00: 2930277168 sectors, multi 0: LBA48 NCQ (depth 32), AA
[  147.194852] ata9.00: configured for UDMA/133
[  147.194882] sd 8:0:0:0: [sdh] tag#28 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[  147.194887] sd 8:0:0:0: [sdh] tag#28 Sense Key : Illegal Request [current] 
[  147.194892] sd 8:0:0:0: [sdh] tag#28 Add. Sense: Unaligned write command
[  147.194898] sd 8:0:0:0: [sdh] tag#28 CDB: Read(10) 28 00 00 00 00 00 00 00 08 00
[  147.194901] print_req_error: I/O error, dev sdh, sector 0
[  147.200557] Buffer I/O error on dev sdh, logical block 0, async page read
[  147.207755] ata9: EH complete
[  147.213383] print_req_error: I/O error, dev sdh, sector 0
[  147.218902] Buffer I/O error on dev sdh, logical block 0, async page read
[  147.231533] print_req_error: I/O error, dev sdh, sector 0
[  147.237212] Buffer I/O error on dev sdh, logical block 0, async page read
[  147.249645] print_req_error: I/O error, dev sdh, sector 0
[  147.255247] Buffer I/O error on dev sdh, logical block 0, async page read
[  147.267774] print_req_error: I/O error, dev sdh, sector 0
[  147.273370] Buffer I/O error on dev sdh, logical block 0, async page read
[  147.285716] print_req_error: I/O error, dev sdh, sector 0
[  147.291294] Buffer I/O error on dev sdh, logical block 0, async page read
[  147.303662] print_req_error: I/O error, dev sdh, sector 0
[  147.309163] Buffer I/O error on dev sdh, logical block 0, async page read
[  147.321413] print_req_error: I/O error, dev sdh, sector 0
[  147.326922] Buffer I/O error on dev sdh, logical block 0, async page read
[  147.333896] Dev sdh: unable to read RDB block 0
[  147.344221] print_req_error: I/O error, dev sdh, sector 0
[  147.349722] Buffer I/O error on dev sdh, logical block 0, async page read
[  147.362236] print_req_error: I/O error, dev sdh, sector 0
[  147.367897] Buffer I/O error on dev sdh, logical block 0, async page read
[  147.386028]  sdh: unable to read partition table
[  147.386068] ata9.00: detaching (SCSI 8:0:0:0)
[  147.387013] sd 8:0:0:0: [sdh] Attached SCSI disk
[  147.387731] sd 8:0:0:0: [sdh] Synchronizing SCSI cache
[  147.388682] sd 8:0:0:0: [sdh] Stopping disk
[  177.994433] ahci 0000:03:00.0: AHCI controller unavailable!
[  178.053717] ata10: limiting SATA link speed to 1.5 Gbps
[  178.053724] ata10.00: exception Emask 0x0 SAct 0x8000 SErr 0x0 action 0x6 frozen
[  178.061352] ata10.00: failed command: READ FPDMA QUEUED
[  178.066678] ata10.00: cmd 60/08:78:20:7b:a8/00:00:ae:00:00/40 tag 15 ncq dma 4096 in
[  178.082278] ata10.00: status: { DRDY }
[  178.086294] ata10: hard resetting link
[  178.102558] ahci 0000:03:00.0: AHCI controller unavailable!
[  178.658609] ata10: SATA link up 3.0 Gbps (SStatus 123 SControl 3F0)
[  179.145242] ata10.00: failed to enable AA (error_mask=0x1)
[  179.150999] ata10.00: configured for UDMA/133
[  179.846763] ata9: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[  180.510978] ata9.00: configured for UDMA/133
[  180.510989] ata9.00: device reported invalid CHS sector 0
[  180.511036] sd 8:0:0:0: [sdh] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[  180.511042] sd 8:0:0:0: [sdh] Sense Key : Illegal Request [current] 
[  180.511046] sd 8:0:0:0: [sdh] Add. Sense: Unaligned write command
[  180.563300] sd 8:0:0:0: [sdh] 2930277168 512-byte logical blocks: (1.50 TB/1.36 TiB)
[  180.563307] sd 8:0:0:0: [sdh] 4096-byte physical blocks
[  180.563341] sd 8:0:0:0: [sdh] Write Protect is off
[  180.563346] sd 8:0:0:0: [sdh] Mode Sense: 00 3a 00 00
[  180.563397] sd 8:0:0:0: [sdh] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[  180.670690] ata10: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[  180.689131] ata10.00: configured for UDMA/133
[  180.689157] sd 9:0:0:0: [sdi] tag#15 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[  180.689163] sd 9:0:0:0: [sdi] tag#15 Sense Key : Illegal Request [current] 
[  180.689168] sd 9:0:0:0: [sdi] tag#15 Add. Sense: Unaligned write command
[  180.689174] sd 9:0:0:0: [sdi] tag#15 CDB: Read(10) 28 00 ae a8 7b 20 00 00 08 00
[  180.689179] print_req_error: I/O error, dev sdi, sector 2930277152
[  180.695669] ata10: EH complete
[  207.597542] udevd[103]: worker [120] /devices/pci0000:00/0000:00:1c.3/0000:03:00.0/ata10/host9/target9:0:0/9:0:0:0/block/sdi is taking a long time
[  210.759171] ata9: limiting SATA link speed to 1.5 Gbps
[  210.759177] ata9.00: exception Emask 0x52 SAct 0x20000 SErr 0xffffffff action 0xe frozen
[  210.767694] ata9: SError: { RecovData RecovComm UnrecovData Persist Proto HostInt PHYRdyChg PHYInt CommWake 10B8B Dispar BadCRC Handshk LinkSeq TrStaTrns UnrecFIS DevExch }
[  210.783586] ata9.00: failed command: READ FPDMA QUEUED
[  210.788866] ata9.00: cmd 60/08:88:00:00:00/00:00:00:00:00/40 tag 17 ncq dma 4096 in
[  210.804921] ata9.00: status: { DRDY }
[  210.808780] ata9: hard resetting link
[  210.827969] ahci 0000:03:00.0: AHCI controller unavailable!
[  210.886974] ata10.00: exception Emask 0x52 SAct 0x200000 SErr 0xffffffff action 0xe frozen
[  210.895448] ata10: SError: { RecovData RecovComm UnrecovData Persist Proto HostInt PHYRdyChg PHYInt CommWake 10B8B Dispar BadCRC Handshk LinkSeq TrStaTrns UnrecFIS DevExch }
[  210.911575] ata10.00: failed command: READ FPDMA QUEUED
[  210.917099] ata10.00: cmd 60/08:a8:20:7b:a8/00:00:ae:00:00/40 tag 21 ncq dma 4096 in
[  210.933225] ata10.00: status: { DRDY }
[  210.937069] ata10: hard resetting link
[  210.955765] ahci 0000:03:00.0: AHCI controller unavailable!
[  211.881778] ata9: link resume succeeded after 3 retries
[  212.113768] ata10: link resume succeeded after 4 retries
[  215.547449] ata10: SATA link up 1.5 Gbps (SStatus 113 SControl 3F0)
[  215.547788] ata10.00: link online but device misclassified
[  217.866583] ata9: SATA link up 1.5 Gbps (SStatus 113 SControl 3F0)
[  220.681669] ata10.00: qc timeout (cmd 0xec)
[  220.682541] ata10.00: failed to IDENTIFY (I/O error, err_mask=0x4)
[  220.682544] ata10.00: revalidation failed (errno=-5)
[  220.687670] ata10: hard resetting link
[  220.700542] ata9.00: configured for UDMA/133
[  220.700553] ata9.00: device reported invalid CHS sector 0
[  220.700577] ata9: EH complete
[  221.777784] ata10: link resume succeeded after 4 retries
[  223.864574] sd 8:0:0:0: [sdh] Attached SCSI disk
[  223.864812] sdh: detected capacity change from 0 to 1500301910016
[  224.777320] ata10: softreset failed (device not ready)
[  224.782541] ata10: reset failed (errno=-19), retrying in 6 secs
[  230.921659] ata10: hard resetting link
[  230.940997] ahci 0000:03:00.0: AHCI controller unavailable!
[  232.081324] ata10: failed to resume link (SControl FFFFFFFF)
[  232.239059] ata10: SATA link down (SStatus C00040 SControl 3F0)
[  237.321663] ata10: hard resetting link
[  237.438903] ata9.00: exception Emask 0x73 SAct 0x20 SErr 0xffffffff action 0xe frozen
[  237.446995] ata9.00: irq_stat 0xffffffff, unknown FIS 00000000 00000000 00000000 00000000, host bus 
[  237.456550] ata9: SError: { RecovData RecovComm UnrecovData Persist Proto HostInt PHYRdyChg PHYInt CommWake 10B8B Dispar BadCRC Handshk LinkSeq TrStaTrns UnrecFIS DevExch }
[  237.472786] ata9.00: failed command: READ FPDMA QUEUED
[  237.478159] ata9.00: cmd 60/08:28:80:7a:a8/00:00:ae:00:00/40 tag 5 ncq dma 4096 in
[  237.494209] ata9.00: status: { DRDY }
[  237.497981] ata9: hard resetting link
[  237.517515] ahci 0000:03:00.0: AHCI controller unavailable!
[  237.853733] ata10: SATA link down (SStatus 0 SControl 3F0)
[  237.854187] ata10.00: disabled
[  237.854310] ata10.00: device reported invalid CHS sector 0
[  237.854550] sd 9:0:0:0: [sdi] tag#21 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[  237.854555] sd 9:0:0:0: [sdi] tag#21 Sense Key : Illegal Request [current] 
[  237.854560] sd 9:0:0:0: [sdi] tag#21 Add. Sense: Unaligned write command
[  237.854565] sd 9:0:0:0: [sdi] tag#21 CDB: Read(10) 28 00 ae a8 7b 20 00 00 08 00
[  237.854569] print_req_error: I/O error, dev sdi, sector 2930277152
[  237.861066] Buffer I/O error on dev sdi, logical block 366284644, async page read
[  237.868708] ata10: EH complete
[  237.868725] ata10.00: detaching (SCSI 9:0:0:0)
[  237.870738] sd 9:0:0:0: [sdi] Synchronizing SCSI cache
[  237.870817] sd 9:0:0:0: [sdi] Synchronize Cache(10) failed: Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[  237.870822] sd 9:0:0:0: [sdi] Stopping disk
[  237.870843] sd 9:0:0:0: [sdi] Start/Stop Unit failed: Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[  238.255109] ata9: SATA link down (SStatus 0 SControl 310)
[  243.465660] ata9: hard resetting link
[  243.782347] ata9: SATA link down (SStatus 0 SControl 310)
[  248.841669] ata9: hard resetting link
[  249.158180] ata9: SATA link down (SStatus 0 SControl 310)
[  249.158633] ata9.00: disabled
[  249.158998] sd 8:0:0:0: [sdh] tag#5 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[  249.159003] sd 8:0:0:0: [sdh] tag#5 Sense Key : Illegal Request [current] 
[  249.159008] sd 8:0:0:0: [sdh] tag#5 Add. Sense: Unaligned write command
[  249.159013] sd 8:0:0:0: [sdh] tag#5 CDB: Read(10) 28 00 ae a8 7a 80 00 00 08 00
[  249.159017] print_req_error: I/O error, dev sdh, sector 2930276992
[  249.165483] ata9: EH complete
[  249.165516] ata9.00: detaching (SCSI 8:0:0:0)
[  249.165553] print_req_error: I/O error, dev sdh, sector 2930276992
[  249.171927] Buffer I/O error on dev sdh, logical block 366284624, async page read
[  249.181103] sd 8:0:0:0: [sdh] Synchronizing SCSI cache
[  249.181180] sd 8:0:0:0: [sdh] Synchronize Cache(10) failed: Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[  249.181184] sd 8:0:0:0: [sdh] Stopping disk
[  249.181203] sd 8:0:0:0: [sdh] Start/Stop Unit failed: Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK

---

---

Odpovědi

[NN]

Muzes otestovat live nejaky starsi kernel jestli se to bude opakovat.

[Petr Tomášek]

Hm, uvidim, jestli nekde najdu obraz stare live distribuce, ktera ma zapnutou RS232 konzoli

[PetebLazar]

Jde o miniPCI nebo miniPCIe kartu? V tom druhem případě se mi doma válí řadič 2xSATAIII s ASM1061. Používaný v MB Johnstown 945GSEJ, která se po šesti letech 24x7 odebrala na odpočinek a pro řadič již nebudu mít další uplatnění.

[PetebLazar]

Teď koukám, že podle dmesg by mělo jít o PCIe device (tudíž asi o miniPCIe).

[Petr Tomášek]

Ano, jedná se o miniPCIe (miniPCI je překlep, sorry za zmatek), přesně taková, jakou uvádíš/te výše. Pokud bys(te) se jí chtěl zbavit za malou cenu, asi bych neodmítnul, ale nejdřív chci vyzkoušet tu starší live distribuci - jen asi budu muset přinést servřík někam, kde je k dispozici VGA monitor. Dám vědět.

[PetebLazar]

Dejte vědět. Věnuji ji zdarma, snad ještě poslouží. Detailnější domluva případně přes e-mail radic(zavinac)monitos.cz.

[trubicoid2]

někde kolem toho jádra 4.19 začali automaticky dělat AHCI ALPM (Aggressive Link Power Management), možná je to tím?

co ukazuje /sys/class/scsi_host/host*/link_power_management_policy ?

a s tím starým jádrem 3.16-4.0 to jede?

[Petr Tomášek]

je tam max_performance, takže to tím nebude...

[trubicoid2]

jo, tím to nebude, od 4.15 si tam dej med_power_with_dipm

ještě mě napadlo co je v /sys/class/scsi_host/host*/device/power/control ?

mělo by být on, auto sice šetří, ale někdy blbne, třeba při připojení disku do e-sata.

[Petr Tomášek]

Tak jsem to zkusil s jádrem 3.2.0 a bez problému. Výběr z dmesg:

[    0.835474] pci 0000:03:00.0: [1b21:0612] type 0 class 0x000106
[    0.836593] pci 0000:03:00.0: reg 10: [io  0x2008-0x200f]
[    0.837379] pci 0000:03:00.0: reg 14: [io  0x2018-0x201b]
[    0.838174] pci 0000:03:00.0: reg 18: [io  0x2000-0x2007]
[    0.900454] pci 0000:03:00.0: reg 1c: [mem 0x00000000-0x0000000f]
[    0.901237] pci 0000:03:00.0: reg 20: [io  0x2000-0x201f]
[    0.902028] pci 0000:03:00.0: reg 24: [mem 0xd0500000-0xd05001ff]
[    0.904404] pci 0000:03:00.0: reg 30: [mem 0xffff0000-0xffffffff pref]
[    0.986610] pci 0000:03:00.0: address space collision: [io  0x2000-0x201f] conflicts with 0000:03:00.0 [io  0x2000-0x2007]
[    1.011375] pci 0000:03:00.0: no compatible bridge window for [mem 0xffff0000-0xffffffff pref]
[    1.011565] pci 0000:03:00.0: BAR 6: assigned [mem 0xd0b00000-0xd0b0ffff pref]
[    1.011572] pci 0000:03:00.0: BAR 4: assigned [io  0x2020-0x203f]
[    1.011583] pci 0000:03:00.0: BAR 3: assigned [mem 0xd0500200-0xd050020f]
[    1.808470] ata9: SATA max UDMA/133 abar m512@0xd0500000 port 0xd0500100 irq 44
[    1.808483] ata10: SATA max UDMA/133 abar m512@0xd0500000 port 0xd0500180 irq 44
[    2.299733] ata9: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[    2.306242] ata9.00: ATA-8: ST1500LM006 HN-M151RAD, 2BC10008, max UDMA/133
[    2.306258] ata9.00: 2930277168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA
[    2.312794] ata9.00: configured for UDMA/133
[    4.083420] scsi 8:0:0:0: Direct-Access     ATA      ST1500LM006 HN-M 2BC1 PQ: 0 ANSI: 5
[    4.573361] ata10: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[    4.579859] ata10.00: ATA-8: ST1500LM006 HN-M151RAD, 2BC10001, max UDMA/133
[    4.579875] ata10.00: 2930277168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA
[    4.586445] ata10.00: configured for UDMA/133
[    4.586738] scsi 9:0:0:0: Direct-Access     ATA      ST1500LM006 HN-M 2BC1 PQ: 0 ANSI: 5
[    4.615844] sd 8:0:0:0: [sdh] 2930277168 512-byte logical blocks: (1.50 TB/1.36 TiB)
[    4.615853] sd 8:0:0:0: [sdh] 4096-byte physical blocks
[    4.615980] sd 9:0:0:0: [sdi] 2930277168 512-byte logical blocks: (1.50 TB/1.36 TiB)
[    4.615988] sd 9:0:0:0: [sdi] 4096-byte physical blocks
[    4.616349] sd 9:0:0:0: [sdi] Write Protect is off
[    4.616358] sd 9:0:0:0: [sdi] Mode Sense: 00 3a 00 00
[    4.616409] sd 8:0:0:0: [sdh] Write Protect is off
[    4.616418] sd 8:0:0:0: [sdh] Mode Sense: 00 3a 00 00
[    4.616548] sd 9:0:0:0: [sdi] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    4.616696] sd 8:0:0:0: [sdh] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    4.625506] sd 8:0:0:0: Attached scsi generic sg7 type 0
[    4.625644] sd 9:0:0:0: Attached scsi generic sg8 type 0
[    4.832096]  sdi: unknown partition table
[    4.832636] sd 9:0:0:0: [sdi] Attached SCSI disk
[    4.856447]  sdh: unknown partition table
[    4.857110] sd 8:0:0:0: [sdh] Attached SCSI disk

(ty disky jsou prázdný, proto to nenajde tabulku rozdělení disku, to je v pořádku...)

[k3dAR]

zkus novejsi jadro, 5.2/5.3rc... nebo s tim 4.19 zkus pridat kernel parametr:

libata.force=9:3.0G,10:3.0G

tedy ata9 a ata10 prepnuto do rezimu SATA II...

[Petr Tomášek]

zkus novejsi jadro, 5.2/5.3rc... nebo s tim 4.19 zkus pridat kernel parametr:

libata.force=9:3.0G,10:3.0G

tedy ata9 a ata10 prepnuto do rezimu SATA II...

To tam bylo, viz výše: ata9: FORCE: PHY spd limit set to 3.0Gbps

Kde najdu 5.2/5.3rc jádro pro Devuan beowulf/ceres? Ze zdrojáḳů jsem jádro neskládal snad 10 let...

[k3dAR]

koukam ani pro Debian nevidim, takze bud muzes se vrhnout na https://kernel-team.pages.debian.net/kernel-handbook/ch-common-tasks.html
nebo nainstalovat 'Ubuntu "Mainline" Kernel', ted sem overil ze 5.2.5 v Debian 10 jde nainstalovat/nastartovat v pohode...

[trubicoid2]

no a nebyl právě ten nefungující kernel omezenej na sata II (3Gbps), kdežto ten starej fungující měl sata III (6GBps):

z nefungujícího dmesg:

[ 4.426395] ata9: FORCE: PHY spd limit set to 3.0Gbps

[ 4.426513] ata10: FORCE: PHY spd limit set to 3.0Gbps

tak se podívat, proč tam to FORCE je a oddělat to? nebo předělat na 6?

[Petr Tomášek]

tak se podívat, proč tam to FORCE je a oddělat to? nebo předělat na 6?

Ach jo, rychlostí PHY to NENÍ, nevím, jak už to napsat. To "FORCE" už jsem odstranil i sám (jen jsem zapomněl zpustit update-grub, takže se to do výpisu dostlo po staru) - na problém to nemá vliv, dal jsem to tam kdysi dávna kvůli nekvalitním SATA-kabelů a mizernému napájení (udělal jsem si nakonec napájecí kabely na 2,5" HDD bez 12V větve - jenom +5V a GND a přidal měnič 12V⇒5V a od té doby to šlapalo bez problémů, snad se na té 12V větvi něco indukovalo, či co; bylo tam ale stejně nechanýcch těch 3G, protože disky stejně tak jak tak víc jak 120~130MB/s nedávají...)

Jinak problém jsem našel, ale napíšu zítra (prosím vydržte s označováním jako "vyřešené", protože musím ještě najít způsoba, jak efektu dosáhnout trvale, asi budu muset napsat patch do jádra nebo dělat opičiny s rc skripty nebo initramfs...)

[Petr Tomášek]

Takže, jak jsem psal, příčina je nalezena. Jedná se o bug #102311 jádra, v souvislosti tímto patchem, týká se to jader od verze 4.1, do 4.0 fungují.

Jde o to, že do jádra 4.0. kernel vypínal ASPM (power-management pro PCIe) i když jej předtím BIOS zapnul. Bohužel se v mém případě jedná o levný čínský šmejd, který (snad v kombinaci s danou základní deskou???) sice ASPM BIOSem zapne, ale pak s tím nefunguje (zřejmě linka usne a už se včas neprobudí).

Bohužel od jádra 4.1. není kernelu jak říci, aby natvrdo i přes nastavení BIOSu ASPM zakázal (chtělo by to dodělat něco jako aspm_pcie=force_off, zkusím se na to po prázdninách kouknout).

Do té doby je potřeba vypnout ASPM pomocí utilitky setpci přímým zápisem do PCI(e) registrů. Důležité při tom je, vypnout to jak na straně SATA řadiče, tak na straně PCIe bridge (případně host adapteru) se kterým ten SATA řadič přes PCIe komunikuje. Pro krátký test stačí na vypnutí něco takovéhoto (vypne všechny PCIe zařízení):

#!/bin/bash

ALLPCIS=$(lspci | cut -f 1 -d " ")
for PCI in $ALLPCIS;
do
 setpci -s $PCI CAP_EXP+10.b=40
done

To je nám ovšem naprd, anžto chceme aby se toto nastavení událo ještě před inicializací mdraidu (na řadiči mi visí dva disky z raidu), což se musí stát ještě v initramfs. Proto je nutné napsat skript pro initramfs, který spustí setpci s příslušnými parametry. Jenže, aby to bylo možné, je nutné nejdřív přesvědčit update-initramfs, aby do initramfs nejdříve přidal samotnou utilitku setpci. To se prove následujícím hookem, který uložíme do /etc/initramfs-tools/hooks/disable_aspm_asm1062 a nezapomene mu nastavit spouštěcí příznak (pomocí chmod +x):

#!/bin/sh
PREREQ=""
prereqs()
{
        echo "$PREREQ"
}

case $1 in
prereqs)
        prereqs
        exit 0
        ;;
esac

. /usr/share/initramfs-tools/hook-functions

echo "Adding 'setpci' to the initramfs..." 1>&2
copy_exec /usr/bin/setpci /sbin

exit 0

Potom potřebujeme zjistit čísla PCI zařízení pro SATA řadič a příslušný PCIe bridge na kterém řadič visí (např. pomocí lshw). V mém případě je řadič 03:00.0 a bridge 00:1c.3. Podle toho vložíme následující skript (mutatis mutandis) do /etc/initramfs-tools/scripts/init-top/disable_aspm_asm1062 (a nezapomene nastavit spouštěcí příznak pomocí chmod +x:

#!/bin/sh
PREREQ=""
prereqs()
{
        echo "$PREREQ"
}

case $1 in
prereqs)
        prereqs
        exit 0
        ;;
esac

. /scripts/functions

log_begin_msg "Setting ASPM off for ASM1062... "

/sbin/setpci -A linux-sysfs -s 03:00.0 CAP_EXP+10.b=40 || log_warning_msg "setpci failed for 03:00.0"
/sbin/setpci -A linux-sysfs -s 00:1c.3 CAP_EXP+10.b=40 || log_warning_msg "setpci failed for 00:1c.3"

log_end_msg

exit 0

Poté vygenerujeme příslušný/é initramfs (pomocí update-initramfs -u -k [verze_jádra]. Pokud je vše v pořádku, zahlásí to v rámci updatu „Adding 'setpci' to the initramfs...“. Pomocí lsinitrafs se můžeme přesvědčit, že vytvořený initrd obsahuje jak náš skript, tak binárku setpci. Pak už stačí jen spustit update-grub (nebo alternativně lilo) a provést reset.

[PetebLazar]

Dobrá práce. Takže náhradní řadič asi třeba nebude (zruším připravený komunikační kanál).

[Petr Tomášek]

Pokud bych se pustil do kuchání jádra, možná by se další HW hodil na otestování (zda-li to dělá jen konkrétní kus, či tak). Ale do 18.8. jsem stejně mimo (na cestách)...

[Zoufalec]

Bohužel od jádra 4.1. není kernelu jak říci, aby natvrdo i přes nastavení BIOSu ASPM zakázal (chtělo by to dodělat něco jako aspm_pcie=force_off, zkusím se na to po prázdninách kouknout).

pcie_aspm=off?

[Petr Tomášek]

Nene, to (od 4.1.) právěže ponechá to, co nastavil BIOS. O tom to celé je, pročti si ten bug.

[Zoufalec]

Právě jsem si ho přečetl a omlouvám se za zbytečnou odpověď. :-/