I guess this is old for many developers but it is new to me. I have been asked to join an investigation of OutOfMemoryError issue occurred in a project outside my division. Actually, it was a brief involvement. My colleague who was handling the issue already got a possible root cause. He believed that it’s something about the compressing code that just had been added in the newest release. The compressing logic used java.util.zip.Deflater and the end() method of Deflater objects hadn’t been explictly closed once the compressing was done. Cleaning up mechanism relied on Java Finalizer to call finalize() method of Deflater objects

My colleague suspected that a Deflater object consumed a little space in Java heap but also allocated much bigger space of native memory. He believed it was possible that a large number of Deflater objects had been created which caused OOM in native side. Most of the Deflater objects were unreachable but GC didn’t kick in because overall heap consumption was still low. The result was that all those unreachable objects hadn’t been scheduled for Finalizer yet so all the native memory allocations were still retained

I was skeptical of his assumption at first. I thought if JVM was being under the risk of OOM then way didn’t GC try to reclaim java heap to let the object that allocated native memory be cleaned up. I decided to write a simple code to prove the scenario

public static void main(String[] args) throws IOException {
        int testSize = 1;
        if (args.length > 0) {
            testSize = Integer.parseInt(args[0]);
        }

        String content = readConent(Main.class.getResourceAsStream("data.txt"));
        byte[] input = content.getBytes("UTF-8");

        System.out.println("Test size = " + testSize);
        for (int i = 0; i < testSize; i++) {
            byte[] output = new byte[500];
            Deflater deflater = new Deflater();
            deflater.setInput(input);
            deflater.finish();
            deflater.deflate(output);
            //deflater.end();
        }
        System.out.println("Done");
        //Let it run for a while so I can monitor the java process.
        try {
            Thread.sleep(60 * 60 * 1000);
        } catch (InterruptedException ex) {
        }
    }

The program repeatedly compresses a short string (around 300 bytes). Notice that the line deflater.end() has been commented out which will defer the cleaning up process until the Finalizer thread start looking at the objects

I got OOM when I ran the program to create 6300 instances of Deflater

java -cp build\classes -verbose:gc -Xmx300m -Xms300m deflat.Main 6300

Exception in thread “main” java.lang.OutOfMemoryError
at java.util.zip.Deflater.init(Native Method)
at java.util.zip.Deflater.(Deflater.java:123)
at java.util.zip.Deflater.(Deflater.java:140)
at deflat.Main.main(Main.java:23)

I ran the program with –verbose:gc to check whether GC would try to collect objects in heap before OOM occurred or not. There was no GC activity logged to console at all. My colleague’s assumption was right; GC are not able to aware that native memory usage is about to exceed limit

I ran the program again with test size of 6200 to let it finish execution successfully then checked the current heap size

“C:\Program Files\Java\jdk1.6.0_13\bin\jstat.exe” -gc 2936

S0C          S1C        S0U    S1U   EC              EU          OC                OU 
2304.0    2304.0   0.0     0.0     19008.0   4186.7   283584.0     0.0 

Only the Eden part of heap size was occupied and the current utilization was just 4186.7 KB (EU column). The size of heap usage wasn’t large enough to trigger any GC activities it wasn’t even large enough for a minor collection in new generation. It was safe to say that the OOM generated with test size of 6300 wasn’t the result of exhausted java heap

While the java process with ID 2936 was still running, I could see in Window Task Manager that the virtual memory of the process was almost 1.9 GB. I guess the OOM from the test size of 6300 is about the memory limit of 32bit process which practically around 2 GB (the rest 2 GB is reserved for Window).

Clean it up as soon as possible

I found a very informative link described this GC behavior. One of SUN engineers has clarified that:

We’re throwing an OOM not because the java heap is (anywhere close to) full,but because the non-java (i.e., C/C++) heap is full: you can get an OOM when either heap is full. The reason for the OOM is because unreachable, but not yet finalized, java objects are holding pointers to C/C++ heap memory, and that memory is deallocated pnly when the finalizers run. The JLS doesn’t specify when finalizers get run, so if the VM delays executing them long enough, the C/C++ heap memory doesn’t get freed soon enough to prevent an OOM

An easy fix for the problem is to clean up the Deflater objects as soon as possible by calling deflater.end() method once the compression is done. The modified version of the program can run with test size of 10000 or more. The interesting thing is that with the test size of 10000, the heap utilization is around 6.4 MB which is still not enough for a minor GC collection so all 10000 Deflater objects are still there in heap but the virtual memory of the Java process is just around 331 MB. It seems like the end() method has cut the link between the a Deflater object and the space it has allocated in native memory

Note: HeapDumpOnOutOfMemoryError

I have tried using -XX:+HeapDumpOnOutOfMemoryError JVM options to get heap dump right at the point of OOM but it doesn’t work so I need to lower the test size a bit to keep the process alive and monitor the process using jstat instead. I found an explanation saying that:

Allocation of a native thread is not from the heap or the permanent generation – hence failure to allocate one does not result in a heap dump. (There would be little point in dumping the heap as that is not what was exhausted.)

The OOM caused by native memory usage will not trigger the JVM option