7

My basic assumption about system "iowait" broke down. Is this expected? If it is expected, is there a set of conditions where I should expect my assumption to hold true?

My basic assumption is that when a process' only limiting factors are disk and CPU, then total system "iowait" + CPU usage should equal at least 100% of one logical CPU. (In other cases this will not hold. E.g. when downloading a file using wget, the network is often the limiting factor).

In a short test, I use dd to request the kernel to generate random bytes, and write them to a file. I run the dd command inside perf stat, just to get a count of the CPU time spent inside the kernel. I also run it inside perf trace -s, to report the time spent inside write(). At the same time, I run vmstat 5 in another terminal, to see the system "iowait".

  1. I expected I would see at least one whole CPU as "non-idle", i.e. 100% of the time it is either running, or halted but waiting for IO ("iowait" state). It was not.
  2. (Also, I was expecting to see "iowait" time roughly match the time spent in write(). But it did not appear to do so.)

The detailed results and test environment are shown below. Also shown is an alternative test, where my assumption did hold. Note: it was necessary to run perf stat inside perf trace, not the other way around. This is detailed here: Does "perf stat" (and "time" !) show incorrect results when running "perf trace -s" ?

Background information on "iowait"

Following is the definition taken from the sar manpage:

%iowait:

Percentage of time that the CPU or CPUs were idle during which the system had an outstanding disk I/O request.

Therefore, %iowait means that from the CPU point of view, no tasks were runnable, but at least one I/O was in progress. iowait is simply a form of idle time when nothing could be scheduled. The value may or may not be useful in indicating a performance problem, but it does tell the user that the system is idle and could have taken more work.

https://support.hpe.com/hpsc/doc/public/display?docId=c02783994

There is also a longer article: Understanding I/O Wait (or why 0% Idle can be OK). This explains how you can see the definition clearly from the kernel code. The code has changed somewhat, but the idea is still clear:

/*
 * Account for idle time.
 * @cputime: the CPU time spent in idle wait
 */
void account_idle_time(u64 cputime)
{
    u64 *cpustat = kcpustat_this_cpu->cpustat;
    struct rq *rq = this_rq();

    if (atomic_read(&rq->nr_iowait) > 0)
        cpustat[CPUTIME_IOWAIT] += cputime;
    else
        cpustat[CPUTIME_IDLE] += cputime;
}

The article also shows a number of related experiments on a single-CPU system. Some of the experiments even use dd with if=/dev/urandom ! However the experiments do not include my test dd if=/dev/urandom of=test.out . It only uses dd if=/dev/urandom of=/dev/null .

"IO wait" is a bit more tricky to think about now because we use multi-CPU systems, but I think I still understand it, based on the quoted code.

See also How does a CPU know there is IO pending? . I notice the answer in this link also quotes the counter-intuitive idea, that cumulative iowait "may decrease in certain conditions". I wonder if this simple test can be triggering such an undocumented condition?

Environment

I have four logical CPUs.

I use LVM, and the ext4 filesystem. I am not using any encryption on my disk or filesystem. I do not have any network filesystem mounted at all, so I am not reading or writing a network filesystem.

The results below are from kernel 4.20.15-200.fc29.x86_64 , using the noop IO scheduler. The cfq IO scheduler also gives similar results.

(I have also seen similar results on a kernel build which was based on a similar configuration, but was closer to kernel version 5.1, and using mq-deadline. So that was using the new blk-mq code).

Test and results

$ sudo perf trace -s \
       perf stat \
       dd if=/dev/urandom of=test.out bs=1M oflag=direct count=3000

3000+0 records in
3000+0 records out
3145728000 bytes (3.1 GB, 2.9 GiB) copied, 31.397 s, 100 MB/s

 Performance counter stats for 'dd if=/dev/urandom of=test.out bs=1M oflag=direct count=3000':

         18,014.26 msec task-clock                #    0.574 CPUs utilized          
             3,199      context-switches          #    0.178 K/sec                  
                 4      cpu-migrations            #    0.000 K/sec                  
               328      page-faults               #    0.018 K/sec                  
    45,232,163,658      cycles                    #    2.511 GHz                    
    74,538,278,379      instructions              #    1.65  insn per cycle         
     4,372,725,344      branches                  #  242.737 M/sec                  
         4,650,429      branch-misses             #    0.11% of all branches        

      31.398466725 seconds time elapsed

       0.006966000 seconds user
      17.910332000 seconds sys

 Summary of events:
