Mind the Debug Message

Consider the following scenario:

MyObject obj = new MyObject();
log.debug("Created an object: " + obj);

This code seems innocent enough. If our logging is set to debug level we will print the message, and if not we won’t print it. Right?

Wrong!

This piece of code is actually quite harmful, especially because it looks so innocent, and may actually cause a major performance problem in your application. For instance, what happens if MyObject’s implementation of toString() is really heavy? This can happen, for instance, if MyObject is a very complex type, it’s string representation is heavy and in order to built it we have to iterate over many objects. In this case, that line of code will do this heavy processing every time it is run, and you will have to pay the performance overhead no matter what your log level is.

This is why it is much better to make sure your logging infrastructure allows you to do something like this:

// Print out one object
MyObject obj = new MyObject();
log.debug("Created an object: {0}", obj);

// Print out several objects
log.debug("Created some objects: {0}, {1}, {2}", new Object[obj0, obj1, obj2]);

and then formats the message with MyObject’s toString representation only if the debug level is high enough. This way you will pay the performance price only when you choose to do so.

Advertisements

3 thoughts on “Mind the Debug Message”

  1. Actually, I don’t think this is such a good idea and for two main reasons:
    1. String parsing is problematic – there are very good reasons why the more advanced programing languages got rid of it. for example:

    log.debug("Created some objects: {0}, {1}, {2}", new Object[obj0, obj1]);

    Here I tried to remove one object from the debug printout but forgot to change the string accordingly, which could be a problem (that will be detected only if the debug is enabled). And there are many more such examples…
    2. The interface is not flexible enough. I may need to change the interface of the debug message quite often (like when I add a new class to the system and need to print it’s content in the debug). For example, I would have expected the second example to be some thing like:

    log.debug("Created some objects: {0}, {1}, {2}", obj0, obj1, obj2);

    Which saves me the need define another object – but clearly shows (at least to me) the flexibility issue (polymorphism out of control).

    I see two way to address this problem, the first one is to do something like this:

    log.debug("Created an object: " + (log.isDebugEnabled()?obj:""));

    Not very elegant, but it will work. The problems: its quite a lot of work writing this very time (programing languages with preprocessor support can make this option more attractive, but I assume we are talking about Java), and there is a good chance that the programmer will forget to do it. Lets see if we can do better.

    What would happen if I write something like this:

    log.debug("Created an object: ").debug(obj);

    Will this work? Yes and no. If the debug message message knows how to get a parameter of the type of “obj” – we’re golden, otherwise, we are still in the same shit as before since “obj” will have to be evaluated to string outside of the debug method.
    OK, we are almost there, just a little longer. We now face a choice: either add support to (almost) every class in the system in our debug methods (lets’ not and say we did), add support for a few master classes that everyone inherit from (could actually be a good option, depending on the system architecture) or be creative. Let’s try creative – it’s more fun (besides, you’ve read so far anyway).

    template
    class DebugMessage
    {
    private:
    T data;
    public:
    DebugMessage(T data_){data=data_;}
    String toString(){ return data.toString()’}
    }

    log.debug(DabugMessage(obj));

    So there are some missing details in the example above, but as this is getting to long by far as it is, filling in the blanks and the analysis (and why I think this is a good solution) – will be left to the reader… ;-)

    P.S.
    Nice blog, by the way.

    1. Hi Noam,
      great comments!
      You are right, of course, I was only thinking about performance and not about maintainability or ease of use.
      I liked your 4th example the most, although (assuming we talk Java), I didn’t understand your last point. Every class in Java implements a toString() method by default, and you *will* have to implement some version of it by yourself if you want your object’s string representation to actually mean anything, so you can just rely on it and let polymorphism do your work for you.
      Since you used templates in this example, I assume you referred to C++. In this case I will have to shamefully admit that I had long ago forgotten most of my C++, and that from what I remember it seems about right (but I can’t say anything interesting about this example anyway, so why believe me?)
      :)

      1. I have to admit, I am a poor Java programmer and in my last example (as you have guessed), I “thought” in C++ pseducode. I’ll try to rewrite it in Java to make the point clearer:

        public abstract class BasicDebugMessage
        {
        public abstract String toString() {
        return "Error! Method should be overwritten!";
        }
        }

        public class DebugMessage extends BasicDebugMessage
        {
        private:
        T data;
        public:
        DebugMessage(T data_){data=data_;}
        String toString(){return data;}
        }

        Now it we were VERY strict, then the debug method will only except objects of type BasicDebugMessage (or types which extends it, of course). Which will make the code look like this:

        log.debug(DebugMessage("Created a new object: ")).debug(DebugMessage(obj));

        This is as safe as it gets (I think), generic as hell (which I think the examples clearly illustrates), but it is annoying that we have to cast the string itself – then again, if we didn’t force that, we were risking someone using it as a workaround to the performance saving mechanism.
        So I see reasons why it should be and shouldn’t be implemented this way and the final decision should be taken considering the wider system architecture considerations.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s