ahci timeout during boot on a particular mobo

From: Andriy Gapon <avg_at_FreeBSD.org>
Date: Fri, 19 Aug 2016 11:30:54 +0300
The motherboard is Asus M4A89GTD PRO.  This is how the manufacturer describes
its storage hardware:

AMD® SB850 chipset
	 -	 6 x SATA 6.0 Gb/s ports with RAID 0, 1, 5, and 10 support
JMicron® JMB361 PATA and SATA controller
	 -	 1 x Power eSATA 3.0 Gb/s port
	 -	 1 x Ultra DMA 133/100 for up to 2 PATA devices

This is what pciconf tells about the additional controller:
atapci0_at_pci0:2:0:0:     class=0x010185 card=0x824f1043 chip=0x2361197b rev=0x02
hdr=0x00
    vendor     = 'JMicron Technology Corp.'
    device     = 'JMB361 AHCI/IDE'
    class      = mass storage
    subclass   = ATA

At the moment there is a SATA disk connected to one of the chipset's ports and
an old optical disk drive connected to the IDE port.

Here is what FreeBSD sees during boot:

atapci0: <JMicron JMB361 UDMA133 controller> port
0xcc00-0xcc07,0xc880-0xc883,0xc800-0xc807,0xc480-0xc483,0xc400-0xc40f mem
0xfe8fe000-0xfe8fffff irq 18 at device 0.0 on pci2
ahci0: <JMicron JMB361 AHCI SATA controller> at channel -1 on atapci0
ahci0: AHCI v1.00 with 2 3Gbps ports, Port Multiplier supported
ahci0: quirks=0x1<NOFORCE>
ahci0: Caps: 64bit NCQ ALP AL CLO 3Gbps PM PMD SSC PSC 32cmd 2ports
ahcich0: <AHCI channel> at channel 0 on ahci0
ahcich0: Caps: HPCP
ahcich1: <AHCI channel> at channel 1 on ahci0
ahcich1: Caps: HPCP
ata2: <ATA channel> at channel 0 on atapci0
ahci1: <ATI IXP700 AHCI SATA controller> port
0xa000-0xa007,0x9000-0x9003,0x8000-0x8007,0x7000-0x7003,0x6000-0x600f mem
0xfe5ffc00-0xfe5fffff irq 19 at device 17.0 on pci0
ahci1: AHCI v1.20 with 6 6Gbps ports, Port Multiplier supported
ahci1: Caps: 64bit NCQ SNTF MPS ALP AL CLO 6Gbps PM PMD SSC PSC 32cmd 6ports
ahci1: Caps2:
ahcich2: <AHCI channel> at channel 0 on ahci1
ahcich2: Caps:
ahcich3: <AHCI channel> at channel 1 on ahci1
ahcich3: Caps:
ahcich4: <AHCI channel> at channel 2 on ahci1
ahcich4: Caps:
ahcich5: <AHCI channel> at channel 3 on ahci1
ahcich5: Caps:
ahcich6: <AHCI channel> at channel 4 on ahci1
ahcich6: Caps:
ahcich7: <AHCI channel> at channel 5 on ahci1
ahcich7: Caps:
ahcich0: AHCI reset...
ahcich0: SATA connect timeout time=10000us status=00000000
ahcich0: AHCI reset: device not found
ahcich1: AHCI reset...
ahcich1: SATA connect time=0us status=00000123
ahcich1: AHCI reset: device found
ata2: reset tp1 mask=03 ostat0=50 ostat1=00
ata2: stat0=0x00 err=0x01 lsb=0x14 msb=0xeb
ata2: stat1=0x00 err=0x00 lsb=0x00 msb=0x00
ata2: reset tp2 stat0=00 stat1=00 devices=0x10000
ahcich2: AHCI reset...
ahcich2: SATA connect timeout time=10000us status=00000000
ahcich2: AHCI reset: device not found
ahcich3: AHCI reset...
ahcich3: SATA connect time=800us status=00000123
ahcich3: AHCI reset: device found
ahcich4: AHCI reset...
ahcich4: SATA connect timeout time=10000us status=00000000
ahcich4: AHCI reset: device not found
ahcich5: AHCI reset...
ahcich5: SATA connect timeout time=10000us status=00000000
ahcich5: AHCI reset: device not found
ahcich6: AHCI reset...
ahcich6: SATA connect timeout time=10000us status=00000000
ahcich6: AHCI reset: device not found
ahcich7: AHCI reset...
ahcich7: SATA connect timeout time=10000us status=00000000
ahcich7: AHCI reset: device not found
ahcich3: AHCI reset: device ready after 100ms
ahcich1: AHCI reset: device not ready after 31000ms (tfd = 000000ff)
ahcich1: Poll timeout on slot 0 port 15
ahcich1: is 00000000 cs 00000001 ss 00000000 rs 00000001 tfd 77 serr 00000000
cmd 0004c011
(aprobe1:ahcich1:0:15:0): SOFT_RESET. ACB: 00 00 00 00 00 00 00 00 00 00 00 00
(aprobe1:ahcich1:0:15:0): CAM status: Command timeout
(aprobe1:ahcich1:0:15:0): Error 5, Retries exhausted
run_interrupt_driven_hooks: still waiting after 60 seconds for xpt_config
ahcich1: Poll timeout on slot 0 port 15
ahcich1: is 00000000 cs 00000001 ss 00000000 rs 00000001 tfd 77 serr 00000000
cmd 0004c011
(aprobe1:ahcich1:0:15:0): SOFT_RESET. ACB: 00 00 00 00 00 00 00 00 00 00 00 00
(aprobe1:ahcich1:0:15:0): CAM status: Command timeout
(aprobe1:ahcich1:0:15:0): Error 5, Retries exhausted
ahcich1: Poll timeout on slot 0 port 0
ahcich1: is 00000000 cs 00000001 ss 00000000 rs 00000001 tfd 77 serr 00000000
cmd 0004c011
(aprobe0:ahcich1:0:0:0): SOFT_RESET. ACB: 00 00 00 00 00 00 00 00 00 00 00 00
(aprobe0:ahcich1:0:0:0): CAM status: Command timeout
(aprobe0:ahcich1:0:0:0): Error 5, Retries exhausted
ada0 at ahcich3 bus 0 scbus4 target 0 lun 0
ada0: <ST3500410AS CC34> ATA-8 SATA 2.x device
ada0: Serial Number 5VM0NB43
ada0: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes)
ada0: Command Queueing enabled
ada0: 476940MB (976773168 512 byte sectors: 16H 63S/T 16383C)
pass0 at ata2 bus 0 scbus2 target 0 lun 0
pass0: 33.300MB/s transfers (UDMA2, ATAPI 12bytes, PIO 65534bytes)
pass1 at ahcich3 bus 0 scbus4 target 0 lun 0
pass1: <ST3500410AS CC34> ATA-8 SATA 2.x device
pass1: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes)
cd0 at ata2 bus 0 scbus2 target 0 lun 0
cd0: 33.300MB/s transfers (UDMA2, ATAPI 12bytes, PIO 65534bytes)

