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.