How Logging Killed a Java Web Server

by Patson Luk on March 5, 2014

Java-logging-api

Logging is an essential component in any application as it gives useful insight into code execution. When tracking down bugs, robust logging aids developers by providing additional information without deploying debugging tools. However, in a recent memory problem we investigated, a seemingly harmless logging statement almost killed the whole web application!

The Problem

We received a report of unexpectedly high RAM usage in a web application. Web requests were taking 10-20 times longer to complete than usual. Since we did not have access to the memory dump at first, we could only scan through code for usual suspects such as static references, collections and ThreadLocals. However, we could not find anything that could explain the memory problem as described. Fortunately, we were given the JVM memory dump shortly after. At the first glance, char arrays were taking a huge chunk of the memory. Most of them had no GC roots, which means they were eligible for garbage collection. This actually supported the behavior reported – slow system and high RAM usage, but no out of memory exception. As these char arrays piled up in the heap, the JVM was probably running a frequent, costly GC to clean up all the big temporary char array instances. Now the question was – what exactly were those array instances? Since we didn’t have any more information from the application itself, we dumped sections of the memory itself. The objects themselves seemed to resemble configuration files: XML nodes with class names and system passwords. Oops. Each of those lines started with the same header, so by text searching the codebase, we eventually drilled down to this line of code:

logger.debug("Found HttpServlet Object [" + servlet + "]");

If you look more closely at the statement, it’s quite obvious that the “servlet” object is the culprit! The string operation above implicitly called the toString() method on the servlet object (which is an instance of a custom class that extends javax.servlet.http.HttpServlet). In this case, the toString() method was overridden and returned a full state dump of the entire servlet: an unbelievably long String.

Lessons learned

Be super careful when calling toString() method (whether implicitly or explicitly)

The expectation of all toString() methods should return something reasonable is unfortunately nothing more than wishful thinking. In a perfect world, each toString() would return a simple representation; but in reality, complex subclass and 3rd party library usage mean that developers have no control over the full output. In our case, concatenating everything about the servlet turned out to be a huge amount of work, eating enormous amounts of memory and causing inordinate GC slowdown. Printing an object as quick debug might be acceptable (IDEs do that too in debug view), but having the same call in a production environment could be harmful. Therefore, we need to defend ourselves with extra caution. In this particular case, what we want is the type of servlet, not every detail about the servlet’s running state. To get this information, we can either pick primitive values or Object with class types that are well known and final. In the above case, we can simply change the debug statement into:

logger.debug("Found HttpServlet Object [" + servlet.getClass().getName() + "] );

(The identity of the instance can be retrieved via hashcode() or System.identityHashCode(Object)) Also, watch out for String concatenation, as toString() method gets called implicitly on the object operands!

Code around Logger carefully

One of the reasons this call escaped our notice early on is because it’s a debug call. In this case we were using Log4J logger and the low logging level DEBUG, which, when used properly, won’t do any work unless we’ve configuring the application to log debug statements. Ideally, this means the Object received will not be further converted and printed to the output. Unfortunately, by building the the string before passing it to the logger (in this case toString() and String concatenation), the line can still drain memory quickly without actually outputting anything. Consider the example given earlier:

logger.debug("Found HttpServlet Object [" + servlet + "]");

The servlet object’s toString() method and the string concatenation will both be executed even if the logger is configured to not output any message with “debug” level. One possible fix: we can enclose log preparation and reporting logic with a block such as:

if (logger.isDebugEnabled()) {
    //log reporting logic...
}

Avoid String concatenation in Logger

Logging frameworks such as log4j2 and slf4j supports Substituting Parameters. This provide an even better alternative of avoiding extra isDebugEnabled() check and unnecessary String concatenation:

logger.debug("Printing big object [{}]", bigObject);

The bigObject’s toString() method would not be invoked unless the logger is configured to process “debug” level messages.

Summary
Article Name
How Logging Killed a Java Web Server
Author
Description
Logging is an essential component in any Java web application as it aids developers. Recently, a logging statement almost killed the whole web application!
TwitterFacebookLinkedInRedditEmail

Ready to go beyond logging?

Get deep Java application visibility in less than 5 minutes. Deploy TraceView Now