今回は、(CloudWatchではなくて) ふつーの Linux 的な方法で 負荷原因となっているプロセスを特定するための方法について調べます。




・前提
複数のプログラムが動作している状況で、いずれかのプログラムがHDDを高頻度に利用し、サーバ負荷を高めている。この負荷原因となっているプログラムとプロセスを特定したい。

ここでは、「負荷試験用にEC2ラージインスタンスを用意し、sysbench を使ってソコソコ以上の HDD 負荷を発生させる」という状況を作っておきます。
今回は負荷試験が目的なので、負荷試験中でも快適な(?)操作が出来るように性能の高いEC2インスタンスにしてみました。



・EC2インスタンス作成と準備

まずは EC2インスタンスを作成します。
HDDの負荷試験を行うので、EBSタイプでなく InstanceStore (ローカルの EphemeralDisk を使用する)タイプのインスタンスを作成します。
OSは Ubuntu Server 12.04 (64bit)  を選択します。
上記の条件で検索するとAMI-ID が「ami-9763e696」のものが合致していたので、コレを使用します。
$ ec2-run-instances  \
     ami-01008700 \
     --group web  \
     --key innerkey  \
     --instance-count 1  \
     --instance-type m1.large


RESERVATION     r-9f52c89c      488224276535    web
INSTANCE        i-7b370f78      ami-01008700                    pending innerkey        0             m1.large        2013-02-26T08:32:57+0000        ap-northeast-1a aki-44992845                  monitoring-disabled                                     instance-store                                paravirtual     xen             sg-33bace32     default false

$ ec2-describe-instances i-7b370f78
RESERVATION     r-9f52c89c      488224276535    web
INSTANCE        i-7b370f78      ami-01008700    ec2-54-248-22-153.ap-northeast-1.compute.amazonaws.com        ip-10-132-148-246.ap-northeast-1.compute.internal       running innerkey      0               m1.large        2013-02-26T08:32:57+0000        ap-northeast-1a aki-44992845                  monitoring-disabled     54.248.22.153   10.132.148.246                  instance-store                                        paravirtual     xen             sg-33bace32   default false
ec2-describe-instances で確認しても BLOCKDEVICE 行が無いので EBS はアタッチされていないようですね。

今回のインスタンスは bitnami (?)というところが作成したものらしく、ログイン時のアカウントも bitnami となっています。
$ ssh \
     -i ~/.ssh/innerkey.pem \
     -l bitnami \
     ip-10-132-148-246.ap-northeast-1.compute.internal

ssh でログインできたら、sysbench をインストールしておきます。
$ sudo apt-get update
$ sudo apt-get install sysbench
最後に 接続されているディスクの状態を確認しておきます。

$ df -h
Filesystem Size Used Avail Use% Mounted on
/dev/xvda1 9.9G 1.8G 7.6G 20% /
udev 3.7G 8.0K 3.7G 1% /dev
tmpfs 1.5G 168K 1.5G 1% /run
none 5.0M 0 5.0M 0% /run/lock
none 3.7G 0 3.7G 0% /run/shm
/dev/xvdb 414G 199M 393G 1% /mnt

$ mount
/dev/xvda1 on / type ext4 (rw)
proc on /proc type proc (rw,noexec,nosuid,nodev)
sysfs on /sys type sysfs (rw,noexec,nosuid,nodev)
none on /sys/fs/fuse/connections type fusectl (rw)
none on /sys/kernel/debug type debugfs (rw)
none on /sys/kernel/security type securityfs (rw)
udev on /dev type devtmpfs (rw,mode=0755)
devpts on /dev/pts type devpts (rw,noexec,nosuid,gid=5,mode=0620)
tmpfs on /run type tmpfs (rw,noexec,nosuid,size=10%,mode=0755)
none on /run/lock type tmpfs (rw,noexec,nosuid,nodev,size=5242880)
none on /run/shm type tmpfs (rw,nosuid,nodev)
/dev/xvdb on /mnt type ext3 (rw,_netdev)
(負荷試験に)使えそうなディスクは / と /mnt にマウントされているようですが…。
まぁ、Ephemeral Disk (ローカルHDD)であれば、中身は気にしないので コレで良いということにしておきます。

前準備はこれで終わり。



・負荷試験の実施
HDDに対する負荷試験なので、まずはHDD側の準備。
$ cd /mnt
$ sudo mkdir loadtest
$ sudo chown bitnami:bitnami loadtest
$ cd loadtest/
$ ls -lah
total 8.0K
drwxr-xr-x 2 bitnami bitnami 4.0K Feb 26 09:07 .
drwxr-xr-x 4 root    root    4.0K Feb 26 09:07 ..
次に、負荷試験を実行します。特に言及しない限り、この以降の操作は この負荷試験が実行継続している状態であることを前提としておきます。
$ sysbench \
     --max-requests=9999999 \
     --max-time=900 \
     --num-threads=2 \
     --test=fileio \
     --file-test-mode=rndrw  \
     prepare

sysbench 0.4.12:  multi-threaded system evaluation benchmark

128 files, 16384Kb each, 2048Mb total
Creating files for the test...

$ sysbench \
     --max-requests=9999999 \
     --max-time=900 \
     --num-threads=2 \
     --test=fileio \
     --file-test-mode=rndrw  \
     run
sysbench 0.4.12:  multi-threaded system evaluation benchmark

Running the test with following options:
Number of threads: 2

Extra file open flags: 0
128 files, 16Mb each
2Gb total file size
Block size 16Kb
Number of random requests for random IO: 9999999
Read/Write ratio for combined random IO test: 1.50
Periodic FSYNC enabled, calling fsync() each 100 requests.
Calling fsync() at the end of test, Enabled.
Using synchronous I/O mode
Doing random r/w test
Threads started!
以下、(負荷試験状態を継続したまま)続きます。



・よくある調べ方
初心者のサーバ運用者(自分だ!)だと、まずは以下のようなコマンドで負荷の全体像をつかみます。
top
vmstat
iostat
     ※ iostat は標準ではインストールされていないようなので、
       sudo apt-get install sysstat でインストールしておいて下さい。
sysbench で 負荷試験実行中に 上記コマンドを試してみます。

まずは topコマンド。
$ top
Tasks:  82 total,   1 running,  81 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.0%us,  1.0%sy,  0.0%ni, 43.8%id, 55.2%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   7629484k total,  2892128k used,  4737356k free,    40052k buffers
Swap:        0k total,        0k used,        0k free,  2426708k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 1993 bitnami   20   0 21764 1144  808 S    2  0.0   0:06.43 sysbench
  618 root      20   0     0    0    0 S    0  0.0   0:00.99 kjournald
 2612 bitnami   20   0 17336 1244  944 R    0  0.0   0:00.03 top
    1 root      20   0 24340 2268 1360 S    0  0.0   0:01.54 init
    2 root      20   0     0    0    0 S    0  0.0   0:00.00 kthreadd
    3 root      20   0     0    0    0 S    0  0.0   0:00.01 ksoftirqd/0
    4 root      20   0     0    0    0 S    0  0.0   0:00.00 kworker/0:0
    5 root      20   0     0    0    0 S    0  0.0   0:00.02 kworker/u:0
    ~
topコマンド 一発で 原因である sysbench を発見!!!
…と思ったら、単に CPU負荷/利用率からみて top に表示されているだけでした。
肝心の HDD への負荷によって順位が上がっているワケではないようです。
コレではちょっと使えないです(x_x;


次は vmstat 。
$ vmstat 4
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 0  2      0 4742504  35308 2426628    0    0    29   742   61   53  1  0 93  6
 0  1      0 4742336  35532 2426632    0    0     0  4728  375  214  0  1 51 48
 0  1      0 4742172  35740 2426632    0    0     1  4258  328  171  0  1 53 46
 0  2      0 4741940  35944 2426636    0    0     0  4246  328  182  0  1 53 46
IO負荷(というか IOwait ... waカラム)が高いことはスグに分かりますが…肝心の「どのブログラムが原因なのか」がサッパリ分かりません。

次は iostat を試してみます。
$ iostat
Linux 3.2.0-38-virtual (ip-10-132-148-246)      02/26/2013      _x86_64_        (2 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.38    0.00    0.49   14.26    0.38   84.49

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
xvdap1            4.32        30.20        80.20     128153     340388
xvdb            104.86         0.52      1981.51       2201    8409580
xvdc              0.12         0.36         0.00       1540          0
どの HDD を、どのぐらい読み書きしているのかはハッキリ分かりますが、これも原因を特定してはくれません…。
⇒ 「重いHDDドレなのか?」が分かるのは、ソレはそれで価値があるので iostat は、その点では便利でしょう!



・もっと調べる
インフラに詳しい人に教えてもらったところ、HDD/負荷を調査するのであれば 以下のようなコマンドが使えるらしいです。
lsof
iotop
dstat
ps (で stat が Dであるものを探す)
早速使ってみましょう。



・lsof コマンド
まずは lsof コマンド。どのプロセスがどのファイルを操作しているのか調べられるらしいですが…root 権限が必要らしいです。
$ sudo lsof 
COMMAND    PID       USER   FD      TYPE             DEVICE SIZE/OFF       NODE NAME
init         1       root  cwd       DIR              202,1     4096          2 /
init         1       root  rtd       DIR              202,1     4096          2 /
init         1       root  txt       REG              202,1   167192      17027 /sbin/init
init         1       root  mem       REG              202,1    52120     395345 /lib/x86_64-linux-gnu/libnss_files-2.15.so
init         1       root  mem       REG              202,1    47680     395347 /lib/x86_64-linux-gnu/libnss_nis-2.15.so
~略~
全プロセスが対象になるらしく、リストが長すぎて探すのが困難です。grep してみましょう…。
$ sudo lsof \
| egrep -e '/mnt/loadtest/' -e '^COMMAND'
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
sysbench 2687 bitnami 3u REG 202,16 16777216 4931586 /mnt/loadtest/test_file.0
sysbench 2687 bitnami 4u REG 202,16 16777216 4931587 /mnt/loadtest/test_file.1
sysbench 2687 bitnami 5u REG 202,16 16777216 4931588 /mnt/loadtest/test_file.2
sysbench 2687 bitnami 6u REG 202,16 16777216 4931589 /mnt/loadtest/test_file.3
sysbench 2687 bitnami 7u REG 202,16 16777216 4931590 /mnt/loadtest/test_file.4
sysbench 2687 bitnami 8u REG 202,16 16777216 4931591 /mnt/loadtest/test_file.5
sysbench 2687 bitnami 9u REG 202,16 16777216 4931592 /mnt/loadtest/test_file.6
sysbench 2687 bitnami 10u REG 202,16 16777216 4931593 /mnt/loadtest/test_file.7
sysbench 2687 bitnami 11u REG 202,16 16777216 4931594 /mnt/loadtest/test_file.8
sysbench 2687 bitnami 12u REG 202,16 16777216 4931595 /mnt/loadtest/test_file.9
~略~
大量に発見できますが…。今回は 操作対象のファイルが分かっているので lsof で特定できますが、そうできない状況の方が多いような気もします…。
結局 lsof も便利ではありますが、今回欲しかったコマンドではなさそうです。
⇒ もし対象ファイル/ディレクトリが判明しているのであれば、使えるコマンドですね。



・iotopコマンド

次は iotop コマンド。Ubuntu には標準インストールされていないようなので sudo apt-get install iotop  としてインストールしておきます。
インストールできたら使ってみましょう。root 権限が必要なので、sudo 経由で使用します。
$ sudo iotop
Total DISK READ: 0.00 B/s | Total DISK WRITE: 5.83 M/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
618 be/4 root 0.00 B/s 0.00 B/s 0.00 % 94.75 % [kjournald]
2722 be/4 bitnami 0.00 B/s 2.73 M/s 0.00 % 34.81 % sysbench --max-requests 9999999 --~ fileio --file-test-mode rndrw run
2721 be/4 bitnami 0.00 B/s 2.80 M/s 0.00 % 18.32 % sysbench --max-requests 9999999 --~ fileio --file-test-mode rndrw run
1 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % init
2 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % [kthreadd]
3 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % [ksoftirqd/0]
4 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % [kworker/0:0]
5 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % [kworker/u:0]

ズバリ判明!
恐ろしい!!!
もう、他のコマンド要らないかも…(^^;



・dstatコマンド
dstat コマンドはUbuntu標準ではインストールされていないので sudo apt-get install dstat としてインストールしておきます。
インストールできたら、dstat を実行してみます。

dstat

何も考えずにdstatを実行したら、ものすごくカラフルな結果になりました。
色を抑制したい場合は --nocolor オプションが使えるようです。

man dstat として中を読んでみると、--top-* 系オプションで一番コストがかかっているモノをいろいろ検索できるようです。
今回は IO 処理 なので、--top-io で調べてみます。
$ dstat --nocolor --time --top-io
----system---- ----most-expensive----
time | i/o process
26-02 10:57:14| 3173k 2363k
26-02 10:57:15|sysbench 7680k 5120k
26-02 10:57:16|sysbench 6720k 4480k
26-02 10:57:17|sysbench 3840k 2560k
26-02 10:57:18|sysbench 10M 7040k
26-02 10:57:19|sysbench 7680k 5120k
26-02 10:57:20|sysbench 8640k 5760k
26-02 10:57:21|sysbench 8656k 5760k
26-02 10:57:22|sysbench 4800k 3200k
26-02 10:57:23|sysbench 8624k 5776k
26-02 10:57:24|sysbench 7696k 5104k
こちらも、そのままズバリ sysbench が発見されていますね。「一番重いプロセス」を見つけるには最適なコマンドかもしれません。
他のオプションも付与してみると、もっと楽しく(?)なります。
$ dstat --nocolor --time --top-io --disk
----system---- ----most-expensive---- -dsk/total-
time | i/o process | read writ
26-02 11:00:57| 3902k 2842k| 15k 3041k
26-02 11:00:58|sysbench 8640k 5776k| 0 5676k
26-02 11:00:59|sysbench 6720k 4480k| 0 5228k
26-02 11:01:00|sysbench 8640k 5760k| 0 5840k
26-02 11:01:01|sysbench 6736k 4464k| 0 5056k
26-02 11:01:02|sysbench 6720k 4480k| 0 4760k
26-02 11:01:03|sysbench 7664k 5136k| 0 5412k
26-02 11:01:04|sysbench 8640k 5760k| 0 6128k
26-02 11:01:05|sysbench 8640k 5760k| 0 5964k
ディスクIOの数値も表示されるようになりました。
dstat も、かなり使えるコマンドですね。



・ps で stat = D のものを探す
ps コマンドの表示結果から、STAT 列が D であるものダケを探せば、HDDに負荷をかけているプロセスの正体が判明するそうです。stat の意味を man ps で調べると…
PROCESS STATE CODES
       Here are the different values that the s, stat and state output specifiers (header "STAT" or "S") will display to
       describe the state of a process:
       D    uninterruptible sleep (usually IO)
       R    running or runnable (on run queue)
       S    interruptible sleep (waiting for an event to complete)
       T    stopped, either by a job control signal or because it is being traced.
       W    paging (not valid since the 2.6.xx kernel)
       X    dead (should never be seen)
       Z    defunct ("zombie") process, terminated but not reaped by its parent.
       .....
…ということなので、まぁ、そんなもんなのでしょう。

まずは ps auxwww として、プロセス一覧を表示してみます。
$ ps auxwww | head
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1 0.0 0.0 24340 2268 ? Ss 08:35 0:01 /sbin/init
root 2 0.0 0.0 0 0 ? S 08:35 0:00 [kthreadd]
root 3 0.0 0.0 0 0 ? S 08:35 0:00 [ksoftirqd/0]
root 4 0.0 0.0 0 0 ? S 08:35 0:00 [kworker/0:0]
root 5 0.0 0.0 0 0 ? S 08:35 0:00 [kworker/u:0]
root 6 0.0 0.0 0 0 ? S 08:35 0:00 [migration/0]
root 7 0.0 0.0 0 0 ? S 08:35 0:00 [watchdog/0]
STAT が D であるものだけを見つけるのは、目視でも grep でも困難に思えます。

ps の --format オプションを使用して出力の順序を変更し、先頭に stat が来るようにします。その上で、grep ^D で絞り込んでみます。
$ ps ax --format 'stat %cpu %mem user cmd' \
     | grep '^D'

D     0.1  0.0 root     [kjournald]
期待とは違う結果になりましたね…。

sysbenchの状態がどのようになっているのか……sysbenchダケを探してみます。
$ ps ax --format 'stat %cpu %mem user cmd' \
     | grep 'sysbench'

Sl+   2.3  0.0 bitnami  sysbench --max-requests 9999999 --max-time 900 --num-threads 2 --test fileio --file-test-mode rndrw run
S+    0.0  0.0 bitnami  grep --color=auto sysbench
sysbench の stat は D ではなく Sl+ となっていますね…。+ は「foregroud process」という意味らしいので、Slに意味があるんだけれど…「長時間のevent待ち」 って...。
⇒ 他の環境で、HDDのアクセス負荷が問題になっていた時には この stat=D を探す方法で発見できたのですが…。

原因は何なのか? あるいは調べ方が悪いのか...?
  1. HDDが遅くて待たされているわけではないため、stat=Dとはならない。
  2. sysbenchの使用しているAPIは stat=D ではなく、stat=Sl を発生させる。
  3. AWSのEphemeralDiskは(ドライバか何かの都合で) stat=D とはならない。 
妄想だけはいくらでもできますが、真実は不明…。今度 調べるときに sysbench 以外を使ってみようかな…。
⇒ sysbench のスレッド数を2倍にしても stat=D は発生しなかったので、(1)は違う気がしています。


・まとめ
HDD負荷が疑われる場合、以下のように問題を絞り込めるでしょう。
  1. top、vmstat、iostat などで 負荷の傾向と量を把握する
  2. iotop、dstat --top-io コマンドで、負荷原因となったプロセスを特定する
  3. ファイル/ディレクトリが特定できているなら lsof で問題プロセスを特定する
  4. root が取れないのであれば、ps コマンド等でガンバる


・後始末
作成したラージインスタンスは、時間当たりの利用料が高いので、作業が終わったらサッサと STOP、TERMINATE しておきましょう。

インスタンスを消去しないのであれば、sysbench を停止した後、以下のコマンドで sysbench ファイルの後始末をしておいてください。
$ sysbench \
     --max-requests=9999999 \
     --max-time=900 \
     --num-threads=2 \
     --test=fileio \
     --file-test-mode=rndrw  \
     cleanup


sysbench 0.4.12:  multi-threaded system evaluation benchmark
Removing test files..



今回はここまで。