Linux で strace を使ってシステムコールのトレースを調べる時によく使うオプションをメモ。
特にお気に入りのオプションは -T、-c、-ff & -o です。
書式
システムコールを詳細に追う
$ strace -Ttt -ff -s 1500000 -o <ログ出力先ファイル名> -p <PID> もしくは $ strace -Ttt -ff -s 1500000 -o <ログ出力先ファイル名> <コマンド>
strace したプロセスが起動している間に /proc/[pid]/fd でファイルディスクリプタ番号とファイルパスの対応を確認しておくと、strace で read(17, ... などと出力されている場合に、17 のファイルパス、つまりどのファイルを読んでいるかが分かります。
$ ls -l /proc/[pid]/fd
4.7 (2012年5月リリース) から -y、4.12 (2016年5月リリース) から -yy オプションでファイルディスクリプタ番号をファイル名、ソケットを送信元と送信先のIPアドレスとポート番号に置き換えてくれるようになっているようです。
strace -o out -y cp ubuntu-16.04-desktop-amd64.iso /tmp/blahWe still get to keep the file descriptors, but it appends the filename of the file it was reading from! Awesome! We can see that it's reading 128KB (128 * 1024 = 131072 bytes) at a time from the source file (/home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso), and writing them into the destination file (/tmp/blah). Seems reasonable!
read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "\315\350\5p\244\334\266\213 \2553~\37\7\330w\3125\316\360u\204P\236\255\n\244\344\264\327\213\241"..., 131072) = 131072 write(4</tmp/blah>, "\315\350\5p\244\334\266\213 \2553~\37\7\330w\3125\316\360u\204P\236\255\n\244\344\264\327\213\241"..., 131072) = 131072 read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "\37\367\336\377\247!\357\377\200\337wV\335\366|\232\337?\373iz\37r\376/z5\275\377\360\247\335"..., 131072) = 131072 write(4</tmp/blah>, "\37\367\336\377\247!\357\377\200\337wV\335\366|\232\337?\373iz\37r\376/z5\275\377\360\247\335"..., 131072) = 131072 read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "x\321/|'m\25\313o \261t^b\306\17r4~\3138j\6\4\244\3308\300E\366\364\22"..., 131072) = 131072 write(4</tmp/blah>, "x\321/|'m\25\313o \261t^b\306\17r4~\3138j\6\4\244\3308\300E\366\364\22"..., 131072) = 131072 read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "j\273\324\332\216\361\207\204\336\243\326\267\227\35\322\370\205\245N6+\211h\246\215\32k\336\0\r\320."..., 131072) = 131072 write(4</tmp/blah>, "j\273\324\332\216\361\207\204\336\243\326\267\227\35\322\370\...
If you run strace with -yy, and you're doing networking, it'll resolve file descriptors into a source & destination IP address and port, like this!
This is querying my DNS server on localhost for blah.com and getting no answer.
$ strace -yy wget blah.com recvfrom(3<UDP:[127.0.0.1:46218->127.0.1.1:53]>, "\270\222\201\205\0\1\0\0\0\0\0\0\4blah\3com\0\0\1\0\1", 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.1.1")}, [16]) = 26A useful new strace feature - Julia Evans
システムコールの種類別に集計（時間・回数）する
$ strace -fc -o <ログ出力先ファイル名> -p <PID> もしくは $ strace -fc -o <ログ出力先ファイル名> <コマンド>
実行例
システムコールを詳細に追う
$ ps -ef|grep [t]nslsnr oracle 55447 1 0 Feb09 ? 00:04:00 /u01/app/12.1.0.2/grid/bin/tnslsnr MGMTLSNR -no_crs_notify -inherit oracle 56996 1 0 Feb09 ? 00:33:21 /u01/app/12.1.0.2/grid/bin/tnslsnr LISTENER_SCAN3 -no_crs_notify -inherit oracle 69013 1 0 Mar03 ? 01:29:18 /u01/app/12.1.0.2/grid/bin/tnslsnr LISTENER -no_crs_notify -inherit $ ls -l /proc/55447/fd total 0 lrwx------. 1 oracle oinstall 64 Mar 19 02:18 0 -> /dev/null lrwx------. 1 oracle oinstall 64 Mar 19 02:18 1 -> /dev/null l-wx------. 1 oracle oinstall 64 Mar 19 02:18 10 -> pipe:[28070704] lrwx------. 1 oracle oinstall 64 Mar 19 02:18 11 -> socket:[28104650] lrwx------. 1 oracle oinstall 64 Mar 19 02:18 12 -> socket:[28104651] lrwx------. 1 oracle oinstall 64 Mar 19 02:18 13 -> socket:[28107334] lrwx------. 1 oracle oinstall 64 Mar 19 02:18 14 -> socket:[28107317] lrwx------. 1 oracle oinstall 64 Mar 19 02:18 15 -> socket:[28088239] lrwx------. 1 oracle oinstall 64 Mar 19 02:18 16 -> socket:[28107433] lrwx------. 1 oracle oinstall 64 Mar 19 02:18 17 -> socket:[28107447] lrwx------. 1 oracle oinstall 64 Mar 19 02:18 18 -> socket:[28188383] lrwx------. 1 oracle oinstall 64 Mar 19 02:18 19 -> socket:[28188384] lrwx------. 1 oracle oinstall 64 Mar 19 02:18 2 -> /dev/null lr-x------. 1 oracle oinstall 64 Mar 19 02:18 3 -> /u01/app/12.1.0.2/grid/rdbms/mesg/diaus.msb lr-x------. 1 oracle oinstall 64 Mar 19 02:18 4 -> /proc/55447/fd lr-x------. 1 oracle oinstall 64 Mar 19 02:18 5 -> /u01/app/12.1.0.2/grid/network/mesg/nlus.msb lrwx------. 1 oracle oinstall 64 Mar 19 02:18 6 -> anon_inode:[eventpoll] lr-x------. 1 oracle oinstall 64 Mar 19 02:18 7 -> pipe:[28070703] lr-x------. 1 oracle oinstall 64 Mar 19 02:18 8 -> /u01/app/12.1.0.2/grid/network/mesg/tnsus.msb lrwx------. 1 oracle oinstall 64 Mar 19 02:18 9 -> socket:[28104649] $ strace -Ttt -ff -s 1500000 -o strace -p 55447 Process 55447 attached with 2 threads - interrupt to quit ^CProcess 55447 detached Process 55470 detached $ ls strace.55447 strace.55470 o と ff オプションにより、スレッド別にファイルが生成されている $ head strace.55447 12:14:50.669465★タイムスタンプ(-tt) epoll_wait(6, {{EPOLLIN, {u32=39785040, u64=39785040}}}, 1024, 4294967295) = 1 <7.441963>★システムコールで使った時間(-T) 12:14:58.111594 times(NULL) = 1506816866 <0.000013> 12:14:58.111651 getsockname(9★, {sa_family=AF_FILE, path="/var/tmp/.oracle/sMGMTLSNR"}, [29]) = 0 <0.000014> ↑ファイルディスクリプタ番号9は "socket:[28104649]" 12:14:58.111716 chmod("/var/tmp/.oracle/sMGMTLSNR", 0777) = 0 <0.000029> 12:14:58.111784 accept(9, {sa_family=AF_FILE, NULL}, [2]) = 20 <0.000019> 12:14:58.111836 fcntl(20, F_SETFD, FD_CLOEXEC) = 0 <0.000011> 12:14:58.111877 times(NULL) = 1506816866 <0.000011> 12:14:58.111967 rt_sigaction(SIGPIPE, {SIG_IGN, ~[ILL ABRT BUS FPE SEGV USR2 TERM XCPU XFSZ SYS RTMIN RT_1], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7f27716f9710}, {SIG_IGN, ~[ILL ABRT BUS FPE KILL SEGV USR2 TERM STOP XCPU XFSZ SYS RTMIN RT_1], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7f27716f9710}, 8) = 0 <0.000013> 12:14:58.112057 epoll_ctl(6, EPOLL_CTL_ADD, 20, {EPOLLIN, {u32=40329456, u64=40329456}}) = 0 <0.000016> 12:14:58.112109 times(NULL) = 1506816866 <0.000011>
システムコールの種類別に集計（時間・回数）する
$ ps -ef|grep [j]ava oracle 10498 10412 0 Apr21 ? 11:37:56 /u01/app/emcc/agent/core/12.1.0.4.0/jdk/bin/java ... ... $ strace -fc -o strace.log -p 10498 Process 10498 attached with 236 threads - interrupt to quit ^CProcess 10498 detached Process 10499 detached Process 10500 detached ... $ cat strace.log % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 69.28 0.171635 439 391 98 futex 15.34 0.037999 1809 21 13 restart_syscall 10.84 0.026860 86 313 sched_yield 4.04 0.009999 5000 2 epoll_wait 0.40 0.001000 48 21 recvfrom 0.06 0.000156 6 27 6 stat 0.04 0.000106 18 6 write 0.00 0.000000 0 4 read 0.00 0.000000 0 7 open 0.00 0.000000 0 11 close 0.00 0.000000 0 8 fstat 0.00 0.000000 0 1 poll 0.00 0.000000 0 3 lseek 0.00 0.000000 0 4 mprotect 0.00 0.000000 0 1 access 0.00 0.000000 0 2 dup2 0.00 0.000000 0 4 socket 0.00 0.000000 0 3 connect 0.00 0.000000 0 13 sendto 0.00 0.000000 0 3 recvmsg 0.00 0.000000 0 1 bind 0.00 0.000000 0 3 getsockname 0.00 0.000000 0 2 setsockopt 0.00 0.000000 0 3 getsockopt 0.00 0.000000 0 1 uname 0.00 0.000000 0 14 fcntl 0.00 0.000000 0 7 rename 0.00 0.000000 0 6 5 unlink 0.00 0.000000 0 24 clock_gettime ------ ----------- ----------- --------- --------- ---------------- 100.00 0.247755 906 122 total
関連
参考
- 日々の覚書: straceでthreadの確保するメモリ量を調べてみる
- strace コマンドの使い方をまとめてみた - sonots:blog
- 第11回「 strace ノススメ」 | NTTデータ先端技術株式会社
- strace(1) - Linux manual page
-c Count time, calls, and errors for each system call and
report a summary on program exit. On Linux, this
attempts to show system time (CPU time spent running in
the kernel) independent of wall clock time. If -c is
used with -f or -F (below), only aggregate totals for all
traced processes are kept.
...
-ff If the -o filename option is in effect, each processes
trace is written to filename.pid where pid is the numeric
process id of each process. This is incompatible with
-c, since no per-process counts are kept.
...
-t Prefix each line of the trace with the time of day.
-tt If given twice, the time printed will include the
microseconds.
-ttt If given thrice, the time printed will include the
microseconds and the leading portion will be printed as
the number of seconds since the epoch.
-T Show the time spent in system calls. This records the
time difference between the beginning and the end of each
system call.
...
-o filename Write the trace output to the file filename rather than
to stderr. Use filename.pid if -ff is used. If the
argument begins with '|' or with '!' then the rest of the
argument is treated as a command and all output is piped
to it. This is convenient for piping the debugging
output to a program without affecting the redirections of
executed programs.
...
-p pid Attach to the process with the process ID pid and begin
tracing. The trace may be terminated at any time by a
keyboard interrupt signal (CTRL-C). strace will respond
by detaching itself from the traced process(es) leaving
it (them) to continue running. Multiple -p options can
be used to attach to many processes in addition to
command (which is optional if at least one -p option is
given). -p "`pidof PROG`" syntax is supported.
...
-s strsize Specify the maximum string size to print (the default is
32). Note that filenames are not considered strings and
are always printed in full.
/proc/[pid]/fd/
This is a subdirectory containing one entry for each file
which the process has open, named by its file descriptor, and
which is a symbolic link to the actual file. Thus, 0 is
standard input, 1 standard output, 2 standard error, and so
on.
For file descriptors for pipes and sockets, the entries will
be symbolic links whose content is the file type with the
inode. A readlink(2) call on this file returns a string in
the format:
type:[inode]
