Saturday, September 4, 2010

Log Level Inflation

There are many types of inflation.  The best known inflation, economic inflation, represents a "rise in the general level of prices of goods and services in an economy over a period of time" (Wikipedia article).  The rise in prices makes the money people have worth less (can purchase less with the same money).  Cost of living wage increases and minimum wage increases are often used to try to help people lose less of their purchasing power, but such increases also impact the very inflation whose effect they are intended to address.

Log Level Inflation works in much the same way: developers may "temporarily" (read sometimes permanently through accident or intent) increase the log level of logged messages to make them stand out more (have more value) from the crowd of logged messages.  The problem is that this can lead to messages logged at those higher levels now being reduced in value (more difficult to find) because the messages of truly less import are now artificially valued at the higher level.  This can become a cyclic effect if left unchecked, making the logs virtually useless and often resulting in having to turn logging off or turn it up to log only the highest level messages (FATAL in Log4j or SEVERE in java.util.logging for example).

Fortunately, dealing with logging issues effectively, although difficult, is not as difficult as dealing with complex economic policies.  In this blog post, I look at some of the reasons log level inflation occurs and will look at steps that can be taken to stop or slow down log level inflation.


What Causes Log Level Inflation?

There are several intentional and accidental causes of log level inflation.

Overzealous Logging
Too much logging can lead to log level inflation because developers feel the need to turn up the log level of their messages to stand out from the crowd.  This is a natural reaction to having a difficult time finding relevant logs in the middle of the verbose logs.

Neglecting 'Temporary' Logging
It is not uncommon for a developer to add logging temporarily to help diagnose and fix a particular problem.  This includes adding logging that would not otherwise be included or adjusting logging to a higher severity to make it stand out while debugging the problem.  If the developer forgets to remove this extraneous logging or to turn it back to do its typical level, the new logging remains in the code base and contributes to log level inflation.

Log Levels Not Well Understood
If the meaning or severity of log levels is not well advertised or understood, developers are more likely to place their log messages at the wrong level.  This can lead to log level inflation when developers inadvertently set messages at a higher level than they are worth.

Using Logging Less Effectively
Logging may not always be the best diagnostic tool for debugging.  When logging is used in cases where there is a better alternative, it is more likely to lead to log level inflation.


Reducing or Eliminating Log Level Inflation

Fortunately, stopping or minimizing log level inflation is not as difficult as doing the same to economic inflation. However, it still can be difficult. Here are some ways to do this.

Use the Correct Tool for the Job
In some cases, adding logging may not be the best way to diagnose the problem at hand.  Logging should be considered in conjunction with other diagnostic tools such as debuggers, monitoring tools and approaches (such as via JMX), unit tests, and code analysis.  The best tool should be used for the particular job.

Choose Clear Guidelines for Log Levels
On the surface, Log4j log levels such as TRACE, DEBUG, INFO, WARN, ERROR, and FATAL might sound self-explanatory.  However, it is useful to make sure developers understand the sometimes subtle differences between adjoining levels (such as DEBUG versus INFO).  Developers who understand the purpose of each log level may still choose to put messages at the wrong level to make them stand out, but at least they won't inadvertently do so.  With log levels such as FINE, FINER, and FINEST that come with java.util.logging, this definition of the levels is even more of a necessity.

Include Logging Frequency and Level in Code Reviews
Logging is one of those things that often is neglected in reviews because of its simplicity.  However, for long-term benefit, it is worth reviewing the choice of logging and the level of logging used during code reviews.  This can help prevent log level inflation.  In my undergraduate electrical engineering program, the department chose to prevent grade inflation from occurring by forcing instructors to give grades in any given class that had an average of a B-.  Similar policies could be used to ensure that log levels are appropriate and not inflated in importance.

Explicitly Remove Temporary Logging before Placing Under Source Control
Developers should also review their own code before checking it into the configuration management system to ensure that temporary logging has been removed.  Many developers use tactics to try to mark logging code that is intended for removal.  Such tactics include different/no indentation, inclusion of special symbols, and comments stating the temporary nature.  If such tactics were standardized, scripts and other tools could be used automatically remove these log calls from the source code before merging in into source control.

Use Tools and Scripts to Emphasize Current Logs of Interest
One way to combat log level inflation that occurs as a natural result of developers using inappropriately high levels of logging to emphasize logic related to the problem being worked on is to use tools (such as Chainsaw) and scripts to highlight those logs rather than setting them to an inappropriately high log level. A tool or script can make it easier to find relevant log statements without artificially changing their log level.

Purge and Adjust Logging Regularly
Logging seems like a simple thing, but bad things can happen when simple things get out of hand.  If excessive logging or logging at incorrect levels gets out of hand, it is worth the effort to review code and logged output to determine what can be removed or reduced in severity.

Log Effectively
One way to reduce log level inflation is to log effectively.  Effective logging reduces log level inflation through the concept of quality over quantity.  High-quality logging messages with carefully selected content placed in strategic locations with the program logic can often reduce the need for additional logging messages.  There are numerous online resources that provides ideas for more effective logging.  These include Keith Gregory's Effective Logging (on a totally unrelated note, see his recent and brief Agile Isn't New post), Eric's Effective Logging, About Effective Logging (a PDF), Effective Logging Practices Ease Enterprise Development, StackOverflow thread on Logging Best Practices and related StackOverflow thread on What Do We Log and Why Do We Log?

Conclusion

Log level inflation has many negatives effects on software development, maintenance, and bug diagnosis.  It can even have real effects on the performance of the software in extreme cases.  Therefore, it's important to take steps to prevent log level inflation and to fix any inflation that occurs.  In this post, I've quickly reviewed some of the reasons log level inflation occurs and ways to prevent it or fix it.

1 comment:

JTraining said...

Hi Dustin,

I've been reading your blog. I think you got some interesting views on Java.
That is why I was wondering something... We have just launched a new
initiative called JTraining. This is a Java community focused on learning
and sharing Java knowledges. I'm looking for people to contribute on the
community and since you are an experienced blogger, I was wondering if
you would be interested?

If you are, come and sign up for an account at http://www.jtraining.com
and a blogging account will be automatically generated for you. We have
only recently planned on promoting JTraining, so after a while the traffic will
increase a lot and that means you will be able to get some good hits too!

Also if you think it's too much work to do that, you can also just give me
permission to share your blogs on JTraining. I'll pick them out from your site.
You should definitely sign up for an account to keep in touch though!

If you have any questions or comments, feel free to e-mail me back! I would
love to hear from you.

Kind regards,

Casandra