This post is based on an email one of the Principal Engineers at my company sent to the R&D mailing list a few months ago. The scenario he described in the email is so obvious, and yet I can honestly say — that when I looked back at commits I did — I found that I did it myself from time to time. I liked it so much that I had so share it. Two things to note It talks about in but you will see that the concept is easily imported to other languages. logging Java We wrapped log4j with a LogWrapper object we wrote, that among other things checks to see what is the current log level in the system before it continues to log the messages it got. So, when you see — it is of type LogWrapper, and when you see it’s the wrapped logger. logger.debug m_logger This is an example of some code that logs messages the way: wrong List<Stuff> veryLongList = … … // explicit invoke object's toString()logger.debug(“my long list is “ + veryLongList.toString()); logger.debug(“my extra long list is %s”, veryLongList.toString()); // implicit invoke object's toString()logger.debug(“my long list is “ + veryLongList); All three of these versions are inefficient and and should be avoided. error prone The reason is the call to it forces the creation of a possibly expensive String object that is then passed to the LogWrapper.debug() method. toString(). To understand the problem with this, look at how the method is implemented: debug public void debug(Object message) {if (ThreadedLogLevelManager. (m_logger)) {m_logger.log( , Level. , message, null);}} isDebugEnabled s_className DEBUG public void debug(Object message, Object arg) {if (ThreadedLogLevelManager. (m_logger)) {m_logger.log( , Level. , message, arg);}} isDebugEnabled s_className DEBUG ... public void debug(Object message, Object... args) {if (ThreadedLogLevelManager. (m_logger)) {m_logger.log( , Level. , message, args);}} isDebugEnabled s_className DEBUG You can see that we first check and see the debug mode is enabled for this piece of code and only then goes to call the m_logger that does the logging. Usually the m_logger won’t even be called since debug logging is generally disabled in production. The m_logger itself then goes and turn the message into a string.You can see below that the way it converts it into string is also an important check that we as developers sometime forget to do: protected final String convertToString(Object message) {return message == null ? (String)message : message.toString();} This protects you from getting a NullPointerException. The Right Way The way to do such logs is simply: logger.debug(“my long list is %s”, veryLongList); This has 3 benefits: LogWrapper will call toString() only when logging is enabled. If the object in question is null, it will be logged as the “null” string rather than raising an exception. The code is cleaner. This may sound obvious but that are about 100 such cases in the code. On a personal note, be minded in what you log. don’t log just for the sake of logging. No better then Winston Churchill to sum it up most accurately: “This report, by its very length, defends itself against the risk of being read.” P.S. my good friend , while giving me notes on the post mentioned that: elad shmidov Python has something similar about this in it’s logging under the optimization section best practice P.S. 2 Another good friend/Editor/critic , shared how they are doing it in Ruby: Guy Cepelevich // define the log methoddef loglogger.debug yield if Environment.type == DEVELOPMENTend // use itlog {"this is what i want to log: " + String(element_list)} The content of the curly brackets will be evaluated only when Environment.type == DEVELOPMENT
