Re: High %wa, irregular blocking
> Hi
>
> On Wed, Jun 04, 2014 at 08:49:44AM +0200, b-misc@gmx.ch wrote:
> > Hi,
> >
> > Some weeks ago I installed Testing on my wife's iMac [1] from 2008.
> > Unfortunately it has one issue:
> >
> > There are irregular periods of very high %wa, maybe 3-5 times per hour,
> > not
> > directly related to a certain user action. They last for some seconds up
> > to
> > even a minute or so and render the machine unusable for that time. top
> > shows %wa of 80 or 90%, load can go up to 9 on this dual core machine,
> > iotop shows only a few KB/s.
>
> High wait-for-IO combined with very little disk throughput usually
> points towards disk problems...
>
> Anything interesting from e.g. "iostat -kNx" ? That should tell you
> which disk and partition is suffering. (Or if you already think you
> know, this should confirm it)
Well, I already had a look at hdparm, but everything looks ok.
Booting OSX there are no similar problems, so a cable problem doesn't seem to be the case.
I will have a look at iostat when there are huge hangs again (I'm a bit in a hurry now...)
>
> > I already added pcie_aspm=off to the boot options which seems to help,
> > but I still see this I/O hangs (without, I had about 10+ hangs per hour).
> >
> > Any idea what could cause these blockings? How can I find out more? I use
> > Linux for 15+ years but I never saw such things... and I want to show my
> > wife, that Linux is the better OS, of course... ;-)
>
> My first call would be the kernel logs. IIRC in the default syslog
> config this goes to /var/log/kern.log, but you can see the most recent
> output with e.g. "dmesg" or "dmesg -T"
$ grep ata kern.log:
Jun 5 19:50:02 Yucca kernel: [ 0.000000] BIOS-e820: [mem 0x00000000bfec5000-0x00000000bfec7fff] ACPI data
Jun 5 19:50:02 Yucca kernel: [ 0.000000] BIOS-e820: [mem 0x00000000bfedf000-0x00000000bfeeefff] ACPI data
Jun 5 19:50:02 Yucca kernel: [ 0.000000] ACPI: SSDT 00000000bfedf000 000137 (v01 APPLE SataAhci 00001000 INTL 20061109)
Jun 5 19:50:02 Yucca kernel: [ 0.000000] Memory: 3962208K/4190296K available (4811K kernel code, 693K rwdata, 1596K rodata, 984K init, 952K bss, 228088K reserved)
Jun 5 19:50:02 Yucca kernel: [ 0.088000] perf_event_intel: PEBS disabled due to CPU errata
Jun 5 19:50:02 Yucca kernel: [ 0.179283] ACPI : EC: GPE = 0x17, I/O: command/status = 0x66, data = 0x62
Jun 5 19:50:02 Yucca kernel: [ 1.641833] Write protecting the kernel read-only data: 8192k
Jun 5 19:50:02 Yucca kernel: [ 1.777770] libata version 3.00 loaded.
Jun 5 19:50:02 Yucca kernel: [ 1.800870] ata1: SATA max UDMA/133 abar m2048@0xd0704000 port 0xd0704100 irq 46
Jun 5 19:50:02 Yucca kernel: [ 1.800872] ata2: DUMMY
Jun 5 19:50:02 Yucca kernel: [ 1.800874] ata3: DUMMY
Jun 5 19:50:02 Yucca kernel: [ 1.800918] ata_piix 0000:00:1f.1: version 2.13
Jun 5 19:50:02 Yucca kernel: [ 1.802216] scsi3 : ata_piix
Jun 5 19:50:02 Yucca kernel: [ 1.802263] scsi4 : ata_piix
Jun 5 19:50:02 Yucca kernel: [ 1.802292] ata4: PATA max UDMA/100 cmd 0x4108 ctl 0x411c bmdma 0x40e0 irq 21
Jun 5 19:50:02 Yucca kernel: [ 1.802293] ata5: PATA max UDMA/100 cmd 0x4100 ctl 0x4118 bmdma 0x40e8 irq 21
Jun 5 19:50:02 Yucca kernel: [ 1.967781] ata4.00: ATAPI: MATSHITADVD-R UJ-875, DB09, max UDMA/66
Jun 5 19:50:02 Yucca kernel: [ 1.980376] ata4.00: configured for UDMA/66
Jun 5 19:50:02 Yucca kernel: [ 2.120029] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jun 5 19:50:02 Yucca kernel: [ 2.120893] ata1.00: ACPI cmd ef/90:03:00:00:00:a0 (SET FEATURES) rejected by device (Stat=0x51 Err=0x04)
Jun 5 19:50:02 Yucca kernel: [ 2.158384] ata1.00: ATA-8: WDC WD5000AAKS-40YGA0, 58.01E02, max UDMA/133
Jun 5 19:50:02 Yucca kernel: [ 2.158387] ata1.00: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA
Jun 5 19:50:02 Yucca kernel: [ 2.159267] ata1.00: ACPI cmd ef/90:03:00:00:00:a0 (SET FEATURES) rejected by device (Stat=0x51 Err=0x04)
Jun 5 19:50:02 Yucca kernel: [ 2.159469] ata1.00: configured for UDMA/133
Sometimes there are also several/many lines like:
May 20 18:50:09 XXX kernel: [ 1542.816063] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
May 20 18:50:09 XXX kernel: [ 1542.816073] ata1.00: failed command: READ DMA EXT
May 20 18:50:09 XXX kernel: [ 1542.816083] ata1.00: cmd 25/00:00:40:bc:cd/00:02:1d:00:00/e0 tag 0 dma 262144 in
May 20 18:50:09 XXX kernel: [ 1542.816083] res 40/00:00:00:4f:c2/00:00:00:00:00/00 Emask 0x4 (timeout)
May 20 18:50:09 XXX kernel: [ 1542.816088] ata1.00: status: { DRDY }
May 20 18:50:09 XXX kernel: [ 1542.816095] ata1: hard resetting link
May 20 18:50:09 XXX kernel: [ 1543.136059] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
May 20 18:50:09 XXX kernel: [ 1543.136992] ata1.00: ACPI cmd ef/90:03:00:00:00:a0 (SET FEATURES) rejected by device (Stat=0x51 Err=0x04)
May 20 18:50:10 XXX kernel: [ 1543.168706] ata1.00: ACPI cmd ef/90:03:00:00:00:a0 (SET FEATURES) rejected by device (Stat=0x51 Err=0x04)
May 20 18:50:10 XXX kernel: [ 1543.168840] ata1.00: configured for UDMA/133
May 20 18:50:10 XXX kernel: [ 1543.168848] ata1.00: device reported invalid CHS sector 0
May 20 18:50:10 XXX kernel: [ 1543.168868] ata1: EH complete
May 20 18:53:29 XXX kernel: [ 1742.816060] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
May 20 18:53:29 XXX kernel: [ 1742.816070] ata1.00: failed command: READ DMA EXT
May 20 18:53:29 XXX kernel: [ 1742.816079] ata1.00: cmd 25/00:00:40:db:cd/00:02:1d:00:00/e0 tag 0 dma 262144 in
May 20 18:53:29 XXX kernel: [ 1742.816079] res 40/00:00:00:4f:c2/00:00:00:00:00/00 Emask 0x4 (timeout)
May 20 18:53:29 XXX kernel: [ 1742.816084] ata1.00: status: { DRDY }
May 20 18:53:29 XXX kernel: [ 1742.816092] ata1: hard resetting link
May 20 18:53:29 XXX kernel: [ 1743.136059] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
May 20 18:53:29 XXX kernel: [ 1743.137023] ata1.00: ACPI cmd ef/90:03:00:00:00:a0 (SET FEATURES) rejected by device (Stat=0x51 Err=0x04)
May 20 18:53:30 XXX kernel: [ 1743.176409] ata1.00: ACPI cmd ef/90:03:00:00:00:a0 (SET FEATURES) rejected by device (Stat=0x51 Err=0x04)
May 20 18:53:30 XXX kernel: [ 1743.176547] ata1.00: configured for UDMA/133
May 20 18:53:30 XXX kernel: [ 1743.176556] ata1.00: device reported invalid CHS sector 0
May 20 18:53:30 XXX kernel: [ 1743.176577] ata1: EH complete
May 20 18:54:00 XXX kernel: [ 1773.920067] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
May 20 18:54:00 XXX kernel: [ 1773.920077] ata1.00: failed command: READ DMA EXT
May 20 18:54:00 XXX kernel: [ 1773.920087] ata1.00: cmd 25/00:00:40:db:cd/00:02:1d:00:00/e0 tag 0 dma 262144 in
May 20 18:54:00 XXX kernel: [ 1773.920087] res 40/00:00:00:4f:c2/00:00:00:00:00/00 Emask 0x4 (timeout)
May 20 18:54:00 XXX kernel: [ 1773.920092] ata1.00: status: { DRDY }
May 20 18:54:00 XXX kernel: [ 1773.920099] ata1: hard resetting link
May 20 18:54:01 XXX kernel: [ 1774.240071] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
May 20 18:54:01 XXX kernel: [ 1774.241054] ata1.00: ACPI cmd ef/90:03:00:00:00:a0 (SET FEATURES) rejected by device (Stat=0x51 Err=0x04)
May 20 18:54:01 XXX kernel: [ 1774.277500] ata1.00: ACPI cmd ef/90:03:00:00:00:a0 (SET FEATURES) rejected by device (Stat=0x51 Err=0x04)
May 20 18:54:01 XXX kernel: [ 1774.277643] ata1.00: configured for UDMA/133
May 20 18:54:01 XXX kernel: [ 1774.277652] ata1.00: device reported invalid CHS sector 0
May 20 18:54:01 XXX kernel: [ 1774.277677] ata1: EH complete
So there _is_ a problem - but what'n'why?
>
> Combine this with the disk-related snippets from /var/log/dmesg (which
> has the kernel output from boot) and you may see further clues...
>
> Which kernel are you using? Stock kernel, or self-compiled? 32bit?
> 64bit?
x86_64 Debian default kernel.
>
> The firmware version may also be relevant here.
>
> > Aside from that issue everything runs quite nicely.
> >
> > Thanks & best regards,
> > Bernd
> >
> > [1] iMac 8,1: 2008, Core 2 Duo 2.8 GHz, GB RAM, 500 GB WD HDD, ATI Radeon
> > HD
> > 2600 PRO (PCIe)
>
> Looks similar to this one? http://www.odi.ch/prog/macbookpro/#3
A bit...
Thanks a lot for further ideas!
Best regards,
Bernd
>
> Hope this helps
> --
> Karl E. Jorgensen
Reply to: