据我了解,time
将记录系统调用所花费的总时间。然后我希望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 次,它们都给出了一致的结果)
答案1
进程可以花费任意时间不执行任何系统调用。
例如,执行 a 的 shellwhile :; do :; done
将花费无限量的时间不执行任何系统调用,并且不花费任何sys
CPU 时间,而只花费user
CPU 时间。
strace -c
尝试计算sys
每个系统调用的 CPU 时间。 Ananosleep(1000000000)
将花费接近 0ms 的 CPU 时间,但 1s 的挂钟时间。
$ 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 时间都花费在这些系统调用中。例如,访问映射数据可能会使进程花费大量系统时间而不执行任何系统调用。
在这里,那些大量的mmaps()
调用可能是为了分配内存。这些都是即时的,因为它们只是更新一些映射。但是,当您第一次写入这些内容时,需要一些系统时间来用实际内存支持这些写入。
或者它们可能会映射像共享库这样的目标文件(这也是一种可能,因为数量与 的数量相差不远open()s
)。话又说回来,速度mmap()
很快,但是稍后读取内存也意味着一些页面错误和从磁盘读取数据的实际时间,这不计入任何系统调用。
更根本的是,如果您time strace -f your-application
像问题的早期版本一样执行操作,time
则会对命令和strace
.
strace
增加了很多开销。它会为 straced 应用程序的每个系统调用自行执行一些系统调用。
正在做
strace -fc time your-application
代替
time strace -fc your-application
更有可能为您提供更好的匹配。
但我发现,对于wait*()
进程等待子进程进行的系统调用,strace
将这些系统调用报告的时间计wait*()
为系统时间,这意味着子进程的时间(至少是等待的子进程)是数了好几遍。这很重要,strace -f time cmd
因为它在子进程中time
运行cmd
并等待它。
$ 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
,这意味着计算两次(不完全)。对孙子的 stracing 确实仍然会产生一些与 straced 进程有关的开销,因为我们得到 1.33,而不是之前的 0.76。如果我强制 strace、time 和 head 在同一处理器上运行(使用taskset 1
),则该值会大大减少。