I/O負荷の正確な状況はiowaitでは分かりません

さくらインターネットのアドベントカレンダー9日目として、サーバ屋らしく、運用に関するコマンドの使い方を紹介します。

サーバの負荷が高まってきたときに、vmstatやtopなどのコマンドで調査する事が出来ますが、I/O負荷をwa(iowait)によって判断する人も多いと思います。
ただ、結論から言うと、iowaitは正確にI/Oの負荷を表しているわけではありません。
これらを、実際に演習をしながら見ていきたいと思います。

# iowaitとidle

iowaitとはあくまでも、CPUが空いているのにI/Oがボトルネックになっているプロセスを示しているだけで、CPUの利用率が高いときにはI/Oがボトルネックになっていてもiowaitが上がりません。
同様に勘違いされがちなのが、id(idle)はCPUの空きを示しているというものですが、idleは必ずしもCPUの空き時間を示しているものではありません。
us(user)がユーザプロセスでのCPU使用率、sy(system)がカーネルでのCPU使用率であり、userとsystemを足したものがいわゆるCPU使用率を示しています。
そして、user + system + idle + iowait は必ず100になります（ここではstの説明は省きます）。
例えば、userもsystemも0の状態、つまりCPU利用率が0%のときに、I/Oに大きな負荷がかかってiowaitが100になると、idleは0になります。CPU使用率が0%なのにidleは0になるのです。
CPUの空きをidleで確認していた場合には、CPU使用率は0%なのに、CPUの空きがない、つまりCPUが食いつぶされていると読み取ってしまいます。

逆に言うと、I/Oに大きな負荷がかかっていたとしても、CPU使用率が100%の場合には、iowaitは0のままです。
I/O負荷をiowaitで確認していた場合には、負荷が発生しているのに0としか読み取ることができず、I/Oが空いていると勘違いしてしまいます。

```shell-session
# vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 2  0   1004 290756  47660 441328    0    0     2     1   41   32  0  0 100  0  0
```

# I/O負荷を発生させてみる

それでは、実際にI/Oに対して負荷を発生して見たいと思います。
以下のコマンドを実行すれば、キャッシュ無しで500MBのファイルを作成します。
別のセッションでvmstatを実行すると、書き込み中の各数値の変化が読み取れます。

```shell-session
# dd if=/dev/zero of=test bs=1M count=512 oflag=direct
```
```shell-session
# vmstat 1
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   1004 283272  51228 442416    0    0     0     0   59   48  0  0 100  0  0
 0  1   1004 281440  51232 442480    0    0    80 137216  438  419  0  5 13 82  0
 0  1   1004 281440  51240 442516    0    0     4 153600  446  446  0  4  0 96  0
 0  1   1004 281440  51256 442568    0    0    16 153600  480  458  0  6  0 94  0
 0  0   1004 282404  51256 442772    0    0   232 79872  270  272  0  2 46 52  0
 0  0   1004 282404  51256 442796    0    0     0     0   56   42  0  0 100  0  0
```

この場合、I/Oウェイトは、82->96->94->52 と変化し、数値が大きくなっているので、I/Oに負荷がかかっているんだろうなということが推測できます。
ちなみに、procsのbが1になっていることが分かりますが、これはI/Oが原因で待ち状態になっているプロセスが一個あるということを示しています。
実際にpsを実行すると、STATがDになっていることが分かります。

```shell-session
# ps aux
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root     12572  4.0  0.1 108984  1668 pts/0    D+   14:18   0:00 dd if=/dev/zero of=test bs=1M count=512 oflag=direct
```

# CPU負荷を発生させてみる

次に、CPU負荷を発生させてみましょう。
無駄にforループするperlスクリプトを作ったので、これをダウンロードして実行してみてください。
いまどきPerlで申し訳ないですが・・・。

```shell-session
# curl -O https://tanaka.sakura.ad.jp/loadtest.pl
# chmod +x loadtest.pl
```

ソースを見れば分かりますが、引数に指定された数の子プロセスを生成して、延々とループするだけのスクリプトです。
例えば、第1引数に4と指定して実行すれば、4つプロセスがCPUを使い尽くします。

```shell-session
# ./loadtest.pl 4
```
```shell-session
# vmstat 1
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   1004 274652  51388 450624    0    0     0     0   46   40  0  0 100  0  0
 4  0   1004 273580  51388 450640    0    0     0     4  909  107 87  1 12  0  0
 4  0   1004 273580  51388 450640    0    0     0     0 1047  117 100  0  0  0  0
 4  0   1004 273580  51388 450640    0    0     0     0 1015  110 100  0  0  0  0
 0  0   1004 274388  51388 450640    0    0     0     0  788  123 75  0 25  0  0
 0  0   1004 274404  51388 450640    0    0     0    80   52   45  0  0 100  0  0
```

