strace でプログラムの動きを追ってみよう

こんにちは。サイオステクノロジーの貝野です。

プログラム (特定のプロセス) があるひとつの処理を実行する際、内部的にどのような処理がどのような順序で実行されているのか確認したい場合があると思います。
しかし、ログファイルからは詳細な処理内容が確認できない場合も多いです。

このような時、strace というデバッグツールを使用する方法があります。
strace は、特定プロセスのシステムコールレベルでの処理をトレースできるツールです。

今回は、strace コマンドの実行例を元に、実行結果の見方や主なシステムコールについてご紹介します。

1 strace コマンドの概要
2 strace コマンド実行例1
3 strace コマンド実行例2
4 おわりに

strace コマンドの概要

strace コマンドの使用方法、および主なオプションについてご説明します。

以下のように、コマンドの前に “strace” を指定すると、実行したコマンドの strace が取得できます。

$ strace <コマンド>

また、既に実行されているプロセス (デーモンなど) の strace を取得することもできます。
以下のように “-p” オプションの後にプロセスの PID を指定します。

コマンドを終了するには、[Ctrl] + C を実行してください。

strace -p <プロセスの PID>

通常、実行結果はターミナル上に出力されますが、ファイルに出力したい場合は “-o” オプションを指定します。
この場合、ターミナル上に実行結果は表示されず、コマンドの実行結果のみが表示されます。
簡単なコマンドでも strace の実行結果は 100行を軽く超えるため、予めファイルに出力しておくことをおすすめします。

$ strace -o <出力先のパス> <コマンド>

コマンド (もしくはプロセス) においてシステムコールが実行された時間を表示する場合は “-t” または “-tt” オプションを指定します。”-t” を指定した場合は秒単位で、”-t” を指定した場合はマイクロ秒単位で、実行された時間が出力されます。
ログと突き合わせて調査する場合など、時間が表示されていると分かりやすいです。

$ strace -t <コマンド>

子プロセスの情報も併せて取得する場合は “-f” オプションを指定します。
特にデーモンプロセスの場合は、親プロセス + 複数の子プロセスが実行される事が多いため、”-f” を指定しないと何も出力されない場合があります。

$ strace -f <コマンド>

strace コマンド実行例1

簡単な実行例として、ls コマンドでカレントディレクトリにあるファイル (ディレクトリ) の一覧を表示した場合の strace を取得してみます。
行数が多いので、-o オプションで実行結果をファイルに出力してから確認します。

$ strace -o strace_ls.txt ls .
rh  test1  test2  testdir  testt
$
$ less -N strace_ls.txt
1 execve("/usr/bin/ls", ["ls", "."], [/* 26 vars */]) = 0
2 brk(NULL)                               = 0x22ec000
3 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4c04346000
4 access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
5 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
…
(省略)
…
116 write(1, "rh  test1  test2  testdir  testt"..., 37) = 37
117 close(1)                                = 0
118 munmap(0x7f4c04345000, 4096)            = 0
119 close(2)                                = 0
120 exit_group(0)                           = ?
121 +++ exited with 0 +++

すると、たくさんの情報が出力されます。

1行目	execve：プログラム (コマンド) を実行します。
5行目	open：ファイルをオープンします。コマンドの実行に必要なライブラリなどがオープンされます。しばらく関連ライブラリのオープンが続きます。
116行目	write：ファイルディスクリプタに情報を書き込みます。今回の場合、ls コマンドの実行結果が write 関数によって標準出力に書き込まれています。
121行目	コマンドが正常終了 (0) したことを意味します。

このように、strace からシステムコールを追っていくと、どのタイミングでどのようなライブラリが呼び出され、いつコマンドの実行結果が出力されるかが明確になります。

strace コマンド実行例2

次は、もう少し複雑なプログラムの動作を確認してみます。

logrotate の処理において、以下のような設定を追加しました。

