strace -c 不显示正确的秒数

Question

我在 RHEL 7 和 RHEL 6 上得到了 strace -c 的结果对于此命令：

strace -c /bin/sleep 20

而且我不明白为什么 nanosleep 的 seconds 列等于 0。我原以为它是 20。

  0.00    0.000000           0         1           nanosleep

这是完整的 strace 报告：

$ strace -c /bin/sleep 20 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000019           1        15        12 open
  0.00    0.000000           0         1           read
  0.00    0.000000           0         5           close
  0.00    0.000000           0         8         6 stat
  0.00    0.000000           0         3           fstat
  0.00    0.000000           0         9           mmap
  0.00    0.000000           0         3           mprotect
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         1         1 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.000019                    52        19 total

并且在详细报告中有对nanosleep的调用：

nanosleep({20, 0}, NULL)                = 0

所以秒数一定是20，不是0，你怎么看？

Answer 1

为了理解这个问题我运行 strace for strace -c /bin/sleep:

这是它的样子：

$ strace -T -o syscalls.txt -v strace -c /bin/sleep 20
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 31.54    0.000429          29        15        12 open
 13.68    0.000186          23         8           mmap
 13.60    0.000185          46         4           mprotect
 11.62    0.000158          20         8         6 stat
  6.91    0.000094          19         5           close
  5.96    0.000081          81         1           munmap
  4.63    0.000063          16         4           brk
  3.38    0.000046          46         1           arch_prctl
  3.16    0.000043          43         1           nanosleep
  2.21    0.000030          30         1           read
  1.47    0.000020          20         1         1 access
  1.32    0.000018           6         3           fstat
  0.51    0.000007           7         1           execve
------ ----------- ----------- --------- --------- ----------------
100.00    0.001360                    53        19 total

下面是 sycalls.txt 中与 nanosleep 系统调用相关的一些行：

ptrace(PTRACE_SYSCALL, 6498, 0, SIG_0)  = 0 <0.000028>
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000017>
wait4(-1, [{WIFSTOPPED(s) && WSTOPSIG(s) == 133}], __WALL, {ru_utime={0, 0}, ru_stime={0, 3706}, ru_maxrss=616, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=205, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=108, ru_nivcsw=1}) = 6498 <20.000423>
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_TRAPPED, si_pid=6498, si_status=SIGTRAP, si_utime=0, si_stime=0} ---

因此，nanosleep 本身持续 20 秒，如行末所示：<20.000423>。然而 wait4 returns 为它：

{ru_utime={0, 0}, ru_stime={0, 3706}

所以根据报告做nanosleep需要3微秒。因此 seconds 列可能意味着 OS 花费了 (user_time + sys_time + some-unclear-overhead) 来处理系统调用。这并不意味着是系统调用的挂钟时间。

Answer 2

来自 strace(1) 的手册页：

-c On Linux, this attempts to show system time (CPU time spent running in the kernel)

我认为：

当进程调用 nanosleep() 时，它要求内核暂停一段时间。内核设置一些东西（比如一些标志、计时器、时间戳……），挂起调用进程，然后去做其他事情。 strace(1) 报告内核 花费的时间 执行此操作，而不是进程保持挂起的时间。

可能这个 -c strace 选项可以被认为是“-cost”：这个系统调用花费了多少时间？

strace -c 不显示正确的秒数

strace -c does not show correct seconds

linux

strace