Tool to help me make sense out of `strace -f` output.

strace_process_tree.py

in/python
# -*- coding: UTF-8 -*-
"""
Usage:
  strace-process-tree filename

Read strace -f output and produce a process tree.

Recommended strace options for best results:

    strace -f -e trace=process -s 1024 -o filename.out command args

"""

import argparse
import re
import string
from collections import defaultdict


__version__ = '0.6.0'
__author__ = 'Marius Gedminas <marius@gedmin.as>'
__url__ = 'https://gist.github.com/mgedmin/4953427'
__licence__ = 'GPL v2 or later' # or ask me for MIT


def events(stream):
    RESUMED_PREFIX = re.compile(r'<... \w+ resumed> ')
    UNFINISHED_SUFFIX = ' <unfinished ...>'
    DURATION_SUFFIX = re.compile(r' <\d+([.]\d+)?>$')
    TIMESTAMP = re.compile(r'^\d+([.]\d+)?\s+')
    pending = {}
    for line in stream:
        pid, space, event = line.rstrip().partition(' ')
        try:
            pid = int(pid)
        except ValueError:
            raise SystemExit(
                "This does not look like a log file produced by strace -f:\n\n"
                "  %s\n"
                "There should've been a PID at the beginning of the line."
                % line)
        event = event.lstrip()
        event = TIMESTAMP.sub('', event)
        event = DURATION_SUFFIX.sub('', event)
        m = RESUMED_PREFIX.match(event)
        if m is not None:
            event = pending.pop(pid) + event[len(m.group()):]
        if event.endswith(UNFINISHED_SUFFIX):
            pending[pid] = event[:-len(UNFINISHED_SUFFIX)]
        else:
            yield (pid, event)


class ProcessTree:
    def __init__(self):
        self.names = {}
        self.parents = {}
        self.children = defaultdict(list)
        self.roots = set()
        self.all = set()
        # invariant: self.roots == self.all - set(self.parents), probably

    def make_known(self, pid):
        if pid not in self.all:
            self.roots.add(pid)
            self.all.add(pid)

    def has_name(self, pid):
        return pid in self.names

    def set_name(self, pid, name):
        self.make_known(pid)
        self.names[pid] = name

    def add_child(self, ppid, pid):
        self.make_known(ppid)
        self.make_known(pid)
        if pid in self.roots:
            self.roots.remove(pid)
        self.parents[pid] = ppid
        self.children[ppid].append(pid)

    def _format(self, pids, indent='', level=0):
        r = []
        for n, pid in enumerate(pids):
            if level == 0:
                s, cs = '', ''
            elif n < len(pids) - 1:
                s, cs = '  ├─', '  │ '
            else:
                s, cs = '  └─', '    '
            name = self.names.get(pid, '')
            children = sorted(self.children.get(pid, []))
            if children:
                ccs = '  │ '
            else:
                ccs = '    '
            name = name.replace('\n', '\n' + indent + cs + ccs + '    ')
            r.append(indent + s + '{} {}\n'.format(pid, name))
            r.append(self._format(children, indent+cs, level+1))

        return ''.join(r)

    def format(self):
        return self._format(sorted(self.roots))

    def __str__(self):
        return self.format()


def simplify_syscall(event):
    # clone(child_stack=0x..., flags=FLAGS, parent_tidptr=..., tls=..., child_tidptr=...) => clone(FLAGS)
    if event.startswith('clone('):
        event = re.sub('[(].*, flags=([^,]*), .*[)]', r'(\1)', event)
    return event.rstrip()


def extract_command_line(event):
    # execve("/usr/bin/foo", ["foo", "bar"], [/* 45 vars */]) => foo bar
    if event.startswith('clone('):
        if 'CLONE_THREAD' in event:
            return '(thread)'
        else:
            return '...'
    elif event.startswith('execve('):
        command = re.sub(r'^execve\([^[]*\[', '', re.sub(r'\], \[/\* \d+ vars \*/\]\)$', '', event.rstrip()))
        command = parse_argv(command)
        return format_command(command)
    else:
        return event.rstrip()


