Contents: Examining the Trace class Using Trace Configuring Trace Performance considerations Versioning Wrap up Resources About the author Rate this article Related content: Techniques for adding trace statements to your Java application Debugging integrated Java and C/C++ code IBM developer kits for Java (downloads) Subscriptions: dW newsletters dW Subscription (CDs and downloads)

Scott Clee (mailto:Scott_Clee@uk.ibm.com?cc=&subject=Use a consistent trace system for easier debugging)
CICS Tester, IBM
4 November 2003

When faced with a thorny bug, many developers use System.out.println statements to send status messages to the console so that they can more easily pin down the moment at which their program goes awry. But those statements slow down program execution and can be difficult to clean up once the code is ready for production; more to the point, they are more of a stop-gap measure than a truly consistent debugging system. In this article, Scott Clee introduces a tracing utility class that improves upon this debugging method. He explains how the class works and how you can configure it for your particular needs, and offers examples to show how you can integrate it into your own projects.

We've all been there: just as your program is nearing completion, you run it once more to bask in its glory and ... it's broken. You can't remember what you added to break it, and have no idea what's gone wrong. Like many developers, you decide to bring out the trusty old System.out.println command to help you get in there and fix it. By inserting these tracing statements into your code, you can see the progress of your program execution at the console and figure out where it all goes wrong. You add a few trace statements, then a few more, and a few more. And once you've cracked the problem, you have to remove all those extraneous trace statements, because they'll only get in the way in a production environment. "That wasn't so bad after all," you think once you're done. But then you find another bug, and the trace statements that helped you last time are, of course, gone -- if only you'd kept them! Well, there's no reason you can't leave debugging code in your applications to help you troubleshoot throughout the development process.

The assertion functionality built into version 1.4 of the Java language shows us how it can be done. On its Web site, Sun claims that assertions have zero performance impact if the language's assertion facility is switched off:

To ensure that assertions are not a performance liability in deployed applications, assertions can be enabled or disabled when the program is started, and are disabled by default. Disabling assertions eliminates their performance penalty entirely.

(See Resources for more on assertions and other useful information.)

What this means is that assertion statements in compiled code are somehow not actually executed, and hence incur no performance penalty. Now, if Sun could take the same approach with a built-in Java trace system, the world would be a much better place. But until then, we have to do it ourselves.

What we need is a single Java class that will contain all the tracing functionality we could ever want. We should be able to reuse this class in all of our Java projects. This will give us confidence that our code can be debugged easily with a consistent look and feel.

Luckily for you, I'll discuss just such a class in this article.

Examining the Trace class
The class we'll introduce here is called Trace; it exists in a package called T. We've placed this class in a package so that it can be called from any Java class that may also exist in a package; there is a Java language restriction that prevents classes in packages from calling classes that exist in the default package (that is, in no package). We've called the package for this class T solely to save on typing when using it. You'll find it helpful to download the class and examine it as we discuss it in this section; the code is fully commented.

On initialization of the class, a static initialize() method is called that reads in any trace configuration parameters passed to the JVM and stores them in static variables. This only happens once, during the static initialization of the class, and hence causes a minimal performance hit. See the section below entitled "Is it configurable?" for more details on this.

To minimize the footprint of the class, a lot of functionality is reused. Essentially, there are three variations of the out() method for stdout, and three variations of the very similar err() method for stderr. All of these methods invoke a method called outputMessage(), where all the hard work is done. The outputMessage() method is defined with the Java modifier synchronized to aid safe usage in a multi-threaded system. First, let's look at the methods we'll be calling directly:

The out() method

1. public static void out(String txt)
2. public static void out(String txt, int level)
3. public static void out(String txt, int level, boolean forceTime)

The err() method

1. public static void err(String txt)
2. public static void err(String txt, int level)
3. public static void err(String txt, int level, boolean forceTime)

For each of the methods above, there is also an equivalent outln() or errln() method, which simply appends a new line character \n to the end of txt. This means that our class follows a convention similar to the System.out.print() and System.out.println() methods.

Working backwards, let's first take a look at methods numbered 3 in the lists above. The parameters are shown in Table 1.

Table 1. Parameters for methods numbered 3

String txt	The trace message to output
int level	The importance of the trace statement, with one 1 being the least important and Integer.MAX_VALUE being the most important
boolean forceTime	If true, forces a time stamp to be output even if one is not expected (more on this shortly)

Redirecting trace If your tracing statements are sending a lot of data to the console, here's a little tip that will make that data easier to read. You can pipe stdout and stderr from a Java program (or indeed from any program) executed on the command line to files by using the following syntax: java MyProg 1>stdout.txt 2>stderr.txt This technique is helpful for capturing any output from a program. Want to pipe the output to a file but still see that output as it's sent to the console? Under Linux and UNIX, you can view the output file created in this way using the tail -f <filename> command, which will show the data from a file as it grows dynamically. So, to view the stdout.txt file we created above as it grows, you would use the command: tail -f stdout.txt Unfortunately, there is no default command similar to tail for Windows.

