随分久々の 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 に負荷をかけているプロセスだと言えるでしょう。もっともある1つのプロセスを見ただけでは比較ができないので判別は難しいので、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 を使いましょう。きっと今まで以上に原因の特定に近づくことができることでしょう。
あとは経験と勘で・・・w