Debugging with printf()

© 2016 Fritz Sieker


Two common techniques for debugging are adding printf() calls to your code and using debuggers. The methods are complimentary techniques that have different strengths and weaknesses. To be a good programmer, you must be familiar with both.

Advantages of debuggers:

Advantages of printf() debugging

Using printf() for debugging is a subset of the general problem of logging. Logging frameworks provide substantial capabilites and flexability. This page provides simple mechanisms that are sufficient for many student programs.


printf() debugging

It is easy to add printf() statements to your code to print out messages. In general, if you add printf() calls, you should print as much information as possible. For example, the meaning of the output "here" quickly gets lost. The ouput "DEBUG: i=27; count=35" conveys much more.

But, inserting printf() code in your program has a major disadvantage. The only way to get rid of the output is to remove the code or comment it out. If you remove it, you have lost something that you put effort into, and which might be useful in the future. If you comment it out, you may create bugs if you comment out too much/little. And to turn it back on, you must un-comment it. Of course, C and C++ users may use conditional compilation. An ideal solution to printf() style debugging would have the following characteristics:


Implementations for Java, C, C++

The other three tabs present printf() style debugging "helpers". These were created after lots of reading on the web (particularly stackoverflow.com). The code is my attempt to provide code students may use in debugging their programming assignments. The primary goal of these implementations was simplicity, with the other goals addressed consistent with an easy/short solution that they could read and study.

All of the soutions presented here have the characteristics described above. Each prints its output to the error stream (System.err, stderr, cerr). This allows the users to take advantage of output redirection to capture the output. Alternatively, the file may be specified. Each also prefices the output with "DEBUG" to allow convenient filtering with tools like grep.

The Java solution relies on a single class Debug.java. This is the javadoc for the class. The two major methods are Debug.printf() and Debug.format(). The first is identical to the System.out.printf() method except that the print is wrapped in a condition to check whether debugging is turned on. It also calls Debug.format() before printing and automatically adds a newline after the output. The Debug.format() method is an extension of String.format() that formats all array parameters using Arrays.toString(), thus releiving the user of needing to do it to see the values.

Since this relies on a method call and the evaluation of parameters, it has a code size and performance impact. To minimize performance hits, the Debug.printf() always returns true. This means that an assert may be placed before the call and the JVM will do a fast check before doing any other work. The JVM may choose to optimize out all the calls thus eliminating the memory size and perfomance implications of its use. This is an "abuse" of the assert capability of java but works well here. For more information on java assertions see this discussion.

To use Debug with you code, simply copy the Debug.java file into your code base. For simplicity, the code is not part of a package.

This is a short test program ( Test.java) that demonstrates how to use some of the features of Debug.java.


 1 public class Test {
 2 
 3   private static void foo() {
 4     Debug.HERE();
 5   }
 6 
 7   public static void main (String[] args) {
 8     args = Debug.init(args); // set debugLevel, reset args
 9 
10     System.out.println("Hello world");
11     foo();
12 
13     Debug.printf("called with %d args %s", args.length, args);
14     Debug.printf(2, "level 2 debug output");
15 
16     //  this is only printed if asserts enabled AND debug turned on
17     assert Debug.printf("asserted args: %s", (Object) args); // demo reqd cast
18     assert Debug.printf(2, "asserted level 2 debug output");
19   }
20 }

Running the program in various ways produces the following outputs. Note that the call to Debug.init() checks for the the debug switch in the first parameter and sets DEBUG.debugLevel as appropriate. The call is not required, but the user must then set Debug.debugLevel with other code.


$: javac Test.java Debug.java

$: java Test
Hello world

$: java Test -debug foo
Hello world
DEBUG Test.java[4] foo() HERE
DEBUG Test.java[13] main() called with 1 args [foo]

$: java -ea Test -debug2 foo bar
Hello world
DEBUG Test.java[4] foo() HERE
DEBUG Test.java[13] main() called with 2 args [foo, bar]
DEBUG Test.java[14] main() level 2 debug output
DEBUG Test.java[17] main() asserted args: [foo, bar]
DEBUG Test.java[18] main() asserted level 2 debug output

