Christian's team was writing a time-management application in Java and utilizing a third party library. The application needed to be up and running 24/7.

A few days after a recent release, a customer called in a problem report complaining that the JVM heap was growing in size over time until it crashed with an out-of-memory error.

Upon stressing the application with a mouse macro, Christian verified the problem. After pouring over the application code searching for a memory leak and not finding one, he performed the test again, taking a jmap heap dump at the start, and after a significant period of time. When he compared the dumps, he found that there were 19,000+ instances of one particular class that were consuming more than 40M of heap space, and it was all string data.

When he crawled through the heap dump, he found that the string data was actually a series of gargantuan strings, each consisting of the following pattern:

  "*** <SomeObject> SOME-VALUE*** <SomeObject> SOME-VALUE*** <SomeObject> SOME-VALUE..."

The longer the app ran, the more repetitions of the substring showed up in the large strings. Christian noted that SOME-VALUE was passed to one of the third party library calls. After putting in a test string, repeating the test and verifying his theory, he opened a ticket with the vendor.

After receiving the usual helpful fix instructions of installing the latest update of the latest version of Java (he was already there), and a long wait, the vendor finally provided a patch.

When Christian repeated the test on the patch-code, he got the same problem as before. Frustrated by the vendor, he decompiled the patched class for the method he was calling, and progressively walked the call stack, decompiling at each step, until he found this:

public void someThirdPartyMethod(SomeObject object) { 
  manager.log("*** "+this.getClass().getName()+" "+object.getValue()); 
  // ...
}

But that looked suspiciously like the repeated string pattern in the giant strings in the heap dump. So he spelunked further down the rabbit hole and found this:

public class ManagerClass { 
  private String      debugCache = ""; 
  private boolean     debugSet   = false; 
  private DebugLevels debug      = DebugLevels.DEBUG_NONE; 

  public void setDebugLevel(DebugLevels level) { 
    debug    = level;
    debugSet = true; 
  } 

  public void log(String message) { 
    if (!debugSet || debug == DebugLevels.ERROR || ...) {
       debug(message); 
    }
  }

  public void debug(String message) { 
    if (debugSet && !debugCache.equals("")) { 
       System.out.println(debugCache); 
       debugCache = ""; 
       System.out.println(message); 
    } else if(debugSet) {
      System.out.println(message); 
    } else { 
      debugCache = debugCache + message; 
    } 
  } 
}

Basically, the debug-level variable seemed to be for internal-use only and was never called in Christian's code, or any of the library methods his code was calling. Ultimately, the log method was called from everywhere. Since the flag was always false, every debug got appended to the debug-cache string until the heap was exhausted.

Christian added a call in his own code to set the debug level, which solved his problem, but kept the vendor-ticket open, wondering how long it would take them to figure out the actual problem.

[Advertisement] BuildMaster allows you to create a self-service release management platform that allows different teams to manage their applications. Explore how!