Decode / summarise strace logs

Question

OK, so it's no secret that strace produces vast amounts of output. (I'm aware there are various options to filter the output a bit.)

Are there any tools to process a raw strace log into something more human-readable?

What kind of "decoding" am I looking for? Well, by design strace works at a very low level. I'm looking for something that can summarize the most important points. For example, FD 4 might point to different files at different instants; it would be useful to have the machine keep track of this, rather than me. Ditto for PIDs. I would like to be able to see process trees at different moments in the trace, and so forth. A GUI tool would be great, but even something text-based would be acceptable if it makes things a bit easier to follow.

Answer 1

Summary while strace runs

strace has the -c switch which will give you a summary report of the various system calls that were made.

excerpt strace man page

-c      Count time, calls, and errors for each system call and report a 
        summary on program exit.  On Linux, this attempts to show system 
        time (CPU  time  spent  running in the kernel) independent of wall 
        clock time.  If -c is used with -f or -F (below), only aggregate 
        totals for all traced processes are kept.

Example

$ strace -c systemctl list-unit-files --type=service
...
...
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 51.81    0.001831        1831         1           waitid
  8.15    0.000288           7        39           mmap
  7.89    0.000279          19        15           read
  6.11    0.000216           8        26           mprotect
  4.56    0.000161          11        15           open
  2.91    0.000103         103         1           connect
  2.24    0.000079          79         1           clone
  2.15    0.000076          38         2           statfs
  2.01    0.000071           4        19           close
  1.95    0.000069           5        13           poll
  1.90    0.000067           5        14         2 recvmsg
  1.70    0.000060           4        16           fstat
  0.88    0.000031           8         4         3 stat
  0.82    0.000029          29         1           socket
  0.65    0.000023           8         3           munmap
  0.57    0.000020           5         4           sendto
  0.42    0.000015           5         3           ioctl
  0.40    0.000014           7         2           lstat
  0.40    0.000014           7         2           sendmsg
  0.34    0.000012           4         3           brk
  0.23    0.000008           8         1           pipe
  0.23    0.000008           4         2           fcntl
  0.20    0.000007           4         2           rt_sigaction
  0.20    0.000007           7         1         1 access
  0.20    0.000007           4         2           geteuid
  0.17    0.000006           6         1           execve
  0.14    0.000005           5         1           getsockname
  0.11    0.000004           4         1           dup2
  0.11    0.000004           4         1           getresuid
  0.11    0.000004           4         1           getresgid
  0.11    0.000004           4         1           arch_prctl
  0.08    0.000003           3         1           rt_sigprocmask
  0.08    0.000003           3         1           getrlimit
  0.08    0.000003           3         1           set_tid_address
  0.08    0.000003           3         1           set_robust_list
  0.00    0.000000           0         4           write
  0.00    0.000000           0         1           kill
------ ----------- ----------- --------- --------- ----------------
100.00    0.003534                   207         6 total

Analyzing strace logs postmortem

I found this Perl scripts called Strace_analyzer.pl which sounds like what you're looking for.

Usage

$ ./strace_analyzer_ng_0.03.pl -help
Usage: strace-analyze [OPTION]… [FILE]
Analyzes strace output for IO functions. It creates statistics
on IO functions and performance of the read and write functions.
The strace file should have been run with ‘strace -tt [PROGRAM]

There's an example of the output on the page I linked to above. It's too long to post here. I've posted here on pastebin.com as well.

• Strace_Analyzer.pl sample output
• IO Profiling of Applications: strace_analyzer - Linux Magazine article

Alternative to strace, ioapps

I came across this app called ioapps which can give you a more visual breakdown of what your app is doing when it's running. Perhaps this might be better for what you're trying to accomplish than processing strace logs.

Usage

  $ ioprofiler-trace thunderbird

Once it loads, we just close the thunderbird window and check we have a trace log called "ioproftrace.log" because that's the default name of the log (one can specify another name using -o command line option):

  $ ls -l ioproftrace.log 
  -rw-r--r-- 1 user user 74890554 Apr  4 22:04 ioproftrace.log

It seems OK, so we can run ioprofiler over it:

  $ ioprofiler ioproftrace.log 

Example GUI

   

Another alternative to strace, strace+

NOTE: The project, strace+, is no longer being maintained, and in fact many of its features have been merged into the default strace via the -k switch. So you might want to make sure your version of strace is at least up to 4.9, which is when that switch was merged in.

excerpt strace man page

-k          Print the execution stack trace of the traced processes after 
            each system call (experimental).

excerpt from strace+ project page

strace+ is an improved version of strace that collects stack traces associated with each system call. Since system calls require an expensive user-kernel context switch, they are often sources of performance bottlenecks. strace+ allows programmers to do more detailed system call profiling and determine, say, which call sites led to costly syscalls and thus have potential for optimization.