Home	Article List

Print Debugging

Print debugging. Is it as bad as they say? I don’t think it has to be. After all, many software applications include debug information being printed to some hidden buffer that can be exposed through a dev console or log file. I would even argue that it is good practice to implement some form of print debugging and, like anything else, wielding it wisely.

dbg_printf

In my frequently-copied-from-project-to-project utils, I implement a function I call dbg_printf and a helper.

void dbg_set_log_file(FILE *fp);
void dbg_printf(const char *fmt, ...);

The dbg_printf is called like the standard library printf, except it actually calls vfprintf on an output log file. That log file by default is stderr, but can be changed with dbg_set_log_file.

#ifndef NDEBUG

static FILE *log_file = NULL;

static inline FILE *get_log_file_(void)
{
    return log_file ? log_file : stderr;
}

void dbg_set_log_file(FILE *fp)
{
    log_file = fp;
}

void dbg_printf(const char *fmt, ...)
{
    va_list args;
    va_start(args, fmt);
    vfprintf(get_log_file_(), fmt, args);
    va_end(args);
}

#else

void dbg_set_log_file(__attribute__((unused)) FILE *fp)             {}
void dbg_printf      (__attribute__((unused)) const char *fmt, ...) {}

#endif

You’ll notice that I have a static inline helper function that effectively causes the dbg_printf to print to the unbuffered stderr by default. If static variables, like our global log_file, could be assigned non-constant values, we could have just done static FILE *log_file = stderr instead. But, this option also allows the user to set the log file to NULL as an easy way to reset the output file to stderr. A helpful side effect from the workaround to an unfortunate side effect :)

Anyway, conditionally compiling our dbg_printf as either a proper, useful, populated function or an empty function allows you to print debug whenever you want. If you compile with -DNDEBUG (or define it otherwise) then the compiler will optimize away the call and any code that surrounds it.

void buggy_function()
{
    // ....
    
    for (int i = 0; i < buggy_count; i++)
    {
        // ...
        if (bug_encountered)
            dbg_printf("Bug encountered on %d iteration!\n", i);
        // ...
    }

    // ...
}

I think debug printing with this utility is absolutely fine and could help you catch silly bugs faster than using a debugger. In complex systems, like a simulation software or video game, providing a file stream that renders as text in the application window sometimes is a much preferred alternative to a debugger. But, regardless of whether it is printing to a command line or dev console, leaving these in is sloppy and everyone is prone to doing that. You could argue that some cases are unavoidable, but a good rule of thumb is to provide useful dynamic debug data at all times and log static debug information at integral stages of execution.

Dynamic Debug Information

Think things like frame rate, hardware utilization (RAM, CPU cores, etc.), and state data (user state, app state, event logs, etc.). If you find yourself debugging a complex piece of software, these sorts of info could be incredibly useful throughout the entire process, from troubleshooting, to patching, to testing.

A very simple example would be dropping this right into your main loop.

void log_dynamic_debug()
{
    dbg_printf("FPS: %d\n", calculate_fps());
    dbg_printf("RAM: %fGB/%fGB\n", calculate_ram(), get_total_ram());
    dbg_printf("Active Threads: %d\n", get_num_threads());
}

int main()
{
    // ...
    while (1)
    {
        update();
        log_dynamic_debug();
        render();
    }
    // ...
}

Static Debug Information

At integral phases of program execution (app startup, state transition, network connections, etc.), you often do a lot of setup and teardown that has a lot of precious information that you could use. Often times this is where you would see developers with such logging systems call out the initial steps of loading/processing resources, successes and non-fatal failures, or even just a message per phase that says “hey, this is what I’m doing right now”. It isn’t a bad idea to log this data so that it is always accessible in your debug builds, as preparation and cleanup are often large and convoluted steps.

void renderer_init()
{
    // ...
    for (int i = 0; i < texture_list.size; i++)
    {
        Texture *t = &texture_list.arr[i];
        
        if (t == NULL)
        {
            dbg_printf("Invalid texture at index %d in texture list.\n", i);
            continue;
        }

        dbg_printf("Loading texture '%s', size %dB\n", t->name, t->size);
        
        if (renderer_load_texture(t) == NULL)
            dbg_printf("Failed to load texture '%s'\n", t->name);
        // ...
    }
    // ...
}

One Thing You Might Want to Change

Things don’t have to be hard to change, especially something as simple as this. Maybe you want to be able to toggle debug on and off, rather than compile it conditionally. That’s an easy enough change.

static FILE *log_file = NULL;
static bool debug_mode = false;

static inline FILE *get_log_file_(void)
{
    return log_file ? log_file : stderr;
}

void dbg_toggle_debug_mode(bool mode)
{
    debug_mode = mode;
}

void dbg_set_log_file(FILE *fp)
{
    log_file = fp;
}

void dbg_printf(const char *fmt, ...)
{
    if (!debug_mode) return;
    va_list args;
    va_start(args, fmt);
    vfprintf(get_log_file_(), fmt, args);
    va_end(args);
}

I showed a screenshot of Minecraft’s debug mode. That’s an example of a toggle-able debug mode. You lose the advantage of the compiler optimizing the calls away in many cases, but the performance impact is negligible in many applications.