IO Accounting 機能で I/O 負荷の高いプロセスを特定

随分久々の Linux ネタです。以前にロードアベレージに関する考察などの記事も書きましたが、多くのサーバーサイドエンジニアはサーバ負荷と日々戦っていることかと思います。過去多くの場合、負荷の原因特定はおおよそ下記のような手順で分析をしていたことかと思います。※詳しい手順は別エントリとして記載予定。

top をみて上位に張り付いているプロセスを確認しつつ CPU or I/O のどちらが原因か判別
ps を使ってプロセスの状態を確認して(T),(D)の状態から CPU or I/O のどちらが原因か判別
vmstat で procs の r, b の数、swap の si, so の状態、I/O の bi, bo の状態を確認
iostat を使って disk の read/write の状態をさらに詳しく確認
sar を使って os の状態をさらに詳しく確認
おおよその原因特定から設定を見直したりチューニング作業を実施

過去の経験上では CPU 負荷の場合は原因特定に至り、プログラムの実装見直しなどで対処可能な場合が多いのですが、ディスク I/O が原因の時には明確な原因特定に至らず手探りでチューニングするパターンが多いように思います。

- スポンサーリンク -

そんなもやもや感を一気に解消してくれるのが kernel 2.16.20 以降で実装された IO Accounting 機能です。プロセス毎の I/O に関する統計情報が /proc/[pid]/io に出力されるようになっています。その情報を分析していけば、どのプロセスで原因で iowait を発生させているかを判別することが可能となります。

例としとうちの自宅サーバの top で上に張り付いているプロセスの IO 統計情報を見てみましょう。

top - 17:51:14 up 41 days, 10:54,  1 user,  load average: 0.63, 0.56, 0.42
Tasks: 234 total,   2 running, 231 sleeping,   0 stopped,   1 zombie
Cpu(s): 16.9%us,  2.0%sy,  0.0%ni, 80.6%id,  0.0%wa,  0.2%hi,  0.3%si,  0.0%st
Mem:   4048980k total,  3965488k used,    83492k free,    53504k buffers
Swap:  8388600k total,    45528k used,  8343072k free,  2275580k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                     
26664 drk       20   0  179m  87m 4412 S 31.7  2.2 709:24.43 gungho                                                                      
18370 apache    20   0  146m  16m 2588 S  2.0  0.4   1:51.41 AmazonSimilarit                                                             
18338 apache    20   0 51580 6876  912 S  1.3  0.2   1:22.47 lighttpd                                                                    
20943 apache    20   0  163m  23m 2940 S  1.0  0.6   0:34.28 xml2json.fcgi                                                               
 2904 root      20   0  308m  67m  64m S  0.7  1.7 357:45.97 ttserver                                                                    
24808 apache    20   0 14880 1252  872 R  0.7  0.0   0:00.09 top                                                                         
    1 root      20   0  4032  724  584 S  0.0  0.0   0:02.66 init                                                                        
    2 root      15  -5     0    0    0 S  0.0  0.0   0:00.00 kthreadd

crawler の gungho が CPU 消費で張り付いているのがわかります。まあ例としては不適切ですが、とりあえず IO Accounting 情報をみてみましょう。

[user01@srv01 2904]$ cat /proc/26664/io
rchar: 5003188894
wchar: 67923618
syscr: 3404355
syscw: 224322
read_bytes: 3633152
write_bytes: 144248832
cancelled_write_bytes: 59867136

それぞれのパラメータの意味は以下の通りです。

rchar, wchar はシステムコール read, write の実行 byte 数
syscr, syscw はシステムコール read, write の実行回数
read_bytes はプロセスにより HDD 等のブロックデバイスからファイルキャッシュへのデータロードの byte 数
write_bytes はプロセスによりファイルキャッシュのデータの dirty フラグが立った byte 数
cancelled_write_bytes は write_bytes のうちブロックデバイスに write される前に、別のデータによってデータが書き換えられ、実際には write されなかった byte 数

これらの値が総じて高ければ I/O に負荷をかけているプロセスだと言えるでしょう。もっともある１つのプロセスを見ただけでは比較ができないので判別は難しいので、Tokyo Tyrant のプロセスの情報をみてみましょう。基本的にストレージにひたすらアクセスをしているプロセスなので、総じて値が高いと推測できます。

[user01@srv01 2904]$ cat /proc/2904/io
rchar: 237416348388
wchar: 76469372829
syscr: 97349737
syscw: 84108222
read_bytes: 179451441152
write_bytes: 101826129920
cancelled_write_bytes: 0

