こんにちは。@kalibora です。
私は職業プログラマー歴20年弱になるのですが、
数年に一度くらいの割合で strace のお世話になることがあります。
今日はそんな話をしたいと思います。
といっても、strace の挙動についての深い話は一切ないので、
対象者としては strace というものを知らない、もしくは名前は知っているが使ったことがないようないわゆる #駆け出しエンジニア のような方に読んでいただければ幸いです。
strace とは
そもそも strace とはなんでしょうか。wikipedia を引用します。
straceはLinuxのデバッグユーティリティであり、プログラムが使用するシステムコールおよび受け取るシグナルを監視するものである。
だ、そうです。
man を引いてみましょう。
$ man strace
*snip*
NAME
strace - trace system calls and signals
*snip*
やはり、システムコールとシグナルをトレースする。と出てきました。
ここでシステムコールとはなんぞや。という疑問も出てきたかもしれません。 再度 wikipedia を引用します。
システムコール（英: system call、日: システム呼出し[1][2][3]）とは、オペレーティングシステム (OS)（より明確に言えばOSのカーネル）の機能を呼び出すために使用される機構のこと。実際のプログラミングにおいては、OSの機能は関数 (API) 呼び出しによって実現されるので、OSの備える関数 (API) のことを指すこともある。
というわけで、ざっくりいうと、 strace は OS の機能呼び出しをトレースするものだと言えると思います。
よくわかりませんね。実際に使ってみましょう。
strace 使ってみる
まずは hello strace と表示するだけのコマンドを適当な linux 上で打ちます。
言語は何でもいいんですが、ここでは PHP を使いたいと思います。
$ php -r 'echo "hello strace\n";' hello strace
表示されました。これに strace をかましてみます。 先程のコマンドの前に strace を入れるだけでOKです。
$ strace php -r 'echo "hello strace\n";' *snip* munmap(0x7fd31e600000, 2097152) = 0 munmap(0x7fd320c67000, 323584) = 0 exit_group(0) = ? +++ exited with 0 +++
上記と表示は異なるかもしれませんが、ずらずらーっと謎の文字列が表示されるかと思います。 細かく内容を見ていきたいので less をつないで見てみます。（エラー出力に出るので 2>&1 します）
$ strace php -r 'echo "hello strace\n";' 2>&1 | less
いろんな文字列がたくさん出ていると思うのですが、その中に下記のような表示も見つかると思います。
write(1, "hello strace\n", 13hello strace ) = 13
この行が実際に hello strace と画面に表示するための OS への機能呼び出しです。
はい。これが strace の機能です。
といっても、これが一体何の役に立つのだろうと思いませんか。 次節から実際に私が strace に助けられたケースを書いていきたいと思います。
ケース1: 自分の書いたテストは悪くないはずなのに・・
私がある機能を実装し、それに対するテストも追加し GitHub に push したところ、 その後の Circle CI 上でのテストがエラーになってしまいました。
エラーの内容を確認すると
Too long with no output (exceeded 10m0s): context deadline exceeded
と出ており、テスト（この時は phpunit ）実行時に10分間何の出力もないためエラーになったようです。
自分が追加したテストでそんなに変なことはしていないはずなので、
Circle CI に ssh 接続し、色々とデバッグを試みたところ、
追加したテスト単体で実行すると成功、そのテストを含むディレクトリをまるごと実行しても成功、しかしテストスイート全体を実行すると同じエラーで止まる。といった状態でした。
正直何が原因かまったく心当たりがなかったので strace を install し
$ strace ./vendor/bin/phpunit ...
のように、 テストコマンドを strace してみることにしました。 すると、
sendto(151, " \0\0\0\3TRUNCATE hoge_table"..., 36, MSG_DONTWAIT, NULL, 0) = 36
poll([{fd=151, events=POLLIN|POLLERR|POLLHUP}], 1, 86400000
のように、 TRUNCATE のSQLで MySQL から反応が返ってこない事がわかりました。
さらに mysql-client を install し、MySQL クライアント上で show processlist; したところ、
Waiting for table metadata lock が原因で反応が返ってきてこないこと、
たくさんコネクションが張られ続けること、などが分かりました。
これらの状況から、各テストコードで MySQL に接続したまま、それが閉じられていないことが原因と推測し、各テストコードでテストが終わったら接続を切るようにしたところ問題が解決しました。
ケース2: 終わらぬバッチ処理
いつもは数時間で終わる日次で実行しているバッチ処理があるのですが、それが数日経っても終わっていないということがありました。
まずは ps コマンドで該当のバッチ処理が存在し続けていること、プロセスIDを確認し、 該当のプロセスに対し strace コマンドを実行してみました。
-p オプションを使うと、処理中のプロセスに対しても strace をかけることが可能です。
（下記はプロセスID: 2354 に対して strace しています）
$ sudo strace -p 2354
strace: Process 2354 attached
*snip*
poll([{fd=11, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f24ff97e390}, NULL, 8) = 0
poll([{fd=11, events=POLLIN}], 1, 1000^Cstrace: Process 2354 detached
<detached ...>
上記はその時の結果なのですが、その中の下記の表示、
poll([{fd=11, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
fd=11（ファイルディスクリプタ=11） をpollしている（イベントを待っている）が、それがタイムアウトしているようでした。
ファイルディスクリプタ=11 の中身が何なのかを調べるには lsof コマンドを使います。
-p でプロセスID, -d でファイルディスクリプタを指定します。-a は AND 条件を表します。
（下記は一部表示を****でマスキングし、IPアドレスもダミーのものです）
$ sudo lsof -p 2354 -a -d 11 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME php 2354 **** 11u IPv4 22163744 0t0 TCP ****:40922->192.0.2.1:https (ESTABLISHED)
このように表示され、3rd Party の API との https 接続の結果が返ってきていないということが分かりました。
これに関してはプログラム中で、該当するAPIとのhttp通信時に適切なタイムアウトを設定していないことが原因だったため、タイムアウトを設定することで解決しました。
まとめ
なにか問題が起きているが、実際何が起きているのかよく分からない。
そんなときに strace はとても役に立つ可能性があります。
頭の片隅に入れておくといいかも。
