私が知っているのは、timeシステムコールに費やされた合計時間を記録します。その後、time報告されたシステム時間の累積合計がstrace -fc等しくなることを望みます。しかし、その2つはかなり異なります（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を実行するシェルは、システムコールを実行せず、CPU時間もwhile :; do :; done使用せず、CPU時間のみを使用するのに無限の時間を費やします。sysuser
strace -csys各システムコールのCPU時間を計算してみてください。 Aはnanosleep(1000000000)CPU時間はほぼ0msに近いですが、壁時計時間は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時間全体がこれらのシステムコールに費やされるわけではありません。たとえば、マッピングされたデータにアクセスすると、プロセスがシステムコールを実行せずに大量のシステム時間を費やす可能性があります。
ここでこのような多くの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
timestrace同じシステム時間（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これは、2回（不完全に）計算されることを意味します。以前の0.76ではなく1.33を取得したため、孫を追跡すると、追跡プロセスに関連するいくつかのオーバーヘッドがまだ発生します。 strace、time、およびheadを同じプロセッサで強制的に実行すると（使用taskset 1）、値が大幅に減少します。