How to use strace to only show calls that take a lot of time?

Question

Is there a way to grep for only calls that over a certain amount of time?

Answer 1

It looks like there is a flag that shows the CPU time in the output (-c):

man strace

Sample output:

sysadm@brownie:~$ strace -c ./crypt_crack.py
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 84.38    0.000027           0       340       273 open
 15.63    0.000005           0        67           rt_sigaction
  0.00    0.000000           0        91           read
  0.00    0.000000           0        67           close
  0.00    0.000000           0       117        89 stat
  0.00    0.000000           0        96           fstat
  0.00    0.000000           0         1           lstat
  0.00    0.000000           0         3           lseek
  0.00    0.000000           0        64           mmap
  0.00    0.000000           0        17           mprotect
  0.00    0.000000           0        30           munmap
  0.00    0.000000           0         8           brk
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         4         2 ioctl
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           uname
  0.00    0.000000           0         2           fcntl
  0.00    0.000000           0         4           getdents
  0.00    0.000000           0         1           getcwd
  0.00    0.000000           0         1         1 readlink
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         2           futex
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.000032                   923       366 total

sysadm@brownie:~$

When run with the -c flag, strace appears to hold all output until execution terminates (gracefully or ctrl-c)

And with awk to look for CPU time == 0.0:

sysadm@brownie:~$ strace -c ls -la 2>&1 | awk '{if ($2 == 0.0) print;}'
  0.00    0.000000           0        23           read
  0.00    0.000000           0         1           write
  0.00    0.000000           0        34        12 open
  0.00    0.000000           0        27           close
  0.00    0.000000           0        34           stat
  0.00    0.000000           0        23           fstat
  0.00    0.000000           0        34           lstat
  0.00    0.000000           0         1           lseek
  0.00    0.000000           0        41           mmap
  0.00    0.000000           0        12           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         2         2 ioctl
  0.00    0.000000           0         2         1 access
  0.00    0.000000           0         4           socket
  0.00    0.000000           0         4         4 connect
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           uname
  0.00    0.000000           0        13           fcntl
  0.00    0.000000           0         2           getdents
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0        67        67 getxattr
  0.00    0.000000           0         1           futex
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           clock_gettime
  0.00    0.000000           0         1           set_robust_list
sysadm@brownie:~$