Linux straceコマンドでシステムコールをトレースしデバッグする。プログラムの動作確認、性能調査に役に立つ

Linuxのstraceコマンドを使いこなせると、プログラムのデバッグや性能問題など調査に非常に役に立ちます。

この記事では実用的な使い方に絞って説明します。

straceをインストール

CentOSにstraceをインストールします。

# yum -y install strace

Ubuntuに straceをインストールします。
# apt install strace

straceコマンドの基本的な使い方は、他のサイト「straceコマンドの使い方」を参照ください。
（そちらが詳しいです。オプションの説明が充実しています。）

#
# yum -y install strace

# strace -V
strace -- version 4.24


# strace -h

Output format:
  -a column  alignment COLUMN for printing syscall results (default 40)
  -i         print instruction pointer at time of syscall
  -k         obtain stack trace between each syscall
  -o file    send trace output to FILE instead of stderr
  -q         suppress messages about attaching, detaching, etc.
  -r         print relative timestamp
  -t         print absolute timestamp
  -tt        print absolute timestamp with usecs
  -T         print time spent in each syscall
  -x         print non-ascii strings in hex
  -xx        print all strings in hex

Statistics:
  -c         count time, calls, and errors for each syscall and report summary
  -C         like -c but also print regular output
  -w         summarise syscall latency (default is system time)

Filtering:
  -e expr    a qualifying expression: option=[!]all or option=[!]val1[,val2]...
     options:trace, abbrev, verbose, raw, signal, read, write, fault, inject, kvm

Tracing:
  -b execve  detach on execve syscall
  -D         run tracer process as a detached grandchild, not as parent
  -f         follow forks
  -ff        follow forks with output into separate files

まず、dstatで当たりを付ける

dstatを実行し、５秒ごとの値が表示されるので、何が遅いかおおよその見極めを行います。

cpu、dsk(ディスク)、net(ネットワーク)、paging(メモリ不足でスワップ)　の値の変化で判断します。

今回は、ディスクのI/O(write/read)が多いケースで説明します。

straceで解析方法

１．流れを確認
２．システムコールの呼び出し回数を確認

呼び出しの流れを見る場合は　-t オプション

システムコール実行時刻（秒単位）の表示方法(-t) -tオプションを指定してstraceコマンドを実行します。
システムコールの実行時刻が秒単位で表示（左端の時刻）されます。

プロセスの動きの流れを見る場合に適しています。以下はPIDが1234の場合に実行方法です。

strace -t -p 1234

ただし、これだと大量に出力され、解析が難しいです。
不要なシステムコールのフィルタが必要です。

特定のシステムコールを表示(-e trace=システムコール名)

特定のシステムコールを表示する方法(-e trace=システムコール名)

以下のようにファイルI/O関連のシステムコールをトレースします。(正確には他にもあります)

-e ‘trace=open,read,write,close,pwrite64,pread64,sync,fsync’

PROGRAM01 は解析対象のプログラム名です。

すでに動作中のプログラムも解析可能です。

strace -t -e ‘trace=open,read,write,close,pwrite64,pread64,sync,fsync’ -f -p `pidof PROGRAM01`

：
strace -t -e 'trace=open,read,write,close,pwrite64,pread64,sync,fsync' -f -p `pidof PROGRAM01`
　：
[pid  2495] 15:42:49 pwrite64(57, "0\0\0\0\0\0\0\0", 8, 9530) = 8
[pid  2495] 15:42:49 pwrite64(57, "\0dS\0\0\0\0\213Q\v\0\0\0\0\0\327\1\0\0213"..., 48, 9538) = 48
[pid  2495] 15:42:49 pwrite64(12, "\210\1\2301\0\0\0\0\0\0\\355\235y\\"..., 7168, 9306112) = 7168
[pid  2495] 15:42:50 pwrite64(57, "0\0\0\0\0\0\0\0", 8, 9586) = 8
[pid  2495] 15:42:50 pwrite64(57, "\0eS\0\0\1\0\0\0\0\0\0\2\0\0\0\0\0\0\0\216"..., 48, 9594) = 48
[pid  2495] 15:42:50 pwrite64(57, "0\0\0\0\0\0\0\0", 8, 9642) = 8
[pid  2495] 15:42:50 pwrite64(57, "\0fS0\331\1\0\0\0\0\0\0\2\0\0\0\0\0\0\0\222"..., 48, 9650) = 48
[pid  2495] 15:42:50 pwrite64(12, "\210315\24\0\0\0\0\31\5x\1\355\235yX"..., 7168, 9764864) = 7168：
：

