printf Debugging with Minimal Overhead

printf-debugging has always worked well for me. And it's not because I don't use a debugger, but often, a well-placed printf tells me exactly what is going on.

In libvfn, I've added an infrastructure that allows me to spread printfs all over the code with very low overhead (and for production builds, zero).

It is inspired in part from QEMU and the Kernel, but like a lot of the other stuff I have copied from there, it's dumbed down quite a bit. It works like this.

I define a set of debug events that I can toggle statically and dynamically.

#define DEBUG_EVENT_FOO "foo"
#define DEBUG_EVENT_FOO_DISABLED 0

bool debug_event_foo_active;

struct debug_event {
        const char *name;
        bool *active;
};

struct debug_event debug_events[] = {
        {"foo", &debug_event_foo_active},
};

#define DEBUG_NUM_EVENTS 1

The above is an obvious candidate for code generation, so naturally I use a perl script for that.

When disabled statically the code has zero overhead, and dynamically the overhead is that of a single conditional.

Using it looks like this:

__debug(FOO) {
     __emit("value of v is %d\n", v);
}

__debug is a funky macro that basically expands to a conditional with a statement expression. The statement expression is such that I can set a global thread-local variable with the name of the debug event.

#define __debug(name) \
     if (({ \
             bool cond = ((!DEBUG_ ## name ## _DISABLED) && debug_ ## name ## _active); \
             if (cond) \
                     __debug_event = DEBUG_ ## name; \
             cond; \
     }))

Since all DEBUG_name_DISABLED are compile-time constants, compilers will use it to either emit no code for the debug event (if statically disabled) or just the check on the _active static variable.

The great thing about having __debug expand to a condition is that we also open a scope where we can easily do more computationally heavy stuff for debugging purposes:

__debug(FOO) {
     int v = compute_something(x);

     __emit("computed v to %d\n", v);
}

Within __emit we use the __debug_event to get some nice prints:

#define __emit(fmt, ...) \
        fprintf(stderr, "D %s " fmt, __debug_event, ##__VA_ARGS__)

This should be safe across threads, so as I mentioned, __debug_event is thread-local:

static __thread const char *__debug_event;

I've also wired this up with a __attribute__((constructor)) initializer so I can toggle non-statically disabled events with an environment variable.