2.6.11: iostat values broken ?

2.6.11: iostat values broken ?

[Miquel van Smoorenburg]

I just upgrades one of our newsservers from 2.6.9 to 2.6.11. I
use "iostat -k -x 2" to see live how busy the disks are. But
I don't believe that Linux optimizes things so much that a disk
can be 1849.55% busy :)

(you'll have to stretch out your xterm to be able to read this):

Device:    rrqm/s wrqm/s   r/s   w/s  rsec/s  wsec/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util
hda          0.00  50.00  0.00 18.18    0.00  545.45     0.00   272.73    30.00     2.35  129.00  86.25 156.82
hdc          0.00  45.45 77.27 31.82 3927.27  618.18  1963.64   309.09    41.67     6.27   57.42  38.42 419.09
hdd          4.55   0.00 63.64  0.00   68.18    0.00    34.09     0.00     1.07     1.11   17.43  17.43 110.91
hde        477.27   0.00 45.45  0.00  522.73    0.00   261.36     0.00    11.50     0.40    8.90   8.90  40.45
hdg         18.18 70154.55 22.73 172.73   40.91 70727.27    20.45 35363.64   362.07  1010.36 1127.72  94.63 1849.55

With 2.6.9, %util never came above 100% (and that was indeed "fully loaded".
I have systems with a comparable load running 2.6.10 and 2.6.11-rc3-bk4
that also don't show this behaviour (but those are SCSI, not IDE).

I use CFQ, but changing that to deadline doesn't make a difference.

Mike.

Re: 2.6.11: iostat values broken, or IDE siimage driver ?

[Miquel van Smoorenburg]

In article <d053g8$6et$1@news.cistron.nl>,
Miquel van Smoorenburg <miquels@cistron.nl> wrote:
>I just upgrades one of our newsservers from 2.6.9 to 2.6.11. I
>use "iostat -k -x 2" to see live how busy the disks are. But
>I don't believe that Linux optimizes things so much that a disk
>can be 1849.55% busy :)
>

The stats also show 10-30 MB/sec writes to the disks, which make
no sense at all. The system feels very slow and (being a usenet
news server) can only keep up with about 8 mbit/sec (so it should
in this case write 1 MB/sec to all disks combined).

Perhaps this is the cause:

Mar  2 19:55:25 hdg: sata_error = 0x00000000, watchdog = 0, siimage_mmio_ide_dma_test_irq
Mar  2 19:55:26 quantum last message repeated 12 times
hdg: sata_error = 0x00000000, watchdog = 0, siimage_mmio_ide_dma_test_irq
Mar  2 19:55:57 quantum last message repeated 172 times
Mar  2 19:56:58 quantum last message repeated 551 times
Mar  2 19:57:59 quantum last message repeated 517 times
Mar  2 19:59:00 quantum last message repeated 608 times
.. etc etc ..

I have a serial console attached, so that probably explains why
the system feels so slow when it is spewing these errors (but
it doesn't explain the weird iostat values, or does it ?)

This is the config:

ICH5-SATA: not 100%% native mode: will probe irqs later
    ide0: BM-DMA at 0xfc00-0xfc07, BIOS settings: hda:DMA, hdb:pio
    ide1: BM-DMA at 0xfc08-0xfc0f, BIOS settings: hdc:DMA, hdd:DMA
Probing IDE interface ide0...
hda: Maxtor 6Y080L0, ATA DISK drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Probing IDE interface ide1...
hdc: Maxtor 6Y080M0, ATA DISK drive
hdd: Maxtor 6Y080M0, ATA DISK drive
ide1 at 0x170-0x177,0x376 on irq 15
SiI3112 Serial ATA: IDE controller at PCI slot 0000:03:03.0
ACPI: PCI interrupt 0000:03:03.0[A] -> GSI 19 (level, low) -> IRQ 19
SiI3112 Serial ATA: chipset revision 2
SiI3112 Serial ATA: 100%% native mode on irq 19
    ide2: MMIO-DMA , BIOS settings: hde:pio, hdf:pio
    ide3: MMIO-DMA , BIOS settings: hdg:pio, hdh:pio
Probing IDE interface ide2...
hde: Maxtor 6Y080M0, ATA DISK drive
ide2 at 0xf8802e80-0xf8802e87,0xf8802e8a on irq 19
Probing IDE interface ide3...
hdg: Maxtor 6Y080M0, ATA DISK drive
ide3 at 0xf8802ec0-0xf8802ec7,0xf8802eca on irq 19
Probing IDE interface ide4...
Probing IDE interface ide5...
hda: max request size: 128KiB
hda: 160086528 sectors (81964 MB) w/2048KiB Cache, CHS=65535/16/63, UDMA(100)
hda: cache flushes supported
 hda: hda1 hda2 hda3 < hda5 hda6 hda7 >
hdc: max request size: 128KiB
hdc: 160086528 sectors (81964 MB) w/7936KiB Cache, CHS=65535/16/63, UDMA(33)
hdc: cache flushes supported
 hdc: hdc1 hdc2
hdd: max request size: 128KiB
hdd: 160086528 sectors (81964 MB) w/7936KiB Cache, CHS=65535/16/63, UDMA(33)
hdd: cache flushes supported
 hdd: hdd1
hde: max request size: 64KiB
hde: 160086528 sectors (81964 MB) w/7936KiB Cache, CHS=65535/16/63
hde: cache flushes supported
 hde: hde1
hdg: max request size: 64KiB
hdg: 160086528 sectors (81964 MB) w/7936KiB Cache, CHS=65535/16/63
hdg: cache flushes supported
 hdg:<4>hdg: sata_error = 0x00000000, watchdog = 0, siimage_mmio_ide_dma_test_irq
 hdg1

I've now rebooted to 2.6.9 and that kernel runs just fine.

Mike.

Re: 2.6.11: iostat values broken, or IDE siimage driver ?

[Rick Lindsley]

Mike -- where did you get your iostat from?  There's a couple of different
flavors out there and it may not make a difference but just in case ...

Rick

Re: 2.6.11: iostat values broken, or IDE siimage driver ?

[Miquel van Smoorenburg]

In article <200503022202.j22M2KUK020376@owlet.beaverton.ibm.com>,
Rick Lindsley  <ricklind@us.ibm.com> wrote:
>Mike -- where did you get your iostat from?  There's a couple of different
>flavors out there and it may not make a difference but just in case ...

Debian, sysstat+5.0.6-4

I know about the iostat problems - there were 32/64 bit issues,
etc - but those have been solved in this version. Also the exact
same iostat works fine on 2.6.10 and 2.6.11-rc3 kernels.

Mike.

Re: 2.6.11: iostat values broken, or IDE siimage driver ?

[Miquel van Smoorenburg]

In article <d05513$8fr$1@news.cistron.nl>,
Miquel van Smoorenburg <miquels@cistron.nl> wrote:
>In article <d053g8$6et$1@news.cistron.nl>,
>Miquel van Smoorenburg <miquels@cistron.nl> wrote:
>>I just upgrades one of our newsservers from 2.6.9 to 2.6.11. I
>>use "iostat -k -x 2" to see live how busy the disks are. But
>>I don't believe that Linux optimizes things so much that a disk
>>can be 1849.55% busy :)
>
>Perhaps this is the cause:
>
>Mar  2 19:55:25 hdg: sata_error = 0x00000000, watchdog = 0,
>siimage_mmio_ide_dma_test_irq
>Mar  2 19:55:26 quantum last message repeated 12 times
>hdg: sata_error = 0x00000000, watchdog = 0, siimage_mmio_ide_dma_test_irq

I just recompiled and reconfigured with libata sata_sil.c instead
of ide siimage.c, and now everything just works fine.

I just noticed this in dmesg:

** PCI interrupts are no longer routed automatically.  If this
** causes a device to stop working, it is probably because the
** driver failed to call pci_enable_device().  As a temporary
** workaround, the "pci=routeirq" argument restores the old
** behavior.  If this argument makes the device work again,
** please email the output of "lspci" to bjorn.helgaas@hp.com
** so I can fix the driver.

.. so perhaps that might causing siimage.c to break, but this
being a production server now catching up with a backlog I can't
try it right away.

Mike.

Re: 2.6.11: iostat values broken ?

[Andrew Morton]

"Miquel van Smoorenburg" <miquels@cistron.nl> wrote:
>
> I just upgrades one of our newsservers from 2.6.9 to 2.6.11. I
> use "iostat -k -x 2" to see live how busy the disks are. But
> I don't believe that Linux optimizes things so much that a disk
> can be 1849.55% busy :)
> 
> (you'll have to stretch out your xterm to be able to read this):
> 
> Device:    rrqm/s wrqm/s   r/s   w/s  rsec/s  wsec/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util
> hda          0.00  50.00  0.00 18.18    0.00  545.45     0.00   272.73    30.00     2.35  129.00  86.25 156.82
> hdc          0.00  45.45 77.27 31.82 3927.27  618.18  1963.64   309.09    41.67     6.27   57.42  38.42 419.09
> hdd          4.55   0.00 63.64  0.00   68.18    0.00    34.09     0.00     1.07     1.11   17.43  17.43 110.91
> hde        477.27   0.00 45.45  0.00  522.73    0.00   261.36     0.00    11.50     0.40    8.90   8.90  40.45
> hdg         18.18 70154.55 22.73 172.73   40.91 70727.27    20.45 35363.64   362.07  1010.36 1127.72  94.63 1849.55
> 
> With 2.6.9, %util never came above 100% (and that was indeed "fully loaded".
> I have systems with a comparable load running 2.6.10 and 2.6.11-rc3-bk4
> that also don't show this behaviour (but those are SCSI, not IDE).
> 
> I use CFQ, but changing that to deadline doesn't make a difference.
> 

Mike, did you ever get to the bottom of this?  Still happening in 2.6.12-rc1?

Re: 2.6.11: iostat values broken ?

[Miquel van Smoorenburg]

On Mon, 21 Mar 2005 23:09:42, Andrew Morton wrote:
> "Miquel van Smoorenburg" <miquels@cistron.nl> wrote:
> >
> > I just upgrades one of our newsservers from 2.6.9 to 2.6.11. I
> > use "iostat -k -x 2" to see live how busy the disks are. But
> > I don't believe that Linux optimizes things so much that a disk
> > can be 1849.55% busy :)
> > 
> > (you'll have to stretch out your xterm to be able to read this):
> > 
> > Device:    rrqm/s wrqm/s   r/s   w/s  rsec/s  wsec/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util
> > hda          0.00  50.00  0.00 18.18    0.00  545.45     0.00   272.73    30.00     2.35  129.00  86.25 156.82
> > hdc          0.00  45.45 77.27 31.82 3927.27  618.18  1963.64   309.09    41.67     6.27   57.42  38.42 419.09
> > hdd          4.55   0.00 63.64  0.00   68.18    0.00    34.09     0.00     1.07     1.11   17.43  17.43 110.91
> > hde        477.27   0.00 45.45  0.00  522.73    0.00   261.36     0.00    11.50     0.40    8.90   8.90  40.45
> > hdg         18.18 70154.55 22.73 172.73   40.91 70727.27    20.45 35363.64   362.07  1010.36 1127.72  94.63 1849.55
> > 
> > With 2.6.9, %util never came above 100% (and that was indeed "fully loaded".
> > I have systems with a comparable load running 2.6.10 and 2.6.11-rc3-bk4
> > that also don't show this behaviour (but those are SCSI, not IDE).
> > 
> > I use CFQ, but changing that to deadline doesn't make a difference.
> > 
> 
> Mike, did you ever get to the bottom of this?  Still happening in 2.6.12-rc1?

Sortof... (I already posted this before:) the siimage.c driver was broken for me with
2.6.11. Lots of IDE warning messages to /dev/console @ 9600 baud also makes
things slow and weird. I couldn't find what caused this, though, there
weren't much (if any) changes in siimage.c so it must have been something
different. Perhaps the IRQ changes.

I moved to sata_sil.c and everything now works fine. I tried sata_sil around 2.6.5
or so, and it was very unstable, but I was pleasantly surprised to see that
the new SATA code has come a long way.

So I still don't know what the _actual_ problem was, but the solution is
"use libata instead of the old IDE driver". As "make menuconfig" tells you
something similar it's probably an acceptable solution.

Mike.