How to calculate and group the time differences of specified syscalls when running strace

Question

I'm planing to do some web performance testing (to see how much time it's spent for each file), but it could be useful for any application.

I exactly know existence and how to use different performance applications, so I'm only interested in solution for strace.

Basically I'd like to calculate the time execution differences of my filtered syscalls and then group them, sort them and produce the summary (similar to -C option).

Some examples of usage:

$ strace -ttt -s1500 -o/dev/stdout -e trace=open,access sleep 1 | awk '{print $1 " " $2}'
$ strace -ttt -s1500 -s/dev/stdout -e trace=access drush ev '' | awk '{print $1 " " $2}'
(some example output)
1344416787.291395 execve("/bin/sleep",
1344416787.291796 brk(0)
1344416787.291879 access("/etc/ld.so.nohwcap",
1344416787.291960 mmap(NULL,
1344416787.292026 access("/etc/ld.so.preload",
1344416787.292089 open("/etc/ld.so.cache",
...
1344416787.294428 nanosleep({1,
1344416788.294726 close(1)
1344416788.294814 close(2)
1344416788.294906 exit_group(0)

Then from above output I'd like to calculate the time difference between the last printed calls (in human format):

Pseudo code:
echo "1344416788.294906 1344416788.294814" | awk '{print $2 - $1}'
0.00101089

Hint: in strace, you could use different format like -t, -tt or -ttt (you could use any which is easier to parse).

Then generate the list like (using e.g. sort, uniq, etc, without headers):

seconds  syscall
------ -----------
0.001580   close(2)
0.000132   close(1)
0.000032   exit_group(0)
0.000022   access("/etc/ld.so.preload",
0.000012   access("/etc/ld.so.cache",

Don't group it only by syscall name, but by the whole phrase ($2).

This should be as easy as possible. If there is any one-liner, I'd like to see it. Thanks.

P.S. If you think it's pointless your you, please ignore it.

--

Related topics (which could be useful for some ideas):

How to extract two numbers from two strings and calculate the difference in Bash?

http://www.unix.com/shell-programming-scripting/121053-sum-value-selected-lines-script-awk-perl.html

http://unstableme.blogspot.ch/2009/12/sum-numbers-in-each-row-awk.html

http://www.unix.com/shell-programming-scripting/157047-awk-compare-previous-value-current.html

Answer 1

You can do it like this:

$ strace -ttt ls 2>&1 1>&2- | awk '{ if (NR < 2) {last_time=$1} else {sec[$2]+=($1-last_time)}} END {for (i in sec) printf("%f %s\n", sec[i], i)}'| sort -n
0.000874 access("/etc/ld.so.preload",
0.000944 open("/etc/ld.so.cache",
0.001242 open("/lib/x86_64-linux-gnu/libselinux.so.1",
0.001490 mprotect(0x7f0166a2b000,
0.001543 mmap(0x7f0166c2a000,

There is much better tool if you want to profile system calls on Linux:

• perf
• Performance scripts

BTW, $2 does not contain all system call arguments, you will see 0.073917 mmap(NULL, in your output