☰

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에 고정되어 있더라도 동시에 호출을 차단할 수 있습니다.

관련 정보