☰

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）进行了重新实验，但问题仍然存在。

编辑：

我确实使用了任务集和--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 。

相关内容