Subject: new SATA controller/drive _very_ slow (PIO mode 0)
To: None <current-users@netbsd.org>
From: Jim Bernard <jbernard@mines.edu>
List: current-users
Date: 12/16/2007 19:41:37
Howdy,

  I've recently added to an old x86 system a PCI SATA controller (VIA VT6421)
with a single SATA disk (WDC WD5000AAKS) attached.  The system is running
-current built from sources updated Nov. 17.  The disk works, but the data
transfer rate is excruciatingly slow, about 4 MB/sec, because the driver uses
PIO mode 0.

  Problems appear to begin when the PIO mode support is to be probed
(ata_set_mode=0xc) and __wdccommand_start waits for WDCS_DRQ to be deasserted
before actually starting the transfer.  The status read by __wdcwait always
has the WDCS_DRQ bit set, so the command eventually times out:

  ata_set_mode=0xc
  wdc_exec_command viaide1:0:0
  ata_exec_xfer 0xc1b44f88 channel 0 drive 0
  atastart from ata_exec_xfer, flags 0x100
  atastart: xfer 0xc1b44f88 channel 0 drive 0
  __wdccommand_start viaide1:0:0
  __wdcwait viaide1:0
  __wdcwait: viaide1:0: timeout (time=11), status 58 error 0 (mask 0x8 bits 0x0)
  ...  [previous 2 lines repeated 100 more times]
  __wdccommand_done viaide1:0:0 flags 0x108
    [ata_command flag 0x100 is AT_TIMEOU, command timed out]

  I don't have any alternative SATA drives or controllers to try, but I did
boot a knoppix (linux) CD, and it is able to transfer data from the disk
at full speed, about 85 MB/sec.  Thus, the hardware is apparently not
malfunctioning.

  So, can anyone offer any suggestions (better yet, code) for fixing this?
I'll include below a more substantial subset of the dmesg output (lots of
debugging is turned on), as well as output from "atactl wd2 identify", which
shows what the drive supports.  I can supply the full dmesg output to anyone
who is interested.

  Thanks!

--Jim


selected dmesg output:

