LinuxでのStrace活用術:システムコール追跡でプロセスのハングやファイル欠落をデバッグする

Linux tutorial - IT technology blog
Linux tutorial - IT technology blog

現場の課題:ログを残さずにアプリケーションが停止するとき

ターミナルが無反応のまま立ち尽くした経験は誰にでもあるはずです。systemdユニットを再起動したり、デプロイスクリプトを実行したり、あるいはベンダー提供のバイナリを起動したものの、何の反応も返ってこない状態です。CPU使用率は0%に落ち込み、カーソルは点滅し続け、シェルには何のエラーコードも出力されません。

サイレント終了も同様に頭を抱える問題です。バイナリは起動した瞬間に終了し、手元に残るのは exit status 1 だけです。journalctl -u api-worker.service を確認し、/var/log/ 内をくまなく探しても何も見つかりません。アプリケーションがロギングフレームワークを初期化する前の段階でクラッシュした場合、標準的なログファイルから原因を突き止めることは不可能です。

クローズドソースのバイナリを逆コンパイルするのは現実的ではありません。稼働中の本番デーモンにGDBをアタッチするのもリスクが高すぎます。プロセスが異常停止する直前にLinuxカーネルへ何を要求していたのかを、迅速かつ低侵襲で可視化する手段が求められます。

根本原因の分析:ユーザー空間とカーネル空間の境界、そしてシステムコール

ローカルレジスタの演算や内部メモリアクセスを除き、ユーザー空間のアプリケーションがハードウェアを直接操作することはできません。プログラムがファイルを読み込む、ソケットをバインドする、スレッドを生成するなどの処理を行う際は、必ずシステムコール(syscall)を発行してカーネル空間へ移行する必要があります。

原因不明の停止やクラッシュは、ほぼ常に以下の3つのカーネルレベルの事象のいずれかに起因しています。

  • ネットワークの宛先に到達できない: プロセスがリモートのエンドポイントに対して connect() を呼び出します。アップストリームのファイアウォールがTCP RST を返さずにパケットをサイレントドロップすると、カーネルはSYNパケットの再送を繰り返します。Linuxのデフォルト設定では、タイムアウトするまでにソケットが最大127秒間ブロックされます。
  • ファイルの欠落とパーミッションの壁: バイナリが設定ファイルやTLS証明書に対して openat() または access() を呼び出します。対象のパスが存在しない場合、カーネルは -1 ENOENT を返します。権限が不足している場合は -1 EACCES を返します。適切に設計されていないバイナリは、これらのエラーを握りつぶして静かに終了してしまうケースが多々あります。
  • ロック競合とデッドロック: マルチスレッドのランタイムは futex() システムコールを介して排他制御を実装しています。ワーカースレッドがロックを取得したままクラッシュしたり、2つのワーカー間でデッドロックが発生したりすると、依存するスレッドはカーネルの待機キューに入ったまま無期限に停止します。

あらゆるI/OトランザクションはLinuxカーネルが処理するため、この境界線をトレースすることで障害原因を即座に特定できます。Go、Python、Rust、Cなど、ランタイムの言語を問わず通用するアプローチです。

ツールの比較:適切な診断ツールの選定

Linux環境で解決が難しいワークロードのトラブルシューティングを行う際、エンジニアは通常4つの診断レイヤーから選択します。それぞれに固有の役割と特徴があります。

1. 詳細ログフラグと環境変数

DEBUG=* や RUST_LOG=trace を設定したり、-vvv オプションを渡したりする方法は、ロジックエラーの特定に有効です。ただし、開発者が該当のコードパスにログ出力を仕込んでいることが前提となります。環境変数のパース前に初期化が中断される場合、デバッグフラグは役に立ちません。

2. インタラクティブデバッガ(GDB)

GNU Debugger(GDB)を使用すると、スタックフレーム、レジスタ、メモリ割り当てを詳細に検査できます。セグメンテーション違反(Segmentation Fault)の診断には最適です。しかし、GDBは実行スレッドを一時停止させる上に、通常はDWARFデバッグシンボル付きのストリップされていないバイナリを必要とします。本番稼働中の環境で使用するには大きな運用リスクが伴います。

3. eBPFおよびbpftrace

近年のLinuxカーネルは、bpftrace に代表されるExtended Berkeley Packet Filter(eBPF)ツールをサポートしています。オーバーヘッドが非常に小さく(多くの場合2%未満)、システム全体の可視化が可能です。一方で導入のハードルは高めです。カスタムBPFプローブの記述には CAP_BPF またはroot権限、カーネルヘッダー、そして専用のスクリプト技術が求められます。

4. Strace(システムコールトレーサー)

strace は ptrace() インターフェースを利用して、対象プロセスが発行するすべてのシステムコールをインターセプトします。引数、戻り値、消費された実行時間を出力します。ソースコードもデバッグシンボルも必要ありません。

ただし、strace には無視できないオーバーヘッドが伴います。ptrace() はシステムコール1回につき2回のコンテキストスイッチを発生させるため、アタッチされている間、I/O負荷の高いサービスでは処理速度が10倍から40倍遅くなる場合があります。適切なフィルタリングを活用して、オーバーヘッドを最小限に抑えることが重要です。