...
 dd (4620), 12156 events, 12.0%

   syscall            calls    total       min       avg       max      stddev
                               (msec)    (msec)    (msec)    (msec)        (%)
   --------------- -------- --------- --------- --------- ---------     ------
   read                3007 17624.985     0.002     5.861    12.345      0.21%
   write               3003 13722.837     0.004     4.570   179.928      2.63%
   openat                12     0.371     0.002     0.031     0.267     70.36%
...

I read the iowait figure from the wa column of vmstat. You can tell when the test is running by looking at the io column (bo = 1K blocks output).

$ vmstat 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0 5126892 176512 1486060   0   0  1788  4072  321  414  4  4 83  9  0
 1  0      0 5126632 176520 1485988   0   0     0     7  212  405  0  1 99  0  0
 0  0      0 5126884 176520 1485988   0   0     0     0  130  283  0  0 99  0  0
 0  0      0 5126948 176520 1485908   0   0     0     1  157  325  0  0 99  0  0
 0  0      0 5126412 176520 1486412   0   0   115     0  141  284  0  0 99  0  0
 0  2      0 5115724 176548 1487056   0   0     0  6019 18737 10733  3  6 89  2  0
 1  0      0 5115708 176580 1487104   0   0     3 91840 1276  990  0 13 77  9  0
 1  0      0 5115204 176600 1487128   0   0     2 91382 1382 1014  0 14 81  4  0
 1  0      0 5115268 176636 1487084   0   0     4 88281 1257  901  0 14 83  3  0
 0  1      0 5113504 177028 1487764   0   0    77 92596 1374 1111  0 15 83  2  0
 1  0      0 5114008 177036 1487768   0   0     0 113282 1460 1060  0 16 81  2  0
 1  0      0 5113472 177044 1487792   0   0     0 110821 1489 1118  0 16 74 10  0
 0  0      0 5123852 177068 1487896   0   0     0 20537  631  714  1  3 94  2  0
 0  0      0 5123852 177076 1487856   0   0     0    10  324  529  2  1 98  0  0
 2  0      0 5123852 177084 1487872   0   0     0    70  150  299  0  0 99  0  0

Test results where it does hold (inside a VM)

I tried the same test inside a VM with 1 CPU, which was running the kernel 5.0.9-301.fc30.x86_64 and using mq-deadline (and hence blk-mq). In this test, it worked how I expected it to.

$ sudo perf trace -s \
       perf stat \
       dd if=/dev/urandom of=test.out bs=1M oflag=direct count=3000
[sudo] password for alan-sysop:
3000+0 records in
3000+0 records out
3145728000 bytes (3.1 GB, 2.9 GiB) copied, 46.8071 s, 67.2 MB/s

 Performance counter stats for 'dd if=/dev/urandom of=test.out bs=1M oflag=direct count=3000':

         18,734.89 msec task-clock                #    0.400 CPUs utilized
            16,690      context-switches          #    0.891 K/sec
                 0      cpu-migrations            #    0.000 K/sec
               328      page-faults               #    0.018 K/sec
   <not supported>      cycles
   <not supported>      instructions
   <not supported>      branches
   <not supported>      branch-misses

      46.820355993 seconds time elapsed

       0.011840000 seconds user
      18.531449000 seconds sys


 Summary of events:
...
 dd (1492), 12156 events, 38.4%

   syscall            calls    total       min       avg       max      stddev
                               (msec)    (msec)    (msec)    (msec)        (%)
   --------------- -------- --------- --------- --------- ---------     ------
   write               3003 28269.070     0.019     9.414  5764.657     22.39%
   read                3007 18371.469     0.013     6.110    14.848      0.53%
   execve                 6    10.399     0.012     1.733    10.328     99.18%
...

Output of vmstat 5:

