내가 아는 바로는 time시스템 호출에 소요된 총 시간이 기록됩니다. 그런 다음 time보고된 시스템 시간의 누적 합계가 strace -fc동일해지기를 원합니다 . 그러나 그 둘은 상당히 다릅니다(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, 이는 두 번(불완전하게) 계산된다는 의미입니다. 이전 0.76 대신 1.33을 얻으므로 손자를 추적하면 추적 프로세스와 관련된 일부 오버헤드가 여전히 발생합니다. strace, time 및 head를 동일한 프로세서에서 강제로 실행하면(사용 taskset 1) 값이 크게 줄어듭니다.