Sergei Kurenkov Sergei Kurenkov -4 years ago 105
Linux Question

strace -c does not show correct seconds

I have got results for

strace -c
on RHEL 7 and RHEL 6
for this command:

strace -c /bin/sleep 20


and I don't understand why the
seconds
column for
nanosleep
is equal to 0. I had expected it to be 20.

0.00 0.000000 0 1 nanosleep


Here is a full strace report:

$ strace -c /bin/sleep 20
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00 0.000019 1 15 12 open
0.00 0.000000 0 1 read
0.00 0.000000 0 5 close
0.00 0.000000 0 8 6 stat
0.00 0.000000 0 3 fstat
0.00 0.000000 0 9 mmap
0.00 0.000000 0 3 mprotect
0.00 0.000000 0 1 munmap
0.00 0.000000 0 3 brk
0.00 0.000000 0 1 1 access
0.00 0.000000 0 1 nanosleep
0.00 0.000000 0 1 execve
0.00 0.000000 0 1 arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00 0.000019 52 19 total


And there is a call to nanosleep in a detailed report:

nanosleep({20, 0}, NULL) = 0


So seconds must be 20, not 0. What do you think?

Answer Source

From the manual page of strace(1):

-c On Linux, this attempts to show system time (CPU time spent running in the kernel)

I think that:

when a process calls nanosleep(), it asks the kernel to be suspended for a period of time. The kernel sets up a few things (like some flag, a timer, a timestamp...), suspends the calling process, and goes to do something else. strace(1) reports the time spent by the kernel to do this, not the time the process stays suspended.

May be that this -c strace option can be thought as "-cost": how much time this syscall costs?

Recommended from our users: Dynamic Network Monitoring from WhatsUp Gold from IPSwitch. Free Download