$ vmstat 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----                                                                     
 r  b  swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st                                                                     
 0  0     0 726176  52128 498508    0    0  2040   231  236  731  7  5 77 11  0                                                                     
 0  0     0 726176  52136 498508    0    0     0    10   25   46  0  0 99  1  0                                                                     
 0  0     0 726208  52136 498508    0    0     0     0   29   56  0  0 100  0  0                                                                    
 0  1     0 702280  55944 511780    0    0  2260 13109 4399 9049  3 17 55 25  0                                                                     
 0  1     0 701776  56040 511960    0    0    18 129582 1406 1458 0 73  0 27  0                                                                    
 0  2     0 701524  56156 512168    0    0    22 87060  960  991  0 50  0 50  0                                                                     
 3  1     0 701524  56228 512328    0    0    14 118170 1301 1322 0 68  0 32  0                                                                    
 1  1     0 701272  56260 512392    0    0     6 86426  994  982  0 53  0 46  0                                                                     
 0  2     0 701020  56292 512456    0    0     6 56115  683  660  0 37  0 63  0                                                                     
 3  2     0 700540  56316 512504    0    0     5 33450  446  457  0 26  0 74  0                                                                     
 0  2     0 700860  56332 512536    0    0     3 16998  311  240  0 19  0 81  0                                                                     
 1  2     0 700668  56368 512616    0    0     7 32563  443  428  0 24  0 76  0                                                                     
 1  0     0 700668  56392 512648    0    0     3 20338  245  272  0 12  0 88  0                                                                   
 0  1     0 707096  56408 512920    0    0    54 20913  312  530  0 12 79  8  0                                                                     
 0  0     0 707064  56432 512920    0    0     0    49   39   64  0  0 45 55  0                                                                     
 0  0     0 707064  56432 512920    0    0     0     0   24   46  0  0 100  0  0                                                                    
 0  0     0 707064  56432 512920    0    0     0    80   28   47  0  0 100  0  0

I tried hot-adding a CPU to the VM and testing again. The results were variable: sometimes it showed about 0% in the idle column, and sometimes it showed about 50% idle (i.e. one out of two CPUs). In the case of 0% "idle", "iowait" was very high i.e. more than one CPUs' worth. I.e. my expectation point 2 was not correct. I can begrudgingly accept this apparent limitation of "iowait" on multi-CPU systems. (Though I don't quite understand it. If someone wants to explain it exactly, that would be great). However, "idle" was not above 50% in either case, so these tests were still consistent with my first assumption about "iowait".

I tried shutting the VM down and starting it with 4 CPUs. Similarly, often I had exactly 75% idle, and sometimes I had as low as 50% idle, but I did not see more than 75% idle (i.e. more than three out of four CPUs).

Whereas on the physical system with 4 CPUs, I can still reproduce the result of more than 80% idle as shown above.

  • Would you mind annotating your two expectations a little. Could you add whether the real value was was more or less than your expectation. I understand this is in the raw data, it would just be a little more readable. I'm a little unclear on why you expect 1 cpu (100%). Based on one of your links and the kernel code you quote, a single IO operation will switch all IDLE time to to IOWAIT time (all 4 cores - 400%). – Philip Couling May 14 at 9:25
  • @PhilipCouling "I expected I would see at least one whole CPU as "non-idle"... It was not". Idle time was higher than expected, which I blame on iowait time being lower than I expected. In the kernel code, I think this_rq()->nr_iowait is the number of tasks which are waiting using io_schedule() on the current CPU only. Am I wrong? – sourcejedi May 14 at 9:31
  • I'm not certain at all, but I find it surprising if it is. This surprise appears to tally with Stephen Kitt's answer where he says "iowait tries to measure time spent waiting for I/O, in general. It’s not tracked by a specific CPU, nor can it be". Let me stress I'm not certain of this, just expressing surprise. – Philip Couling May 14 at 9:53
  • @PhilipCouling if you run atop, or atopsar -c 5, you will see per-cpu usage figures. They include iowait, and the per-CPU iowait figures can show different, non-zero values :-). Or sar -P ALL 1 , if you do not use atop. This is the way the iowait model has been extended for multi-CPU systems... What I am unclear on is whether this model is actually usable, or whether this is a way that lets the iowait code continue to work when there is only one CPU online, but it is just not trustworthy otherwise. – sourcejedi May 14 at 10:05
  • 1
    @PhilipCouling huh. Thanks for prodding, because I seem to have a simpler test case, without needing /dev/urandom. At least on the 5.1-ish kernel I have right now. 1) start a root shell and run sync, just to settle the system 2) wait until the cpu usage inc. iowait shows the system is nice and idle 3) dd if=/dev/sda bs=10M of=/dev/null iflag=direct . Result: ~360% idle and ~40% iowait (using atopsar where 100% = one logical CPU). – sourcejedi May 14 at 10:21

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.