概要

straceについての備忘録です。
個人的に利用頻度は高くないですが、時々実行しようとすると忘れていることが多いのでまとめておきます。

straceについて

straceは実行中のプログラムが呼んだシステムコールを表示してくれるツールです。
straceの結果から、どのシステムコールで待っているのか・OSの何の関数で待機しているかが確認可能です。
アプリケーションプログラムが内部でどの部分で待機しているかは確認できません。

インストール(CentOS)

CentOS

yum install strace

ubuntu

apt-get install strace

オプション(使用頻度が高いもの)

Options	Description
s	表示する最大文字列サイズを指定(デフォルトは32)。システムコールなどで読み書きした内容を全て確認したい場合は大きくする。
tt	行頭にタイムスタンプを出力(マイクロ秒)
T	行末にシステムコールに費やした時間(※)を表示。※各システムコールの開始と終了の間の時間差を記録
ff	子プロセスのシステムコールもトレース。-oが有効な場合プロセス(スレッド)毎に別ファイルに出力
o	指定したファイル名に出力。-ffとの併用でファイル名. に出力
p	プロセスIDを指定
e	どのイベントをトレースするか、またはどのようにトレースするかを変更する修飾表現
c	システムコールごとに統計情報(時間/呼び出し/エラーのカウント)を表示
r	システムコールが要した時間を出力

-f オプションの場合、別プロセスのトレース結果が同一ファイルに出力される。
別ファイルにしたい場合は、-ff オプションにすれば良い。

基本的な使用方法

$ strace [command]

実行例

実行コマンドのトレース「$ strace <実行コマンド>」

$ strace ls

ファイルのトレース「$ strace <./ファイル名>」

$ strace ./hello >/dev/null

確認するシステムコールを限定する「$ strace -e trace=<システムコール名(,システムコール名)>」

$ strace -e trace=open,read,write,close ./hello data >/dev/null

PIDを指定してstrace 「$ strace -p 」

$ strace -p 1111

トレース結果をファイル出力「$ strace -o <出力ファイル>」

$ strace -o strace-output.txt ls

システムコールが要した時間を出力「$ strace -r」

$ strace -r ls

トレース結果の統計情報を出力「$ strace -c」

$ strace -c ls

実行時刻（秒単位）の表示(-t)「$ strace -t」

$ strace -t -p 2298

実行時刻（マイクロ秒単位）の表示(-tt)「$ strace -t」

$ strace -tt -p 2298

実行時間の表示方法(-T)「$ strace -T」

$ strace -T -p 2298

特定のシステムコールを実行結果から除外「$ strace -e 'trace=!<除外対象のシステムコール>'」※複数可

$ strace -e 'trace=!write' -p 1347

表示する文字列数を調整する(-s)「$ strace -s <数値>」

$ strace -s 100 -p 4159

実行結果をプロセス毎にわける方法(-ff)「$ strace -ff」

$ strace -ff -p 3311,3312,3313,3314,3315,3316 -o strace.log

実用的な使用方法

システムコールの詳細確認

$ strace -Ttt -ff -s 1500000 -o <ログ出力先ファイル名> -p <PID>

$ strace -Ttt -ff -s 1500000 -o <ログ出力先ファイル名> <コマンド>

$ strace -Ttt -ff -s 1500000 -o /home/oracle/work/strace_ls.log ls
dump strace_ls.log.15881
[oracle@consrsec work]$ head strace_ls.log.15881 
02:37:42.710875 execve("/usr/bin/ls", ["ls"], [/* 55 vars */]) = 0 <0.000175>
02:37:42.711208 brk(0)                  = 0x7bb000 <0.000007>
02:37:42.711253 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1bd8854000 <0.000009>
02:37:42.711289 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000010>
02:37:42.711332 open("/u01/app/oracle/product/18.0.0/dbhome_1/lib/tls/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000013>
02:37:42.711378 stat("/u01/app/oracle/product/18.0.0/dbhome_1/lib/tls/x86_64", 0x7ffca63648b0) = -1 ENOENT (No such file or directory) <0.000009>
02:37:42.711402 open("/u01/app/oracle/product/18.0.0/dbhome_1/lib/tls/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000008>
02:37:42.711425 stat("/u01/app/oracle/product/18.0.0/dbhome_1/lib/tls", 0x7ffca63648b0) = -1 ENOENT (No such file or directory) <0.000017>
02:37:42.711458 open("/u01/app/oracle/product/18.0.0/dbhome_1/lib/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000008>
02:37:42.711480 stat("/u01/app/oracle/product/18.0.0/dbhome_1/lib/x86_64", 0x7ffca63648b0) = -1 ENOENT (No such file or directory) <0.000007>

システムコールの種類別に集計(時間・回数)

$ strace -fc -o <ログ出力先ファイル名> -p <PID>

$ strace -fc -o <ログ出力先ファイル名> <コマンド>

$ strace fc -o /home/oracle/work/strace_ls.log ls
execve("/usr/bin/fc", ["fc", "-o", "/home/oracle/work/strace.log", "ls"], [/* 55 vars */]) = 0
brk(0)                                  = 0x1fe7000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc2bb9c1000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/u01/app/oracle/product/18.0.0/dbhome_1/lib/tls/x86_64/libtinfo.so.5", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/u01/app/oracle/product/18.0.0/dbhome_1/lib/tls/x86_64", 0x7ffe3891ae20) = -1 ENOENT (No such file or directory)
open("/u01/app/oracle/product/18.0.0/dbhome_1/lib/tls/libtinfo.so.5", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/u01/app/oracle/product/18.0.0/dbhome_1/lib/tls", 0x7ffe3891ae20) = -1 ENOENT (No such file or directory)
open("/u01/app/oracle/product/18.0.0/dbhome_1/lib/x86_64/libtinfo.so.5", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/u01/app/oracle/product/18.0.0/dbhome_1/lib/x86_64", 0x7ffe3891ae20) = -1 ENOENT (No such file or directory)
open("/u01/app/oracle/product/18.0.0/dbhome_1/lib/libtinfo.so.5", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/u01/app/oracle/product/18.0.0/dbhome_1/lib", {st_mode=S_IFDIR|0755, st_size=12288, ...}) = 0
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=113542, ...}) = 0
mmap(NULL, 113542, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fc2bb9a5000
close(3)                                = 0
open("/lib64/libtinfo.so.5", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@\316\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=174576, ...}) = 0
mmap(NULL, 2268928, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fc2bb577000
mprotect(0x7fc2bb59c000, 2097152, PROT_NONE) = 0
mmap(0x7fc2bb79c000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x25000) = 0x7fc2bb79c000
close(3)                                = 0

見方

Column	Examples	Description
1	02:37:42.710875	システムコール実行開始時刻(時:分:秒.マイクロ秒)
2	execve("/usr/bin/ls", ["ls"], [/ 55 vars /]) = 0	システムコール
3	<0.000175>	システムコール実行に要した時間(秒.マイクロ秒)