From owner-freebsd-drivers@FreeBSD.ORG Mon Jun 6 17:29:01 2011 Return-Path: Delivered-To: freebsd-drivers@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id E13AF1065670 for ; Mon, 6 Jun 2011 17:29:01 +0000 (UTC) (envelope-from dieterbsd@engineer.com) Received: from mailout-us.gmx.com (mailout-us.gmx.com [74.208.5.67]) by mx1.freebsd.org (Postfix) with SMTP id 845968FC15 for ; Mon, 6 Jun 2011 17:29:01 +0000 (UTC) Received: (qmail 3587 invoked by uid 0); 6 Jun 2011 17:29:00 -0000 Received: from 67.206.162.132 by rms-us013.v300.gmx.net with HTTP Content-Type: text/plain; charset="utf-8" Date: Mon, 06 Jun 2011 17:28:55 +0000 From: "Dieter BSD" Message-ID: <20110606172857.298480@gmx.com> MIME-Version: 1.0 To: mav@freebsd.org X-Authenticated: #74169980 X-Flags: 0001 X-Mailer: GMX.com Web Mailer x-registered: 0 Content-Transfer-Encoding: 8bit X-GMX-UID: YTzUeKM533enLRTfGHFzR94xU3U4N88S Cc: freebsd-drivers@freebsd.org Subject: Re: ahci(4) doesn't work with Hitachi 3TB drive X-BeenThere: freebsd-drivers@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Writing device drivers for FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 06 Jun 2011 17:29:02 -0000 > Is the 2TB disk is also SATA3? I think it is just 300MB/s, so that is a difference. (Which I managed to not notice until you pointed it out, thanks.) ada10 at ahcich0 bus 0 scbus4 target 0 lun 0 ada10: ATA-8 SATA 2.x device ada10: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes) ada10: Command Queueing enabled ada10: 1907729MB (3907029168 512 byte sectors: 16H 63S/T 16383C) ada11 at ahcich1 bus 0 scbus5 target 0 lun 0 ada11: ATA-8 SATA 3.x device ada11: 150.000MB/s transfers (SATA 1.x, UDMA6, PIO 8192bytes) ada11: Command Queueing enabled ada11: 2861588MB (5860533168 512 byte sectors: 16H 63S/T 16383C) I turned on the bootverbose debugging in ahci.c and added a few of my own. hint.ahcich.1.sata_rev="1" dd if=/dev/ada11 bs=1500k count=1 > /dev/null 1+0 records in 1+0 records out 1536000 bytes transferred in 60.285139 secs (25479 bytes/sec) dmesg | grep -i ahci on atapci3 ahci0: [ITHREAD] ahci0: AHCI v1.00 with 2 3Gbps ports, Port Multiplier supported ahci0: Caps: 64bit NCQ ALP AL CLO 3Gbps PM PMD SSC PSC 32cmd 2ports at channel 0 on ahci0 ahci_ch_attach() i=0 sata_rev = 0 ahci_ch_attach() i=1 sata_rev = 0 ahci_ch_attach() i=2 sata_rev = 0 ahci_ch_attach() i=3 sata_rev = 0 ahci_ch_attach() i=4 sata_rev = 0 ahci_ch_attach() i=5 sata_rev = 0 ahci_ch_attach() i=6 sata_rev = 0 ahci_ch_attach() i=7 sata_rev = 0 ahci_ch_attach() i=8 sata_rev = 0 ahci_ch_attach() i=9 sata_rev = 0 ahci_ch_attach() i=10 sata_rev = 0 ahci_ch_attach() i=11 sata_rev = 0 ahci_ch_attach() i=12 sata_rev = 0 ahci_ch_attach() i=13 sata_rev = 0 ahci_ch_attach() i=14 sata_rev = 0 ahci_ch_attach() i=15 sata_rev = 0 ahcich0: [ITHREAD] ahcich0: Caps: HPCP at channel 1 on ahci0 ahci_ch_attach() i=0 sata_rev = 1 ahci_ch_attach() i=1 sata_rev = 1 ahci_ch_attach() i=2 sata_rev = 1 ahci_ch_attach() i=3 sata_rev = 1 ahci_ch_attach() i=4 sata_rev = 1 ahci_ch_attach() i=5 sata_rev = 1 ahci_ch_attach() i=6 sata_rev = 1 ahci_ch_attach() i=7 sata_rev = 1 ahci_ch_attach() i=8 sata_rev = 1 ahci_ch_attach() i=9 sata_rev = 1 ahci_ch_attach() i=10 sata_rev = 1 ahci_ch_attach() i=11 sata_rev = 1 ahci_ch_attach() i=12 sata_rev = 1 ahci_ch_attach() i=13 sata_rev = 1 ahci_ch_attach() i=14 sata_rev = 1 ahci_ch_attach() i=15 sata_rev = 1 ahcich1: [ITHREAD] ahcich1: Caps: HPCP ahcich0: AHCI reset... ahci_sata_phy_reset() sata_r ahcich0: SATA connect time=100us status=00000123 ahcich0: AHCI reset: device found ahcich0: AHCI reset: device ready after 0ms ahciaction() d->revision = 0 ahciaction() d->revision = 0 ahciaction() d->revision = 0 ahcich1: AHCI reset... ahciaction() d->revision = 0 ahciaction() d->revision = 0 ahciaction() d->revision=0 ahciaction() d->revision = 0 ahciaction() status = 32 revision=2 ahci_sata_phy_reset() sata_rev = 1ahciaction() status = 32 revision=2 ahciaction() d->revision=0 ahciaction() d->revision = 0 ahciaction() d->revision=0 ahciaction() d->revision = 0 ahciaction() status = 32 revision=2 ahcich1: SATA connect time=200us status=00000113 ahcich1: AHCI reset: device found ahcich1: AHCI reset: device ready after 0ms ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 ahciaction() status = 16 revision=1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 ada10 at ahcich0 bus 0 scbus4 target 0 lun 0 ahciaction() status = 32 revision=2 ada11 at ahcich1 bus 0 scbus5 target 0 lun 0 ahciaction() status = 16 revision=1 ahciaction() status = 32 revision=2 ahciaction() status = 32 revision=2 ahciaction() status = 32 revision=2 ahciaction() status = 32 revision=2 ahciaction() status = 32 revision=2 ahciaction() status = 32 revision=2 ahciaction() status = 16 revision=1 ahciaction() status = 16 revision=1 ahcich1: Timeout on slot 0 ahcich1: is 00000000 cs 00000000 ss 00000001 rs 00000001 tfd 50 serr 00000000 ahcich1: AHCI reset... ahci_sata_phy_reset() sata_rev = 1 ahcich1: SATA connect time=200us status=00000113 ahcich1: AHCI reset: device found ahcich1: AHCI reset: device ready after 100ms ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 ahciaction() status = 16 revision=1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 ahcich1: Timeout on slot 0 ahcich1: is 00000000 cs 00000000 ss 00000001 rs 00000001 tfd 50 serr 00000000 ahcich1: AHCI reset... ahci_sata_phy_reset() sata_rev = 1 ahcich1: SATA connect time=200us status=00000113 ahcich1: AHCI reset: device found ahcich1: AHCI reset: device ready after 100ms ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 ahciaction() status = 16 revision=1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 Next, I limited the speed for the 2TB drive on port 0: hint.ahcich.0.sata_rev="1" hint.ahcich.1.sata_rev="1" on atapci3 ahci0: [ITHREAD] ahci0: AHCI v1.00 with 2 3Gbps ports, Port Multiplier supported ahci0: Caps: 64bit NCQ ALP AL CLO 3Gbps PM PMD SSC PSC 32cmd 2ports at channel 0 on ahci0 ahci_ch_attach() i=0 sata_rev = 1 ahci_ch_attach() i=1 sata_rev = 1 ahci_ch_attach() i=2 sata_rev = 1 ahci_ch_attach() i=3 sata_rev = 1 ahci_ch_attach() i=4 sata_rev = 1 ahci_ch_attach() i=5 sata_rev = 1 ahci_ch_attach() i=6 sata_rev = 1 ahci_ch_attach() i=7 sata_rev = 1 ahci_ch_attach() i=8 sata_rev = 1 ahci_ch_attach() i=9 sata_rev = 1 ahci_ch_attach() i=10 sata_rev = 1 ahci_ch_attach() i=11 sata_rev = 1 ahci_ch_attach() i=12 sata_rev = 1 ahci_ch_attach() i=13 sata_rev = 1 ahci_ch_attach() i=14 sata_rev = 1 ahci_ch_attach() i=15 sata_rev = 1 ahcich0: [ITHREAD] ahcich0: Caps: HPCP at channel 1 on ahci0 ahci_ch_attach() i=0 sata_rev = 1 ahci_ch_attach() i=1 sata_rev = 1 ahci_ch_attach() i=2 sata_rev = 1 ahci_ch_attach() i=3 sata_rev = 1 ahci_ch_attach() i=4 sata_rev = 1 ahci_ch_attach() i=5 sata_rev = 1 ahci_ch_attach() i=6 sata_rev = 1 ahci_ch_attach() i=7 sata_rev = 1 ahci_ch_attach() i=8 sata_rev = 1 ahci_ch_attach() i=9 sata_rev = 1 ahci_ch_attach() i=10 sata_rev = 1 ahci_ch_attach() i=11 sata_rev = 1 ahci_ch_attach() i=12 sata_rev = 1 ahci_ch_attach() i=13 sata_rev = 1 ahci_ch_attach() i=14 sata_rev = 1 ahci_ch_attach() i=15 sata_rev = 1 ahcich1: [ITHREAD] ahcich1: Caps: HPCP ahcich0: AHCI reset... ahci_sata_phy_reset() sata_rev ahcich0: SATA connect time=100us status=00000113 ahcich0: AHCI reset: device found ahcich0: AHCI reset: device ready after 0ms ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahcich1: AHCI reset... ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 ahci_sata_phy_reset() sata_rev = 1ahciaction() status = 16 revision=1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 ahcich1: SATA connect time=200us status=00000113 ahcich1: AHCI reset: device found ahcich1: AHCI reset: device ready after 0ms ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 ahciaction() status = 16 revision=1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 ada10 at ahcich0 bus 0 scbus4 target 0 lun 0 ahciaction() status = 16 revision=1 ada11 at ahcich1 bus 0 scbus5 target 0 lun 0 ahciaction() status = 16 revision=1 ahcich0: Timeout on slot 0 ahcich0: is 00000000 cs 00000000 ss 00000001 rs 00000001 tfd 50 serr 00000000 ahcich0: AHCI reset... ahci_sata_phy_reset() sata_rev = 1 ahcich0: SATA connect time=100us status=00000113 ahcich0: AHCI reset: device found ahcich0: AHCI reset: device ready after 0ms ahciaction() d->revision = 1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 ahciaction() status = 16 revision=1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() d->revision=1 ahciaction() d->revision = 1 ahciaction() status = 16 revision=1 Now I get timeouts on the 2TB drive! Next I turned off loading ahci.  The ata(4) driver also gets timeouts on the 3TB drive. ad12: 1907729MB at ata6-master UDMA100 SATA 3Gb/s ad14: 2861588MB at ata7-master UDMA100 SATA 1.5Gb/s ad14: TIMEOUT - READ_DMA retrying (1 retry left) LBA=768 ad14: TIMEOUT - READ_DMA retrying (1 retry left) LBA=1024 ad14: TIMEOUT - READ_DMA retrying (1 retry left) LBA=1536 Summary of clues: 600MB/s Hitachi disk + JMB363 talk at 150MB/s rather than 300, with both ahci(4) and ata(4). Hitachi disk + JMB363 + not running at disk's fastest speed = timeouts or maybe it is Hitachi disk + JMB363 + running at 150MB/s = timeouts Hitachi disk + SiI3132 + 3726 PM + siis(4) = works as expected