Java In PracticeThe value of logging
- By Ethan Henry
- September 12, 2000
WELCOME TO THE first installment of "Java In Practice," a new column that focuses on various development techniques that Java developers use
in practice. These aren't just ideas that seem good on paper; they are ideas that developers have put into use, that work for them, and that in some cases have transformed the way they develop software. This leaves the column open for a variety of topics, but all with the common theme of drawing on the practical experience of real developers.
To kick things off, let's start with a topic near and dear to every developer's heart: debugging. In my experience, Java developers don't use debuggers very often. That's not to say that there are no good debuggers—there are a few, but they have taken a long time to arrive and many Java debuggers still fall short of debuggers for other languages and environments. This lack of good debuggers can't be blamed solely on vendors' lack of desire to build good products—one of the earliest good Java debuggers was part of the Supercede IDE. The product, however, wasn't an overall success: The whole company went out of business and the technology was sold off.
Is there no market for Java debuggers, then? No, I don't think it's that either. Almost every developer I talk to is looking for a decent debugger. Look at the current crop of IDEs out there. They all have debuggers and many of them are quite good. So where's the disconnect? What's preventing developers from using the good debuggers out there?
The fundamental problem is that most Java apps are ill-suited for debugging with a debugger. I recently ran across a Usenet post by Gregor Schmid of Quality First Software in which he mirrored many of the same thoughts I've been having for a while now. His post started, "I have only used a Java debugger once or twice in the last two years, but I never have to search long for any bugs."
Debuggers work really well in programming environments such as C, where the developer's primary debugging obstacle is trying to figure out what the heck is going on. In C, when your program crashes you're lost: You often don't have the first idea of what's gone wrong and where. You'll need a debugger just to help you find out what happened.
In Java, you have all sorts of mechanisms that weren't present in C—most notably exceptions, which can give you incredibly valuable information without ever having to resort to using a debugger. Then you get into issues such as multithreading and highly opaque abstract data types. The C standard library has a generally lower level of abstraction than Java's libraries. For example, take string handling. The internal mechanisms of java.lang.String are completely hidden from normal Java developers, while C strings are pretty much defined by their implementation. Java debuggers are, regardless of their quality, just not that valuable to developers (or, put another way, developers get only a small incremental improvement in productivity when using a debugger in Java vs. the huge leap in productivity when using a debugger with C).
So, how does Gregor (and many other developers) track down and identify bugs in Java code? One word: logging. Logging is defined in the dictionary (well, on dictionary.com at least) as, "A record, as of the performance of a machine or the progress of an undertaking." A log is a record of everything the program has done. While it's a less popular mechanism with client-side applications, virtually all server-side applications make extensive use of logging. But it doesn't have to be that way: Logging can be a useful tool for every Java application out there.
To show one example of how valuable logging can be, imagine a mechanism that, whenever an error or problem occurs in your program at runtime, identifies the type of error that occurred and prints not just the line where the problem happened, but also a complete stack trace. Sounds pretty useful, doesn't it? This is, of course, a description of what happens with uncaught exceptions in Java. Java's exception mechanism has become, for many developers, a sophisticated built-in logging mechanism that automatically notifies the user of any problems.
Often, however, you need more specific information or information about the program that's not directly related to an error or malfunction. Do many developers use logging in these sorts of situations, or do they instead reach for a sophisticated tool such as a debugger? Based on my very nonscientific survey (talking with other developers), yes indeed, many developers do use logging. But they don't necessarily know that that's what they're doing. Structured developers such as Gregor use a prebuilt logging class to capture all the events, sort, filter, and then output them. Other developers resort instead to the most basic, time-honored logging techniques, printf, I mean, System.out.println.
This most basic form of logging involves developers manually inserting code into their applications to display small (or large) pieces of internal state information to help understand what's going on. It's a useful technique that every developer has used at least once. The problem is that it doesn't scale. Using print statements for a small program is fine, but for a large, commercial-grade piece of software there is far too much labor involved in manually adding and removing logging statements.
C programmers know, of course, that the way to conditionally add and remove code is via the C preprocessor and the #ifdef directive. Unfortunately, Java doesn't have a preprocessor. So, how can you make logging scale to a useful level in Java without creating extra work? There are a few ways.
One way is to use the Java compiler's ability to evaluate boolean expressions at compile time, provided that all the arguments are known. For example, in this code snippet, the println statements will not only not be executed, they won't be included in the .class file generated by the compiler:
class foo {
static final boolean DEBUG=false;
public bar() {
if(DEBUG) {
System.out.println("Debugging enabled.");
}
}
}
Another way to accomplish this same goal is to add your own preprocessing stage before the Java compiler, using makefiles and some sort of text processing tool, such as Perl, m4, or even the C preprocessor.
This is useful, but it requires that you recompile the code to add or remove logging messages. Plus, it lumps all the messages together under one flag. There's no way to enable only important messages or to enable messages only for certain classes. A much better way, and the way that most logging is done in environments where the logged output is important, is to use a logging class. A logging class collects all the messages in one central place and not only records them, but can also sort and filter them so that you don't have to see every message being generated. One example of a logging class is the one Gregor has written. A logging class provides more information than just the message. It can automatically add information such as the time the event occurred, the thread that generated the message, and a stack trace of where the message was generated. Additionally, it can filter out unwanted messages at runtime based on various criteria, reducing or eliminating any runtime performance penalty.
Some logging classes will write their output directly to the screen or a file. More advanced logging systems may instead open a socket to allow the log messages to be sent to a separate process, which is in turn responsible for passing those messages to the user or storing them. The advantage with this system is that it allows for messages from multiple sources to be aggregated in a single location and it allows for monitoring remote systems—both of which can be huge advantages, especially with server-based applications.
The key element to using logging as a debugging and problem-solving technique is to make sure that lots and lots of events are being logged. This is why it's key to have a logging mechanism that can deal with a large volume of messages without imposing a performance penalty. On the other side of the equation, the onus is on the developer to ensure that he/she is logging events wherever appropriate, so that when a problem does occur it's not necessary to go back to the source code and insert debugging statements. In many cases, problems need to be diagnosed in the field where there may not be source code access. The value of a logging-based debugging strategy is directly proportional to the amount of proactive effort the developer has put into generating events and useful messages.
While there's currently no support in the core Java libraries for logging, this has been recognized as a deficiency. Java Specification Request 47 (JSR-47) is for a logging API specification that would be part of the Java 2 Standard Edition core. While no timeline has been specified yet, this API specification plans to give developers the ability to:
- Enable or disable logging at runtime (for performance or aesthetic reasons)
- Control logging at a fairly fine granularity, so that logging can be enabled or disabled for specific functionality
- Allow registration of logging services at runtime, so third parties can add new log services
- Bridge services that connect the Java logging APIs to existing logging services (e.g., operating system logs)
- Display high-priority messages to end-users (like the current uncaught exception mechanism does)
Overall, logging maintains a pretty low profile in the typical developer's toolbox. Inserting
println statements into code is not seen as a sophisticated technique, but the basic idea is fundamentally sound: You need to get inside the "black box" of the application to determine why things aren't working correctly. Logging, when implemented properly and proactively, is one of the most powerful and sophisticated techniques available to track down bugs.