Sunday September 04, 2005

(See intro for a background and caveats on these coding advice blog entries.)

Rule number one: Don't Log, Debug!

One of my pet peeves in code is gratuitous logging. Gratuitous logging is where every little thing happening in your code is also sent as a log message. In other words, logging is used to record program events, rather than program errors!

The rationale for this is usually that logging is inserted to help find bugs later. "Just turn on logging and comb through the output to trace execution and discover the problem."

I don't buy the above argument, but before I go into that, let me state why I think logging is bad: It reduces code readability. You've probably heard that you shouldn't sprinkle your code with comments that are obvious (and therefore redundant). Sprinkling your code with logging calls describing what's going on is essentially the same thing, only it's even harder to mentally filter these out while reading the code, since they don't have the visual "I can ignore this" property that comments have in syntax highlighting.

There's a much better way to find bugs than by using logging: Use a debugger! I will admit that I used to rely on logging myself, since in the early days restarting the application, and even single stepping the debugger, was frustratingly slow. But with the introduction of Hotswap, and general improvement in features and speed of Java debuggers, there's no good excuse for not using a debugger to track down program bugs today.

The argument that's usually thrown out in defense of logging is that you need it to track down bugs in a deployed environment, for example at a customer's site, where you don't have physical access and cannot debug it yourself. You want to enable logging and use the log from the customer to figure out what's going on.

In my experience, that sounds good in theory but never works in practice. The logging never has all the information you need. To track down a specific bug you typically need fine grained information that you hadn't thought you needed when you wrote the code.

Let me also point out that this is a really rare scenario. Usually, if a customer reports a bug, they can tell you how to reproduce it, and once you can reproduce it locally you don't need to debug it via logs on their system - use a debugger locally.

The scenario has come up once for me. In Creator 1.0, some customers reported that after using the IDE for a while, the IDE would suddenly stop updating the source files even though components were added and properties changed. There were no direct instructions to reproduce, and it was rare - nobody internally had ever seen it. Finally a case for customer site logging! What I did was add a number of targeted logging calls; anything having to do with buffer manipulation was heavily "instrumented". I also developed a couple of hypotheses about what the problem might be, and added special code for checking these hypotheses, adding log messages if they succeeded. I then provided a custom jar to two customers who had reported seeing this problem regularly - and a few days later I had confirmation of one hypothesis.

The key point I want to make here is that even though this actually is a scenario which called for logging, it didn't have to be put in the product a priori. The logging calls were only added temporarily in one of my source trees. And furthermore, to get useful logging data I added a lot more tracking than would have been feasible to do in a product version.

So when should you use logging? To record errors and unexpected conditions - especially non-fatal ones where you don't want to get the user's attention, you simply want to know about it yourself such that you can check your assumptions and improve your program quality later.

If you're not convinced and still want to use logging, here's a tip for how to do it efficiently. There's always the option of statically compiling out all logging:

   private static final boolean LOGGING_ENABLED = false;
   ...

   if (LOGGING_ENABLED) {
       log("foo = " + bar);
   }

By using a final boolean here which is false, the compiler knows that everything, including the if block, can never be executed, so it will be completely eliminated - the class file will not contain any of the byte code; the class String table will not include the string in the log call, etc. This is zero-overhead logging, when logging is disabled. The disadvantage of this approach of course is that it cannot be enabled by the customer, so it's only useful internally. And for that of course, use a debugger!

A modification to this scheme which works well, is to use the assertion facility. This is what I used before I finally removed all non-error-related logging from my code. Create a log function like this:

    public boolean log(String message) {
        // log calls here - perhaps delegate to a logging library

        return true;
    }

Now you can use logging as follows in your code:

    assert log("foo = " + bar);

This is using assertions for a side effect: the assertion will always be true (since the logging call unconditionally returns true) so no AssertionError will be thrown. However, the logging method parameters get evaluated and the logging method called.

This solution gets the best of both worlds: When turned off it has nearly zero overhead (because the class loader will throw away the assertion statements when loading the class), but it can still be turned on in those rare scenarios where you need a customer to provide you with logging calls. (It does however increase the size of your String pools etc. so there is a small cost.)

But again,

• In practice this scenario comes up very rarely
• Even when it does your existing logging calls probably aren't sufficient anyway
• You can get the data you need by providing the customer with a special enhanced logging build
• Logging calls makes your code less readable
• Logging calls makes your source files, and class files, larger
• Without any significant pros, and a significant con, the choice should be easy!

Don't forget - logging is appropriate for logging errors! Don't start writing empty catch blocks and blaming me! For example, in an application built on top of the NetBeans RCP (see a tutorial of the new RCP support), a catch block that doesn't do anything else should at least call

   } catch (WhateverException ex) {
       ErrorManager.getDefault().notify(ex);
   }