# Extremely high IO wait

## vinz

hello

I have a box running which all the time has extremely high IO wait on a 250gb SATA I disk. 

I have recompiled a lot of libraries and core packages, tried different kernels and options.

Any ideas what the cause is?

```

 # hdparm -tT /dev/sda

/dev/sda:

 Timing cached reads:   1280 MB in  2.00 seconds = 639.80 MB/sec

 Timing buffered disk reads:  162 MB in  3.03 seconds =  53.51 MB/sec

# time emerge -pv portage

These are the packages that would be merged, in order:

Calculating dependencies... done!

[ebuild   R   ] sys-apps/portage-2.1.3.19  USE="-build -doc -epydoc (-selinux)" LINGUAS="-pl" 0 kB

Total: 1 package (1 reinstall), Size of downloads: 0 kB

real    0m51.786s

user    0m5.640s

sys     0m0.220s

(part dstat output while running above emerge)

# dstat

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--

usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw

  4   1  92   3   0   1| 103k  133k|   0     0 |5958B 5278B| 441  1652

  2   0   0  98   0   0| 676k    0 |3940B 3385B|   0     0 | 551  1306

  5   1   0  94   0   0| 684k    0 |5568B 4087B|   0     0 | 558  1302

  5   1   0  94   0   0| 604k    0 |4672B 3014B|   0     0 | 530  1265

  4   0   0  96   0   0| 588k    0 |5894B 3556B|   0     0 | 527  1255

  4   0   0  95   0   1| 576k    0 |4060B 2629B|   0     0 | 522  1256

  4   0   0  95   1   0| 672k    0 |4908B 3243B|   0     0 | 546  1300

  5   1   0  90   2   2| 620k    0 |4249B 2803B|   0     0 | 532  1271

  7   0   0  92   1   0| 476k    0 |5434B 3558B|   0     0 | 506  1196

 21   1   0  77   0   1| 508k    0 |3404B 2308B|   0     0 | 501  1208

 11   0   0  89   0   0| 464k    0 |4184B 2830B|   0     0 | 500  1207

  0   0   0 100   0   0| 516k    0 |3238B 2329B|   0     0 | 512  1243

 11   0   0  88   1   0| 492k    0 |3854B 2610B|   0     0 | 505  1228

  1   0   0  98   0   1| 532k    0 |4468B 2972B|   0     0 | 514  1237

 14   1   0  85   0   0| 480k    0 |4028B 2567B|   0     0 | 496  1223

 20   0   0  80   0   0| 400k    0 |4974B 5524B|   0     0 | 495  1223

 14   1   0  85   0   0| 420k    0 |4392B 6729B|   0     0 | 493  1248

```

Here s a text file with some info:

http://www.trans.am/info.txt

Thanks in advance

----------

## format_c

did you check that you have DMA support for your hard disk controller?:

```

 # hdparm /dev/hda

....

using_dma     =  1 (on)

...

```

If not, you need to compile chipset support for your mainboard into your kernel.

Cheers Alex

----------

## vinz

It is a SATA disk for which no dma mode needs to be specified...

----------

## likewhoa

 *vinz wrote:*   

> It is a SATA disk for which no dma mode needs to be specified...

 

what scheduler are you running? try switching to a different iosched. also raise your Timer frequency to 1000Hz if not already on there.

----------

## vinz

I have cfq as default. It makes no difference which of the following schedulers I choose of

```

# cat /sys/block/sda/queue/scheduler

noop anticipatory deadline [cfq]

```

----------

## likewhoa

 *vinz wrote:*   

> I have cfq as default. It makes no difference which of the following schedulers I choose of
> 
> ```
> 
> # cat /sys/block/sda/queue/scheduler
> ...

 

are you using CONFIG_SATA_AHCI if so disable it and see if that helps.

----------

## vinz

It was enabled, I now disabled it and it did not make any difference.

```
# gzip -cd /proc/config.gz |grep -i ahci

# CONFIG_SATA_AHCI is not set
```

----------

## likewhoa

post your .config and also take a look at https://forums.gentoo.org/viewtopic-t-482731.html which should give you more tips on troubleshooting this issue, I don't have this problem anymore as of 2.6.23 using CFQ

----------

## vinz

the .config is part of the link I have posted in the initial post.  If it is inaccessible for some reason, use this link: http://pastebin.ca/792719

So the problem was solved for your box just by using 2.6.23? Or did you change anything else? I don't really have the time to read through a 23 page thread. I would appreciate quick summary or hints in the right direction.

As I mentioned above, it makes no difference which of the 2.6.23 schedulers I use

----------

## likewhoa

you have a timer frequency of 250Hz on that .config have you tried 1000Hz? also I noticed high memory support when you only have 512MB of RAM, you should disable that and any other options which you don't need like the deprecated sysfs option.

----------

## vinz

I have set the frequency to 1khz, disabled high memory support, removed the deprecated sysfs support and cleaned up the configuration quite a bit, the new config is here: http://pastebin.ca/792989

so far, still the same issue

----------

## Cyker

What do you mean by high IOWait time exactly?

Some iowait is to be expected; HDs are several orders of magnitude slower than most everything else in the compy after all.

Just doing a "cp file1 file1.copy" on my RAID5 array, I get ~50% iowait on both CPU cores for the duration.

As I write this I'm doing a verify on a 160GB backup job with the source PC which is on the other end of a CAT5e cable, and it bounces between 2-15% iowait according to htop (top sucks! long live htop!  :Razz: ). The large variation seems to be down to sections where it's parsing one big file vs lots of little ones.

If your compy's getting maxed out on iowait just listening to mp3s in the backgrounds, then there's something wrong, but if it's just during heavy file ops, it's probably normal...

----------

## vinz

the write throughput is fine, sort of, but what definitively  is not fine is this:

```

