Better printf(3) Debugging in C - Vancouver Computer Science Tutoring

(I’ve also written another version of this print-debugging blog post in Java.)

Typical printf(3) Debugging

In today’s blog post, we’ll look at one way to improve printf(3) and fprintf(3) debugging in C. Namely, let’s make it so our printf(3) debugging outputs include the name of the source code file, the function name, and the line number where the output happens.

Let’s start by admitting we all do printf(3) debugging, and it’s almost always ad-hoc and ugly:

void some_func(void)
{
  [...]
  printf("i = %d\n", i);
  [...]
  printf("NOW HERE\n");
  [...]
  printf("Second time, i = %d\n", i);
  [...]
  printf("NOW OTHER HERE\n");
  [...]
}

And when we use it, our programs produce a mess of unreadable debugging output:

% ./my_prog
i = 5
i = 6
i = 20
NOW HERE
i = 2
i = 2
i = 2
NOW OTHER HERE
NOW HERE
NOW OTHER HERE
i = 5

This blog post isn’t going to pontificate about using a proper debugger instead of printf(3). Debugging with printf(3) is fast and easy, and it’s not going anywhere. So, let’s just make its output more useful, so it doesn’t produce the unintelligible slop above.

Getting the Current Filename, Function Name, and Line Number

We’ll improve the debugging output of our programs using three preprocessor macros that are defined as part of the C99 standard:

__FILE__, which expands to the filename of the current source file;
__func__, which expands to the name of the current function; and,
__LINE__, which expands to the line number in the current source file.

To demonstrate how we can use these three macros, let’s pass the three of them as arguments to a printf(3) call:

#include <stdio.h>

void my_func(void)
{
  printf("%s:%s:%d\n", __FILE__, __func__, __LINE__);
}

int main(void)
{
  my_func();
  return 0;
}

Assuming this program is in a file called my_prog.c, the program’s output shows that the printf(3) call occurs on line 5 of my_prog.c, in the my_func function:

my_prog.c:my_func:5

Creating a Macro

Our ultimate goal will be to create a macro called DEBUG() that outputs a general, printf(3)-style message — but, a message that includes the filename, function name, and line number where the macro is called. As a starting point, let’s make the DEBUG() macro a replacement for our previous printf(3) call that outputs the current location in the source code:

#include <stdio.h>

#define DEBUG() \
printf("%s:%s:%d\n", __FILE__, __func__, __LINE__)

void my_func(void)
{
  DEBUG();
}

int main(void)
{
  my_func();
  return 0;
}

We added three lines to the source code file when we defined the DEBUG() macro, so the call to printf(3) is three lines lower than before. But, other than that three line difference, the output of our program is unchanged — the DEBUG() macro is called on line 8 of my_prog.c:

my_prog.c:my_func:8

Adding Variable-Argument Output

The next feature we’d like to add to our macro is the ability to output additional (arbitrary) debugging information. That is, we’d like to be able to treat the DEBUG() macro like a printf(3) call:

DEBUG("my_int = %d, my_str = %s", my_int, my_str);

To make our macro work like printf(3), we’ll make the macro accept an arbitrary number of arguments, then pass those arguments directly to a printf(3) call. To do that, we use a “...” as the parameter list of the macro. Inside the macro body, all the arguments the macro receives in place of the “...” can be expanded using the identifier __VA_ARGS__. So, let’s add a second printf(3) statement to our macro that prints all the arguments that DEBUG() receives:

#define DEBUG(...)                                     \
do {                                                   \
  printf("%s:%s:%d - ", __FILE__, __func__, __LINE__); \
  printf(__VA_ARGS__);                                 \
  printf("\n");                                        \
} while (0)

So, when we call

DEBUG("i = %d", i);

The macro expands to:

do {
  printf("%s:%s:%d - ", __FILE__, __func__, __LINE__);
  printf("i = %d", i);
  printf("\n");
} while (0)

Because there are now multiple calls to printf(3) in our macro, we’ve enclosed them in a “do/while” structure. I’ve written another blog post that discusses in detail why we need to enclose multiline macros in a “do/while“. But, for the purposes of this article: the “do/while” needs to be there, because the macro body contains more than one line of code.

Let’s place that new macro into our original program. But, this time, let’s add a message that outputs the current value of a variable, i:

#include <stdio.h>

#define DEBUG(...)                                     \
do {                                                   \
  printf("%s:%s:%d - ", __FILE__, __func__, __LINE__); \
  printf(__VA_ARGS__);                                 \
  printf("\n");                                        \
} while (0)

void my_func(void)
{
  int i = 5;
  DEBUG("i = %d", i);
}

int main(void)
{
  my_func();
  return 0;
}

The output of this program now includes our arbitrary message that contains the value of i:

my_prog.c:my_func:13 - i = 5

A Completed Utility Header

Let’s now make our DEBUG() macro, which can be used to output debugging information just like a printf(3) call, accessible to all the source code files in our program. To do that, we’ll move it into its own header file, vcsdebug.h:

#ifndef VCSDEBUG_H_
#define VCSDEBUG_H_

#include <stdio.h>

#define DEBUG(...)                                     \
do {                                                   \
  printf("%s:%s:%d - ", __FILE__, __func__, __LINE__); \
  printf(__VA_ARGS__);                                 \
  printf("\n");                                        \
} while (0)

#endif

Let’s look at the vcsdebug.h header in action. Consider the following code from, for example, a course assignment, stored in the file assignment1.c:

#include <stdio.h>

void my_func(void)
{
  int i = 5;
  printf("NOW HERE - i = %d\n", i);
}

int main(void)
{
  my_func();
  return 0;
}

Currently, this code outputs:

NOW HERE: i = 5

But, let’s change that printf(3) call to a DEBUG() call:

#include <stdio.h>
#include "vcsdebug.h"

void my_func(void)
{
  int i = 5;
  printf("NOW HERE - i = %d\n", i);
  DEBUG("i = %d", i);
}

int main(void)
{
  my_func();
  return 0;
}

Now, the output of our program is the following:

assignment1.c:my_func:6 - i = 5

Now, we know that our printf(3)-esque debugging statement was output on line 6 of assignment1.c; and, for ease of reference, line 6 is inside the my_func function. If you find the output easier to read without the function name, that portion of the output can be removed from the DEBUG() method definition.

Now, instead of littering our code with printf(3) debugging calls, we can instead litter our code with DEBUG() calls, which provide more informative output. As a bonus, DEBUG() calls are easier to find than printf(3) calls, if we want to remove debugging output from our code.

For more tips, and to arrange for personalized tutoring for yourself or your study group, check out Vancouver Computer Science Tutoring.