...
viaide1 at pci0 dev 11 function 0
...  [omitted most of pci config dump]
VIA Technologies VT6421 Serial RAID Controller (RAID mass storage, revision 0x50) at ? dev 11 function 0 (tag 0x80005800, intrtag 0x80005800, intrswiz 0, intrpin 0x1, i/o on, mem on, no quirks)
viaide1: VIA Technologies VT6421 Serial RAID Controller (rev. 0x50)
viaide1: bus-master DMA support present
viaide1: using irq 10 for native-PCI interrupt
viaide1: primary channel wired to native-PCI mode
atabus2 at viaide1 channel 0
viaide1: secondary channel wired to native-PCI mode
atabus3 at viaide1 channel 1
...
viaide1 port 0: device present, speed: 1.5Gb/s
viaide1: port 0: scnt=0x1 sn=0x1 cl=0x0 ch=0x0
viaide1:0:0: after reset, sc=0x1 sn=0x1 cl=0x0 ch=0x0
viaide1:0:1: after reset, sc=0x0 sn=0x0 cl=0x0 ch=0x0
viaide1:0: wdcwait_reset() end, st0=0x50 st1=0x0
...
wd2 at atabus2 drive 0wdattach
ata_get_params
wdc_exec_command viaide1:0:0
ata_exec_xfer 0xc1b44f88 channel 0 drive 0
atastart from ata_exec_xfer, flags 0x100
atastart: xfer 0xc1b44f88 channel 0 drive 0
__wdccommand_start viaide1:0:0
__wdcwait viaide1:0
wdccommand viaide1:0:0: command=0xec cylin=0 head=0 sector=0 count=0 features=0
wdcintr
__wdccommand_intr viaide1:0:0
__wdcwait viaide1:0
__wdccommand_done viaide1:0:0 flags 0x49
: <WDC WD5000AAKS-00YGA0>
wd2: drive supports 16-sector PIO transfers, LBA48 addressing
wd2: 465 GB, 969021 cyl, 16 head, 63 sec, 512 bytes/sect x 976773168 sectors
wd2: atap_dmatiming_mimi=120, atap_dmatiming_recom=120
ata_get_params
wdc_exec_command viaide1:0:0
ata_exec_xfer 0xc1b44f88 channel 0 drive 0
atastart from ata_exec_xfer, flags 0x100
atastart: xfer 0xc1b44f88 channel 0 drive 0
__wdccommand_start viaide1:0:0
__wdcwait viaide1:0
wdccommand viaide1:0:0: command=0xec cylin=0 head=0 sector=0 count=0 features=0
wdcintr
__wdccommand_intr viaide1:0:0
__wdcwait viaide1:0
__wdccommand_done viaide1:0:0 flags 0x49
ata_get_params
wdc_exec_command viaide1:0:0
ata_exec_xfer 0xc1b44f88 channel 0 drive 0
atastart from ata_exec_xfer, flags 0x100
atastart: xfer 0xc1b44f88 channel 0 drive 0
__wdccommand_start viaide1:0:0
__wdcwait viaide1:0
wdccommand viaide1:0:0: command=0xec cylin=0 head=0 sector=0 count=0 features=0
wdcintr
__wdccommand_intr viaide1:0:0
__wdcwait viaide1:0
__wdccommand_done viaide1:0:0 flags 0x49
ata_set_mode=0xc
wdc_exec_command viaide1:0:0
ata_exec_xfer 0xc1b44f88 channel 0 drive 0
atastart from ata_exec_xfer, flags 0x100
atastart: xfer 0xc1b44f88 channel 0 drive 0
__wdccommand_start viaide1:0:0
__wdcwait viaide1:0
__wdcwait: viaide1:0: timeout (time=11), status 58 error 0 (mask 0x8 bits 0x0)
...  [previous 2 lines repeated 100 more times]
__wdccommand_done viaide1:0:0 flags 0x108
ata_set_mode=0xb
wdc_exec_command viaide1:0:0
ata_exec_xfer 0xc1b44f88 channel 0 drive 0
atastart from ata_exec_xfer, flags 0x100
atastart: xfer 0xc1b44f88 channel 0 drive 0
__wdccommand_start viaide1:0:0
__wdcwait viaide1:0
__wdcwait: viaide1:0: timeout (time=11), status 58 error 0 (mask 0x8 bits 0x0)
...  [previous 2 lines repeated 100 more times]
__wdccommand_done viaide1:0:0 flags 0x108
wd2(viaide1:0:0): using PIO mode 0
...
wdopen
ata_get_params
wdc_exec_command viaide1:0:0
ata_exec_xfer 0xc1b44f88 channel 0 drive 0
atastart from ata_exec_xfer, flags 0x0
atastart: xfer 0xc1b44f88 channel 0 drive 0
__wdccommand_start viaide1:0:0
__wdcwait viaide1:0
__wdcwait: viaide1:0: timeout (time=11), status 58 error 0 (mask 0x48 bits 0x40)
__wdccommand_start viaide1:0:0
__wdcwait viaide1:0
__wdcwait: viaide1:0: timeout (time=11), status 58 error 0 (mask 0x48 bits 0x40)
...  [previous 2 lines repeated 300 more times]
__wdccommand_done viaide1:0:0 flags 0x109
ata_get_parms: ata_c.flags=0x129
wdgetdisklabel
wdgetdefaultlabel
wdstrategy (wd2)
wdstart wd2
ata_exec_xfer 0xc1b44f88 channel 0 drive 0
atastart from ata_exec_xfer, flags 0x0
atastart: xfer 0xc1b44f88 channel 0 drive 0
wdc_ata_bio_start viaide1:0:0
wdc_ata_bio_start viaide1:0:0
__wdcwait viaide1:0
wdccommandshort viaide1:0:0 command 0x10
__wdcwait viaide1:0
wdccommand viaide1:0:0: command=0xc6 cylin=0 head=0 sector=0 count=16 features=0
__wdcwait viaide1:0
_wdc_ata_bio_start viaide1:0:0
__wdcwait viaide1:0
wdccommand viaide1:0:0: command=0x20 cylin=0 head=64 sector=0 count=1 features=0
wdctimeout
viaide1:0:0: lost interrupt
	type: ata tc_bcount: 512 tc_skip: 0