＜以下の１行を説明＞
[pid 2495] 15:42:49 pwrite64(57, “\0dS\0\213Q\v\”…, 48, 9538) = 48

■表示の意味
・pid 2495 : スレッドID。マルチスレッドプログラムの場合は複数のPIDが表示される。

・pwrite64(57,　：　57はファイルディスクリプタ(FD)　（後程説明）

・pwrite64(…) = 48 ：最後の数字が書き込んだバイト数

ファイルディスクリプタ57のファイルにスレッドID 2495が、48バイト書き込んだということです。

作成したプログラムで書き込んだファイルと書き込みサイズが正しいかなどを確認できます。

どういったスレッドが存在するかは、pstackで確認

■どういったスレッドが存在するかを、pstackで確認します。
pstack `pidof PROGRAM01`

＜例＞

：

$ pstack 2662

Thread 4 (Thread 0x7fab02be4700 (LWP 2667)):
#0 0x00007fab13b15c3d in poll () from /lib64/libc.so.6
#1 0x00007fab16cb237c in g_main_context_iterate.isra.19 () from /lib64/libglib-2.0.so.0
#2 0x00007fab16cb24ac in g_main_context_iteration () from /lib64/libglib-2.0.so.0
#3 0x00007fab16cb24e9 in glib_worker_main () from /lib64/libglib-2.0.so.0
#4 0x00007fab16cd9540 in g_thread_proxy () from /lib64/libglib-2.0.so.0
#5 0x00007fab13df7ea5 in start_thread () from /lib64/libpthread.so.0
#6 0x00007fab13b2096d in clone () from /lib64/libc.so.6
Thread 3 (Thread 0x7fab023e3700 (LWP 2669)):
#0 0x00007fab13b15c3d in poll () from /lib64/libc.so.6
#1 0x00007fab16cb237c in g_main_context_iterate.isra.19 () from /lib64/libglib-2.0.so.0
#2 0x00007fab16cb26ca in g_main_loop_run () from /lib64/libglib-2.0.so.0
#3 0x00007fab16995ed6 in gdbus_shared_thread_func () from /lib64/libgio-2.0.so.0
#4 0x00007fab16cd9540 in g_thread_proxy () from /lib64/libglib-2.0.so.0
#5 0x00007fab13df7ea5 in start_thread () from /lib64/libpthread.so.0
#6 0x00007fab13b2096d in clone () from /lib64/libc.so.6

Thread 4 (Thread 0x7fab02be4700 (LWP 2667)):

LWP が　straceの[PID]に相当します。

pstackでスレッドのコールスタックを確認しながら、straceのシステムコールの呼び出しと突き合わせると、どの処理がシステムコールを呼び出したかが解析可能です。

システムコールをフックするような性質上、pstackとstraceは同時に実行はできません。
strace を実行中の場合、pstack は空振りします。(何も出力されません)

システムコールの呼び出し回数を採取(-c)

-c オプションで　システムコールの呼び出し回数を採取可能です。

[Ctrl] + [C]キーで停止すると画面にstraceを起動してから停止まで実行された統計値が出力されます。
以下のように出力されます。

＜例＞
strace -c -e ‘trace=open,read,write,close,pwrite64,pread64,fallocate,sync’ -f -p `pidof PROGRAM01`

：
-
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- -------
 92.72    1.125218         855      1316           fallocate
  7.06    0.085648          40      2094           pwrite64
  0.15    0.001874         156        12           open
  0.04    0.000541          36        15           close
  0.01    0.000157          11        14           write
  0.01    0.000118          13         9           read
------ ----------- ----------- --------- --------- -------
100.00    1.213556                  3460           total

以下の観点で確認します。
calls: 呼び出し回数が妥当か
usecs/call : １回callが遅くないか

オープンしているファイル（ファイルディスクリプタ）

lsof コマンドでプログラムがオープンしているファイルを確認できます。
（ネットワークのSocketも表示されます。）

$ lsof -p `pidof PROGRAM01`

COMMAND　 PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
PROGRAM01 8831 user1 54u REG 8,17 36634 77794 /tmp/1.data
PROGRAM01 8831 user1 57u REG 8,17 0 10780394 /tmp/1.log ★
PROGRAM01 8831 user1 59u REG 8,17 0 21535328 /tmp/2.data