為什麼time和strace -c不同？
據我了解，
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 次，它們都給出了一致的結果）
一個程序可以花費任何時間不進行任何系統呼叫。
例如，執行 a 的 shell
while :; 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。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 total1.33是一個
wait4()系統呼叫報告的時間time。報告head(time的孩子) 的系統時間。但是，除此之外，
strace它還會嘗試為其head孫子的每個系統呼叫獲取系統時間，這意味著它被計算了兩次（不完全）。由於我們得到 1.33 而不是之前的 0.76，因此對孫子的跟踪仍然會產生一些成本，這些成本與跟踪過程有關。如果我強制 strace、time 和 head 在同一個處理器上執行（使用taskset 1），這將大大減少。