wdc_ata_bio_intr viaide1:0:0
wdc_ata_bio_done viaide1:0:0: flags 0x2
wdc_ata_done: drv_done
wddone wd2
wdc_reset_drive viaide1:0 for drive 0
wd2d: device timeout reading fsbn 0 (wd2 bn 0; cn 0 tn 0 sn 0), retrying
atastart from wdc_ata_done, flags 0x200
viaide1:0:0: after reset, sc=0x1 sn=0x1 cl=0x0 ch=0x0
viaide1:0:1: after reset, sc=0x0 sn=0x0 cl=0x0 ch=0x0
viaide1:0: wdcwait_reset() end, st0=0x50 st1=0x0
wdrestart wd2
ata_exec_xfer 0xc1b44f88 channel 0 drive 0
atastart from ata_exec_xfer, flags 0x0
atastart: xfer 0xc1b44f88 channel 0 drive 0
wdc_ata_bio_start viaide1:0:0
wdc_ata_bio_start viaide1:0:0
__wdcwait viaide1:0
wdccommandshort viaide1:0:0 command 0x10
__wdcwait viaide1:0
__wdcwait: viaide1:0: timeout (time=11), status d0 error 1 (mask 0x40 bits 0x40)
__wdcwait viaide1:0
__wdcwait: viaide1:0: timeout (time=11), status d0 error 1 (mask 0x40 bits 0x40)
__wdcwait viaide1:0
__wdcwait: viaide1:0: timeout (time=11), status d0 error 1 (mask 0x40 bits 0x40)
__wdcwait viaide1:0
wdccommand viaide1:0:0: command=0xc6 cylin=0 head=0 sector=0 count=16 features=0
__wdcwait viaide1:0
__wdcwait: viaide1:0: did busy-wait, time=1
_wdc_ata_bio_start viaide1:0:0
__wdcwait viaide1:0
wdccommand viaide1:0:0: command=0x20 cylin=0 head=64 sector=0 count=1 features=0
wdcintr
wdc_ata_bio_intr viaide1:0:0
__wdcwait viaide1:0
wdc_ata_bio_done viaide1:0:0: flags 0x0
wdc_ata_done: drv_done
wddone wd2
wd2: soft error (corrected)
wdstart wd2
atastart from wdc_ata_done, flags 0x0
wdstrategy (wd2)
wdstart wd2
ata_exec_xfer 0xc1b44f88 channel 0 drive 0
atastart from ata_exec_xfer, flags 0x0
atastart: xfer 0xc1b44f88 channel 0 drive 0
wdc_ata_bio_start viaide1:0:0
_wdc_ata_bio_start viaide1:0:0
__wdcwait viaide1:0
wdccommand viaide1:0:0: command=0xc4 cylin=0 head=64 sector=63 count=2 features=0
wdcintr
wdc_ata_bio_intr viaide1:0:0
__wdcwait viaide1:0
wdc_ata_bio_done viaide1:0:0: flags 0x0
wdc_ata_done: drv_done
wddone wd2
wdstart wd2
atastart from wdc_ata_done, flags 0x0
wdstrategy (wd2)
wdstart wd2
ata_exec_xfer 0xc1b44f88 channel 0 drive 0
atastart from ata_exec_xfer, flags 0x0
atastart: xfer 0xc1b44f88 channel 0 drive 0
wdc_ata_bio_start viaide1:0:0
_wdc_ata_bio_start viaide1:0:0
__wdcwait viaide1:0
wdccommandext viaide1:0:0: command=0x24 blkno=976773167 count=1
wdcintr
wdc_ata_bio_intr viaide1:0:0
__wdcwait viaide1:0
wdc_ata_bio_done viaide1:0:0: flags 0x0
wdc_ata_done: drv_done
wddone wd2
wdstart wd2
atastart from wdc_ata_done, flags 0x0
wdioctl
wdioctl
wdstrategy (wd2)
wdstart wd2
ata_exec_xfer 0xc1b44f88 channel 0 drive 0
atastart from ata_exec_xfer, flags 0x0
atastart: xfer 0xc1b44f88 channel 0 drive 0
wdc_ata_bio_start viaide1:0:0
wdc_ata_bio_start viaide1:0:0
__wdcwait viaide1:0
wdccommandshort viaide1:0:0 command 0x10
__wdcwait viaide1:0
__wdcwait: viaide1:0: timeout (time=11), status d0 error 0 (mask 0x40 bits 0x40)
__wdcwait viaide1:0
__wdcwait: viaide1:0: timeout (time=11), status d0 error 0 (mask 0x40 bits 0x40)
__wdcwait viaide1:0
__wdcwait: viaide1:0: timeout (time=11), status d0 error 0 (mask 0x40 bits 0x40)
__wdcwait viaide1:0
wdccommand viaide1:0:0: command=0xc6 cylin=0 head=0 sector=0 count=16 features=0
__wdcwait viaide1:0
__wdcwait: viaide1:0: did busy-wait, time=1
_wdc_ata_bio_start viaide1:0:0
__wdcwait viaide1:0
wdccommand viaide1:0:0: command=0xc4 cylin=0 head=64 sector=64 count=4 features=0
wdcintr
wdc_ata_bio_intr viaide1:0:0
__wdcwait viaide1:0
wdc_ata_bio_done viaide1:0:0: flags 0x0
wdc_ata_done: drv_done
wddone wd2
wdstart wd2
atastart from wdc_ata_done, flags 0x0
wdclose

