Package: strace
Version: 4.5.14-2
strace -T shows the time spent in each syscall. Looking at the source,
it records the syscall entry time in tcp->etime, and then calculates the
duration on syscall exit.
This clearly fails for multithreaded processes. To get accurate
results, there ought to be a separate "etime" for each thread of the
process. I'm guessing it's just not possible to fork a new strace
instance for each thread :-).
I found this bug after running strace on udevd, with an unpublished
patch to use a thread for each event. It's not obvious why the time
goes negative though. Perhaps there's another error I missed.
$ sudo strace -qc udevd & sudo udevtrigger; sudo udevsettle; sudo killall udevd
[1] 4937
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
7.33 0.821332 205333 4 getdents
7.25 0.811993 38666 21 mremap
6.29 0.705333 705333 1 execve
6.29 0.705333 705333 1 chdir
6.29 0.705333 705333 1 umask
6.29 0.705333 705333 1 setsid
6.29 0.705333 705333 1 setpriority
6.29 0.705333 705333 1 uname
6.29 0.705333 705333 1 rt_sigprocmask
6.29 0.705333 705333 1 getrlimit
6.29 0.705333 705333 1 getuid32
6.29 0.705333 705333 1 set_thread_area
6.29 0.705333 705333 1 set_tid_address
6.29 0.705333 705333 1 inotify_init
6.29 0.705333 705333 1 set_robust_list
6.29 0.705333 705333 1 send
5.74 0.642664 80333 8 8 access
5.74 0.642664 80333 8 socket
4.62 0.517142 670 772 _llseek
4.14 0.463996 38666 12 fcntl64
3.66 0.410666 205333 2 pipe
3.66 0.410666 205333 2 bind
3.66 0.410666 205333 2 setsockopt
3.66 0.409705 946 433 fstat64
2.07 0.231998 38666 6 rt_sigaction
2.07 0.231998 38666 6 5 connect
1.04 0.115999 38666 3 dup2
1.04 0.115999 38666 3 1 inotify_add_watch
7.76 -1.1869222 2031 428 munmap
4.70 -1.1526656 21066 25 5 sigreturn
3.50 -1.1391924 3379 116 read
2.99 -1.1334703 37189 9 brk
1.33 -1.1149311 6492 23 mkdir
1.32 -1.1147927 224 659 mmap2
1.11 -1.1124873 2191 57 futex
-2.84 -1.681908 -1472 216 mprotect
-2.12 -2.1762887 -277 852 3 open
-2.66 -2.1701830 -691 431 1 select
-4.03 -2.1547986 -963 469 23 stat64
-4.93 -2.1447442 -1340 412 362 unlink
-5.22 -2.1414563 -1420 412 recv
-5.26 -2.1410899 -1429 412 1 symlink
-5.26 -2.1410589 -1430 412 412 rmdir
-5.77 -2.1352966 -751 860 close
-8.07 -2.1095702 -2189 413 time
-9.16 -2.973253 -2485 413 1 clone
-11.17 -2.748609 -2837 441 write
------ ----------- ----------- --------- --------- ----------------
100.00 11.205400 8356 822 total
--
To UNSUBSCRIBE, email to [EMAIL PROTECTED]
with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]