$ cat /etc/logrotate.d/hoge
/var/log/hoge.log {
        daily
        missingok
        rotate 4
        compress
        copytruncate
}

daily…日次でローテートします。
missingok…ログファイルが存在しなくても、エラーを出しません。
rotate 4…4世代分、ログを残します。
compress…ログファイルを圧縮します。
copytruncate…ログをコピーした後に、既存のログのサイズを 0にします。
通常は、既存のログを移動させた後に新しいログファイルを作ります。ログファイルを閉じないプログラムを動作させる場合は、この設定が必要です。

これらの設定が、どのような順序で処理されるかを strace から確認してみます。

以下のコマンドで、logrotate を手動で実行した際の strace を取得します。

今回は、logrotate の圧縮処理 (gzip) など、別のプログラムが呼び出されることを考慮し、-f オプションを付与しています。
-f オプションがある場合、プログラムの PID (下記の例ですと logrotate の PID は 11638) が表示されます。

$ strace -f -o strace_logrotate.txt /usr/sbin/logrotate -f /etc/logrotate.d/hoge
$
$ less -N strace_logrotate.txt
1 11638 execve("/usr/sbin/logrotate", ["/usr/sbin/logrotate", "-f", "/etc/logrotate.d/hoge"], [/* 26 vars */]) = 0
2 11638 brk(NULL)                         = 0x143e000
3 11638 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbc87133000
4 11638 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
5 11638 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
…
(省略)
…
116 open("/etc/logrotate.d/hoge", O_RDONLY) = 3
…
(省略)
…
320 11638 rename("/var/log/hoge.log.4.gz", "/var/log/hoge.log.5.gz") = 0
321 11638 rename("/var/log/hoge.log.3.gz", "/var/log/hoge.log.4.gz") = 0
322 11638 rename("/var/log/hoge.log.2.gz", "/var/log/hoge.log.3.gz") = 0
323 11638 rename("/var/log/hoge.log.1.gz", "/var/log/hoge.log.2.gz") = 0
324 11638 rename("/var/log/hoge.log.0.gz", "/var/log/hoge.log.1.gz") = -1 ENOENT (No such file or directory)
325 11638 access("/var/log/hoge.log.5.gz", F_OK) = 0
326 11638 open("/proc/thread-self/attr/fscreate", O_RDWR|O_CLOEXEC) = -1 ENOENT (No such file or directory)
327 11638 gettid()                          = 11638
328 11638 open("/proc/self/task/11638/attr/fscreate", O_RDWR|O_CLOEXEC) = 3
329 11638 write(3, NULL, 0)                 = 0
330 11638 close(3)                          = 0
331 11638 open("/var/log/hoge.log", O_RDWR|O_NOFOLLOW) = 3
332 11638 write(3, NULL, 0)                 = 0
333 11638 close(3)
…
(省略)
…
371 11640 execve("/bin/gzip", ["/bin/gzip"], [/* 26 vars */]) = 0
…
(省略)
…
423 11638 open("/var/log/hoge.log.5.gz", O_RDWR|O_NOFOLLOW) = 3
424 11638 unlink("/var/log/hoge.log.5.gz")  = 0
425 11638 close(3)                          = 0

1行目	execve：logrotate コマンドを実行します。
5行目	コマンドの実行に必要なライブラリなどがオープンされます。しばらく関連ライブラリのオープンが続きます。
116行目	今回作成した設定ファイル (/etc/logrotate.d/hoge) がオープンされます。
320～325行目	rename：ファイルの名前を変更します。ログがローテートされる処理になります。
331～333行目	copytruncate の設定により、/var/log/hoge.log のログサイズが 0 (NULL) となります。
371行目	compress の設定により gzip コマンドが実行され、ログを圧縮します。
423～425行目	unlink：ファイルシステムから削除します。今回は rotate を 4 に指定しているため、ローテートの過程で作成された /var/log/hoge.log.5.gz は削除されます。