Be careful with the parametrized log methods!

Most logging frameworks provide handy methods to pass in a formatted message together with arbitrary parameters. But as simple the call looks, you have to know that there are consequences!

logger.info("Successfully processed {}.", heavyObject); 

Most of us would automatically assume that the execution of the line above leads to a call to heavyObject.toString() inside logger.info(). But it does not!

Depending on the logging framework, but most likely, this will create an instance of an object representing the logging event. The event object holds references to the passed message arguments, here "heavyObject". If you think about the logging concepts this is quite clear. The logger forwards the events to the "appenders". The idea of the appender interface includes that there can be various types with manifold functions. To give the appenders maximum flexibility they have to get the events with all the available information. This includes the message argument object.

So, the concept of logging events holding references to the arbitrary input objects is OK and brings a lot of possibilities. However, the effect is that there is another place holding references to your objects! This means:

• It can be a garbage collection issue for your application!
• Content consistency requires immutability!

Issue 1, Garbage Collection 

I saw the garbage collection problem in a project lately. The application crashed with OutOfMemoryException at 6 GB. The reason was an asynchronous log appender sending logging events over the network. Inside it was holding a queue buffering events during network latencies. Everything worked fine as long as there were no real connections problems. But, as you can imagine, some day the network problem happened. The appender was getting high loads, the queue grew and collected thousands of entries. And some of them were really big!

JVM heap usage during network problems to remote log receiver

I know, the developers that wrote the logging statements didn't want more than just a toString() of the arguments. However, passed were objects holding the complete tree of an unmarshalled, mega bytes big XML document-- and this every couple of seconds!

Issue 2, Content Consistency

When you pass an object to the logger, you don't know when the data will actually be accessed, i.e. when the log statement is finally written. If your objects state is mutable and the reference is further processed in your applications, it is very likely that your log output is falsified! This is a real issue! It annuls the basic idea of the logging to help you to understand the state of your application.

When I discussed this with somebody that is involved in development of logging frameworks he told me that passing a mutable objects to a logger is not a good practice. I heard that advice the first time. So, please take you this to heart!

Conclusion

The bottom line is that there are advantages in the logging via message template with parameters. The major one is performance. The application thread is kept fast by passing the effort for the message formatting, including the toString(), to the (potentially) asynchronous log writer.

However, every developer should be aware that this is another handover of an object reference to something out of scope. If you prefer or depend on the object to be transient, you better do the toString() explicitly!

logger.info("Successfully processed {}.", heavyObject.toString());