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

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

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

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

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

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 +++

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

このように、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. ファイルのコピー
2. 既存のログのサイズを 0 に設定
3. zgip による圧縮

の順番で処理されていることが分かりました。

なお、今回は logrotate -f で強制的に logrotate を実行しており、かつログファイルも予め作成済みであったため、daily および missingok の項目に関する動作は反映されませんでした。

おわりに

strace の取得方法と、ほんの一部ではありますがシステムコールの意味について説明しました。
システムコールの種類は他にもたくさんありますので、必要に応じて確認してみてください。

https://linuxjm.osdn.jp/html/LDP_man-pages/man2/syscall.2.html

では、また。

About 貝野 友香 71 Articles

OSSよろず相談室でサポートをやっています。時々ライブ配信や勉強会に出ていることもあります。

Twitter YouTube