ESCAPES = {
    'n': '\n',
    'r': '\r',
    't': '\t',
    'b': '\b',
    '0': '\0',
    'a': '\a',
}


def parse_argv(s):
    # '"foo", "bar"..., "baz", "\""' => ['foo', 'bar...', 'baz', '"']
    it = iter(s + ",")
    args = []
    for c in it:
        if c == ' ':
            continue
        assert c == '"'
        arg = []
        for c in it:
            if c == '"':
                break
            if c == '\\':
                c = next(it)
                arg.append(ESCAPES.get(c, c))
            else:
                arg.append(c)
        c = next(it)
        if c == ".":
            arg.append('...')
            c = next(it)
            assert c == "."
            c = next(it)
            assert c == "."
            c = next(it)
        args.append(''.join(arg))
        assert c == ','
    return args


SHELL_SAFE_CHARS = set(string.ascii_letters + string.digits + '%+,-./:=@^_~')
SHELL_SAFE_QUOTED = SHELL_SAFE_CHARS | set("!#&'()*;<>?[]{|} \t\n")


def format_command(command):
    return ' '.join(map(pushquote, (
        arg if all(c in SHELL_SAFE_CHARS for c in arg) else
        '"%s"' % arg if all(c in SHELL_SAFE_QUOTED for c in arg) else
        "'%s'" % arg.replace("'", "'\\''")
        for arg in command
    )))


def pushquote(arg):
    return re.sub('''^(['"])(--[a-zA-Z0-9_-]+)=''', r'\2=\1', arg)


def main():
    parser = argparse.ArgumentParser(
        description="""
            Read strace -f output and produce a process tree.

            Recommended strace options for best results:

                strace -f -e trace=process -s 1024 -o FILENAME COMMAND
            """)
    parser.add_argument('--version', action='version', version=__version__)
    parser.add_argument('-v', '--verbose', action='store_true',
                        help='more verbose output')
    parser.add_argument('filename', type=argparse.FileType('r'),
                        help='strace log to parse (use - to read stdin)')
    args = parser.parse_args()

    tree = ProcessTree()

    mogrifier = simplify_syscall if args.verbose else extract_command_line

    for pid, event in events(args.filename):
        if event.startswith('execve('):
            args, equal, result = event.rpartition(' = ')
            if result == '0':
                name = mogrifier(args)
                tree.set_name(pid, name)
        if event.startswith(('clone(', 'fork(', 'vfork(')):
            args, equal, result = event.rpartition(' = ')
            if result.isdigit():
                child_pid = int(result)
                name = mogrifier(args)
                if not tree.has_name(child_pid):
                    tree.set_name(child_pid, name)
                tree.add_child(pid, child_pid)

    print(tree.format().rstrip())


if __name__ == '__main__':
    main()

strace_process_tree_example_output.txt

25510 make binary-package
  ├─25511 /bin/sh -c 'dpkg-parsechangelog | awk '\''$1 == "Source:" { print $2 }'\'''
  │   ├─25512 dpkg-parsechangelog
  │   │   └─25514 tail -n 40 debian/changelog
  │   └─25513 awk '$1 == "Source:" { print $2 }'
  ├─25515 /bin/sh -c 'dpkg-parsechangelog | awk '\''$1 == "Version:" { print $2 }'\'''
  │   ├─25516 dpkg-parsechangelog
  │   │   └─25518 tail -n 40 debian/changelog
  │   └─25517 awk '$1 == "Version:" { print $2 }'
  ├─25519 /bin/sh -c 'dpkg-parsechangelog | grep ^Date: | cut -d: -f 2- | date --date="$(cat)" +%Y-%m-%d'
  │   ├─25520 dpkg-parsechangelog
  │   │   └─25525 tail -n 40 debian/changelog
  │   ├─25521 grep ^Date:
  │   ├─25522 cut -d: -f 2-
  │   └─25523 date --date=" Thu, 18 Jan 2018 23:39:51 +0200" +%Y-%m-%d
  │       └─25524 cat
  └─25526 /bin/sh -c 'dpkg-parsechangelog | awk '\''$1 == "Distribution:" { print $2 }'\'''
      ├─25527 dpkg-parsechangelog
      │   └─25529 tail -n 40 debian/changelog
      └─25528 awk '$1 == "Distribution:" { print $2 }'

