Garbage Collection Rubbish

More memory leaks recently and again from various byte-code manipulators. A memory dump showed huge swathes of memory taken by classes whose names indicate that they were dynamically generated by CGLIB.

The problem manifested itself during integration test runs where we constantly start and stop Jetty servers. Since we start and stop Jetty programatically (see a previous post) and the way we used Spring seemed to dynamically generate many classes, these classes ultimately consumed all the memory because they were then be stored in static references - that is, they are stored with the classes. And these classes were not garbage collected since Spring's classloader was the same as that running the test.

"Types loaded through the bootstrap class loader will always be reachable and will never be unloaded. Only types loaded through user-defined class loaders can become unreachable and can be unloaded by the virtual machine." - Inside the Java 2 Virtual Machine, Bill Venners, p266.

If we'd deployed a WAR file presumably all generated classes would have been garbage collected when the web app was unloaded in the test's tear down method.

To demonstrate our problem, let's:

1. write our own class loader
2. use it to load a class
3. instantiate an instance of that class and let it consume lots of memory by storing objects in one of its static references.
4. allow the classloader to be garbage collected
5. see how the memory changed during all these steps

OK, so here's the class loader:



package com.henryp.classloader;

import java.io.IOException;
import java.io.InputStream;
import java.net.URL;

public class MyClassLoader extends ClassLoader {

    private final String baseDir;

    MyClassLoader(String baseDir) {
        super();
        this.baseDir = baseDir;
    }

    @Override
    protected Class findClass(String filename) throws ClassNotFoundException {
        filename                        = filename.replace(".", "/") + ".class";
        InputStream resourceAsStream    = null;

        try {
            URL     url         = new URL(baseDir + filename);
            System.out.println("URL = " + url);
            resourceAsStream    = url.openStream();
            System.out.println("Resource null? " + (resourceAsStream == null));
            byte[]  buffer      = new byte[4096];
            byte[]  bytes       = new byte[4096];
            int     read        = resourceAsStream.read(buffer);
            int     total       = 0;

            while (read != -1) { // this could be a lot more efficient but it does the job
                System.out.println("Read " + read + " bytes");
                byte[] dest = new byte[total + read];
                System.arraycopy(bytes,     0, dest, 0, total);
                System.arraycopy(buffer,    0, dest, total, read);
                bytes = dest;
                total += read;
                read = resourceAsStream.read(buffer);
            }
            return defineClass(null, bytes, 0, total);
        } catch (IOException e) {
            e.printStackTrace();
            throw new ClassNotFoundException(filename);
        } finally {
            try {
                resourceAsStream.close();
            } catch (Throwable e) {
                e.printStackTrace();
            }
        }
    }
}


Not awfully pretty but it doesn't need to be terribly efficient.

The main class that uses our class loader looks like this (notice that we measure the memory before and after our class loader is eligible for garbage collection):

package com.henryp.classloader;


public class Main {
    
    public static void main(String[] args) {
        Main app = new Main();
        app.doClassloading();
    }

    private void doClassloading() {
        MyClassLoader   classLoader = new MyClassLoader("file:/Users/phenry/Documents/workspace/TestOther/bin/");
        consumeMemory(classLoader);
        long            beforeNull  = gcThenLogMemory();
        System.out.println("Making classloader eligible for garbage collection");
        classLoader                 = null;
        long            afterNull   = gcThenLogMemory();
        System.out.println("Memory usage change: " + (afterNull - beforeNull) + " bytes liberated");
    }

    private void consumeMemory(MyClassLoader classLoader) {
        try {
            // filename from a project that depends on this but this project does not depend on that
            Class clazz = classLoader.findClass("com.henryp.classloader.OtherStaticReferenceBloater");
            consumeMemory(clazz);
        } catch (Exception e) {
            e.printStackTrace();
            System.exit(-1);
        }
    }

    private static long gcThenLogMemory() {
        System.gc();
        long freeMemory = Runtime.getRuntime().freeMemory();
        System.out.println("After garbage collection, free memory = " + freeMemory);
        return freeMemory;
    }

    private void consumeMemory(Class clazz) throws Exception {
        LargeMemoryConsumable   memoryConsumer  = instantiateMemoryConsumer(clazz);
        long                    initialMemory   = Runtime.getRuntime().freeMemory();
        doCallOnForeignObject(memoryConsumer);
        System.gc();
        long                    finalMemory     = Runtime.getRuntime().freeMemory();
        System.out.println("Initial memory = " + initialMemory);
        System.out.println("Final   memory = " + finalMemory);
        System.out.println("Total consumed = " + (initialMemory - finalMemory));
    }