この場合、cpuのusが100になり、ユーザプロセスによってCPUが使い尽くされていることが分かります。
ちなみに、procsのrが4になっていることが分かりますが、これはCPUが原因で待ち状態になっているプロセスが4個あるということを示しています。
実際にpsを実行すると、STATがRになっていることが分かります。

```shell-session
# ps aux
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root     12592  0.0  0.2 129668  2028 pts/0    S+   14:26   0:00 /usr/bin/perl ./loadtest.pl 4
root     12593 20.3  0.0 129668   400 pts/0    R+   14:26   0:00 /usr/bin/perl ./loadtest.pl 4
root     12594 20.3  0.0 129668   400 pts/0    R+   14:26   0:00 /usr/bin/perl ./loadtest.pl 4
root     12595 20.3  0.0 129668   400 pts/0    R+   14:26   0:00 /usr/bin/perl ./loadtest.pl 4
root     12596 20.3  0.0 129668   400 pts/0    R+   14:26   0:00 /usr/bin/perl ./loadtest.pl 4
```

# I/OとCPUの両方に負荷を発生させてみる

では、CPUとI/Oの両方に負荷を発生させてみましょう。

まず、CPUに負荷を発生させます。

```shell-session
# ./loadtest.pl 4
```
```shell-session
# vmstat 1
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   1004 274764  51396 450636    0    0     0     0   44   43  0  0 100  0  0
 4  0   1004 273568  51396 450656    0    0     0     0  595   90 55  0 45  0  0
 4  0   1004 273568  51396 450656    0    0     0     0 1022  114 100  0  0  0  0
```
vmstatによると、cpuのusが100になっていて、ユーザプロセスによってCPUが使い尽くされていることが分かります。

では、CPUに負荷を発生させたまま、ddを実行してI/Oに負荷をかけてみましょう。
直感的には、I/O負荷が高まるとcpuのwa、つまりiowaitの数値が上がりそうなものですが、loadtest.plを実行したままなのでusが100になっているなかで、どうなるでしょうか？

```shell-session
# dd if=/dev/zero of=test bs=1M count=512 oflag=direct
```
```shell-session
# vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 4  0   1004 268672  51500 451064    0    0     0     0 1016  110 100  0  0  0  0
 4  1   1004 268036  51500 451040    0    0     0 27648 1145  196 98  2  0  0  0
 4  1   1004 267540  51508 451088    0    0     8 89088 1269  266 100  0  0  0  0
 4  1   1004 267048  51512 451168    0    0     0 92160 1224  243 100  0  0  0  0
 4  1   1004 269172  51520 451056    0    0     0 92264 1283  264 100  0  0  0  0
 5  1   1004 269188  51520 451064    0    0     0 89088 1251  235 100  0  0  0  0
 4  1   1004 269188  51524 451072    0    0     0 94208 1235  231 100  0  0  0  0
 4  0   1004 270444  51524 451072    0    0     0 39936 1125  177 100  0  0  0  0
 4  0   1004 270444  51524 451072    0    0     0     0 1033  114 100  0  0  0  0
```
結論としては、I/Oに負荷がかかっているのに、iowaitが上がらないというものでした。
では、どのようにして負荷をみればいいのかということですが、vmstatの場合には、ioのbiとboがそれぞれデバイスへの書き込みと読み込みを示しており、上記の出力では、90MB/sec前後で6秒ほど書き込みが発生していることがわかります。

# iostatをつかう

vmstatでI/Oの状況を確認できましたが、より詳しく見るためにはiostatコマンドを利用しましょう。
細かな解説は省きますが、以下のように実行すれば1秒ごとにI/Oの状態を表示してくれます。
コマンドがインストールされていない場合には、CentOSの場合は yum install sysstat を実行すればインストールされます。

以下ケースでは、%utilで示されるI/Oの利用率が、23.27% -> 44.90%と上がって行っていることが分かります。

```shell-session
# iostat -x 1
Linux 3.10.0-693.2.2.el7.x86_64 (tanaka)        2017年12月05日  _x86_64_        (1 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          99.01    0.00    0.99    0.00    0.00    0.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
vda               0.00     0.00    0.00  151.49     0.00 51706.93   682.67     0.70    4.61    0.00    4.61   1.54  23.27

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
         100.00    0.00    0.00    0.00    0.00    0.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
vda               0.00     0.00    0.00  270.00     0.00 92160.00   682.67     1.35    4.99    0.00    4.99   1.66  44.90
```

ということで、簡単ではありましたが、vmstatとiowaitについての紹介でした。