Merge Parallel strace Logs into One Timeline

Trace a shell script with strace -ff and you get a pile of per-process log files that tell you nothing about the order things actually happened in. strace-log-merge interleaves them by timestamp so you can follow the whole process tree in one pass. The examples use strace 6.8, supplied by the Ubuntu package strace 6.8-0ubuntu2.

Allow about 10 minutes. You need strace and strace-log-merge installed, a shell, and a command that is safe to observe. Tracing a command does not normally require elevated privileges, but attaching to an existing process often does. This guide only starts a new command.

1. Check the installed command

Confirm the helper is on your path and read its local usage text. This is a read-only check.

$ command -v strace-log-merge
/usr/bin/strace-log-merge
$ strace-log-merge --help
Usage: strace-log-merge STRACE_LOG

Finds all STRACE_LOG.PID files, adds PID prefix to every line,
then combines and sorts them, and prints result to standard output.

The argument is a file name prefix, not one complete log name. If the prefix is trace, the helper reads files matching trace.*. It adds the PID from each suffix to every output line, then sorts using the timestamp in the trace.

2. Capture a small process tree

Choose an output prefix that is private to this run. -ff gives each traced process its own file, while -tt adds a time-of-day timestamp with microseconds. The trace filter below keeps the demonstration short.

$ mkdir -p "$HOME/strace-merge-demo"
$ cd "$HOME/strace-merge-demo"
$ strace -o sleepy -ff -tt -e trace=execve,nanosleep \
    sh -c 'sleep 0.1 & sleep 0.2 & sleep 0.3'
$ ls -1 sleepy.*
sleepy.12340
sleepy.12341
sleepy.12342
sleepy.12343

Your numeric suffixes will differ. The shell and each background sleep can receive different PIDs, so do not copy the names from the example into a later command. The trace files land in the current directory and the traced program's own files are untouched.

$ printf '%s\n' sleepy.*
sleepy.12340
sleepy.12341
sleepy.12342
sleepy.12343

A stale file with the same prefix gets pulled in too. Use a new directory or a new prefix for each capture. If these logs contain command arguments or environment-derived data, treat them as sensitive: set their permissions or remove them after checking, and do not upload them casually.

3. Merge and inspect the timeline

Pass only the prefix to strace-log-merge. It writes the combined result to standard output, so redirect it if you want a durable report.

$ strace-log-merge sleepy | head -12
12340 21:13:52.040837 execve("/bin/sh", ["sh", "-c", "sleep 0.1 & sleep 0.2 & sleep 0.3"], ...) = 0
12343 21:13:52.044050 execve("/bin/sleep", ["sleep", "0.3"], ...) = 0
12341 21:13:52.044269 execve("/bin/sleep", ["sleep", "0.1"], ...) = 0
12342 21:13:52.044389 execve("/bin/sleep", ["sleep", "0.2"], ...) = 0
12343 21:13:52.046207 nanosleep({tv_sec=0, tv_nsec=300000000}, NULL) = 0
12341 21:13:52.046303 nanosleep({tv_sec=0, tv_nsec=100000000}, NULL) = 0

The PIDs and exact timestamps vary. What matters is the order: lines from different files are interleaved by their trace timestamps, and the PID at the start of each line tells you which process made the call.

Save the complete merge when you need to search it later:

$ strace-log-merge sleepy > merged.log
$ grep -E 'execve|nanosleep|exited|SIGCHLD' merged.log | head

The grep is ordinary inspection. It does not change the trace.

4. Use absolute timestamps for anything that might cross midnight

With -tt, the timestamp is time-of-day only. The manpage warns that sorting becomes unreliable once a run passes midnight, because the date is missing from the line. Capture with -ttt instead: it records seconds since the Unix epoch, so ordering survives the date rollover.

$ strace -o overnight -ff -ttt -e trace=execve,nanosleep \
    sh -c 'sleep 0.1' >/dev/null 2>&1
$ strace-log-merge overnight | head -4
12350 1790479678.986258 execve("/usr/bin/sh", ["sh", "-c", "sleep 0.1"], ...) = 0
12351 1790479678.987814 execve("/usr/bin/sleep", ["sleep", "0.1"], ...) = 0
12351 1790479679.000574 +++ exited with 0 +++
12350 1790479679.000621 --- SIGCHLD ...

5. Diagnose failures without guessing

• No argument given. The helper prints usage and exits non-zero.
• Prefix matches nothing. It fails outright rather than silently printing an empty report.

$ strace-log-merge no-such-prefix
strace-log-merge: no-such-prefix: strace output not found
$ echo $?
1

If this happens, check the current directory, the exact prefix, and the files produced by -ff. Remember that -o sleepy produces names such as sleepy.12340; passing sleepy.12340 itself as the helper argument makes it search for sleepy.12340.*, which is not what you want.

If the output is not in chronological order, check that the trace was made with -tt or -ttt, and that every matching file belongs to the same run. The helper does not validate either assumption for you.