我对系统“iowait”的基本假设不成立

sou*_*edi 13 linux

我的基本假设是,当进程的唯一限制因素是磁盘和 CPU 时,系统总“iowait”+ CPU 使用率应至少等于一个逻辑 CPU 的 100%。(在其他情况下,这将不成立。例如,当使用 下载文件时wget,网络通常是限制因素)。

一个简单的测试违反了这个假设。这是预期的吗?如果预计,有一组,我的条件应该期待我的假设是成立的?

这里有一些关于“iowait”的背景:CPU 如何知道有 IO 挂起? 这里的答案引用了一个违反直觉的想法,即累积 iowait“在某些情况下可能会减少”。我想知道我的简单测试是否会触发这种未记录的情况?

更新:请跳到答案

答案的测试比我最初使用的测试更简单。我保留了下面的原始问题。原始问题可能会显示一些其他详细信息。

原始问题

在一个简短的测试中,我使用dd请求内核生成随机字节,并将它们写入文件。我在dd里面运行命令perf stat,只是为了计算在内核中花费的 CPU 时间。我也在里面运行它perf trace -s,报告里面花费的时间write()。同时,我vmstat 5在另一个终端运行,看到系统“iowait”。

  1. 我预计我会看到至少一个完整的 CPU 为“非空闲”,即 100% 的时间它要么运行,要么停止但等待 IO(“iowait”状态)。不是。
  2. (另外,我期待看到“iowait”时间与在 write() 中花费的时间大致匹配。但它似乎没有这样做。)

详细结果和测试环境如下所示。还显示了一个替代测试,我的假设确实成立。注意:必须在perf stat内部运行perf trace,而不是相反。这在这里有详细说明:在运行“perf trace - s”时,“perf stat”(和“time”!)是否显示不正确的结果?

关于“iowait”的背景信息

以下是来自sar联机帮助页的定义:

%io等待:

在系统有未完成的磁盘 I/O 请求期间 CPU 或多个 CPU 空闲的时间百分比。

因此,%iowait 意味着从 CPU 的角度来看,没有任务可运行,但至少有一个 I/O 正在进行。iowait 只是一种空闲时间形式,此时无法安排任何事情。该值在指示性能问题时可能有用也可能没有用,但它确实告诉用户系统处于空闲状态并且本可以进行更多工作。

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

还有一篇更长的文章:Understanding I/O Wait (or why 0% Idle can be OK)。这解释了如何从内核代码中清楚地看到定义。代码略有改动,但思路还是很清晰的:

