Detecting, locating and fixing referenced based heap memory leaks (Java)

doug
Sun, 06 Feb 2011 23:56:33 +0000

A common problem we all have to deal with is fixing memory leaks. In garbage collecting languages like Java we typically expect not to ever need to worry about memory management. However the limitations of how a garbage collector works means that we can still create leaks. Which defeats the advantage of a garbage collector.

How do leaks get formed?

The Java GC determines which objects to collect by looking for references to the object. If there is no references, then the object is no longer in use and can be safely destroyed without making the application unstable. If an object is now unused but still referenced, a leak occurs. Let's create a leak:

package org.neverfear.leaks;

import java.util.HashMap;
import java.util.Map;

/**
 * Run with -Xloggc:gc.log -verbose:gc -XX:-PrintGCDetails
 *
 * @author kay
 *
 */
public class HolyBucket {

    private static Map<Thread, StringBuilder> builders = new HashMap<Thread, StringBuilder>();

    public static int leak() {
        if (!builders.containsKey(Thread.currentThread())) {
            builders.put(Thread.currentThread(), new StringBuilder());
        }
        return builders.size();
    }

    public static void main(String[] args) {
        while (true) {
            (new Thread(new Runnable() {
                public void run() {
                    System.out.println("Known objects = " + leak());
                }
            })).start();
            try {
                Thread.sleep(100);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }

}

Here we see that we infinitely create threads which die very quickly which at some point call a leaky block of code. The problem here is that long after the thread is dead there still exists a reference in builders to the dead thread. Which from the collectors perspective says that we might still want to use the thread instance. What's even more is that if the thread itself refers to objects that they never get cleaned up either. This can add up to alot of memory quickly.

Detecting leaks

Watching the memory usage via Windows task manager or unix top for the Java process will give you an idea if you're leaking. Another more accurate method of finding memory leaks is to enable the garbage collector logs in the JVM. If you run your Java application with the JVM arguments -Xloggc:gc.log -verbose:gc -XX:-PrintGCDetails you will get a detailed log file called gc.log that you can use to analyse it's usage at run time. If you leave your application doing one constant thing to make the run more fair you can analyse the gc.log and usually it's obvious that memory is allocated but not released. Note that if you do different things with your application through the test run, observing a leak becomes more difficult because the heap usage will vary with the current task the process is doing. The example program above is happy just to sit and spin and it will reveal the leak in the logs.

To analyse the logs I like to use GC Viewer. This is a Java application that will parse your gc.log and give you a graph you can explore that distinguishes different actions that the GC is performing. Such as what it's invoked, when it's cleaning, your heap usage, your heap allocation and so on. Using this you will be able to see the leak. A sample graph for the above HolyBucket program:

In addition to using logging you can eye ball the output from jstat. jstat is a JDK tool that can attach to a particular JVM process ID and provide you with some statistics about the running process. A nice way to get the appropriate process IDs to attach to you can run jps.

$ jps
9212 Jps
5940 Main
18656 HolyBucket

You can get information about gc totals every second by running:

$ jstat -gc 18656 1s
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       PC     PU    YGC     YGCT    FGC    FGCT     GCT
640.0  640.0  544.0   0.0   66944.0  14733.0   136576.0   33109.8   21248.0 2456.9     80    0.337   0      0.000    0.337
640.0  640.0  544.0   0.0   66944.0  28126.9   136576.0   33109.8   21248.0 2456.9     80    0.337   0      0.000    0.337
640.0  640.0  544.0   0.0   66944.0  41520.9   136576.0   33109.8   21248.0 2456.9     80    0.337   0      0.000    0.337
640.0  640.0  544.0   0.0   66944.0  54914.8   136576.0   33109.8   21248.0 2456.9     80    0.337   0      0.000    0.337
640.0  640.0   0.0   544.0  66944.0   1339.0   136576.0   33526.6   21248.0 2456.9     81    0.342   0      0.000    0.342
640.0  640.0   0.0   544.0  66944.0  14733.0   136576.0   33526.6   21248.0 2456.9     81    0.342   0      0.000    0.342
640.0  640.0   0.0   544.0  66944.0  28126.9   136576.0   33526.6   21248.0 2456.9     81    0.342   0      0.000    0.342
640.0  640.0   0.0   544.0  66944.0  41520.9   136576.0   33526.6   21248.0 2456.9     81    0.342   0      0.000    0.342
640.0  640.0   0.0   544.0  66944.0  54914.8   136576.0   33526.6   21248.0 2456.9     81    0.342   0      0.000    0.342
640.0  640.0  576.0   0.0   66944.0   1341.0   136576.0   33943.4   21248.0 2457.0     82    0.343   0      0.000    0.343
640.0  640.0  576.0   0.0   66944.0  14732.9   136576.0   33943.4   21248.0 2457.0     82    0.343   0      0.000    0.343
640.0  640.0  576.0   0.0   66944.0  28126.8   136576.0   33943.4   21248.0 2457.0     82    0.343   0      0.000    0.343
640.0  640.0  576.0   0.0   66944.0  41520.8   136576.0   33943.4   21248.0 2457.0     82    0.343   0      0.000    0.343
640.0  640.0  576.0   0.0   66944.0  54914.7   136576.0   33943.4   21248.0 2457.0     82    0.343   0      0.000    0.343

If you look under the OU (Old generation usage) column you can see that it's increasing. If you were to let this run until exhaustion it never decreases for our leaky program. It's useful to do this if you don't want to have to restart an already running Java application to apply the gc logging parameters.

Locating the leak

Okay so we can see that memory is getting allocated but never freed, how can we find the offending code?

You can use another JDK tool called jmap that will attach to a JVM and create a memory dump of all objects on the heap which we can explore. As a first step we just want a histogram of all the classes that are loaded and how many instances have been created.

$ jmap -histo 18656
     num     #instances         #bytes  class name
----------------------------------------------
   1:         20528       80424224  [C
   2:           842       57302152  [I
   3:          9746        1091552  java.lang.Thread
   4:          4764         576816  <methodKlass>
   5:          4764         543296  <constMethodKlass>
   6:           312         344632  <constantPoolKlass>
   7:          7097         320280  <symbolKlass>
   8:          9753         312096  java.util.HashMap$Entry
   9:           284         247936  <constantPoolCacheKlass>
  10:          9822         235728  java.lang.StringBuilder
  11:           312         227512  <instanceKlassKlass>
  12:          9753         156048  java.lang.Object
  13:            25         128720  [Ljava.util.HashMap$Entry;
  14:           388          73536  [B
  15:           382          39728  java.lang.Class
  16:           513          33096  [I
  17:           976          31232  java.lang.String
  18:           458          30024  [S
  19:            73          25456  <methodDataKlass>
  20:            41          23944  <objArrayKlassKlass>

We wait until an observable increase in heap usage has been seen again, then take a second histogram dump.

$ jmap -histo 18656
     num     #instances         #bytes  class name
----------------------------------------------
   1:         21988       86827824  [C
   2:           850       25963480  [I
   3:         10523        1178576  java.lang.Thread
   4:          4764         576816  <methodKlass>
   5:          4764         543296  <constMethodKlass>
   6:           312         344632  <constantPoolKlass>
   7:         10530         336960  java.util.HashMap$Entry
   8:          7097         320280  <symbolKlass>
   9:         10552         253248  java.lang.StringBuilder
  10:           284         247936  <constantPoolCacheKlass>
  11:           312         227512  <instanceKlassKlass>
  12:         10530         168480  java.lang.Object
  13:            25         128720  [Ljava.util.HashMap$Entry;
  14:           388          73536  [B
  15:           382          39728  java.lang.Class
  16:           513          33096  [I
  17:           458          30024  [S
  18:           929          29728  java.lang.String
  19:            85          29704  <methodDataKlass>
  20:            41          23944  <objArrayKlassKlass>

Next step is to determine the delta between these two intervals. I have a little Python script called parse-gc-histogram.py I wrote to do the leg work, since in large systems the histogram will be huge.

$ python ParseHisto.py histo1.txt histo2.txt
                 Num Class
                1460 [C
                 777 java.util.HashMap$Entry
                 777 java.lang.Thread
                 777 java.lang.Object
                 730 java.lang.StringBuilder
                  12 <methodDataKlass>
                   8 [I
                   0 java.lang.Class
                   0 [I
                   0 [S
                   0 [Ljava.util.HashMap$Entry;
                   0 [B
                   0 <symbolKlass>
                   0 <objArrayKlassKlass>
                   0 <methodKlass>
                   0 <instanceKlassKlass>
                   0 <constantPoolKlass>
                   0 <constantPoolCacheKlass>
                   0 <constMethodKlass>
                 -47 java.lang.String

Isn't that interesting? HashMap.Entry, Thread and Object have gone up in equal measure. The trick now is to figure out which of these is leaking. We happen to already know that HashMap.Entry, Thread, Object and StringBuilder are all leaking. We can do a visual inspection of the code to take an educated guess. Since we've only one Map in our application it must be there. A more real situation I faced not long ago was in a program that was running with 1.5G heap space and was comprised of thousands of classes many dynamically constructed and had many threads legitimately live. There wasn't a chance I could pin down where it might be coming from by inspection. The next tool to advance my quest was jhat.

If we wanted to explore the values and references actively we can do a full heap dump. You might want to do this if the field values of instances will give you a clue as to what part of your code is using those objects.

$ jmap -dump:file=interval1.bin 18656
Dumping heap to /home/kay/interval1.bin ...
Heap dump file created

This will create a file called interval1.bin. At a later date we can use another JDK tool called jhat to open a light webserver to allow us to explore the heap dump:

$ jhat interval1.bin
Reading from interval1.bin...
Dump file created Sun Jan 09 19:05:57 GMT 2011
Snapshot read, resolving...
Resolving 49826 objects...
Chasing references, expect 9 dots.........
Eliminating duplicate references.........
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.

Having identified HashMap.Entry as the likely source of lingering references navigate to that class in the jhat web page.

The simple steps are to go to the web histogram page.

Click on the class you're interested in.

Click on an instance you believe to be leaking this can end up being a guessing game but we have to start somewhere.

The instance has a Thread key and a StringBuilder value. Clicking on what refers to that object until we find the HashMap.

At which point we can see that HolyBucket references that. So we know where in our code the leak could be coming from. Now we open up the code and look for immortal references. Some of this will be obvious if you take it as a black and white process. That is references verus non-references, this is something our code suffers from. We clearly have a reference to the Thread object in our map keys.

I'm going to skip over all the types of reference Java supports. This will play a factor in how you want to handle collection of objects and you should definitely read Strong, Soft, Weak and Phantom References (Java). Assuming you've read that, let us continue.

Our problem now is simply this. We are referring to an object that another part of the code disgards and no longer needs. What we would like to be able to do is cache the creation of a StringBuilder instance on a per thread basis but not keep the thread from dying. One approach we can take is to use weak references. There are many standard Java constructs that have a weak version of themselves. The most primitive of these is a wrapper class called WeakReference which takes a contained instance. When the only reference to the contained object is the WeakReference class, the WeakReference class let's go which allows the GC to collect them. There is also WeakHashMap which wraps the keys of Map entries with a weak reference. The key object then gets collected and the WeakHashMap removes the entry. Note that this does not apply to the values.

A fixed program might look like this

package org.neverfear.leaks;

import java.util.Map;
import java.util.WeakHashMap;

/**
 * Run with -Xloggc:gc.log -verbose:gc -XX:-PrintGCDetails
 *
 * @author kay
 *
 */
public class FixedHolyBucket {

    private static Map<Thread, StringBuilder> builders = new WeakHashMap<Thread, StringBuilder>();

    public static int leak() {
        if (!builders.containsKey(Thread.currentThread())) {
            builders.put(Thread.currentThread(), new StringBuilder(4096));
        }
        return builders.size();
    }

    public static void main(String[] args) {
        while (true) {
            (new Thread(new Runnable() {
                public void run() {
                    System.out.println("Known objects = " + leak());
                }
            })).start();
            try {
                Thread.sleep(100);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }

}

All that was changed was the implementing Map from HashMap to WeakHashMap!

Confirm the fix

Note that there might be more than one leak, use object histograms to confirm the numbers are getting cleared. In the above app you'll notice the number of entries in the map drops.

Conclusions

There's a great many forms of memory leak. I've only looked at reference leaks here. Others to think about are CPU leaks, when intense CPU consumption surpresses the GC from operating properly and eventually drains the program of memory.

Another is restruction leaks which is where objects who override their finalize() method and create additional references to themselves prevent them from ever being collected. They may not do this intentionally but as a blurring of encapsulation in some parts of code.