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

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

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

このような時、strace というデバッグツールを使用する方法があります。

strace は、特定プロセスのシステムコールレベルでの処理をトレースできるツールです。

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

strace コマンドの概要

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

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

また、既に実行されているプロセス (デーモンなど) の strace を取得することもできます。

以下のように “-p” オプションの後にプロセスの PID を指定します。

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

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

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

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

strace コマンド実行例1

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

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

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

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

strace コマンド実行例2

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

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

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

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

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

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

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 は削除されます。

上記の内容をまとめると、

  1. ファイルのコピー
  2. 既存のログのサイズを 0 に設定
  3. zgip による圧縮

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

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

おわりに

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

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

では、また。

>> 雑誌等の執筆依頼を受付しております。
   ご希望の方はお気軽にお問い合わせください!

ご覧いただきありがとうございます! この投稿はお役に立ちましたか?

役に立った 役に立たなかった

1人がこの投稿は役に立ったと言っています。

コメント投稿

メールアドレスは表示されません。


*