結果は、先ほどとは比較にならないほどの IO 値が出力されました。
しかしながら iowait を発生させているかと言えば違います。値と負荷については、そのシステムの今の状態によりけりなので、総合的に意味を把握する必要があるのに変わりはありません。
ちなみに TokyoTyrant は HDD を使いつつも memcached に近いパフォーマンスを出すことで有名で、くわえて自宅サーバ環境ではストレージに SSD を用いているので IO で待たされることは全く経験しておりません。

さて本題に入ってきました。

IO Accounting の値を分析すれば負荷の原因特定に近づくことができるのですが、自前で /proc/[pid]/io を分析するには骨が折れます。そんなわけでツールを使います。それぞれデフォルトでは入っていない場合もありますので、入っていない場合はインストールから。

yum install sysstat 
yum install dstat

pidstat -d を実行すると、実行時の各プロセスの IO 統計情報を出力することができます。

[user01@srv01 2904]$ pidstat -d
Linux 2.6.27.21-170.2.56.fc10.x86_64 (srv01)    2011年07月02日

20時33分38秒       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
20時33分38秒         1     80.86     10.75      0.04  init
20時33分38秒       255      0.00      0.01      0.00  kswapd0
20時33分38秒       331      0.00      0.00      0.00  lighttpd
・・・・
20時33分38秒      2951      0.00      0.34      0.00  perl
20時33分38秒      2965    121.89      3.32      0.00  ttserver
20時33分38秒      2986     26.85     21.88      0.64  crond
20時33分38秒      3018      0.00      0.00      0.00  atd
・・・・

dstat は更に便利です。dstat -M topbio -al を実行すると IO 統計情報で最も負荷をかけているプロセスを cpu, system などの情報を付加させて、だら見することが可能となります。

[user01@srv01 2904]$ dstat -M topbio -al
----most-expensive---- ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system-- ---load-avg---
  block i/o process   |usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw | 1m   5m  15m 
ttserver    122k:3408B|  8   2  89   0   0   1| 281k  104k|   0     0 |  45B   58B|1285   921 | 0.9  0.8  0.6
ttserver    364k:   0 | 11   2  86   0   0   0| 524k    0 |  34k  103k|   0     0 |1587  1022 | 0.9  0.8  0.6
cronolog      0 :4096B|  4   1  93   0   0   0|   0   200k|  92k  108k|   0     0 |1156   761 | 0.8  0.8  0.6
ttserver     20k:  56k| 11   2  87   0   0   0|  24k    0 |  55k  139k|   0     0 |1557  1008 | 0.8  0.8  0.6
ttserver   8192B:  56k|  6   1  92   0   0   0|8192B    0 | 204k  142k|   0     0 |1500   917 | 0.8  0.8  0.6
ttserver     12k:  16k|  8   3  89   0   1   1|  16k    0 | 256k  149k|   0     0 |1633   996 | 0.8  0.8  0.6
ttserver     44k:4096B|  6   1  92   0   0   1|  44k    0 | 135k  148k|   0     0 |1443   963 | 0.8  0.8  0.6
ttserver     12k:  16k|  9   2  88   0   1   1|  16k  328k| 222k   68k|   0     0 |1569   861 | 0.8  0.8  0.6
ttserver    888k:  44k| 23   3  72   2   0   1|1844k    0 | 257k  181k|   0     0 |2691  1500 | 0.8  0.8  0.6
ttserver     64k:4096B|  5   2  92   0   1   1|  64k    0 | 160k  134k|   0     0 |1432   887 | 0.8  0.8  0.6
ttserver     40k:   0 |  5   2  92   0   0   1|  52k 4096B| 146k  131k|   0     0 |1423   859 | 0.8  0.8  0.6
ttserver     36k:   0 |  7   3  89   0   0   0|  40k    0 | 214k  132k|   0     0 |1674  1061 | 0.8  0.8  0.6
ttserver    108k:4096B|  4   1  91   3   0   0| 108k  440k|  75k  143k|   0     0 |1375   885 | 0.8  0.8  0.6
AmazonSimil1088k:   0 | 11   2  86   1   0   1|1140k    0 | 178k  157k|   0     0 |1829  1138 | 0.8  0.8  0.6
AmazonSimil 576k:   0 | 13   2  83   2   0   0|1392k    0 |  68k  107k|   0     0 |1676   989 | 0.8  0.8  0.6
AmazonSimil 472k:   0 | 22   4  73   0   0   1|1056k    0 | 287k  155k|   0     0 |2471  1248 | 0.8  0.8  0.6
ttserver     60k:   0 |  5   2  92   0   0   0|  60k    0 | 193k  176k|   0     0 |1817  1088 | 0.8  0.8  0.6

さて結論です。top などで IO 関連が原因でロードアベレージが高いと感じたら dstat を使いましょう。きっと今まで以上に原因の特定に近づくことができることでしょう。

dstat -M topbio -al

あとは経験と勘で・・・ｗ