strace_process_tree_example_verbose_output.txt

$ strace-process-tree zdaemon-py3.GIT/TRACE3
6184 execve("bin/test", ["bin/test", "-pvc", "-t", "README"], [/* 65 vars */])
  ├─6196 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -p 'echo hello world' "...], [/* 67 vars */])           
  │   └─6197 execve("./zdaemon", ["./zdaemon", "-p", "echo hello world", "fg"], [/* 67 vars */])
  │       └─6199 execve("/bin/echo", ["echo", "hello", "world"], [/* 67 vars */])
  ├─6200 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -p 'sleep 100' start"], [/* 67 vars */])           
  │   └─6201 execve("./zdaemon", ["./zdaemon", "-p", "sleep 100", "start"], [/* 67 vars */])
  │       └─6205 execve("/usr/bin/python3.3", ["/usr/bin/python3.3", "./zdaemon", "-S", "schema.xml", "-b", "10", "-s", "zdsock", "-m", "0o22", "-x", "0,2", "sleep", "100"], [/* 68 vars */])           
  │           └─6212 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f163fcab9d0)
  │               ├─6213 clone(child_stack=0x7f163e4b4ff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f163e4b59d0, tls=0x7f163e4b5700, child_tidptr=0x7f163e4b59d0)
  │               └─6214 execve("/bin/sleep", ["sleep", "100"], [/* 67 vars */])
  ├─6215 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -p 'sleep 100' status"], [/* 67 vars */])           
  │   └─6216 execve("./zdaemon", ["./zdaemon", "-p", "sleep 100", "status"], [/* 67 vars */])
  ├─6217 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -p 'sleep 100' stop"], [/* 67 vars */])           
  │   └─6218 execve("./zdaemon", ["./zdaemon", "-p", "sleep 100", "stop"], [/* 67 vars */])
  ├─6220 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -p 'sleep 100' status"], [/* 67 vars */])           
  │   └─6221 execve("./zdaemon", ["./zdaemon", "-p", "sleep 100", "status"], [/* 67 vars */])
  ├─6225 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -Cconf start"], [/* 67 vars */])           
  │   └─6226 execve("./zdaemon", ["./zdaemon", "-Cconf", "start"], [/* 67 vars */])
  │       └─6253 execve("/usr/bin/python3.3", ["/usr/bin/python3.3", "./zdaemon", "-S", "/home/mg/src/zdaemon-py3.GIT/src"..., "-C", "conf", "sleep", "100"], [/* 68 vars */])           
  │           └─6262 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fd2a97bf9d0)
  │               ├─6263 clone(child_stack=0x7fd2a7fc8ff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fd2a7fc99d0, tls=0x7fd2a7fc9700, child_tidptr=0x7fd2a7fc99d0)
  │               └─6264 execve("/bin/sleep", ["sleep", "100"], [/* 67 vars */])
  ├─6269 execve("/bin/sh", ["/bin/sh", "-c", "ls"], [/* 67 vars */])           
  │   └─6270 execve("/bin/ls", ["ls"], [/* 67 vars */])
  ├─6271 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -Cconf stop"], [/* 67 vars */])           
  │   └─6272 execve("./zdaemon", ["./zdaemon", "-Cconf", "stop"], [/* 67 vars */])
  ├─6278 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -Cconf start"], [/* 67 vars */])           
  │   └─6279 execve("./zdaemon", ["./zdaemon", "-Cconf", "start"], [/* 67 vars */])
  │       └─6288 execve("/usr/bin/python3.3", ["/usr/bin/python3.3", "./zdaemon", "-S", "/home/mg/src/zdaemon-py3.GIT/src"..., "-C", "conf", "sleep", "100"], [/* 68 vars */])           
  │           └─6294 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f44cb0e79d0)
  │               ├─6295 clone(child_stack=0x7f44c98f0ff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f44c98f19d0, tls=0x7f44c98f1700, child_tidptr=0x7f44c98f19d0)
  │               └─6296 execve("/bin/sleep", ["sleep", "100"], [/* 67 vars */])
  ├─6298 execve("/bin/sh", ["/bin/sh", "-c", "ls"], [/* 67 vars */])           
  │   └─6300 execve("/bin/ls", ["ls"], [/* 67 vars */])
  ├─6301 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -Cconf stop"], [/* 67 vars */])           
  │   └─6302 execve("./zdaemon", ["./zdaemon", "-Cconf", "stop"], [/* 67 vars */])
  ├─6304 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -Cconf start 100"], [/* 67 vars */])           
  │   └─6305 execve("./zdaemon", ["./zdaemon", "-Cconf", "start", "100"], [/* 67 vars */])
  │       └─6314 execve("/usr/bin/python3.3", ["/usr/bin/python3.3", "./zdaemon", "-S", "/home/mg/src/zdaemon-py3.GIT/src"..., "-C", "conf", "sleep", "100"], [/* 68 vars */])           
  │           └─6322 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ff8f14959d0)
  │               ├─6323 clone(child_stack=0x7ff8efc9eff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7ff8efc9f9d0, tls=0x7ff8efc9f700, child_tidptr=0x7ff8efc9f9d0)
  │               └─6324 execve("/bin/sleep", ["sleep", "100"], [/* 67 vars */])
  ├─6333 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -Cconf status"], [/* 67 vars */])           
  │   └─6334 execve("./zdaemon", ["./zdaemon", "-Cconf", "status"], [/* 67 vars */])
  ├─6346 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -Cconf stop"], [/* 67 vars */])           
  │   └─6347 execve("./zdaemon", ["./zdaemon", "-Cconf", "stop"], [/* 67 vars */])
  ├─6348 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -Cconf fg"], [/* 67 vars */])           
  │   └─6349 execve("./zdaemon", ["./zdaemon", "-Cconf", "fg"], [/* 67 vars */])
  │       └─6350 execve("/usr/bin/env", ["env"], [/* 68 vars */])
  ├─6351 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -Cconf start"], [/* 67 vars */])           
  │   └─6352 execve("./zdaemon", ["./zdaemon", "-Cconf", "start"], [/* 67 vars */])
  │       └─6354 execve("/usr/bin/python3.3", ["/usr/bin/python3.3", "./zdaemon", "-S", "/home/mg/src/zdaemon-py3.GIT/src"..., "-C", "conf", "tail", "-f", "data"], [/* 68 vars */])           
  │           └─6380 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fb4506119d0)
  │               ├─6381 clone(child_stack=0x7fb44ee1aff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fb44ee1b9d0, tls=0x7fb44ee1b700, child_tidptr=0x7fb44ee1b9d0)
  │               └─6382 execve("/usr/bin/tail", ["tail", "-f", "data"], [/* 67 vars */])
  └─6399 execve("/bin/sh", ["/bin/sh", "-c", "./zdaemon -Cconf reopen_transcri"...], [/* 67 vars */])           
      └─6400 execve("./zdaemon", ["./zdaemon", "-Cconf", "reopen_transcript"], [/* 67 vars */])

Output example moved to a separate file in the gist.

Version 0.2 adds Unicode line art.

0.2.1 fixes incorrect assumption that there are always two spaces between the pid and the event

Version 0.6 introduces new default brief output that just lists program command lines. Use -v to see old-style full system call arguments.

There's also an important bugfix (parent losing the clone race against the new child's execve could clobber its command line in the tree output).

Thanks for the script! very useful. I noticed one thing that exec lines only show the last exec call for a pid so if a process exec multiple times only the last command and arguments will be shown. Might be a bit confusing some times. I tried to do patch that keept a list of names per pid instead and it worked but got messy printing it properly as a tree

Development continued in my scripts repository, https://github.com/mgedmin/scripts/blob/master/strace-process-tree

I think it's time to make this a proper project with its own GitHub repo and everything.

It is moved to https://github.com/mgedmin/strace-process-tree