strace コマンドの使い方をまとめてみました。自分用メモ。

strace コマンドとは

strace を使う事で、プロセスが呼び出すシステムコールをトレースし、その内容を表示することができます。strace を使って、システムコールがエラーになる箇所を探すと、不具合の手がかりが得られることがあります。

strace コマンドの基本

$ strace [command]

strace からコマンドのプロセスを起動して、システムコールをトレースします。例えば、 

$ strace ls /hoge

のように実行すると、

execve("/bin/ls", ["ls", "/hoge"], [/* 45 vars */]) = 0
brk(0)                                  = 0x17a2000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f05b1456000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=59300, ...}) = 0
…
(省略)
...
stat("/hoge", 0x17a20f0)                = -1 ENOENT (No such file or directory)
lstat("/hoge", 0x17a20f0)               = -1 ENOENT (No such file or directory)
write(2, "ls: ", 4ls: )                     = 4
write(2, "cannot access /hoge", 19cannot access /hoge)     = 19
write(2, ": No such file or directory", 27: No such file or directory) = 27

のように表示されます。エラー終了するような場合、strace の出力を最後から見ていくのが解決への近道です。

上記の例では、stat("/hoge", 0x17a20f0) の行で「No such file or directory」ということからファイルが存在しないためにエラーが発生していることがわかります。ls コマンドからは同様なメッセージがエラー出力されるので、原因解析のために strace を使うまでもありませんが、エラーメッセージ(or ログメッセージ)が出力されないようなアプリケーションのエラーの原因を調べるのに役に立ちます。

Linux のシステムコールは man コマンドで調べられます。システムコールはセクション2 なので -S 2 をつけて調べましょう。

$ man stat -S 2

プロセスへのアタッチ

strace からプロセスを起動させるのではなく、デーモンのようにすでに実行されているプロセスの動作を strace で確認するには -p オプションを使用します。

strace -p [pid]

tomcat を例にしてみます。まず ps コマンドを用いてデーモンのプロセス番号を調べます。

$ ps auxww | grep tomcat
root      1882  0.2 23.6 2249336 486784 ?      Sl   03:02   2:13 /usr/java/jdk1.6.0_25/bin/java -Djava.util.logging.config.file=/usr/java/tomcat
... 
(省略)

tomcat のプロセス番号 1882 にアタッチしてみます。

$ sudo strace -p 1882
Process 1882 attached - interrupt to quit
futex(0x7fbc848939e0, FUTEX_WAIT, 1912, NULL

tomcat にリクエストを送ってみます。

$ curl http://localhost:8080/

あれ、何も変わりませんね?pstree で調べるとわかるのですが、tomcat の場合、内部でスレッドが切られているので、スレッドもトレースする -f オプションを使用する必要があります。

$ pstree -p 1882
java(1882)-+-{java}(1912)
           |-{java}(1958)
           |-{java}(1959)
…
(省略)

オプション -f を付けて、

$ sudo strace -f -p 1882

再度、tomcat にリクエストを送ってみます。

$ curl http://localhost:8080/
(省略)
pid  1974] futex(0x403b6994, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, {1348625722, 878871000}, ffffffff 
[pid  2381] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out)
[pid  2381] futex(0x7fbc8037ca28, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  2381] stat("/home/usr/java/apache-tomcat-6.0.33/webapps/ROOT", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  2381] stat("/home/usr/java/apache-tomcat-6.0.33/webapps/ROOT", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  2381] stat("/usr/java/tomcat/conf/context.xml", {st_mode=S_IFREG|0600, st_size=1395, ...}) = 0
(省略)

アクセスした瞬間にトレース結果が出力されるようになりました。ただ、大量に出力されすぎて追いにくいので、-e オプションを使用して特定のシステムコールに絞ってみます。

例えば stat に絞りたい場合は以下のようにします。

$ strace -f -p 1882 -e trace=stat
[pid  2381] stat("/home/usr/java/apache-tomcat-6.0.33/webapps/ROOT", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  2381] stat("/home/usr/java/apache-tomcat-6.0.33/webapps/ROOT", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  2381] stat("/usr/java/tomcat/conf/context.xml", {st_mode=S_IFREG|0600, st_size=1395, ...}) = 0
(省略)

その他のオプション

表示される文字数を増やす -s

1行あたりに表示される文字数は、デフォルトでは32文字でカットされてしまって大事なメッセージが見れなかったりするので、もっと表示したい場合は -s オプションで指定します。

$ strace -s 1024 command

ファイルに出力する -o

表示内容をファイルへ出力するには、-o オプションを用います。

$ strace -o output.log command

時刻を表示する -tt

各システムコールが発行された時刻を -t、または、-tt オプションで表示させることができます。

違いは、-t は秒単位で、-tt はマイクロ秒単位で表示することです。

$ strace -t command
$ strace -tt command

統計情報を表示する -c

システムコールの呼び出された回数、かかった時間などの統計情報を出力するには -c オプションを利用します。

一度統計情報を出してから、明らかに遅いシステムコールに対して -e で指定してあげるとチューニングが捗りそうです。

$ strace -c ls /hoge
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000156           4        35           mmap
  0.00    0.000000           0        14           read
  0.00    0.000000           0         4           write
  0.00    0.000000           0        30        13 open
  0.00    0.000000           0        19           close
  0.00    0.000000           0         4         4 stat
  0.00    0.000000           0        17           fstat
  0.00    0.000000           0         1         1 lstat
  0.00    0.000000           0        18           mprotect
  0.00    0.000000           0         3           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         2           ioctl
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           statfs
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         3         1 futex
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.000156                   163        20 total

応用例

mysql がどの設定ファイルを開いているのか調べる

mysql は /etc/my.cnf 以外にもいろいろな場所から設定ファイルを読み込む可能性があります。実際どのファイルをどの順番で読み込んでいるのか調べられます。

$ strace mysql 2>&1  | grep 'open' | grep '.cnf'
open("/etc/mysql/my.cnf", O_RDONLY|O_LARGEFILE) = 3
open("/home/sonots/.my.cnf", O_RDONLY|O_LARGEFILE) = 3

strace コマンドの出力は標準エラー出力に出るので、 2>&1 で標準出力にリダイレクトして grep しています。

不審なプロセスを監視する

例えば、不審な時刻にシェルにログインしているユーザを発見した場合、そのシェルの pid に strace をアタッチすることで、そのユーザが何を実行しているのかがリアルタイムでわかります。

$ strace -f -e execve -p 26787
[pid 26807] execve("/usr/bin/less", ["less", "+F", "/usr/local/apache/logs/access_lo"...], [/* 33 vars */]) = 0[pid 26807] --- SIGCHLD (Child exited) ---
[pid 26807] --- SIGINT (Interrupt) ---
--- SIGCHLD (Child exited) ---
[pid 26809] execve("/bin/ls", ["ls", "-NF", "--show-control-chars", "-la"], [/* 33 vars */]) = 0
--- SIGCHLD (Child exited) ---

基本テンプレ

自分は -tt と -s オプションは常に指定してることが多いですね。

$ strace -tt -s 1024 -p [pid]

参考サイト