# time emerge -pv htop

These are the packages that would be merged, in order:

Calculating dependencies... done!

[ebuild  N    ] sys-process/htop-0.6.6  USE="-debug" 138 kB

Total: 1 package (1 new), Size of downloads: 138 kB

real    0m51.170s

user    0m5.611s

sys     0m0.472s

```

which sort of says it is using 5s CPU time and 46s it is doing disk I/O

I have boxes with PATA100 disks and slower CPUs and the same amount of memory, basically far inferior hardware then this, which does a job like this in 10 seconds (and I made sure the data was not cached).

The "hdparm -tT" speed is well, the above example tells me there is something utterly wrong.

And it is not a "top" issue, as dstat (look above) does report the same thing

----------

## vinz

*bump*

----------

## vinz

*bump*

----------

## Akkara

That time for a emerge might not be too unusual.

emerge has to go through *a lot* of small files to figure out what needs to be done.  If they are not in cache the disk will be seeking all over the place, especially if /usr/portage is on a main partition (it works much better with /usr/portage on its own partition, additionally you can periodically back it up and recreate the filesystem to clear fragmentation).

What does time emerge -pv htop give when you run it a second time after having just run it?

----------

## vinz

as linux does cache read data from the disk into available RAM, the second time the same command is run is fast since the data is read from the RAM.

the system does respond generally slowly to any command that has to read from the disk.

I have various systems with worse hardware which perform a lot better then this box, so this box has some issues.

----------

## vinz

*bump*   :Sad: 

----------

## zeek

 *vinz wrote:*   

> 
> 
> ```
> 
> # time emerge -pv htop
> ...

 

Brutal ... this probably wont be fixed by tweaks.  Did you check for upgrades to the motherboard bios?  The other thing I would check for is alternatives for drivers that you have compiled in.

Try running emerge under `strace -c` to see what call takes up all the time ie:

```
ember ~ # strace -c emerge -pv dstat

These are the packages that would be merged, in order:

Calculating dependencies... done!

[ebuild   R   ] sys-apps/dstat-0.6.6  0 kB

Total: 1 package (1 reinstall), Size of downloads: 0 kB

% time     seconds  usecs/call     calls    errors syscall

------ ----------- ----------- --------- --------- ----------------

 34.18    0.003846           1      3820       617 stat64

 17.32    0.001949           1      2704           read

  9.91    0.001115           7       152           getdents64

  8.38    0.000943           0      3492      2452 open

  6.45    0.000726         363         2           clone

  5.89    0.000663           0      5000           futex

  4.59    0.000517           0      1048           close

  3.91    0.000440           1       585         5 access

  2.68    0.000302           0       923           mmap2

  1.89    0.000213         213         1           execve

  1.82    0.000205           0      2510           fstat64

  1.23    0.000138           0       813           munmap

  0.84    0.000094           0      1119           gettimeofday

  0.34    0.000038           1        34           mprotect

  0.33    0.000037           0        89           fcntl64

  0.23    0.000026          13         2           waitpid

  0.00    0.000000           0        22           write

  0.00    0.000000           0         1           unlink

  0.00    0.000000           0         2           time

  0.00    0.000000           0         7         7 mkdir

  0.00    0.000000           0         2           pipe

  0.00    0.000000           0        31           brk

  0.00    0.000000           0         7         1 ioctl

  0.00    0.000000           0         3           umask

  0.00    0.000000           0         4         1 readlink

  0.00    0.000000           0         2           getpriority

  0.00    0.000000           0         1           setpriority

  0.00    0.000000           0         4           uname

  0.00    0.000000           0       178         2 _llseek

  0.00    0.000000           0        74           rt_sigaction

  0.00    0.000000           0         1           rt_sigprocmask

  0.00    0.000000           0         1           getcwd

  0.00    0.000000           0         2           getrlimit

  0.00    0.000000           0        21           lstat64

  0.00    0.000000           0         2           getuid32

  0.00    0.000000           0         1           chown32

  0.00    0.000000           0         1           set_thread_area

  0.00    0.000000           0         1           set_tid_address

  0.00    0.000000           0         1           set_robust_list

  0.00    0.000000           0         4           socket

  0.00    0.000000           0         4         4 connect

------ ----------- ----------- --------- --------- ----------------

100.00    0.011252                 22671      3089 total

```

----------

## wyvern5

Could be a dying hard drive or sata controller. That can drastically reduce performance while still maintaining some functionality.

Try doing a dd to see how fast the drive itself can actually read/write.

----------