So, what's suspicious here is that we discover two AHCI channels on the JMicron
device and we seem to discover some sort of a device on one of them.  But the
communication with that (phantom?) device times out and that causes a very long
delay during the boot.

Once the system is up I do not see any problems or strange behavior.

$ camcontrol devlist -v
scbus0 on ahcich0 bus 0:
<>                                 at scbus0 target -1 lun ffffffff ()
scbus1 on ahcich1 bus 0:
<>                                 at scbus1 target -1 lun ffffffff ()
scbus2 on ata2 bus 0:
<HL-DT-ST DVDRAM GSA-4163B A106>   at scbus2 target 0 lun 0 (pass0,cd0)
<>                                 at scbus2 target -1 lun ffffffff ()
scbus3 on ahcich2 bus 0:
<>                                 at scbus3 target -1 lun ffffffff ()
scbus4 on ahcich3 bus 0:
<ST3500410AS CC34>                 at scbus4 target 0 lun 0 (pass1,ada0)
<>                                 at scbus4 target -1 lun ffffffff ()
scbus5 on ahcich4 bus 0:
<>                                 at scbus5 target -1 lun ffffffff ()
scbus6 on ahcich5 bus 0:
<>                                 at scbus6 target -1 lun ffffffff ()
scbus7 on ahcich6 bus 0:
<>                                 at scbus7 target -1 lun ffffffff ()
scbus8 on ahcich7 bus 0:
<>                                 at scbus8 target -1 lun ffffffff ()
scbus9 on sbp0 bus 0:
<>                                 at scbus9 target -1 lun ffffffff ()
scbus-1 on xpt0 bus 0:
<>

Is there a way to fix the boot delay?
Thank you!

P.S.
Searched for JMB361 in the source code, looked at some nearby device entries,
and - is it as simple as adding AHCI_Q_1CH quick for this device?

-- 
Andriy Gapon
Received on Fri Aug 19 2016 - 06:31:35 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:41:07 UTC