ツール 導入の手間 デバッグシンボル 実行速度の低下 最適なユースケース
詳細ログフラグ なし 不要 ごくわずか 既知のアプリケーション層のバグ
GDB 高 必要 高(実行停止) コアダンプ、メモリ破壊、クラッシュ
eBPF / bpftrace 中 不要 極めて低い(<2%) 本番環境での継続的なプロファイリング
strace なし 不要 中〜高 ハング、ファイル欠落、権限問題の迅速な切り分け

実践手順:Straceを用いた目的別のシステムコール追跡

実行中のプロセスに対してフィルタリングを行わずに strace を実行すると、数秒で数百メガバイトもの生テキストがターミナルに溢れ出します。ノイズに埋もれてしまわないよう、必ず調査対象のシステムコール群に絞り込んでトレースしてください。

1. 不足しているファイルとパーミッション拒否の特定

アプリケーションが起動時に何も出力せず終了してしまう場合は、-e trace=openat,access,stat を使用してキャプチャをファイルシステム関連のコールのみに限定します。

strace -e trace=openat,access ./my-application

初期化が途中で停止した際のトレース出力例:

openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/etc/app/config.yaml", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/home/appuser/.config/app.json", O_RDONLY) = -1 EACCES (Permission denied)
exit_group(1)                           = ?

原因は一目瞭然です。バイナリは /etc/app/config.yaml の読み込みを試みて ENOENT を受け取り、フォールバックとして /home/appuser/.config/app.json を開こうとしました。しかしプロセスの実行ユーザーに読み取り権限がなかったため(EACCES)、エラーハンドリングされずに異常終了しています。

2. 応答停止(ハング)したプロセスへのアタッチ

バックグラウンドデーモンがトラフィックの処理を停止した場合は、pgrep でPIDを取得し、-p でアタッチします。-f を追加することで、生成された子ワーカースレッドも追跡対象に含めます。

sudo strace -f -p 18492

未完了のシステムコールで行が止まっている場合は、その最後の行を注意深く確認してください。

[pid 18495] futex(0x7f3d540009c0, FUTEX_WAIT_PRIVATE, 2, NULL

呼び出しに対応する閉じ括弧や戻り値が出力されていないため、スレッド18495は別のスレッドが保持しているミューテックスの解放を待ってブロックされている状態であることがわかります。一方、未完了のソケット呼び出しが表示されている場合:

[pid 18493] connect(7, {sa_family=AF_INET, sin_port=htons(5432), sin_addr=inet_addr("10.0.12.44")}, 16

ワーカーは 10.0.12.44:5432 にあるPostgreSQLへの接続試行中にブロックされています。アプリケーションコードを修正する前に、セキュリティグループやファイアウォールのドロップルールを確認すべき状況です。

3. サマリープロファイリングによるボトルネックの特定

アプリケーションは正常に動作しているものの目に見えて処理が遅い場合は、詳細なトレースをスキップし、-c フラグを指定してstraceを統計モードで実行します。

strace -c python3 batch_processor.py

コマンドの実行が完了すると、straceはプロファイリング結果の集計表を出力します。

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 71.30    3.842100          45     84210           newfstatat
 18.25    0.983410          24     41000           openat
  6.40    0.344890           8     41000           close
  4.05    0.218200          43      5000           read
------ ----------- ----------- --------- --------- ----------------
100.00    5.388600                171210           total

Ubuntu 22.04 LTS環境で実施した実際の検証例では、batch_processor.py が1,000件のレコードを処理するのに5.4秒を要していました。実行時間の89%以上が、変更のないアセットに対する125,000回もの重複した newfstatat および openat ルックアップに費やされていたことが判明しました。メモリ上にパスキャッシュを導入したところ、実行時間は0.42秒へと短縮され、12倍の高速化を達成しました。

本番環境向けコマンドオプション一覧

シェルのセッションを固まらせたり標準出力のバッファを取りこぼしたりすることなく、重要なサービスを安全に追跡するには、実績のある以下のコマンドライン構成を使用します。

sudo strace -tt -T -s 256 -f -o /tmp/trace_$(date +%s).log -p <PID>
  • -o /tmp/trace.log: データを直接ディスクへ書き出します。標準出力の汚染を防ぎ、ターミナルの描画遅延によるオーバーヘッドを回避します。
  • -tt: 各行の先頭にマイクロ秒精度のタイムスタンプ(11:42:09.841023)を出力します。アプリケーションメトリクスとの突き合わせが容易になります。
  • -T: システムコール内部で費やされた時間(例:<0.012410>)を行末に出力し、高レイテンシの原因となっているカーネル呼び出しをあぶり出します。
  • -s 256: 文字列の最大出力長をデフォルトの32バイトから256バイトへ拡張し、完全なファイルパスや接続文字列を確認できるようにします。
  • -f: forkされた子プロセスやPOSIXスレッドも追跡します。このオプションがない場合、親の監視プロセスしかトレースされません。
Share: