☰

Strace は、システムコールが総実行時間よりはるかに長くかかることを示しています。なぜ？

tag-icon • tag-icon system-calls strace profiling
Strace は、システムコールが総実行時間よりはるかに長くかかることを示しています。なぜ？

Tensorflow-gpuに基づいて人工知能推論プログラムを実行しています。

を実行すると、/usr/bin/strace -c -f /usr/bin/time ./program次のような結果が出力されます。

<my program's output>
367.91user 1032.14system 26:43.41elapsed 87%CPU (0avgtext+0avgdata 4158812maxresident)k <----OUTPUT OF TIME
1760inputs+24outputs (0major+4259846minor)pagefaults 0swaps
% time     seconds  usecs/call     calls    errors syscall                              <----OUTPUT OF STRACE
------ ----------- ----------- --------- --------- ----------------
 88.45 34105.209840        7166   4759375    217371 futex
  8.71 3356.854321       49032     68462           poll
  2.68 1032.625515     2044803       505           wait4
  0.05   21.006854         119    177269           clock_gettime
<..and some other syscalls that didn't took very long...>
------ ----------- ----------- --------- --------- ----------------
100.00 38559.038652               5385548    247845 total

私のプログラムだけでも34105数秒かかったことがわかりますfutex。20倍長くなる経過した時間26:43.41より

straceコア全体のシステムコール時間を記録することを考えて、tasksetコアを1つだけ有効にした状態で再試行してみましたが、問題は解決しません。

編集する：

私はワークセットと--all-tasksオプションを使用しました。

/usr/bin/taskset --all-tasks --cpu-list 0 /usr/bin/strace  -c -f /usr/bin/time ./program

答え1

私を見ると、man strace次のようになります。

-c
--summary-only
       ...
       If -c is used with -f, only aggregate totals  for  all  traced
       processes are kept.

-f
--follow-forks
       Trace child processes as  they  are  created  by  currently
       traced  processes  as a result of the fork(2), vfork(2) and
       clone(2) system calls.
       ...

ここでは、と-cを指定します-f。プロセスがフォークまたはマルチスレッドの場合、結果はプロセス全体に集約されます。たとえば、複数のスレッドがすべてブロックされている場合、現在表示されてfutex()いる動作を確認できます。

観察された異常に長いシステムコールfutexはブロックコールであるため、CPU時間を積極的に占有しません。複数のスレッドがすべて同じ CPU に固定されていても、同時にコールをブロックできます。

関連情報