    private LargeMemoryConsumable instantiateMemoryConsumer(Class clazz)
            throws InstantiationException, IllegalAccessException {
        System.out.println("Class name: " + clazz.getName());
        gcThenLogMemory();
        LargeMemoryConsumable memoryConsumer = (LargeMemoryConsumable) clazz.newInstance();
        checkDifferentClassLoader(clazz);
        return memoryConsumer;
    }

    private void doCallOnForeignObject(LargeMemoryConsumable memoryConsumer) throws Exception {
        for (int i = 0 ; i < 500000 ; i++) {
            memoryConsumer.consumeMemory();
        }
    }

    private void checkDifferentClassLoader(Class clazz) {
        if (clazz.getClassLoader() == this.getClass().getClassLoader()) {
            System.out.println("Experiment useless if the classloaders are the same");
            System.exit(-1);
        }
    }
}


And the memory consumer we refer to is a simple interface:

package com.henryp.classloader;

public interface LargeMemoryConsumable {
    public void consumeMemory() throws Exception;
}


Now, this is where it gets a little more interesting. In another project, we have an object that just takes up memory. But note that although this new project depends on the classes in our first project, the first project does not reference this new project. It does, however, use a URL that points at the directory that happens to be the directory into which the classes of the new project are compiled.

(I've added a toString method to stop the compiler optimizing away the aString member.)

package com.henryp.classloader;

public class MyOtherFatObject {

    public static Object create() {
        return new MyOtherFatObject("" + System.currentTimeMillis());
    }
    
    private final String aString;

    private MyOtherFatObject(String aString) {
        super();
        this.aString = aString;
    }

    @Override
    public String toString() {
        return "MyOtherFatObject [aString=" + aString + "]";
    }
    
}


In the same project, we have a class that emulates what we saw Spring doing, that is having a static reference to a collection of memory-consuming objects.

package com.henryp.classloader;

import java.util.ArrayList;
import java.util.Collection;

public class OtherStaticReferenceBloater implements LargeMemoryConsumable {
    
    private static final Collection

    public void consumeMemory() throws Exception {
        if (this.getClass().getClassLoader() != MyOtherFatObject.class.getClassLoader()) {
            throw new Exception("Different classloaders");
        }
        objects.add(MyOtherFatObject.create());
    }

    public void addObject(Object object) {
        objects.add(object);
    }

}



Running with these JVM args:



-verbose:gc -Xmx64m -Xmn64m

the output looks like:

URL = file:/Users/phenry/Documents/workspace/TestOther/bin/com/henryp/classloader/OtherStaticReferenceBloater.class
Resource null? false
Read 1300 bytes
Class name: com.henryp.classloader.OtherStaticReferenceBloater
After garbage collection, free memory = 63333768
URL = file:/Users/phenry/Documents/workspace/TestOther/bin/com/henryp/classloader/MyOtherFatObject.class
Resource null? false
Read 896 bytes
Initial memory = 63333768
Final   memory = 15130184
Total consumed = 48203584
After garbage collection, free memory = 15130200
Making classloader eligible for garbage collection
After garbage collection, free memory = 66266816
Memory usage change: 51136616 bytes liberated


(Notice how we explicitly load one class but it implicitly pulls in another using our class loader, the same class loader that loaded it - see the lines beginning with URL = ...).

Noting the usual caveats that System.gc() is a suggestion to the JVM and not a guarantee that the garbage collector should run, making the reference to the class loader null seems to liberate all the objects stored in the static reference of the class it loaded.

What we finally did was make all references we had in our integration tests to Spring's context loaders non-static. As our tests were garbage collected, memory was freed.

And Finally....

Gil Tene of Azul Systems was in town last month and gave a great presentation at University College, London about garbage collection. He mentioned in passing that a client to whom he was consulting had given all classes a finalize method in which all references were set to null. Obviously this is not necessary but less obviously it turned out to be pathological. The client was experiencing 18s pause times.

The reason it's pathological is that it causes more work for the garbage collector. Bill Venners in Inside the Java 2 Virtual Machine says:

"Because of finalizers, a garbage collector in the Java virtual machine must perform some extra steps each time it garbage collects. First, the garbage collector must in some way detect unreferenced objects (call this process Pass I). Then it must examine the unreferenced objects it has detected to see whether any of them declare a finalizer. If it has enough time, the collector may at this point in the garbage collection process finalize all unreferenced objects that declare finalizers.

"After executing all finalizers, the garbage collector must once again detect unreferenced objects starting with the root nodes (call this process Pass II). This step is needed because finalizers can 'resurrect' unreferenced objects and make them referenced again. Finally, the garbage collector can free all objects that were found to be unreferenced in both Passes I and II." - p369

By coincidence, that week, we also had a memory leak in one of our testing applications that pretends to be another system. Memory profiling indicated that it was taking place in Mockito code that the testing application was using to emulate the behaviour of real code. Although we saw memory interminably climbing with JConsole and took snapshots with YourKit, a simple shell script was enough to tell us what was slowly consuming memory:

i=0; while ( true ) ; do { i=`expr $i + 1` ; i=`expr $i % 2` ; other=`expr $i + 1` ; other=`expr $other % 2` ; jmap -histo:live 2584 | head -20 > /tmp/test.$i ; diff /tmp/test.$i /tmp/test.$other ;  sleep 1 ; } done

Lots of java.lang.ref.Finalizers were coming into existence and not disappearing. This is an odd little class since it not immediately obvious who was instantiating it. So, I put a breakpoint on a field initializer of this class and ran the code below:


package com.henryp.memory;

public class ObjectCreator {
    

    public static void main(String[] args) {
        ObjectWithNonTrivialFinalizer myObjectWithFinalizer = new ObjectWithNonTrivialFinalizer();
        System.out.println("That's all folks");
    }

}


Where the object being instantiated has a class that looks like:


package com.henryp.memory;

public class ObjectWithNonTrivialFinalizer {

    @Override
    protected void finalize() throws Throwable {
        System.out.println("finalize!");
    }

}


Upon the ObjectCreator instantiating the ObjectWithNonTrivialFinalizer, I hit my breakpoint and the stack looks like this:



Thread [main] (Suspended (breakpoint at line 28 in Finalizer))
Finalizer.(Object) line: 28
Finalizer.register(Object) line: 72
ObjectCreator.main(String[]) line: 7

Which is odd because my code does not explicitly call any Finalizer code. But, look at the Finalizer.register method and you'll see a telling comment:


    /* Invoked by VM */
    static void register(Object finalizee) {
        new Finalizer(finalizee);
    }


So, this appears to be some JVM magic and sure enough, the object being registered is my ObjectWithNonTrivialFinalizer. It is inserted into a double linked list and then control returns to my main method.

If we then modify ObjectCreator so that the myObjectWithFinalizer reference is explicitly set to null and run the code with an appropriate breakpoint in Finalizer, we see our object being removed from the double linked list in a mysterious JVM thread:


Daemon System Thread [Finalizer] (Suspended (breakpoint at line 46 in Finalizer))
        Finalizer.remove() line: 46 [local variables unavailable]
        Finalizer.runFinalizer() line: 78 [local variables unavailable]
        Finalizer.access$100(Finalizer) line: 14
        Finalizer$FinalizerThread.run() line: 160 [local variables unavailable]


shortly before our finalize method is run. (Actually, this thread is created in a static block in the Finalizer class).

Clearly this finalization process was not being performed in our poor testing application. In fact, YourKit told us that there was 11 megs of memory hanging off references of this type.

However, our code did not have any finalize methods. So, where were they coming from? Well, Mockito enhances classes to be mocked and adds them there. To demonstrate:


package com.henryp.mockito;

import java.lang.reflect.Field;
import java.lang.reflect.Method;

import org.mockito.Mockito;

public class MockitoInvestigator {

    public static void main(String[] args) {
        MockitoInvestigator app = new MockitoInvestigator();
        app.investigate();
    }

    private void investigate() {
        Class classToMock = MockitoInvestigator.class;
        MockitoInvestigator mock = Mockito.mock(classToMock);
        inspectAllMethods(mock.getClass());
        inspectAllFields(mock.getClass());

        Mockito.when(mock.publicMethod()).thenReturn("override");
        System.out.println(mock.publicMethod());

        inspectAllMethods(this.getClass());
    }

    public Object publicMethod() {
        return "test";
    }

    private void inspectAllFields(Class clazz) {
        inspectFields(clazz);
        if (clazz.getSuperclass() != null) {
            inspectAllFields(clazz.getSuperclass());
        }
    }

    private void inspectFields(Class classToMock) {
        Field[] fields = classToMock.getDeclaredFields();
        for (Field field : fields) {
            System.out.println("Field = " + field.getName());
        }
    }

    private void inspectAllMethods(Class mock) {
        Method[] methods = mock.getDeclaredMethods();
        inspectMethods(methods);
        if (mock.getSuperclass() != null) {
            inspectAllMethods(mock.getSuperclass());
        }
    }

    private void inspectMethods(Method[] methods) {
        for (Method method : methods) {
            System.out.println("Method = " + method.getName() + ", declaring class = " + method.getDeclaringClass());
        }
    }
}


And sure enough, you'll see output like:

Method = finalize, declaring class = class com.henryp.mockito.MockitoInvestigator$$EnhancerByMockitoWithCGLIB$$81081bc3

So, the little blighter is putting in finalize methods for us.

This normally isn't a problem in most testing. We're slightly bastardizing what Mockito was written for so we can't complain. But there is talk of a better performing version of the code.