Saturday, August 25, 2012

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.

Sunday, August 12, 2012

JConsole and Firewalls

JConsole is a funny little beast. We had problems connecting it to our remote application from our development machines. While it tried to connect, a quick glance at the current state of active sockets on our desktop showed:


15:59:15 solo:~/trunk/hermes dev$  netstat -na | grep  10.244.144.67
tcp4       0      0  10.240.224.177.53124   10.244.144.67.11191    SYN_SENT


SYN_SENT "represents waiting for a matching connection request after having sent a connection request" [1]. In a healthy situation, this state should transition to ESTABLISHED upon receiving a SYN/ACK and subsequently sending an ACK packet (see p22 of the RFC).

However, nothing came back. This may indicate a firewall problem yet the system administrators confirmed that they had opened the port that we specified on the command line [2] with:

-Dcom.sun.management.jmxremote.port=3000

Having said that, upon SSHing into the remote box, we'd run something like:

09:43:46 solo:~/trunk/sns-conduit dev$ lsof -p `jps | grep CustomAgent | sed -e s/\ .*//g` -P | grep TCP 

java    2388 dev    5u  IPv6 0x731d19c       0t0       TCP *:51652 (LISTEN)
java    2388 dev    6u  IPv6 0x731cf38       0t0       TCP localhost:51651->localhost:51650 (TIME_WAIT)
java    2388 dev    7u  IPv6 0x731d664       0t0       TCP *:3000 (LISTEN)
java    2388 dev    8u  IPv6 0x731db2c       0t0       TCP *:51653 (LISTEN)


(where, say, CustomAgent was the name of our application and the -P flag to lsof tells it not to resolve port numbers in our environment [3]).

So, the port we defined is up and LISTENing. But not only is the port we specified in our command line LISTENing, there appear to be other ports LISTENing too.

By putting breakpoints in the constructor of ServerSocket, we could find out who was opening these ports.

1. The JMX RMIServer for Remote Connections

The first comes from the JVM bootstrap classes staring a JMX RMIServerImpl object. In turn, this tries to export itself via RMI on port 0 (that is, asking the operating system to choose an arbitrary free port for itself). By using lsof, we can see the value of this OS-assigned port - 51652 in the example I am currently playing with.

2. The RMI Registry

