地方エンジニアの学習日記

興味ある技術の雑なメモだったりを書いてくブログ。たまに日記とガジェット紹介。

straceでシステムコールをトレース

straceコマンド

straceコマンドはプロセスが呼び出すシステムコールを出力するコマンド straceを使うことで既に動いているプロセスのシステムコールなどもリアルタイムで表示できる。

またプログラムがエラーになった際の原因となる箇所の特定などにも使える 開発自体は1991年頃から始まったらしい。

ソースはGitHubでも公開されている。

github.com

基本形

$ strace [program]

とりあえず何も考えずに使ってみる

$ strace ls -l
execve("/bin/ls", ["ls", "-l"], 0x7fffd12f1688 /* 25 vars */) = 0
brk(NULL)                               = 0x5617f5705000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=79820, ...}) = 0
mmap(NULL, 79820, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f0b00045000
close(3)                                = 0
(中略)
close(3)                                = 0
write(1, "-rw-rw-r-- 1 ryu ryu 103  1\346\234\210 1"..., 48-rw-rw-r-- 1 ryu ryu 103  1月 16 21:22 hello.c
) = 48
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

ls コマンドにオプション「-l」を指定して実行している。 execveから始まりwriteで標準出力するまでが見れる。

ただ、lsコマンドはエラー時に原因予測がつくエラーメッセージが出力されるので正直使う必要は無いと思う。

エラー出力のない関数でのエラーの発見だったり原因特定に使える。 デバッガー使うよりも手軽に使えるのは間違いない。

プロセスへのアタッチ

起動中のプロセスのトレースは「-p」オプションで行える ちなみにスレッドもトレースする場合は「-f」オプションも追加します

$ strace -p $PID

権限のないプロセスを strace すると、以下のようなエラーになります。

$ strace -p 2129
attach: ptrace(PTRACE_ATTACH, ...): Operation not permitted

統計情報を表示する

システムコールの呼び出し回数とかかった時間を表示するには「-c」を指定します。

$ strace -c ls -la
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 62.23    0.000173           5        35           write
 18.71    0.000052           1        44        17 openat
  5.76    0.000016           0        33           close
  2.88    0.000008           0        30           fstat
  2.52    0.000007           0        19           read
  2.16    0.000006           0        56        56 getxattr
  1.80    0.000005           0        40           mmap
  1.08    0.000003           0        34           lstat
  1.08    0.000003           2         2           getdents
  1.08    0.000003           0        34        34 lgetxattr
  0.72    0.000002           0         9           lseek
  0.00    0.000000           0        24           mprotect
  0.00    0.000000           0         8           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         3           rt_sigprocmask
  0.00    0.000000           0         2           ioctl
  0.00    0.000000           0        15        15 access
  0.00    0.000000           0         4           socket
  0.00    0.000000           0         4         4 connect
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         2         2 statfs
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           futex
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         1           prlimit64
------ ----------- ----------- --------- --------- ----------------
100.00    0.000278                   409       128 total

straceの仕組み的なの

straecはOSの提供するデバッグ用インターフェースを用いてシステムコールのトレースを実装している。 Linuxだとptraceに当たる。ptraceに関してはmanをご参照ください Manpage of PTRACE

ptraceの入り口出口をフックすることでシステムコールの返り値だったり実行時間を計測している。

straceがptraceを使用していることはstraceをstraceすることで見ることができる

$ strace -c -e ptrace strace ls
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000780           2       384           ptrace
------ ----------- ----------- --------- --------- ----------------
100.00    0.000780                   384           total

他の使いそうなオプションとしては「-e」でトレースするシステムコールを指定したり「-o」でログファイルへ出力したりが多分便利

ログファイルへ出力

$ strace -c -e ptrace -o test.log strace ls

$ cat test.log 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000388           1       384           ptrace
------ ----------- ----------- --------- --------- ----------------
100.00    0.000388                   384           total

まとめ

straceを使えば簡単にプログラムのデバッグと動作把握に使えるのがわかった。 他にも普段使ってるコマンドの動作だったりがトレースできるのでまた新たな発見が何かあるかもしれない。