A Note on Logging

Added by Roger Dunn about 9 years ago

A Note on Logging

The instantiations of loggers has caused consternation for developers for years, it's a wonder we use them at all.

Here's how the problem unfolds:
(1) Someone uses a Logger in an early version of their Foo class
(2) Sometime later, someone makes Foo serializable
(3) A runtime exception informs someone discovers that the Logger is not serializable
(4) So they make the Logger transient
(5) Foo then works fine for developer testing, internal QA, even simulated prod environment.
(6) Then, sometime way down the road, in a complex prod environment, null pointer exceptions (NPEs) suddenly begin appearing.
(7) Doh!!!

The root cause is often an edge case, one that was not considered by the developer who did step #4 above, and one that was not caught by then testing done in step #5. It takes two things: (a) an instance of Foo has to be serialized, and (b) the deserialized instance, for which the Logger will be null, has to hit code that actually invokes methods on that logger. And that delivers an NPE. And how frustrating is that, to have an NPE caused by something as innocuous as a logging call!

And the sad thing is that the above scenario has played out countless times, all because developers fail to think about they need to do with transient ivars.

It's even worse, because a lot of teams will remove most logging calls from the code before it goes to production, as a performance optimization. This means that the remaining logging calls tend to be for unusual conditions, which often don't occur until apps are in prod, sometimes for a long time.

Even worse than that, some of the more complex enterprise systems may cause a serialization event that was not foreseen by the original authors. Sure, everyone knows about objectouputstreams, RMI, and so on. And with xweld we're aware of how object graphs serialized around the grid. But there is also code that looks for the Serializable marker interface and will use serialization to operate on graphs of objects that the original developer never even thought might happen. When developers make something serializable, they darn well better mean it!

So we're caught between two choices: use the transient keyword, or make the logger static.

Transient has only one advantage: the Logger isn't instantiated until needed. It has three big disadvantages: (a) the problem outlined above, (b) the increased memory footprint of referring to the Logger with each instance of Foo, and (c) the execution time cost of calling the logging factory every time a Foo is instantiated.

Static has just one disadvantage: it incurs the once-per-class cost of instantiating the Logger when the class is first loaded. Note that this cost is probably not as high as one might think, because most Logger implementations use a single shared logger behind the scenes.

Weighing these alternatives, the choice for xweld is clear: Logger instances are declared as static. This practice avoids potential NPEs, unwarranted memory footprint, and wasted execution cycles.