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]
参考サイト
- 差がつくデバッグテクニック Hack #43-66 http://www.oreilly.co.jp/editors/debug_hacks_43.pdf- Advanced Linux Troubleshooting: strace | Sys::Log http://sys-log.bencane.com/2012/03/advanced-linux-troubleshooting-strace/
- Troubleshooting Apache using strace LG #132 http://linuxgazette.net/132/vishnu.html
- 5 simple ways to troubleshoot using Strace http://www.hokstad.com/5-simple-ways-to-troubleshoot-using-strace.html
- @IT:Security Tips > 不審なプロセスを調査する http://www.atmarkit.co.jp/fsecurity/rensai/securitytips/012strace.html