はじめに
Linux ServerでApplicationのResponse Timeが悪化したり、Processが応答しなくなったりした場合、topやpidstatを使うことでProcessのCPU使用率や状態を確認できます。
しかし、Processを特定できても、「そのProcessがLinux Kernelに何を要求し、どこで待機・失敗しているのか」までは分からないことがあります。Fileを開けない、Network接続に失敗する、I/OやThread Synchronizationを待っている、といった問題はCPU使用率だけでは判断できません。
このような場合に利用できるのがstraceです。straceを利用すると、Processが発行するSystem Callと受信するSignalをTraceし、Argument、Return Value、ErrorなどからProcessとLinux Kernelの境界で何が起きているかを確認できます。
本記事では、Linuxトラブルシューティング連載の第8回として、straceを使い、Process → System Call → Error / Wait → File / Network / Synchronizationと原因を深掘りする方法を解説します。
straceとは
straceは、Processが発行するSystem Callと受信するSignalをTraceするToolです。ApplicationのSource Codeを直接Debugしなくても、ProcessがLinux Kernelに対してどのような処理を要求しているかを観測できます。
System CallはUser SpaceのApplicationがLinux Kernelの機能を利用するためのInterfaceです。straceはApplication内部のFunctionそのものをTraceするToolではなく、ProcessとKernelの境界を観測するToolです。
| 分類 | 代表的なSystem Call | 見るポイント |
|---|---|---|
| File / I/O | openat() / read() / write() / fsync() | File Access、Read / Write、同期 |
| Network | socket() / connect() / sendto() / recvfrom() | 接続、送受信、Error |
| Wait / Event | futex() / poll() / epoll_wait() | Thread / Event待ち |
| Process | clone() / execve() / wait4() | Process / Thread生成、実行、終了待ち |
straceによるトラブルシューティングの全体像
straceはProcess障害の最初に無条件で実行するToolではありません。まずtop、ps、pidstat、Application Logなどで対象を絞り、System Call Levelの確認が必要な場合に利用します。
重要なのは、straceだけでRoot Causeを断定するのではなく、System CallをEvidenceとして次に確認すべきLayerを絞ることです。
straceをインストールする
RHEL / AlmaLinux 9系ではstrace Packageをインストールして利用します。
# dnf install strace
$ strace --versionstraceの基本的な使い方
Commandを指定してTraceする
新しくCommandを起動し、最初からSystem Callを確認する場合はstraceの後ろにCommandを指定します。
$ strace <command>strace ls コマンドの表示例：
出力量は多くなるため、実際の障害調査では後述するFilterで対象を絞ることが重要です。
稼働中ProcessへAttachする
すでに稼働しているProcessをTraceする場合はPIDを指定します。
# strace -p <PID>strace -p <PID> の出力例：
TraceはCtrl + C で終了できます。権限やSecurity設定によっては他ProcessへのAttachが制限される場合があります。
straceの出力を読む
System Call名だけでなく、Argument、Return Value、errnoを確認します。
openat の表示例：
| 項目 | 意味 | 見るポイント |
|---|---|---|
openat() | ファイルをOpenするSystem Call | どのSystem Callが実行されているか |
AT_FDCWD | 相対Pathの場合、現在のWorking Directoryを基準にする指定 | Pathをどこを基準に解決するか |
"/etc/ld.so.preload" | Open対象のFile Path | ApplicationがどのFileへAccessしているか |
O_RDONLY | Read OnlyでOpen | Read / Writeなど、どのAccess Modeか |
O_CLOEXEC | exec時にFile DescriptorをCloseする指定 | File DescriptorにどのFlagが指定されているか |
= 3 | openat()の戻り値。この場合はFile Descriptor 3 | 成功か失敗か。成功時はFile Descriptor、失敗時は通常-1とerrnoが表示される |
Errorを確認する
Applicationが起動しない、Fileを読めない、接続できない場合はSystem CallのErrorが重要なEvidenceになります。
| errno | 意味 | 主な確認ポイント |
|---|---|---|
ENOENT | File / Directoryが存在しない | Path、設定ファイル、Mount |
EACCES | Permission denied | Permission、実行User、SELinuxなど |
ECONNREFUSED | Connection refused | Listen、Port、Firewall / Middlebox |
ETIMEDOUT | Operation timed out | Network経路、接続先、応答 |
EAGAIN | 一時的に処理できない | Non-blocking I/O、Resource状態、文脈 |
Error CodeだけでRoot Causeを断定しないことも重要です。たとえばECONNREFUSEDは接続先Applicationだけでなく、途中の機器などがResetを返すケースもあります。
straceでは、System Callが失敗すると通常= -1とerrnoが表示されます。まずどのSystem Callが、どのArgumentで、どのerrnoを返したかを確認し、具体的な調査はFile / I/OやNetworkなど該当するLayerへ進めます。
File / I/Oを調査する
File AccessやI/Oが疑われる場合はopenat()、read()、write()、fsync()などを確認します。System Call名だけでなく、Return Valueとerrno、さらに-Tで確認できる経過時間も合わせて見ます。
read()の戻り値を確認する
read()は戻り値によって、読み込めたByte数、EOF、Errorを区別できます。
read(3, "Hello Linux\n", 131072) = 12
read(3, "", 131072) = 0
read(3, ..., 131072) = -1 E...| 戻り値 | 意味 | 見るポイント |
|---|---|---|
> 0 | 読み込んだByte数 | Dataを正常に読み込めている |
0 | EOF | File終端など。Errorではない |
-1 | Error | errnoを確認する |
fsync()のErrorを確認する
例えばfsync()がErrorになった場合、以下のようにReturn Valueとerrnoから失敗を確認できます。
この例では/dev/nullに対してfsync()を実行し、意図的にEINVALを発生させています。実際のStorage障害を再現した例ではありません。実環境ではerrnoと対象File、File System、Storage側の状態を合わせて確認します。
read()やfsync()の完了に時間がかかっていても、straceだけでStorageが原因と断定してはいけません。straceで見えるのはProcessから見たSystem Callの挙動です。Block I/O側はiostatやpidstat -dなどで確認します。
Network接続を調査する
Network接続が疑われる場合はsocket()、connect()、sendto() / sendmsg()、recvfrom() / recvmsg()などを確認します。
connect()のReturn ValueからProcessが認識した接続結果を確認できます。
ncコマンドによる接続が失敗した例：
connect()で127.0.0.1の9999番ポートへのTCP接続を試みています。今回は接続先ポートで待ち受けているプロセスがないため、最終的にECONNREFUSEDが返され、Connection refusedとして接続に失敗しています。
なお、connect()のEINPROGRESSは接続失敗そのものではなく、非同期で接続処理中であることを示しています。その後のgetsockopt()でECONNREFUSEDを確認しているのがポイントです。
straceで見えるのはProcessから見たSystem Callの結果です。SYN / SYN-ACK / RST / RetransmissionなどPacket Levelの挙動はtcpdumpやWiresharkで確認します。
Processが何を待っているか確認する
CPU使用率が低いにもかかわらずResponseが遅い場合、ProcessやThreadがEventを待っている可能性があります。
| System Call | 主な意味 | 見るポイント |
|---|---|---|
futex() | Synchronizationに関連する待機 | Mutex / Condition Variableなど |
poll() / ppoll() | FDのEvent待ち | Socket / Pipeなど |
select() | 複数FDのEvent待ち | 対象FD、Timeout |
epoll_wait() | epoll Event待ち | 正常なIdle待機の場合も多い |
futexやepoll_waitが表示されたからといって、それ自体が異常とは限りません。Server Applicationでは正常な待機の場合もあるため、Response TimeやThread状態、Application Logと組み合わせて判断します。
TraceするSystem Callを絞り込む
-e trace=を使うと、仮説に応じてTraceするSystem Callを限定できます。
# strace -e trace=openat,read,write -p <PID>
# strace -e trace=socket,connect,sendto,recvfrom -p <PID>大量のSystem Callを眺めるのではなく、症状から仮説を立ててTrace対象を絞ることが重要です。一部だけをFilterした場合は、表示されていないSystem Callを含むProcess全体の動作を推測しすぎないようにします。
子Process / Threadを追跡する
子ProcessやThreadを生成するApplicationでは-fでfork / cloneなどにより生成されたTraceeも追跡できます。
# strace -f -p <PID>Multi-process / Multi-thread Applicationでは出力量と負荷が増えるため、Filterと組み合わせます。
System Callにかかった時間を確認する
性能問題を調査する場合は、個々のSystem Callの経過時間を見る-Tと、System Callごとの統計を確認する-cを使い分けます。
| Option | 確認できるもの | 向いている用途 |
|---|---|---|
-T | 個々のSystem Callの経過時間 | どの呼び出しで長く待っているか確認する |
-c | System Callごとの回数、Error、時間の統計 | System Call全体の傾向を把握する |
-Tで経過時間を確認する
-Tは各System Callの開始から終了までの経過時間を、行末の<秒>で表示します。
以下では、openat()の経過時間を表示しています。
例えば<0.000013>なら、そのSystem Callの開始からReturnまで約13マイクロ秒かかったことを示します。長時間完了しないSystem Callを探す手掛かりになります。
ただし、System Callの経過時間が長いことと、その下位LayerがRoot Causeであることは同義ではありません。例えばread()が長時間化していても、File、Socket、Pipeなど対象FDによって待っているものは異なります。
-cでSystem Callを集計する
-cはSystem CallごとのCall回数、Error数、時間などを集計してSummary表示します。
# strace -c -p <PID>
# strace -c lslsコマンド実行時の集計値表示例：
| 項目 | 意味 | 見るポイント |
|---|---|---|
% time | straceが集計したSystem Call時間全体に占める割合 | どのSystem Callが計測時間の大きな割合を占めたか |
seconds | そのSystem Callに費やされた集計時間 | System Callごとの時間を比較する |
usecs/call | 1 Callあたりの平均時間（マイクロ秒） | 1回あたりの処理時間の目安 |
calls | 呼び出し回数 | 大量に呼ばれているSystem Callを確認する |
errors | Errorになった回数 | errnoを伴う失敗が多いSystem Callを確認する |
syscall | System Call名 | どの処理の統計か確認する |
例えばwait4の% timeが65.25%なら、straceが集計したSystem Call時間全体のうち65.25%をwait4が占めたことを示します。Application全体のWall-clock実行時間の65.25%という意味ではありません。
また、-cの結果を単純な「待ち時間ランキング」と解釈しないことが重要です。個々のSystem Callが実際にどの程度の経過時間を要したかを調べる場合は、-Tの結果と組み合わせて確認します。
Trace結果をFileへ保存する
障害時のEvidenceとしてTrace結果をFileへ保存できます。
# strace -o /tmp/strace.log -p <PID>Trace LogにはPath、接続先、Argument、場合によってはApplication Dataなど機密情報が含まれる可能性があるため、取扱いに注意してください。
straceを使ったApplication遅延のトラブルシューティング例
Web ApplicationのResponse Timeが悪化しているものの、CPU使用率は高くないケースを例に調査します。
① Processを特定する
# top
# pidstat -u -p <PID> 1対象Processを特定し、CPU Bottleneckではないことを確認したとします。
② straceでSystem Callを確認する
# strace -T -p <PID>③ Wait / Errorを確認する
Application遅延
↓
strace
↓
System Call
├─ connect() → Network?
├─ read() → File / Socket?
├─ fsync() → Storage?
└─ futex() → Synchronization?④ 次のLayerへ進む
| straceで見えた状況 | 次に確認する例 | 対象 |
|---|---|---|
connect()の失敗 / 長時間化 | ss、tcpdump | Network / 接続先 |
read() / fsync()の長時間化 | iostat、pidstat -d | File / Block I/O |
futex()の長時間待機 | Thread Dump、Profiler | Lock / Thread |
openat()がENOENT | Path、Mount、設定 | File / Configuration |
straceの役割はSystem CallだけでRoot Causeを即断することではなく、ProcessがどこでKernelとのやり取りに失敗・待機しているかを確認し、次の調査対象を絞ることです。
straceと他のToolの使い分け
| Tool | 主に見るもの | 用途 |
|---|---|---|
| strace | System Call / Signal | ProcessとKernelの境界、Error / Wait |
| perf | CPU / Function / Call Graph | CPU Hotspot |
| tcpdump | Network Packet | TCP / DNSなどPacket解析 |
| kdump / crash | Kernel Crash / vmcore | Kernel PanicのPostmortem解析 |
| eBPF | Kernel / Process Event | CPU、I/O、Networkなどの動的観測 |
straceを本番環境で使用する際の注意点
Performanceへの影響を考慮する
straceは対象ProcessのSystem CallをTraceするため、Applicationの実行速度に影響を与えます。System Call頻度が高いProcessほど影響が大きくなる可能性があります。本番では対象と時間帯を絞り、短時間・限定的に利用します。
Trace対象を絞る
無条件にすべてTraceせず、障害の仮説に応じて-e trace=などで対象を限定します。
子Process / ThreadのTraceに注意する
-fで多数のProcess / Threadを追跡するとTrace量とOverheadが増えます。Process構成を確認して利用します。
機密情報の取扱いに注意する
System CallのArgumentにはFile Path、接続先、Application Dataなどが表示される場合があります。Trace Logは機密情報として適切に管理します。
straceだけで原因を断定しない
read()が遅いからDisk障害、connect()が遅いからNetwork障害、futex()が見えるからLock障害、と単純には断定できません。iostat、ss、tcpdump、perf、Application Log、Thread Dumpなどと組み合わせます。
まとめ
straceはLinux Processが発行するSystem Callと受信するSignalをTraceし、ProcessとLinux Kernelの境界で何が起きているかを確認するためのToolです。
- Processを特定：top、ps、pidstatで対象を絞る。
- strace：System Call、Argument、Return Valueを確認する。
- Error：errnoから失敗内容を確認する。
- Wait：futex、poll、epoll_waitなどから待機を確認する。
- -e trace=：仮説に応じて対象を絞る。
- -T：System Callの経過時間を確認する。
- 次の調査：File / I/O、Network、Threadなど該当Layerへ進む。
Processトラブルシューティングでは、Process → System Call → Error / Wait → File / Network / Synchronizationと段階的に深掘りすることが重要です。straceを単独で使うのではなく、top、pidstat、iostat、tcpdump、perf、Application Logなどと組み合わせて原因を絞り込みます。
Japanese 
English
コメント