困ったときのstraceとdaemontoolsの組み合わせ

Oct 15, 2012

レスポンスタイムが重要なサービスをやってると、「理由はわからないけどなぜか遅い。調べよう」ってなることが多いと思います。調べ方はいろんなアプローチがあると思いますが、Linux の場合straceというコマンドが超絶便利です。

strace is a system call tracer, i.e. a debugging tool which prints out a trace of all the system calls made by a another process/program.

strace | Free Development software downloads at SourceForge.net

strace とは？

straceはプロセスが発行するシステムコールをトレースできます。システムコールというのはプロセスがカーネルに作業を依頼する API みたいなもので(間違ってたらごめんなさい＞＜)、例えばネットワーク通信とかファイルの読み書きなんかは基本的にシステムコールを介して行われます。たとえばこんな感じ。

[root@host1 ~]# strace -ttT ping 8.8.8.8
21:04:09.575880 execve("/bin/ping", ["ping", "8.8.8.8"], [/* 19 vars */]) = 0 <0.000502>
21:04:09.576740 brk(0)                  = 0x8fb2000 <0.000005>
21:04:09.576788 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000007>
21:04:09.576843 open("/etc/ld.so.cache", O_RDONLY) = 3 <0.000008>
21:04:09.576883 fstat64(3, {st_mode=S_IFREG|0644, st_size=32219, ...}) = 0 <0.000006>
21:04:09.576937 mmap2(NULL, 32219, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7f47000 <0.000008>
21:04:09.576972 close(3)                = 0 <0.000007>
21:04:09.577049 open("/lib/libresolv.so.2", O_RDONLY) = 3 <0.000017>
21:04:09.577152 read(3,     "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300\20\315\0004\0\0\0"..., 512) = 512 <0.000038>
...

序盤だけ表示してますが、pingコマンドを実行したら、ライブラリを探しにいって読み込んでいますね。オプションをつけることで、実行時刻や実行時間を出力させています。(詳しくは man を見て下さい)

で、これがなぜ役立つかというと、特に WEB のアプリなんかは大概がネットワーク通信待ちを含む IO 待ちなので、もし極端に遅い IO があればシステムコールの実行時間をみれば一目瞭然です。なので、僕は意味不明に遅いのを調べるとき、とりあえずアプリのプロセスにstraceでアクセスして遅いシステムコールが無いかというのを真っ先に確認します。

もし、Perl のプロセス内の cpu 計算/memory 操作で時間を食っているとしたらここには現れなくて、その場合にはいわゆるプロファイラを利用すると良い感じです(Perl なら Devel::NYTProf など)。

ちなみに、-cというオプションで統計情報を出すこともできるので、一度統計情報を取ってから、明らかに遅いシステムコールに対して-eで指定して取ってあげると見やすいかもしれませんね。

daemontools と組み合わせるには？

で、今調べてるのがdaemontoolsで管理してるアプリが、なんか再起動が遅いことがあるという問題なので、とりあえずstraceを仕込んで何に時間かかってるのかを確認しようと思って以下の様な run スクリプトに変更しました。

#!/bin/sh
exec 2>&1
exec strace -ttT command...

これで標準出力をmultilogで記録しておいてあげれば(-tt要らないですが)、何が遅いか見れるぜヒャッハーと思ってたんですが、svc -tで TERM シグナルを送ってしまうとstraceのプロセスに飛んでしまうので、実際にアプリケーションが TERM を受け取って死に終わるまでのトレースを取る前にstraceが死んでしまう。。。

そこで、run スクリプトをちょっといじってみました。

#!/bin/sh
PID=$$
strace -p $PID -ttT 2>&1 &

exec 2>&1
exec command...

こうすることで、自分自身の PID に対してstraceを fork してアタッチしたあとに、本命のコマンドにexecで化けるので起動時点からのトレースができます。またsvc -tでシグナルが送る相手は本命のコマンド自身なので、本命のコマンドが死に終わっるまでトレースもできます。気になるのはstrace自身ですが、手元ではstraceがアタッチしてるプロセスが死んだってことで勝手にデタッチして消えてくれていました。

ちなみに-fという、子プロセスまでトレースするオプションをstraceに付けるとうまく死んでくれませんでした。今回はちょうどマネージャプロセスだけトレースできればよかったので放置してますが、子プロセスまでトレースしたい場合はどうにかしてstraceを外から殺してあげる必要がありそうですね。

まとめ

strace便利
daemontoolsの再起動周りとかも調べられる

というわけで Enjoy strace life!