From owner-freebsd-current@freebsd.org Fri Aug 19 08:31:35 2016 Return-Path: Delivered-To: freebsd-current@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 7C758BBE0FF for ; Fri, 19 Aug 2016 08:31:35 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: from citapm.icyb.net.ua (citapm.icyb.net.ua [212.40.38.140]) by mx1.freebsd.org (Postfix) with ESMTP id 0A75719F1; Fri, 19 Aug 2016 08:31:33 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: from porto.starpoint.kiev.ua (porto-e.starpoint.kiev.ua [212.40.38.100]) by citapm.icyb.net.ua (8.8.8p3/ICyb-2.3exp) with ESMTP id LAA18189; Fri, 19 Aug 2016 11:31:31 +0300 (EEST) (envelope-from avg@FreeBSD.org) Received: from localhost ([127.0.0.1]) by porto.starpoint.kiev.ua with esmtp (Exim 4.34 (FreeBSD)) id 1bafD9-000KXV-Or; Fri, 19 Aug 2016 11:31:31 +0300 To: Alexander Motin , FreeBSD Current From: Andriy Gapon Subject: ahci timeout during boot on a particular mobo Message-ID: <4fed11f6-533d-4ec3-81ea-9d326dcb1f45@FreeBSD.org> Date: Fri, 19 Aug 2016 11:30:54 +0300 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:45.0) Gecko/20100101 Thunderbird/45.2.0 MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.22 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 19 Aug 2016 08:31:35 -0000 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@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: port 0xcc00-0xcc07,0xc880-0xc883,0xc800-0xc807,0xc480-0xc483,0xc400-0xc40f mem 0xfe8fe000-0xfe8fffff irq 18 at device 0.0 on pci2 ahci0: at channel -1 on atapci0 ahci0: AHCI v1.00 with 2 3Gbps ports, Port Multiplier supported ahci0: quirks=0x1 ahci0: Caps: 64bit NCQ ALP AL CLO 3Gbps PM PMD SSC PSC 32cmd 2ports ahcich0: at channel 0 on ahci0 ahcich0: Caps: HPCP ahcich1: at channel 1 on ahci0 ahcich1: Caps: HPCP ata2: at channel 0 on atapci0 ahci1: 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: at channel 0 on ahci1 ahcich2: Caps: ahcich3: at channel 1 on ahci1 ahcich3: Caps: ahcich4: at channel 2 on ahci1 ahcich4: Caps: ahcich5: at channel 3 on ahci1 ahcich5: Caps: ahcich6: at channel 4 on ahci1 ahcich6: Caps: ahcich7: 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: 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: 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: 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: 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