Eclipse Shortcuts

To make it easy to use in Eclipse, you might create several shortcuts. Since the first line of your main() must be a call to Debug.init(), define a shortcut to creatre the call. The general sequence for creating an Eclipse shortcut is:
  1. Select Window->Preferences
  2. In the filter box in the upper left corner, type templates
  3. Scroll down to the Java/Editor/Templates and select it.
  4. Select New to create a new shortcut.
  5. In the New Template dialog, give the shortcut a name. This will be the character sequence you type to invoke the shortcut. Give it a brief description. And finally, add what you want the shortcut to generate.
  6. Press OK to complete the definition.
  7. To use the shortcut, type its name, then press [Ctrl] + [space].

The two shortcuts you might find useful is to define dbi (a shortcut to the Debug.init() call) as:


${enclosing_method_arguments} = Debug.init(${enclosing_method_arguments});${cursor}

and dbg (a shortcut to Debug.printf()) as


Debug.printf("${cursor}");

The C implementation relies on the C preprocessor. A very simple implementation for debuging is a single header file:


#ifndef __DEBUG__
#define __DEBUG__

#idfef DEBUG
#define debug(fmt, ...) fprintf(stderr, fmt, ##__VA_ARGS__)
#else
#define debug(fmt, ...) ((void)0)
#endif

#endif 

This implementation compiles the code replacing debug() by fprintf() or by an empty statement that has no effect. This is easy, and has no runtime size/performance penalties, but requires recompile to turn debugging on/off. It does not provide varying the amount of output at runtime nor does it do syntax checking when not enabled. To use it, simply include the header in your code and add the flag -DDEBUG to your compile. The code ##__VA_ARGS__ is a gcc extension.

The following implementation addresses these limitations. Note that the debug code is always compiled. This makes sure the debug code is not out of sync with the main code. Instead, of "eliminating" the code (as in the first example), it relies on the compiler optimizing out the debug code. For convenience, it adds several other handy debugging macros. It also takes advantage of the preprocssor and compiler to add usefull information to every line. The macros use the ability to concatenate adjacent literal strings and to stringify macro variables. Based on code and ideas found here and here.

The implementation consists of two files: a header file Debug.h and a small source file Debug.c. The function debugInit() initializes the module and must be called before any debug code is executed. When compiling the code a -DDEBUG must be part of the compile. Consider the following file test.c that demonstrates various featues of the implementation.


  1 #include 
  2 
  3 #include "Debug.h"
  4 
  5 void foo (void) {
  6   HERE;
  7 }
  8 
  9 int main (int argc, const char* argv[]) {
 10   debugInit(&argc, argv);
 11 
 12   printf("Hello world\n");
 13   foo();
 14 
 15   debug("Simple debug");
 16   lDebug(2, "level 2 %s=(%d)", debugV(argc));
 17   vDebug("%s", argv[0]);
 18 
 19   if (argc > 1)
 20     vDebug("%d", argc);
 21   else
 22     printf("no arguments\n");
 23 }

Running the program in various ways produces the following outputs:


$: gcc -DDEBUG -Wall test.c Debug.c

$: a.out
no arguments

$:a.out -debug
Hello world
DEBUG test.c[6] foo() HERE
DEBUG test.c[15] main() Simple debug
DEBUG test.c[17] main() argv[0]=(a.out)
no arguments

$:a.out -debug2 foo
Hello world
DEBUG test.c[6] foo() HERE
DEBUG test.c[15] main() Simple debug
DEBUG test.c[16] main() level 2 argc=(2)
DEBUG test.c[17] main() argv[0]=(a.out)
DEBUG test.c[20] main() argc=(2)

The main macro from Debug.h defines lDebug


