Better println() Debugging in Java

Typical println() Debugging

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

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

public void someMethod()
{
    [...]
    System.out.println("i = " + i);
    [...]
    System.out.println("NOW HERE");
    [...]
    System.out.println("Second time, i = " + i);
    [...]
    System.out.println("NOW OTHER HERE");
    [...]
}

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

% java MyProgram
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 println(). Debugging with println() 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, Method Name, and Line Number

We’ll improve the debugging output of our programs using the Thread class. Using a reference to the currently running thread, we can generate a stack trace, like the kind we see when an uncaught Exception crashes our program. But, we’ll do it without actually crashing our program:

StackTraceElement[] ste =
    Thread.currentThread().getStackTrace();

The elements in the ste array contain the currently running methods, in order, along with their source filenames, method names, and line numbers.

Consider the following example:

public class MyProg
{
    public static void main(String[] args)
    {
        methodA();
    }

    private static void methodA()
    {
        methodB();
    }

    private static void methodB()
    {
        StackTraceElement[] ste =
            Thread.currentThread().getStackTrace();
    }
}

After the call to getStackTrace():

• ste[3] refers to the main(String[]) method;
• ste[2] refers to methodA();
• ste[1] refers to methodB(); and,
• ste[0] refers to the getStackTrace() method itself, which generated the ste array.

If we wanted to know where we were — where in methodB(), that is — when we called getStackTrace(), we can use some of the methods provided by the StackTraceElement class on ste[1]. Specifically, let’s use the getFileName(), getMethodName(), and getLineNumber() methods, to get that information:

private static void methodB()
{
    StackTraceElement[] ste =
        Thread.currentThread().getStackTrace();
    System.out.println(ste[1].getFileName() +
        ":" + ste[1].getMethodName() +
        ":" + ste[1].getLineNumber());
}

We make the calls to getFileName(), getMethodName(), and getLineNumber() on ste[1] instead of ste[0], because ste[0] refers to the getStackTrace() method itself; ste[1] refers to methodB(). So, the output printed by this method is the filename method name, and line number — inside methodB() — where getStackTrace() was called:

MyProg.java:methodB:15

A Completed Utility Class

Let’s take this design one step further. Let’s write a debugging method that outputs two things: a debugging message, and information about where the debugging method was called from:

public class VCSDebugger
{
    public static void debug(String msg)
    {
        StackTraceElement[] ste =
            Thread.currentThread().getStackTrace();
        System.out.println(ste[2].getFileName() +
            ":" + ste[2].getMethodName() +
            ":" + ste[2].getLineNumber() +
            ": " + msg);
    }
}

Here, we use ste[2] instead of ste[1], because we want to know where the debug(String) method was called from:

• ste[0] refers to the Thread.getStackTrace() method;
• ste[1] refers to the VCSDebugger.debug(String) method; and,
• ste[2] refers to wherever VCSDebugger.debug(String) was called from.

Let’s look at the VCSDebugger class in action. Consider the following code from, for example, a course assignment:

public class Assignment1
{
    public static void main(String[] args)
    {
        methodA();
    }

    private static void methodA()
    {
        methodB();
    }

    private static void methodB()
    {
        int i = 5;
        System.out.println("NOW HERE: i = " + i);
    }
}

Currently, this code outputs:

NOW HERE: i = 5

But, let’s change that System.out.println() call to a VCSDebugger.debug() call:

private static void methodB()
{
    int i = 5;
    System.out.println("NOW HERE: i = " + i);
    VCSDebugger.debug("i = " + i);
}

Now, the output of our program is the following:

Assignment1.java:methodB:16: i = 5

Now, we know that our println()-esque debugging statement was output on line 16 of Assignment1.java; and, for ease of reference, line 16 is inside the methodB method. If you find the output easier to read without the method name, that portion of the output can be removed from the VCSDebugger.debug() method.

Now, instead of littering our code with System.out.println() debugging calls, we can instead litter our code with VCSDebugger.debug() calls, which provide more informative output. As a bonus, VCSDebugger.debug() calls are easier to find and delete than System.out.println() calls, once we’re ready 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.