「time」と「strace -c」はなぜ違うのですか?

「time」と「strace -c」はなぜ違うのですか?

私が知っているのは、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()システムコールによって報告された時間timeheadtime子供の)システム時間を報告します。

ただし、strace孫のシステムコールごとにシステム時間を取得しようとします。headこれは、2回(不完全に)計算されることを意味します。以前の0.76ではなく1.33を取得したため、孫を追跡すると、追跡プロセスに関連するいくつかのオーバーヘッドがまだ発生します。 strace、time、およびheadを同じプロセッサで強制的に実行すると(使用taskset 1)、値が大幅に減少します。

関連情報