/*
 * 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;
}
Run Code Online (Sandbox Code Playgroud)

文章还展示了一些在单 CPU 系统上的相关实验。一些实验中甚至使用dd带有if=/dev/urandom !但是实验不包括我的测试dd if=/dev/urandom of=test.out 。它只使用dd if=/dev/urandom of=/dev/null .

“IO 等待”现在考虑起来有点棘手,因为我们使用多 CPU 系统,但我想我仍然理解它,基于引用的代码。

环境

我有四个逻辑 CPU。

我使用 LVM 和 ext4 文件系统。我没有在我的磁盘或文件系统上使用任何加密。我根本没有安装任何网络文件系统,所以我没有读或写网络文件系统。

下面的结果来自 kernel 4.20.15-200.fc29.x86_64,使用noopIO 调度程序。该cfqIO调度也给出了类似的结果。

(我还在基于类似配置的内核构建中看到了类似的结果,但更接近内核版本 5.1,并且使用mq-deadline. 所以这是使用新blk-mq代码)。

测试和结果

$ 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%
...
Run Code Online (Sandbox Code Playgroud)

我读了iowait从图中wa的列vmstat。您可以通过查看io列(bo= 1K 块输出)来判断测试何时运行。

$ 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
Run Code Online (Sandbox Code Playgroud)

测试结果(在 VM 内)

我在具有 1 个 CPU 的 VM 中尝试了相同的测试,该 VM 正在运行内核5.0.9-301.fc30.x86_64并使用mq-deadline(因此是 blk-mq)。在这个测试中,它按照我的预期工作。

$ 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%
...
Run Code Online (Sandbox Code Playgroud)

的输出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
Run Code Online (Sandbox Code Playgroud)

我尝试将 CPU 热添加到 VM 并再次测试。结果是可变的:有时它在空闲列中显示大约 0%,有时它显示大约 50% 空闲(即两个 CPU 中的一个)。在 0%“空闲”的情况下,“iowait”非常高,即超过一个 CPU 的价值。即我的期望点 2 不正确。我可以勉强接受“iowait”在多 CPU 系统上的这种明显限制。(虽然我不是很明白,如果有人想确切地解释它,那就太好了)。然而,在任何一种情况下,“空闲”都没有超过 50%,所以这些测试仍然与我对“iowait”的第一个假设一致。

我尝试关闭 VM 并使用 4 个 CPU 启动它。同样,我经常有正好 75% 的空闲,有时我有 50% 的空闲,但我没有看到超过 75% 的空闲(即超过四分之三的 CPU)。

而在具有 4 个 CPU 的物理系统上,我仍然可以重现 80% 以上空闲的结果,如上图所示。

sou*_*edi 7

内容通知:这篇文章包括各种 Linux 讨论和代码的链接。某些链接内容不符合StackExchangeLinux的当前行为准则。大多数情况下,他们“侮辱代码[但不是人]”。然而,使用了一些语言,不应该重复。我要求你避免模仿、模仿或辩论这种语言。


回复:iowait 与空闲记帐“不一致”- iowait 太低

在 05/07/2019 12:38,Peter Zijlstra 写道:

在 2019 年 7 月 5 日星期五下午 12:25:46 +0100,Alan Jenkins 写道:

我的 cpu "iowait" 时间似乎报告不正确。你知道为什么会发生这种情况吗?

因为 iowait 是一个神奇的随机数,没有任何意义。就我个人而言,我更愿意删除整个内容,除了ABI:/

另请参阅nr_iowait()附近的评论

谢谢。我认为 [当前文档中提到的问题] 是不同的问题,但您的意思是没有太多需求(或指向)来“解决”我的问题。

我发现了我的问题。五年前就已经注意到了,修复起来并非易事。

“iowait”时间由函数更新account_idle_time()

/*
 * 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;
}
Run Code Online (Sandbox Code Playgroud)

如果您通过使用传统定时器中断(“滴答”)“采样”来估算 CPU 时间,这将按我的预期工作。但是,如果在空闲时间关闭滴答以节省电量,它可能不起作用 - NO_HZ_IDLE。如果出于性能原因允许关闭刻度线,它也可能会失败NO_HZ_FULL- 因为这需要启动VIRT_CPU_ACCOUNTING。大多数 Linux 内核使用省电功能。一些嵌入式系统不使用这两种功能。这是我的解释:

IO 完成后,设备发送中断。内核中断处理程序使用try_to_wake_up(). 它从nr_iowait计数器中减去一:

if (p->in_iowait) {
    delayacct_blkio_end(p);
    atomic_dec(&task_rq(p)->nr_iowait);
}
Run Code Online (Sandbox Code Playgroud)

如果进程在空闲 CPU 上被唤醒,则该 CPU 调用account_idle_time(). 根据适用的配置,这就是所谓的无论是从tick_nohz_account_idle_ticks()__tick_nohz_idle_restart_tick(),或vtime_task_switch()finish_task_switch()

到了这个时候,->nr_iowait已经是递减了。如果减少到零,则不会记录 iowait 时间。

这种影响可能会有所不同:这取决于进程在哪个 CPU 上被唤醒。如果进程在接收到 IO 完成中断的同一 CPU 上被唤醒,则空闲时间可以更早地计算,然后->nr_iowait递减。在我的例子中,我发现 CPU 0 处理ahci中断,通过查看watch cat /proc/interrupts.

我用一个简单的顺序读取测试了这个:

dd if=largefile iflag=direct bs=1M of=/dev/null
Run Code Online (Sandbox Code Playgroud)

如果我使用 将命令固定到 CPU 0 taskset -c 0 ...,我会看到 iowait 的“正确”值。如果我将它固定到不同的 CPU,我看到的值要低得多。如果我正常运行命令,它会因调度程序行为而异,这在内核版本之间发生了变化。在最近的内核(4.17、5.1、5.2-rc5-ish)中,该命令似乎在 CPU 0 上花费了大约 1/4 的时间,因为“iowait”时间减少到了这一部分。

(未解释:为什么现在在我的虚拟机上运行此测试似乎可以为每个(或任何)CPU 重现“正确”的 iowait。我怀疑这可能涉及IRQ_TIME_ACCOUNTING,尽管此功能也在我的 VM 外部测试中使用。

我也没有确切地确认为什么抑制NO_HZ_IDLE会在 4.17+ 上为每个 CPU 提供“正确的”iowait,但在 4.16 或 4.15 上没有。

在我的虚拟机上运行此测试似乎可以为每个(或任何)CPU 重现“正确”的 iowait。这是由于 IRQ_TIME_ACCOUNTING. 它也用于 VM 外部的测试,但在 VM 内部测试时我得到更多中断。具体来说,运行“dd”的虚拟CPU上每秒有1000多个“函数调用中断”。

所以你不应该过分依赖我解释的细节:-)

这里有一些关于“iowait”的背景:CPU 如何知道有 IO 挂起? 这里的答案引用了一个违反直觉的想法,即累积 iowait“在某些情况下可能会减少”。我想知道我的简单测试是否会触发这种未记录的情况?

是的。

当我第一次查看这个时,我发现了“打嗝”的说法。此外,该问题通过显示累积的“iowait”时间是非单调的。那就是它有时会向后跳(减少)。它不像上面的测试那么简单。

然而,当他们调查时,他们发现了同样的基本问题。Peter Zijlstra 和 Hidetoshi Seto 分别提出并制作了一个解决方案。封面消息中解释了该问题:

[RFC PATCH 0/8] 返工 iowait 会计(2014-07-07)

我没有发现除此之外取得进展的证据。关于其中一个细节有一个悬而未决的问题。此外,整个系列涉及 PowerPC、S390 和 IA64 CPU 架构的特定代码。所以我说这不是很容易解决。

  • 您能否确认或拒绝(使用 vmstat):无论启用或禁用空闲状态,内核 4.15 都会执行您的预期;无论如何,内核 4.16 都不会做您期望的事情。vmstat 似乎使用`/proc/stat`,但我使用`/sys/devices/system/cpu/cpu*/cpuidle/state*/usage`,并且据我所知一直是准确的(+- a几个 %)。我不能在旧内核上使用我的工具,因为那里没有一些新信息。请注意,我希望 test1 和 test3 给出相同的结果,因为在空闲状态 0 下滴答永远不会停止。 (2认同)