libata problems with 66Mhz Promise SATA150 TX4

libata problems with 66Mhz Promise SATA150 TX4

[Paul Fisher]

We're experiencing failures on a Promise SATA150 TX4 when run at 66Mhz
on either PCI-X bus on a Tyan S2882 (dual Opteron system).  The
problems manifest themselves rather quickly on an SMP-enabled kernel,
and it takes a bit longer to kill a non-SMP kernel.

We've tried swapping out the motherboard, hard drives (for the same
brand however -- Western Digital), as well as the SATA cables.

The only way we can get a stable system is to run the SATA150 TX4 off
the 33Mhz PCI bus.

Accessing the drives by building a RAID-5 array across four drives
will kill the machine in about 10 minutes.

During the array build, we sometimes receive error messages of:

ataX: status=0x51 { DriveReady, SeekComplete, Error }
ataX: called with no error (51)!

... and then we eventually get:

ataX: command timeout

After the command timeout, we immediately get a fatal Machine Check
Exception.  Turning on ATA_DEBUG and ATA_VERBOSE_DEBUG while using a
serial console causes the machine to die in a different way, as soon
as mdadm starts running.  (With debugging on, the machine dies in the
normal (command timeout) way if we're not using the serial console.)

We've tested 2.6.8, 2.6.9-rc1, and 2.6.9-rc1-bk16.

Below is relevant output from 2.6.9-rc1 along with the MCE following a
command timeout.  Other dumps of PCI information, kernel config, and
full serial console logs are at <URL:http://www.gnu.org/promise/>.

Mounted /pata1: SATA max UDMA/133 cmd 0xFFFFFF0000016200 ctl 0xFFFFFF0000016238 bmdma 0x0 irq 201
roc filesystem
ata2: SATA max UDMA/133 cmd 0xFFFFFF0000016280 ctl 0xFFFFFF00000162B8 bmdma 0x0 irq 201
Mounting sysfs
ata3: SATA max UDMA/133 cmd 0xFFFFFF0000016300 ctl 0xFFFFFF0000016338 bmdma 0x0 irq 201
Loading scsi_modata4: SATA max UDMA/133 cmd 0xFFFFFF0000016380 ctl 0xFFFFFF00000163B8 bmdma 0x0 irq 201
.ko module
Loading sd_mod.ko module
Loading libata.ko module
Loading sata_promise.ko module
ata1: dev 0 ATA, max UDMA/133, 488397168 sectors: lba48
ata1: dev 0 configured for UDMA/133
scsi0 : sata_promise
ata2: dev 0 ATA, max UDMA/133, 488397168 sectors: lba48
ata2: dev 0 configured for UDMA/133
scsi1 : sata_promise
ata3: dev 0 ATA, max UDMA/133, 488397168 sectors: lba48
ata3: dev 0 configured for UDMA/133
scsi2 : sata_promise
ata4: dev 0 ATA, max UDMA/133, 488397168 sectors: lba48
ata4: dev 0 configured for UDMA/133
scsi3 : sata_promise
  Vendor: ATA       Model: WDC WD2500SD-01K  Rev: 08.0
  Type:   Direct-Access                      ANSI SCSI revision: 05
SCSI device sda: 488397168 512-byte hdwr sectors (250059 MB)
SCSI device sda: drive cache: write back
 sda: sda1 sda2 sda3
Attached scsi disk sda at scsi0, channel 0, id 0, lun 0
  Vendor: ATA       Model: WDC WD2500SD-01K  Rev: 08.0
  Type:   Direct-Access                      ANSI SCSI revision: 05
SCSI device sdb: 488397168 512-byte hdwr sectors (250059 MB)
SCSI device sdb: drive cache: write back
 sdb: sdb1 sdb2 sdb3
Attached scsi disk sdb at scsi1, channel 0, id 0, lun 0
  Vendor: ATA       Model: WDC WD2500SD-01K  Rev: 08.0
  Type:   Direct-Access                      ANSI SCSI revision: 05
SCSI device sdc: 488397168 512-byte hdwr sectors (250059 MB)
SCSI device sdc: drive cache: write back
 sdc: sdc1 sdc2 sdc3
Attached scsi disk sdc at scsi2, channel 0, id 0, lun 0
  Vendor: ATA       Model: WDC WD2500SD-01K  Rev: 08.0
  Type:   Direct-Access                      ANSI SCSI revision: 05
SCSI device sdd: 488397168 512-byte hdwr sectors (250059 MB)
SCSI device sdd: drive cache: write back
 sdd: sdd1 sdd2 sdd3
Attached scsi disk sdd at scsi3, channel 0, id 0, lun 0

[...]

ata4: command timeout
CPU 0: Machine Check Exception:                4 Bank 4: b200000000070f0f
RIP !INEXACT! 10:<ffffffffa00244d7> {ata_check_status_mmio+0x7/0x10 [libata]}
TSC 84a68e655e 
Kernel panic - not syncing: Machine check
 Badness in smp_call_function at arch/x86_64/kernel/smp.c:408

Call Trace:<ffffffff8011cdad>{smp_call_function+109} <ffffffff8011cee9>{smp_send_stop+25} 
<ffffffff801381bc>{panic+204} <ffffffff80118140>{mce_available+0} 
<ffffffff8011851b>{do_machine_check+939} <ffffffffa00244d7>{:libata:ata_check_status_mmio+7} 
<ffffffffa00244d7>{:libata:ata_check_status_mmio+7} 
<ffffffff801116eb>{machine_check+127} <ffffffffa00244d7>{:libata:ata_check_status_mmio+7} 
 <EOE> <ffffffffa002f3c8>{:sata_promise:pdc_eng_timeout+136} 
       <ffffffffa00282d2>{:libata:ata_scsi_error+18} <ffffffffa0004152>{:scsi_mod:scsi_error_handler+434} 
       <ffffffff801111b3>{child_rip+8} <ffffffffa0003fa0>{:scsi_mod:scsi_error_handler+0} 
       <ffffffff801111ab>{child_rip+0} 
divide error: 0000 [1] SMP 
CPU 0 
Modules linked in: raid5 xor md5 ipv6 usbserial parport_pc lp parport autofs4 ds yenta_socket pcmcia_core e100 mii tg3 ipt_REJECT ipt_state ip_conntrack iptable_filter ip_tables floppy sg dm_mod ohci_hcd button battery asus_acpi ac ext3 jbd sata_promise libata sd_mod scsi_mod
Pid: 206, comm: scsi_eh_3 Not tainted 2.6.9-rc1
RIP: 0010:[<ffffffff80133e50>] <ffffffff80133e50>{scheduler_tick+1024}
RSP: 0018:ffffffff803ef668  EFLAGS: 00010046
RAX: 000000000000004e RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff803f7508
RBP: ffffffff803ef698 R08: 00000000000927bf R09: 000000000000000a
R10: 0000000000000000 R11: 0000000000000000 R12: 000000000000004e
R13: 000001007fc2eab0 R14: 0000010002c20560 R15: 0000000000000000
FS:  0000002a958624c0(0000) GS:ffffffff80461b00(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000002a956f1bf0 CR3: 0000000000101000 CR4: 00000000000006e0
Process scsi_eh_3 (pid: 206, threadinfo 000001007f344000, task 000001007fc2eab0)
Stack: 0000000000000092 ffffffff8033462f ffffffff80379bc0 0000000000000000 
       00000084a68e5f44 ffffffff8033462f 00000000ffffffff ffffffff8011d6b4 
       0000000000000046 ffffffff80110eab 
Call Trace:<IRQ> <ffffffff8011d6b4>{smp_apic_timer_interrupt+52} <ffffffff80110eab>{apic_timer_interrupt+99} 
        <EOI> <ffffffff8011ceb0>{smp_really_stop_cpu+0} <ffffffff8011ceaf>{smp_stop_cpu+31} 
       <ffffffff801381bc>{panic+204} <ffffffff80118140>{mce_available+0} 
       <ffffffff8011851b>{do_machine_check+939} <ffffffffa00244d7>{:libata:ata_check_status_mmio+7} 
       <ffffffffa00244d7>{:libata:ata_check_status_mmio+7} 
       <ffffffff801116eb>{machine_check+127} <ffffffffa00244d7>{:libata:ata_check_status_mmio+7} 
       <ffffffff8010e9a0>{default_idle+0} 

Code: f7 f3 85 d2 0f 85 a6 00 00 00 be 08 00 00 00 48 c7 c7 08 75 
RIP <ffffffff80133e50>{scheduler_tick+1024} RSP <ffffffff803ef668>
 <0>Kernel panic - not syncing: Aiee, killing interrupt handler!

Re: libata problems with 66Mhz Promise SATA150 TX4

[Marc Bevand]

Paul Fisher wrote:
> We're experiencing failures on a Promise SATA150 TX4 when run at 66Mhz
> on either PCI-X bus on a Tyan S2882 (dual Opteron system).  The
> problems manifest themselves rather quickly on an SMP-enabled kernel,
> and it takes a bit longer to kill a non-SMP kernel.
> [...]
> The only way we can get a stable system is to run the SATA150 TX4 off
> the 33Mhz PCI bus.
> [...]
> We've tested 2.6.8, 2.6.9-rc1, and 2.6.9-rc1-bk16.
> [...]
> CPU 0: Machine Check Exception:                4 Bank 4: b200000000070f0f

I have *exactly* the same problem (MCE b200000000070f0f, which indicates
a watchdog timer timeout), on the same hardware (Promise SATA150 TX4).
Like you, I get the problem only when using a 66MHz PCI bus (no problem
at 33MHz). Like you, the stack trace indicate the problem comes from
the Promise hardware. And like you the watchdog timeout is much harder
to reproduce with a non-SMP kernel.

Here is a short summary of my config:
  - Dual Opteron 244
  - Tyan S2885
  - 4 x 133MHz/64-bit PCI-X slots
  - 1 x 33MHz/32-bit PCI slot
  - Promise SATA150 TX4,
    running at either 66MHz (PCI-X slot), or 33MHz (PCI slot)
  - 4 x Seagate 160Go 7200 RPM S-ATA Barracuda 7200.7

An easy way to reproduce the problem is to run 4 instances of 'dd' reading
from 4 disks at the same time. It is much harder to reproduce when reading
from 3 disks, and quasi-impossible to reproduce when reading from 2 disks.

I have tried kernels 2.6.5 and 2.6.9-rc1 (arch x86_64). I have tried the
latest BIOS for my motherboard, the latest BIOS for the Promise card, and
all the PCI-X slots of the motherboard.

It seems the Promise chip has some problems under high-load conditions:
the throughput I obtain when reading from 4 disks is 100 MB/s (at 33MHz)
and 215 MB/s (at 66MHz)...

I contacted the Promise support some months ago, but they "did not get
this issue before", and finally they told me they "do not support 64 bit
or even PCI-X slots [for this model]" :-/

Actually I would be very interested to know if *anybody* is successfully
using this card at 66MHz with 3 or 4 disks attached to it.

-- 
Marc Bevand                          http://www.epita.fr/~bevand_m
Computer Science School EPITA - System, Network and Security Dept.

Re: libata problems with 66Mhz Promise SATA150 TX4

[Jeff Garzik]

Marc Bevand wrote:
> Actually I would be very interested to know if *anybody* is successfully
> using this card at 66MHz with 3 or 4 disks attached to it.


I'll try to hunt down a PCI-X bus or similar and test, this is the first 
set of reports I've heard of this type.

	Jeff

Re: libata problems with 66Mhz Promise SATA150 TX4

[Andy Warner]

Marc Bevand wrote:
> [...]
> An easy way to reproduce the problem is to run 4 instances of 'dd' reading
> from 4 disks at the same time. It is much harder to reproduce when reading
> from 3 disks, and quasi-impossible to reproduce when reading from 2 disks.

I've tried, but cannot reproduce it here.

System is:
 - Dual Xeon Dell Poweredge 2600
 - Promise TX4 in 100MHz PCI-X slot.
 - 4 x Seagate ST3160023AS
 - 2.6.9-rc1

I've tried both dd and sg_utils, can't make it fail - no way, no how.

> [...]
> It seems the Promise chip has some problems under high-load conditions:
> the throughput I obtain when reading from 4 disks is 100 MB/s (at 33MHz)
> and 215 MB/s (at 66MHz)...

I'm observing a lower throughput than that, though ~60MB/s; so I'm
going to check to see if there is something else throttling
performance, below the point of failure.
-- 
andyw@pobox.com

Andy Warner		Voice: (612) 801-8549	Fax: (208) 575-5634

Re: libata problems with 66Mhz Promise SATA150 TX4

[Marc Bevand]

Andy Warner wrote:
| [...]
| I'm observing a lower throughput than that, though ~60MB/s; so I'm
| going to check to see if there is something else throttling
| performance, below the point of failure.

Personally, I am using a blocksize of 32k with 'dd' in order to reach
215 MB/s, and I set the readahead to 256 on all the disks:

  $ blockdev --setra 256 /dev/sdX

To satisfy my curiosity, could you sent me an excerpt of 'vmstat 1' while
stressing your disks like this ? Thanks.

-- 
Marc Bevand                          http://www.epita.fr/~bevand_m
Computer Science School EPITA - System, Network and Security Dept.

Re: libata problems with 66Mhz Promise SATA150 TX4

[Andy Warner]

Marc Bevand wrote:
> Andy Warner wrote:
> | [...]
> | I'm observing a lower throughput than that, though ~60MB/s; so I'm
> | going to check to see if there is something else throttling
> | performance, below the point of failure.
> 
> Personally, I am using a blocksize of 32k with 'dd' in order to reach
> 215 MB/s, and I set the readahead to 256 on all the disks:
> 
>   $ blockdev --setra 256 /dev/sdX
> 
> To satisfy my curiosity, could you sent me an excerpt of 'vmstat 1' while
> stressing your disks like this ? Thanks.

I reconfigured the system so the TX4 was the only adapter on
the 100MHz PCI-X bus, and re-ran the tests - I'm now seeing ~200MB/s
with dd (bs=1M) and ~110MB/s with sg_utils. It ran for 9 hours
overnight without error.

Here's the vmstat output you requested.

First using dd to read the disks:
procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy id wa
 1  4      0 1067520 856456  71224    0    0   225     3   18   166  0 20 50 30
 1  3      0 1067584 856360  71320    0    0 195320   188 2845  3685  0 23 49 29
 1  3      0 1066640 857356  71364    0    0 196352     4 2806  3703  0 22 51 26
 3  2      0 1066688 857252  71208    0    0 194688    32 2781  3633  0 23 52 25
 1  3      0 1067712 856380  71040    0    0 195712     0 2810  3667  0 23 51 26
 0  4      0 1066624 857392  71068    0    0 190976    16 2762  3564  0 23 51 27
 0  4      0 1067840 856172  71248    0    0 196864     0 2825  3696  0 23 49 28
 4  2      0 1066368 857496  70964    0    0 193792    36 2770  3613  0 22 52 26
 1  4      0 1067648 856388  71292    0    0 195200     0 2772  3586  0 23 53 25
 1  3      0 1066752 857348  71112    0    0 193832    44 2793  3596  0 22 52 26
 1  4      0 1068104 855976  71184    0    0 196952    32 2846  3729  0 23 45 32
 0  4      0 1067272 856848  71092    0    0 197120     0 2812  3689  0 24 47 30
 3  2      0 1066696 857392  71328    0    0 195368    24 2806  3675  0 23 48 30
 0  4      0 1067208 856880  71060    0    0 195160     0 2801  3688  0 23 48 29
 1  3      0 1066364 857732  71248    0    0 195584     4 2835  3695  0 23 44 33
 2  3      0 1067656 856496  71184    0    0 196864     0 2899  3831  0 24 37 39
 2  3      0 1067656 856464  70956    0    0 195200     0 2833  3708  0 24 41 35
 0  4      0 1066784 857312  71148    0    0 194688    24 2840  3718  0 24 42 34
 1  3      0 1067672 856516  71164    0    0 195512     0 2860  3717  0 24 40 37
 3  2      0 1066584 857572  71148    0    0 197448     0 2814  3706  0 24 48 28
 1  3      0 1067608 856520  71160    0    0 195840     0 2812  3644  0 23 49 28

Now using sg_utils to read the disks:
procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy id wa
 0  0      0 1927480   1752  74688    0    0   195     3   63   221  0 20 50 30
 0  0      0 1927480   1752  74688    0    0     0     0 10576 18441  2  8 90  0
 0  0      0 1927480   1752  74688    0    0     0     0 10700 18677  2  8 90  0
 0  0      0 1927480   1752  74688    0    0     0     0 10668 18609  2  8 90  0
 0  0      0 1927480   1752  74688    0    0     0     0 10770 18773  1  9 89  0
 0  1      0 1927480   1760  74680    0    0     0    40 10753 18747  2  8 90  0
 2  0      0 1927480   1760  74680    0    0     0     0 10682 18605  2  9 90  0
 2  0      0 1927480   1760  74680    0    0     0     0 10571 18342  2  9 88  0
 0  0      0 1927480   1760  74680    0    0     0     0 10618 18515  2  8 90  0
 0  0      0 1927480   1760  74680    0    0     0     0 10564 18311  2  9 90  0
 0  0      0 1927480   1760  74680    0    0     0     0 10764 18736  2  9 89  0
 1  0      0 1927480   1760  74680    0    0     0     0 10640 18513  2  9 89  0
 0  0      0 1927480   1760  74680    0    0     0     0 10836 18908  2  9 89  0
 0  0      0 1927480   1760  74680    0    0     0     0 10795 18805  1  8 90  0
 0  0      0 1927480   1760  74680    0    0     0     0 10676 18616  2  8 90  0
 1  0      0 1927480   1760  74680    0    0     0     0 10529 18346  2  8 89  0
 1  0      0 1927480   1760  74680    0    0     0     0 10727 18728  2  8 90  0
 0  0      0 1927480   1760  74680    0    0     0     0 10627 18534  2  9 90  0
 0  0      0 1927480   1760  74680    0    0     0     0 10676 18640  2  8 90  0

-- 
andyw@pobox.com

Andy Warner		Voice: (612) 801-8549	Fax: (208) 575-5634

Re: libata problems with 66Mhz Promise SATA150 TX4

[Marc Bevand]

Andy Warner wrote:
| 
| I reconfigured the system so the TX4 was the only adapter on
| the 100MHz PCI-X bus, and re-ran the tests - I'm now seeing ~200MB/s
| with dd (bs=1M) and ~110MB/s with sg_utils. It ran for 9 hours
| overnight without error.

Hmm. I am disappointed :-/

What the hell could be the problem on Paul's system and mine ?
Both of us have a Tyan motherboard (but not the same model).
Common points are:

  - Dual-opteron (the watchdog timeout error is reported by the
    northbridge, built-in the cpu)
  - Hypertransport bus
  - AMD-8131 PCI-X tunnel chip

| Here's the vmstat output you requested.
| [...]

Thanks.

-- 
Marc Bevand                          http://www.epita.fr/~bevand_m
Computer Science School EPITA - System, Network and Security Dept.

Generic bug/race in the IDE/SATA code ?

[Marc Bevand]

On 2004-09-15, Marc Bevand <bevand_m@epita.fr> wrote:
|  What the hell could be the problem on Paul's system and mine ?
|  Both of us have a Tyan motherboard (but not the same model).

I realize our problem is very similar to this one (excerpt from
linux-x86_64 release notes):

  Reports that dual Tyan S2885 and S2880 can lock up when multiple IDE channels
  are stressed in parallel. "noapic" or "ideFOO=serialize" seems to work
  around it. Andre Hedrick thinks it's a generic bug/race in the IDE code.

(appart the fact we are stressing SATA channels, and that "noapic"
does not work around the problem for me).

I have done an interesting experiment: conduct the exact same test
under another OS, FreeBSD/amd64 (5.2.1, SMP kernel). The result is
that it works perfectly: the Promise card outputs data at the
continuous rate of 210 MB/s and the system never locks up even after
25min of activity (while it takes about 30sec to happen under Linux).

So is this a generic bug/race in the Linux IDE/SATA code ?

-- 
Marc Bevand                          http://www.epita.fr/~bevand_m
Computer Science School EPITA - System, Network and Security Dept.