=================================================
% atactl wd2 identify
Model: WDC WD5000AAKS-00YGA0, Rev: 12.01C02, Serial #:      WD-WCAS81254899
Device type: ATA, fixed
Device supports command queue depth of 31
Device capabilities:
	DMA
	LBA
	ATA standby timer values
	IORDY operation
	IORDY disabling
Device supports following standards:
ATA-1 ATA-2 ATA-3 ATA-4 ATA-5 ATA-6 ATA-7 
Command set support:
	NOP command (enabled)
	READ BUFFER command (enabled)
	WRITE BUFFER command (enabled)
	Host Protected Area feature set (enabled)
	look-ahead (enabled)
	write cache (enabled)
	Power Management feature set (enabled)
	Security Mode feature set (disabled)
	SMART feature set (enabled)
	FLUSH CACHE EXT command (enabled)
	FLUSH CACHE command (enabled)
	Device Configuration Overlay feature set (enabled)
	48-bit Address feature set (enabled)
	Automatic Acoustic Management feature set (disabled)
	SET MAX security extension (disabled)
	SET FEATURES required to spin-up after power-up (enabled)
	Power-Up In Standby feature set (disabled)
	DOWNLOAD MICROCODE command (enabled)
	World Wide name
	General Purpose Logging feature set
	SMART self-test
	SMART error logging
Serial ATA capabilities:
	1.5Gb/s signaling
	3.0Gb/s signaling
	Native Command Queuing
	Host-Initiated Interface Power Management
	PHY Event Counters
Serial ATA features:
	DMA Setup Auto Activate (disabled)
	Software Settings Preservation (enabled)