strace -c を使う際に -w オプションを使い分けよう

strace を使う際に -c をつけると、システムコール呼び出しの統計を取れる

vagrant@xenial:~$ strace -c find >/dev/null
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 47.43    0.033697         145       232           getdents
 46.00    0.032676         141       232           newfstatat
  6.08    0.004320           9       474           close
  0.49    0.000349           0      1045           fcntl
  0.00    0.000000           0        10           read
  0.00    0.000000           0         4           write
  0.00    0.000000           0        15         4 open
  0.00    0.000000           0       129           fstat
  0.00    0.000000           0        21           mmap
  0.00    0.000000           0        14           mprotect
  0.00    0.000000           0         1           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         3         2 ioctl
  0.00    0.000000           0         8         8 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           uname
  0.00    0.000000           0         1           fchdir
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         2         2 statfs
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0       118           openat
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.071042                  2321        16 total

-c が計上するのは system time だと man に書いてあります

       -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) inde‐
                   pendent of wall clock time.  If -c is used with -f or -F (below), only aggregate totals for all traced processes are kept.

-w を一緒につける

strace -c と一緒に -w をつけると「システムコール呼び出しにかかった時間を計測できる」

       -w          Summarise the time difference between the beginning and end of each system call.  
                     The default is to summarise the system time.

-w を付けた場合にどう変化がでるかは sleep 1 ã‚’ strace して nanosleep(2) を見ると理解が早い

vagrant@xenial:~$ strace -c -w sleep 1
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.76    1.042157     1042157         1           nanosleep 👈
  0.05    0.000525          66         8           mmap
  0.04    0.000419         419         1           execve
  0.03    0.000327         109         3           brk
  0.02    0.000251          63         4           mprotect
  0.02    0.000219          73         3           open
  0.02    0.000211          70         3           fstat
  0.02    0.000200          67         3         3 access
  0.02    0.000190          38         5           close
  0.01    0.000064          64         1           read
  0.01    0.000062          62         1           arch_prctl
  0.00    0.000050          50         1           munmap
------ ----------- ----------- --------- --------- ----------------
100.00    1.044675                    34         3 total

-w を外した場合

vagrant@xenial:~$ strace -c sleep 1
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         1           read
  0.00    0.000000           0         3           open
  0.00    0.000000           0         5           close
  0.00    0.000000           0         3           fstat
  0.00    0.000000           0         8           mmap
  0.00    0.000000           0         4           mprotect
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         3         3 access
  0.00    0.000000           0         1           nanosleep 👈
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    34         3 total

ね? ブロックする時間が長いシステムコール呼び出しを追いかける際に便利そう

ソース

-w オプションが実装されたのは下記のコミットで、 4.9 でリリースされたようだ

github.com

strace.io

時間の計測方法

ざっくり調べただけなので詳細は書けないのだが ...

-w 付けた場合は clock_gettime(2) + CLOCK_MONOTONIC でシステムコールを開始した時間を記録し計測しているらしい

void
syscall_entering_finish(struct tcb *tcp, int res)
{

...

    /* Measure the entrance time as late as possible to avoid errors. */ 
    if ((Tflag || cflag) && !filtered(tcp))
        clock_gettime(CLOCK_MONOTONIC, &tcp->etime); 👈

-w をつけない場合の system time は、どうやら wait4(2) の第三引数 struct rusage *rusage を通して取っているらしい

static const struct tcb_wait_data *
next_event(void)
{

...

next_event_wait_next:
        pid = wait4(-1, &status, __WALL | WNOHANG, (cflag ? &ru : NULL));
        wait_errno = errno;
        wait_nohang = true;

まとめ

• 実は -c が出す時間が system time だということを長らくちゃんと理解せずに使っていた
• 直面している問題に合わせて -w を付けたり外したりして、観測/計測していくとよいだろう
• ところで -c は、ペパボ だと pyama くんがバキバキ使い倒している

CentOS6 は 4.8 でまだ使えなかったみたいだが、 CentOS7 では 4.12 なので使えたはず. が、 長らく気がつかずに過ごしてしまった。これ知ってれば解決に導けたm問題も多かったろうなぁ ... という感想