原问题

原问题

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

一个简单的测试就违反了这个假设。这是预期的吗?如果是预期的话,是否有一系列条件可以让我应该期望我的假设成立吗?

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

更新: 请跳到答案

答案有一个比我最初使用的测试更简单的测试。我保留了下面的原始问题。原来的问题可能会显示一些额外的细节。

原问题

在一个简短的测试中,我用来dd请求内核生成随机字节,并将它们写入文件。我运行ddinside 的命令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”(和“时间”!)是否显示不正确的结果?

“iowait”的背景信息

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

%io等待:

系统有未完成的磁盘 I/O 请求期间,一个或多个 CPU 处于空闲状态的时间百分比。

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

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

还有一篇较长的文章:了解 I/O 等待(或者为什么 0% 空闲就可以)。这就解释了如何从内核代码中清楚地看到定义。代码稍有改动,但思路仍然清晰:

/*
 * 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;
}

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

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

环境

我有四个逻辑 CPU。

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

下面的结果来自内核4.20.15-200.fc29.x86_64,使用noopIO 调度程序。 IO调度器cfq也给出了类似的结果。

(我还在内核构建上看到了类似的结果,该内核构建基于类似的配置,但更接近内核版本 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%
...

我从专栏中读到了这个iowait数字。您可以通过查看列(= 1K 块输出)来判断测试何时运行。wavmstatiobo

$ 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

测试结果(在虚拟机内)

我在具有 1 个 CPU 的虚拟机中尝试了相同的测试,该虚拟机正在运行内核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%
...

输出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

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

我尝试关闭虚拟机,然后使用 4 个 CPU 启动它。同样,我经常看到正好 75% 的空闲,有时空闲率低至 50%,但我没有看到超过 75% 的空闲率(即超过 4 个 CPU 中的 3 个)。

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

答案1

内容通知:这篇文章包含各种 Linux 讨论和代码的链接。某些链接内容不符合当前的行为准则堆栈交换或为了Linux。大多数情况下,他们“侮辱代码[而不是人]”。无论使用何种语言,都不应重复。我要求你们避免模仿、鹦鹉学舌或争论此类语言。


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

2019 年 5 月 7 日 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;
}

这正如我预期的那样,如果你是近似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);
}

如果进程在空闲 CPU 上被唤醒,则该 CPU 会调用account_idle_time().根据应用的配置,这称为 from tick_nohz_account_idle_ticks()from__tick_nohz_idle_restart_tick()或 from vtime_task_switch()from finish_task_switch()

此时,->nr_iowait已经减少了。如果减为零,则不会记录 iowait 时间。

这种效果可能会有所不同:这取决于进程在哪个 CPU 上被唤醒。如果在接收 IO 完成中断的同一 CPU 上唤醒进程,则可以在->nr_iowait减少之前更早地计算空闲时间。就我而言,我发现 CPU 0 处理阿奇中断,通过查看watch cat /proc/interrupts.

我通过简单的顺序读取对此进行了测试:

dd if=largefile iflag=direct bs=1M of=/dev/null

如果我使用 将该命令固定到 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,尽管这个功能也在我的虚拟机之外的测试中使用。

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

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

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

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

是的。

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

然而,当他们进行调查时,他们发现了同样的根本问题。 Peter Zijlstra 和 Hidetoshi Seto 分别提出了解决方案并原型化。封面消息中解释了该问题:

[RFC PATCH 0/8] 返工 iowait 记账(2014-07-07)

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

相关内容