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 でリリースされたようだ
時間の計測方法
ざっくり調べただけなので詳細は書けないのだが ...
-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問題も多かったろうなぁ ... という感想