A method numbered 2 in the lists above calls the corresponding method numbered 3 with a default forceTime value of false. Similarly, a method numbered 1 calls a method numbered 2 with a default trace message level of 5 (meaning that the message is not very important, but isn't the least important either -- remember, the value 1 has the least importance).

The reason for having 1 as the least important trace value and Integer.MAX_VALUE as the most important is to make the importance value unbounded, in theory. It's easy to add newer and more important trace statements without having to do too much forward planning. Think of it this way: if the importance levels worked the other way round (with 1 being the most important), then you might add many statements with trace level 1, but at some later point decide to add further statements that were even more important than the previous batch. In such a case, you would have to find all the existing trace statements and reduce their trace level in order to make room for these new trace statements. That would be a lot of unnecessary work, and the current design for our class avoids it.

Now, let's go back to the outputMessage() method. This is where all the trace formatting functionality is contained; it's also the method that you will be most likely to modify should you have any personal features to add to this class. Note that a time stamp is output for each trace call unless implicitly suppressed (we'll discuss this in more detail further on). If a statement happens to cover multiple lines, then margins are set at the length of the time stamp for each subsequent line. This makes the output text easier on the eyes.

The outputMessage() method takes the string, and, if it will fit on the current line, simply outputs it. If that's not possible, then the string is separated into chunks and each is output to a new line. The size of a chunk depends on the width of the output and on any new line characters embedded in the trace message. We'll see examples of this in the next section.

Using Trace
All methods in the class are static, which means that we can call them directly on the class without having to create an instance of it first. In other words, you can use this call:

T.Trace.out("a message\n");

rather than this one:

T.Trace traceObject = new T.Trace();
traceObject.out("a message\n");

Note also that, if you'd like, you could include the statement import T.* at the top of your class and then only call Trace.out("a message\n"); throughout your code. This is a design decision left up to you.

Listing 1 shows some examples of the Trace class in use:

public double deposit(double amount, int accountNum)
{
    double     oldBalance, newBalance;
    Context    context    = null;
    Properties env        = new Properties();        
    
    env.put(javax.naming.Context.PROVIDER_URL, 
            "iiop://jndiserver.ibm.com:900" );
    env.put(javax.naming.Context.INITIAL_CONTEXT_FACTORY, 
            "com.sun.jndi.cosnaming.CNCtxFactory" );

    try 
    {
        // ***** Example 1 - start *****
        T.Trace.outln("Getting initial context", 5);
        context = new InitialContext(env);

        T.Trace.outln("Looking up Account bean", 5);
        Object ref = context.lookup("Account");

        T.Trace.outln("Narrowing Object", 5);
        AccountHome home = (AccountHome) 
          PortableRemoteObject.narrow(ref, AccountHome.class);

        T.Trace.outln("Creating Account object", 5);
        Account accountBean = home.create();
        // ***** Example 1 - end *****
        
        // ***** Example 2 - start *****
        T.Trace.out("Getting old balance", 5);
        oldBalance = accountBean.getBalance(accountNum);
        T.Trace.outln(" - done", 5);
        // ***** Example 2 - end *****

        T.Trace.outln("Depositing money into account", 5);
        accountBean.deposit(amount, accountNum);

        T.Trace.outln("Getting new balance", 5);
        newBalance = accountBean.getBalance(accountNum);

        // ***** Example 3 - start *****
        T.Trace.outln("This is a really long line of trace that " + 
                      "serves no purpose to the code in this  "  +
                      "example but does show trace text split " +
                      "over multiple lines", 5);
        // ***** Example 3 - end *****

        // ***** Example 4 - start *****
        T.Trace.outln("Account details:\n" +
                      "account number = " + accountNum + "\n" +
                      "deposit amount = " + amount     + "\n" +
                      "old balance    = " + oldBalance + "\n" +
                      "new balance    = " + newBalance, 6);
        // ***** Example 4 - end *****
    }
    catch (NamingException e1) { 
      T.Trace.errln("NamingException: " + e1); }
    catch (Exception       e2) {
       T.Trace.errln("Exception: "       + e2); }

    return newBalance;
}

You might think that I've gone over the top with the trace statements here, but this does give you a feel for how they would work in production code. The tracing statements essentially give you updates on everything that's happening in the class as it executes.

So, what does our tracer class output? Nothing -- well, nothing until an appropriate trace level is set. By default, the trace level is 0, which means that nothing is traced. The trace level is set with a -D switch to the JVM, as follows:

java -DTRACE_OUT=5 -DTRACE_ERROR=5 MyClass

If TRACE_OUT is set to 5, then any Trace.out statements of importance 5 or greater will be output to the console. You can set a level for TRACE_ERROR in the same way.

With the trace level set appropriately, Example 1 in Listing 1 should send the contents of Listing 2 to stdout. (In general, stdout will be the command line window where the program is running).

(17:46:28) Getting initial context
(17:46:29) Looking up Account bean
(17:46:30) Narrowing Object
(17:46:31) Creating Account object

Obviously, the data in the parentheses is the time stamp, and the data after it is the trace message. A time stamp will be output for every line of trace unless the trace message does not end in a new line character, in which case a time stamp will not be output on the next call to the method. The class is written this way to allow the sort of logic we wrote for Example 2 in Listing 1. First, (17:46:32) Getting old balance will be output; once the action has completed, it will append - done to the end of the statement, giving the output shown in Listing 3.

(17:46:32) Getting old balance - done

Another feature of this class that helps make the trace information more readable is line wrapping. A particularly long line, like the one in Example 3, will wrap automatically, as shown in Listing 4:

(17:46:33) This is a really long line of trace that ser
           ves no purpose to the code in this example b
           ut does show trace text split over multiple
           lines

Finally, new line characters embedded in trace statements, like the ones in Example 4, can be used to format the output, as illustrated in Listing 5:

(17:46:34) Account details:
           account number = 12345
           deposit amount = 25.0
           old balance    = 150.0
           new balance    = 175.0

Note that the trace level for Example 4 in Listing 1 is set to 6. If we used the command-line option -DTRACE_OUT=6, then only the trace statement in Listing 5 would be output, as the others all have their trace level set to 5.

Configuring Trace
You've already seen that we can configure our class by passing in -D-style command-line JVM options. Table 2 outlines the main options available and explains their use.

Table 2. Command-line JVM options for T.Trace

TRACE_OUT	Sets the debug level for all Trace.out() calls
TRACE_ERROR	Sets the debug level for all Trace.err() calls
TRACE_WIDTH	Sets the trace output's width, in characters, which is very useful for customizing the output for various window terminals

Performance considerations
The truth is that T.Trace statements in your code do affect performance, even if TRACE_OUT and TRACE_ERROR are set to 0. Every time a trace call is made, a conditional statement is executed. If the trace level is set to 0 (the default value), then no further processing is done, and no trace is output. Nevertheless, the JVM still executes each extra conditional statement, and in the end those statements add up. One way to get around this when deploying code to a production system is to simply comment out all the trace statements by globally searching for T.Trace and replacing each instance with ;//T.Trace. The semicolon in the replace string will take care of any trace statements that may be in a loop or conditional statement. This line:

if (X == true) T.Trace.outln("X is true!");

becomes:

if (X == true) ;//T.Trace.outln("X is true!");

This code will not execute the trace call; more importantly, it will not affect any code thereafter.

Versioning
If at any point you alter your tracing class or add some cool new functionality to it, the best way to keep track of your changes is with versioning. This can be essential if you come back to a project and can't remember what version of your trace class you're working with. The tracing class in this article is version 1.0, so if at some point you make a change or add some new functionality, then you'll probably want to increment the version to 1.1 -- 2.0 if it's a complete rewrite.

The version number is always printed at the start of a run if tracing is turned on, so you always know what you're working with. You can suppress this by setting the following -D JVM option:

-DTRACE_VERSION=HIDE

Wrap up
Well, that brings our tour of this handy class to a close. Put this class in all your Java projects and you'll have a consistent, dynamic trace system -- one that is far better than simply scattering System.out.println statements all over your code. I have more ideas on filtering trace output using class, package, and even method names, but that's for another day. I'll save the exploration for you -- and please feel free to e-mail me with your ideas. Enjoy, good luck, and good debugging.

Resources

• Download the source code for the Java trace class described in this article. Don't forget: for compilation, put it into a directory called T, as it's in the Java package T.
  
  
• See Andrei Malacinski's article, "Techniques for adding trace statements to your Java application" (developerWorks, January 2001) for more information on Java tracing.
  
  
• For more information on assertions, see Sun's official Java Assertions page.
  
  
• Check out "Debugging integrated Java and C/C++ code" by Matthew B. White (developerWorks, November 2001) for advice on debugging JNI code.
  
  
• Eric Allen's archived Diagnosing Java code series at developerWorks offers a systematic approach to debugging.
  
  
• Debug code line by line with the Eclipse tooling platform.
  
  
• You'll find hundreds of articles about every aspect of Java programming in the developerWorks Java technology zone.
  
  

About the author Scott Clee currently works as a tester for IBM's CICS product. He's been a Java programmer for five years and has more recently focused on Java testing in CICS, including testing the new Java ORB. He'd like to say hello to Becky, Dave P., Barry S., Kay J., Colin B., Kathy T., Sharon S., Dan W., Ian D., Adam C., and everyone else on his team. Contact Scott at Scott_Clee@uk.ibm.com.

What do you think of this document? Killer! (5) Good stuff (4) So-so; not bad (3) Needs work (2) Lame! (1) Comments?

developerWorks > Java technology