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

レスポンスタイムが重要なサービスをやってると、「理由はわからないけどなぜか遅い。調べよう」ってなることが多いと思います。調べ方はいろんなアプローチがあると思いますが、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!