Recursively time‘ing a Tree of Processes

If you are a bit into using the command line, chances are high you know time. Depending on your environment, it’s either a command of your shell or a real program in /usr/bin. In both cases, it provides a way to run another program and easily get its resource usage. Say it takes 5 seconds for a command to do something, time will tell you.

While pretty handy for simple commands, I recently needed to understand a whole tree of processes. Think of a build system which takes a long time to build some documentation. You know it takes that many minutes in total, but which part is the one you should optimize? In particular if the build system calls many processes which in turn fork more commands and so on…

My solution was the following:

#include <fcntl.h>
#include <locale.h>
#include <stdio.h>
#include <stdlib.h>
#include <sys/resource.h>
#include <unistd.h>

__attribute__((destructor))
void trace_end() {
    char *out = getenv("TRACE_OUT");
    if (out == NULL || *out == '\0') {
        // TODO: Log error? Probably too much spam!
        return;
    }
    char *exe = realpath("/proc/self/exe", NULL);

    // Reset locale to get '.' in decimal notation.
    setlocale(LC_NUMERIC, "C");

    struct rusage usage;
    if (getrusage(RUSAGE_SELF, &usage) != 0) {
        return;
    }
    double utime = ((double) usage.ru_utime.tv_sec) + ((double) usage.ru_utime.tv_usec) * 1e-6;

    int fd = open(out, O_WRONLY | O_APPEND | O_CREAT, 0644);
    if (fd < 0) {
        fprintf(stderr, "Could not open %s\n", out);
    } else {
        dprintf(fd, "%s %f\n", exe, utime);
        close(fd);
    }
    free(exe);
}

Compiling this code gives a shared library:

 $ gcc -shared -fPIC -O2 trace.c -o trace.so

The result can be injected into processes via the environment variable LD_PRELOAD. By specifying a shared library, the dynamic loader will “preload” our code into each process. Eventually this calls the destructor trace_end and adds the spent user time to the file specified via TRACE_OUT. So in total, a traced execution of a command, say make, looks like this:

 $ LD_PRELOAD=trace.so TRACE_OUT=$(pwd)/trace.out make -j4 doc

Note that it sets an absolute path for TRACE_OUT. This is probably a good idea so the code does not need to rely on the current working directory.

After the command finished, you get a list of all processes and how long they took. This needs some further processing to understand the data. To get an idea, here’s some hacky Python script to sum up the time spent by executable. At the end, it prints the executables called most often and spending the most time:

import sys

exes = {}
with open(sys.argv[1]) as f:
    for l in f:
        exe, runtime = l.rsplit(' ', 1)
        old = exes.get(exe, None)
        if old is None:
            old = (0, 0.0)
        exes[exe] = (old[0] + 1, old[1] + float(runtime))

exes_by_call = sorted(exes.items(), key=lambda item: item[1][0], reverse=True)
print(exes_by_call)

exes_by_runtime = sorted(exes.items(), key=lambda item: item[1][1], reverse=True)
print(exes_by_runtime)

No, the output is not nicely formatted, but it was enough to get me the information I needed. In case you also need something like this, go use the code and adapt it if required — you are welcome!

You do not need to agree with my opinions expressed in this blog post, and I'm fine with different views on certain topics. However, if there is a technical fault please send me a message so that I can correct it!