主页 / unix / 问题 / 410877
Accepted
Willem
Asked: 2017-12-15 06:09:09 +0800 CST

为什么`time`和`strace -c`不同？

  • 772

据我了解，time将记录系统调用中花费的总时间。然后我希望 sys 时间的累积总数与报告的time和strace -fc相同。但它们截然不同（13.5 对 0.005）。怎么了？

# time php index.php >/dev/null

real  0m16.292s
user  0m2.728s
sys   0m13.548s

# strace -fc php index.php >/dev/null
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 83.72    0.000365           0     54845           munmap
 10.09    0.000044           0     36705           mmap
  6.19    0.000027           0     18249           madvise
  0.00    0.000000           0       289           read
  0.00    0.000000           0       119           write
  0.00    0.000000           0       118         3 open
  0.00    0.000000           0       118           close
  0.00    0.000000           0        23           stat

[ cut 0 duration syscalls for brevity ]

100.00    0.000436                110951        82 total

（我已经重新运行这些测试大约 50 次，它们都给出了一致的结果）

linux time

1 个回答

  1. Best Answer

    一个进程可以花费任何时间不进行任何系统调用。

    例如，执行 a 的 shellwhile :; do :; done将花费无限的时间不执行任何系统调用并且不花费任何sysCPU 时间，只花费userCPU 时间。

    strace -c尝试sys通过每个系统调用计算 CPU 时间。Ananosleep(1000000000)将花费接近 0 毫秒的 CPU 时间但 1 秒的挂钟时间。

    $ bash -c 'time strace -fc sleep 1'
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  [...]
  0.00    0.000000           0         1           nanosleep
  [...]
100.00    0.000000                    33         3 total

real    0m1.006s
user    0m0.001s
sys     0m0.003s

    将 sys 时间与 strace 报告的时间进行比较会更有意义，但请注意，并非所有用于进程的 sys CPU 时间都花费在这些系统调用中。例如，访问 mmaped 数据会使进程在不进行任何系统调用的情况下花费大量系统时间。

    在这里，那些众多的mmaps()调用可能是分配内存。这些是即时的，因为它们只是更新了一些映射。但是，当您第一次写入这些时，需要一些系统时间来支持这些写入与实际内存。

    或者他们可以映射共享库之类的目标文件（这也是一种可能的可能性，因为数量与 的数量相差不远open()s）。再说一遍，这mmap()很快，但稍后读取内存也意味着一些页面错误和从磁盘读取数据的实际时间，这不计入任何系统调用。

    更根本的是，如果您time strace -f your-application按照问题的早期版本进行操作，time那么命令和strace.

    strace增加了很多开销。它为跟踪应用程序的每个系统调用执行几个系统调用。

    正在做

    strace -fc time your-application

    代替

    time strace -fc your-application

    更有可能给你一个更好的匹配。

    但我发现，对于wait*()进程等待其子进程的系统调用，将strace这些系统调用报告的时间计wait*()为系统时间，这意味着子进程（至少是等待的那些）的时间是数了几遍。这与在子进程中运行并等待它一样重要strace -f time cmd。timecmd

    $ strace -c time head -c 100M /dev/urandom > /dev/null
0.00user 0.76system 0:00.76elapsed 99%CPU (0avgtext+0avgdata 1796maxresident)k
0inputs+0outputs (0major+83minor)pagefaults 0swaps
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.762288      762288         1           wait4
  0.00    0.000000           0         1           read
  0.00    0.000000           0       112           write
  0.00    0.000000           0         2           open
  0.00    0.000000           0         2           close
  0.00    0.000000           0         2           fstat
  0.00    0.000000           0         6           mmap
  0.00    0.000000           0         4           mprotect
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0         1           brk
  0.00    0.000000           0         4           rt_sigaction
  0.00    0.000000           0         3         3 access
  0.00    0.000000           0         1           clone
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.762288                   142         3 total

    time并strace报告相同的系统时间（由wait4()系统调用返回），但具有-f：

    $ strace -fc time head -c 100M /dev/urandom > /dev/null
strace: Process 2298 attached
0.01user 1.33system 0:01.91elapsed 69%CPU (0avgtext+0avgdata 1920maxresident)k
0inputs+0outputs (0major+84minor)pagefaults 0swaps
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 54.60    1.331335     1331335         1           wait4
 39.43    0.961497          75     12804           read
  5.94    0.144825           6     25711           write
  0.01    0.000148          11        13         6 open
  0.00    0.000104           8        13           mmap
  0.00    0.000094          19         5         3 execve
  0.00    0.000063           8         8           mprotect
  0.00    0.000050           6         9           close
  0.00    0.000041           7         6         6 access
  0.00    0.000037           5         7           fstat
  0.00    0.000031          16         2           munmap
  0.00    0.000030           8         4           brk
  0.00    0.000007           4         2           arch_prctl
  0.00    0.000006           6         1         1 ioctl
  0.00    0.000000           0         4           rt_sigaction
  0.00    0.000000           0         1           clone
------ ----------- ----------- --------- --------- ----------------
100.00    2.438268                 38591        16 total

    1.33是一个wait4()系统调用报告的时间time。报告head(time的孩子) 的系统时间。

    但是，除此之外，strace它还会尝试为其head孙子的每个系统调用获取系统时间，这意味着它被计算了两次（不完全）。由于我们得到 1.33 而不是之前的 0.76，因此对孙子的跟踪仍然会产生一些开销，这些开销与跟踪过程有关。如果我强制 strace、time 和 head 在同一个处理器上运行（使用taskset 1），这将大大减少。

    • 7

相关问题