#define lDebug(level, fmt, ...) \
  do { \
       if (DEBUG_ENABLED && (debugLevel >= level)) \
         fprintf((debugFile ? debugFile : stderr), "DEBUG %s[%d] %s() " fmt "\n", 
                  __FILE__, __LINE__, __func__, ##__VA_ARGS__); \
  } while(0)

This macro takes a variable number of parameters. The first is an integer which defines at what point the macro should actually print the message. The second is a format string which is identical to the format string of fprintf(). The remaining parameters are just the values that are printed by the format string. The fmt string MUST be a string literal. The macro expands into an expression consisting of three parts:

  1. A do/while statement in which the while() is always false. This serves two purposes. By wrapping the actual output statement in the do/while, a dangling else is not matched up with the wrong conditional test. Secondly, the while(0) can be optimized out.
  2. An if() statement that decides whether to print of not. The if() has two clauses. The first part evaluates DEBUG_ENABLED. It has a value of 0/1 depending on whether -DDEBUG was included in the compile. When it is 0, the if() can never be true and the optimizer can remove all the debug code. When it is 1, the check is optimized out leaving the comparison of the parameter and the debugLevel to control output.
  3. the fprintf() call to print the message. The actual message begins with the file name and line number (from the C preprocessor) and the function name (from the compiler). Note that the adjacent string literals are merged to produce an single format string for the call to fprintf().

The macro vDebug illustates the ability of the C preprocessor to "stringify" a parameter. This is the construct #name.


#define debugV(name) #name,(name)

#define vDebug(fmt, name) debug("%s=(" fmt ")" , debugV(name))

The C++ implementation presents a stream model of output utilizing the << operator. The implementation consists of two files: Debug.h and Debug.cpp. The method Debug::init() must be called before any of the macros are used. Like the C implementation, this relies on the C preprocessor to determine the file name, line number and function name. Consider the following file test.cpp that demonstrates various features of the implementation.


  1 #include 
  2 #include 
  3 
  4 #include "Debug.h"
  5 
  6 void foo (void) {
  7   HERE;
  8 }
  9 
 10 int main (int argc, const char* argv[]) {
 11   Debug::init(argc, argv); // optional way of initializing module
 12 
 13   std::cout << "Hello world" << std::endl;
 14   foo();
 15 
 16   debug << "Simple debug";
 17   lDebug(2) << "level 2 " << debugV(argc);
 18   vDebug(argv[0]);
 19 
 20   if (argc > 1)
 21     debug << debugV(argc) << debugV(argv[1]);
 22   else
 23     std::cout << "no arguments" << std::endl;
 24 }

Running the program in various ways produces the following output. Note that the -debug is removed from the argument list by the Debug::init() call, so that the program "sees" fewer arguments that were actually passed.


$: g++ -DDEBUG -Wall Debug.cpp test.cpp
$: a.out
Hello world
no arguments

$: a.out -debug
Hello world
DEBUG test.cpp[7] foo() HERE
DEBUG test.cpp[16] main() Simple debug
DEBUG test.cpp[18] main() argv[0]=(a.out) 
no arguments

$: a.out -debug2 foo
Hello world
DEBUG test.cpp[7] foo() HERE
DEBUG test.cpp[16] main() Simple debug
DEBUG test.cpp[17] main() level 2 argc=(2) 
DEBUG test.cpp[18] main() argv[0]=(a.out) 
DEBUG test.cpp[21] main() argc=(2) argv[1]=(foo) 

The implementation relies on expanding the debug macro lDebug() into an if/else statement that control whether the debug output is printed or not. The true portion of the statement is an empty statement that is optimized out. The else contains the actual debug statement. In the else clause, an anoymous instance of the Debug class is created. This starts the output of the debugging. The class overloads the << operator. The instance is destructed at the end of the statement. The if/else is used instead of a plain if to avoid a dangling else problem. The major macro from Debug.h is given below. All the other macros expand into a use of lDebug(). The example code shows how debug may be treated as if it were a stream.


#define lDebug(lvl) \
if ((! DEBUG_ENABLED) || ((lvl) > Debug::debugLevel)) \
  ; \
else \
  Debug(__FILE__, __LINE__, __func__)

Note that Debug::dbOS is a pointer, not an ostream. See this discussion for details on why this is a pointer.