The second hit of the breakpoint indicates it is about to start listening on the port we defined in the command line (that is, 3000). This call is originating in Sun code, the source code of which does not come with the JDK although you can see it if you go to the OpenJDK site (or check it out with something like hg clone http://hg.openjdk.java.net/jdk7/jdk7). But it is apparent from the stack that something RMI related is being started. It turns out that it is an RMI Registry as executing this code with the port of 3000 as an argument demonstrates:




package com.henryp.rmi;

import java.rmi.Remote;
import java.rmi.RemoteException;
import java.rmi.registry.LocateRegistry;
import java.rmi.registry.Registry;
import java.util.HashSet;
import java.util.Set;

public class RmiRegistryLister {
    /**
     * @param args
     */
    public static void main(String[] args) {
        RmiRegistryLister app = new RmiRegistryLister();
        app.listRegistryOnLocalPort(Integer.parseInt(args[0]));
    }


    private void listRegistryOnLocalPort(int port) {
        try {
            Registry registry = LocateRegistry.getRegistry(port);
            String[] entries = registry.list();
            for (String entry : entries) {
                Remote value = registry.lookup(entry);
                System.out.println("Key = " + entry + ", value = " + value);
                printAllInterfaces(value);
            }
        } catch (Exception e) {
            e.printStackTrace();
        }
    }

    private void printAllInterfaces(Object obj) {
        Set alreadSeen = new HashSet();
        printAllInterfaces(obj, alreadSeen);
    }

    private void printAllInterfaces(Object obj, Set alreadSeen) {
        Class[] interfaces = obj.getClass().getInterfaces();
        for (Class anInterface : interfaces) {
            if (!alreadSeen.contains(anInterface)) {
                System.out.println(anInterface.getName());
                alreadSeen.add(anInterface);
                printAllInterfaces(anInterface, alreadSeen);
            }
        }
    }
}


The output from this looks something like:


Key = jmxrmi, value = RMIServerImpl_Stub[UnicastRef2 [liveRef: [endpoint:[192.168.0.3:51652,javax.rmi.ssl.SslRMIClientSocketFactory@8e3e60](remote),objID:[-196ac51:1391aafa8b6:-8000, -8281973287725425859]]]]
javax.management.remote.rmi.RMIServer
java.io.Serializable
java.lang.reflect.GenericDeclaration
java.lang.reflect.Type
java.lang.reflect.AnnotatedElement


So, it looks like the registry contains a stub (remote proxy) to a JMX RMIServer where calling methods on it would be routed through to port 51652 - the port that we started LISTENing to in step 1.

3. Local Connector Server

The final time we hit the ServerSocket breakpoint reveals a stack that looks a lot like the first time we hit it. Indeed, we're exporting another JMX RMIServer. This particular instance is JMX's "local connector server". Connecting jConsole to a JVM running locally uses this RMI server. You can demonstrate this by doing exactly that and then using lsof to show that both the jConsole process and the application are connected to each other on this port. We're not terribly interested in this port.


So, this explains why we can't connect through our firewall. We can see the RMI Registry in which we find the JMX RMIServer stub but on using it, the firewall blocks us.

There are ways around this, but nothing terribly simple. One good idea is here. This requires an appreciation of the JMXServiceURL class which gives us a good idea of how to read these JMX URLs. Take:

service:jmx:rmi://solo/jndi/rmi://solo/jmxrmi

No ports are defined so starting any servers will use OS-assigned, undefined ports.

Adding the RMI port so:

service:jmx:rmi://solo/jndi/rmi://solo:3000/jmxrmi

is a start but note that (i) you need to have started an RMI Registry on port 3000 with something like:

LocateRegistry.createRegistry(3000);

And note (ii) that the port from calling jmxServiceURL.getPort() is still 0! To demonstrate:


    @Test
    public void testNoJmxPortGivesPortOf0() throws Exception {
        JMXServiceURL jmxServiceURL = new JMXServiceURL("service:jmx:rmi://solo/jndi/rmi://solo:3000/jmxrmi");
        assertEquals(0, jmxServiceURL.getPort());
    }


This is because we have only defined the registry port. You can define on which port the RMIServer is actually servicing requests with, say:

service:jmx:rmi://solo:2000/jndi/rmi://solo:3000/jmxrmi

And, to demonstrate:


    @Test
    public void testWhichPort() throws Exception {
        int             jmxPort         = 2000;
        int             rmiPort         = 3000;
        String          url             = String.format("service:jmx:rmi://solo:%d/jndi/rmi://solo:%d/jmxrmi", jmxPort, rmiPort);
        JMXServiceURL   jmxServiceURL   = new JMXServiceURL(url);
        assertEquals(jmxPort, jmxServiceURL.getPort());
    }


It's the second part of the URL that is used first. It defines where we find the registry that points to the RMIServer in the first part. Again, to illustrate:


    @Test
    public void testUrlPath() throws Exception {
        String          urlPath                  = "/jndi/rmi://solo:3000/jmxrmi";
        String          fixedUrlPartPlusProtocol = "service:jmx:rmi://solo:2000";
        JMXServiceURL   jmxServiceURL            = new JMXServiceURL(fixedUrlPartPlusProtocol + urlPath);
        assertEquals(urlPath, jmxServiceURL.getURLPath());
    }


Together, you have the means to connect to a JMX Server via RMI but both have to be accessible if you want to use jConsole.

[Aside: somewhat annoyingly, it does not appear to be possible to start jConsole on the command line with a username and password as part of the jmxUrl. The JavaDocs say: "This address uses a subset of the syntax defined by RFC 2609 for IP-based protocols. It is a subset because the user@host syntax is not supported". Instead, you have to type it into the GUI when it starts.]


[1] RFC-793
[2] Monitoring and Management Using JMX
[3] the environment I was working on can be described as below:


16:53:57 solo:~/trunk/sns-conduit dev$ java -version
java version "1.6.0_33"
Java(TM) SE Runtime Environment (build 1.6.0_33-b03-424-11M3720)
Java HotSpot(TM) 64-Bit Server VM (build 20.8-b03-424, mixed mode)
17:01:51 solo:~/trunk/sns-conduit dev$ uname -a
Darwin solo 11.4.0 Darwin Kernel Version 11.4.0: Mon Apr  9 19:32:15 PDT 2012; root:xnu-1699.26.8~1/RELEASE_X86_64 x86_64