Anatomy of a Java Finalizer

A couple of patterns that could cause Java heap exhaustion were identified from years of research at IBM. One interesting scenario was observed when Java applications generated an excessive amount of finalizable objects whose classes had non-trivial Java finalizers.

What Is a Java Finalizer?
A Java finalizer performs finalization tasks for an object. It's the opposite of a Java constructor, which creates and initializes an instance of a Java class. A Java finalizer can be used to perform postmortem cleanup tasks on an instance of a class or to release system resources such as file descriptors or network socket connections when an object is no longer needed and those resources have to be released for other objects. You don't need any argument or any return value for a finalizer. Unfortunately the current Java language specification does not define any finalizers for a Java class or interface when a class or interface is unloaded. Let's take a closer look at finalize() method of java.lang.Object that provides an instance method, finalize() for finalization:

protected void finalize() throws Throwable

When a Java object is no longer needed, the space occupied by the object is supposed to be recycled automatically by the Java garbage collector. This is one of the significant differences in Java and is not found in most structural programming languages like C. If an instance of a class implements the finalize() method, its space cannot be recycled by the garbage collector in a timely fashion. Worst case, it may not be recycled at all.

Any instances of classes that implement the finalize() method are often called finalizable objects. They will not be immediately reclaimed by the Java garbage collector when they are no longer referenced. Instead, the Java garbage collector appends the objects to a special queue for the finalization process. Usually it's performed by a special thread called a "Reference Handler" on some Java Virtual Machines. During this finalization process, the "Finalizer" thread will execute each finalize() method of the objects. Only after successful completion of the finalize() method will an object be handed over for Java garbage collection to get its space reclaimed by "future" garbage collection. I did not say "current," which means at least two garbage collection cycles are required to reclaim the finalizable object. Sounds like it has some overhead? You got it. We need several shots to get the space recycled.

Finalizer threads are not given maximum priorities on systems. If a "Finalizer" thread cannot keep up with the rate at which higher priority threads cause finalizable objects to be queued, the finalizer queue will keep growing and cause the Java heap to fill up. Eventually the Java heap will get exhausted and a java.lang.OutOfMemoryError will be thrown.

A Java Virtual Machine will never invoke the finalize() method more than once for any object. If there's any exception thrown by the finalize() method, the finalization of the object is halted.

You are free to do virtually anything in the finalize() method of your class. When you do that, please do not expect the memory space occupied by each and every object to be reclaimed by the Java garbage collector when the object is no longer referenced or no longer needed. Why? It is not guaranteed that the finalize() method will complete the execution in timely manner. Worst case, it may not be even invoked even when there are no more references to the object. That means it's not guaranteed that any objects that have a finalize() method are garbage collected. That's a potential hazard from a memory management perspective and, needless to say, there is considerable overhead for queuing, dequeuing, running the finalize() method, and rescanning the object in the next garbage collection cycle.

If you want to run cleanup tasks on objects, consider finalizers as a last resort and implement your own cleanup method, which will be more predictable. It's very risky to rely on finalizers for postmortem cleanup tasks, especially if your finalizable objects have references to native resources.

Hands-on Experience with Java Finalizer
We can easily simulate this scenario with a couple of test applications and take a look at dumps and traces to see what's happening inside of the Java heap and threads for hands-on experience.

Let's build a couple of Java classes to recreate typical scenarios.

In ObjectWYieldFinalizer, we can implement the method finalize() with Thread.yield() so that finalize() cannot complete its execution (see Listing 1) (Listings 1-7 can be downloaded here.)

The Thread.yield() method prevents the currently executing thread from running and allows other threads to execute. If the Finalizer thread calls this finalize() method, it will pause its execution.

In ObjectWExceptionFinalizer, the finalizer() method immediately throws a java.lang.IndexOutOfBoundsException. If the Finalizer thread calls this finalize() method, the object finalization won't be completed because of the exception and there's no second chance to run the finalize() method (see Listing 2).

In ObjectWEmptyFinalizer, we don't implement any code in the finalize() method (see Listing 3). ObjectWOFinalizer doesn't have any finalize() method (see Listing 4).

Let's run each of the classes to see what happens. Sun's Java Virtual Machine (JVM) can be used with the following options for the class TestObjectWYieldFinalizer.

/sun1.6.0_10/bin/java -Xmx50m -verbosegc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+HeapDumpOnOutOfMemoryError TestObjectWYieldFinalizer > verbosegc.txt

It looks very complicated. Why do we need those command-line options? Well, without those options, we only get a little information about Java garbage collection activities like this:

[Full GC 50815K->45644K(50816K), 0.2276940 secs]
[Full GC 48780K->46415K(50816K), 0.2233279 secs]
[Full GC 49551K->49551K(50816K), 0.2396315 secs]
[Full GC 50815K->50815K(50816K), 0.1886312 secs]
[Full GC 50815K->49219K(50816K), 0.1964926 secs]
[Full GC 50815K->50815K(50816K), 0.1865343 secs]
[Full GC 50815K->50815K(50816K), 0.1836961 secs]

We only get a type of garbage collection (Full GC), total Java heap usage before garbage collection (50,815K), total Java heap usage after garbage collection (45,644K), a high watermark of total Java heap (50,816K), and time spent in the garbage collection (0.2276940 secs).

High watermark is the size of the current Java heap. The Java heap can expand its size up to a maximum size or contract to manage Java heap effectively.

The -XX:+PrintGCDetails option lets the JVM provide information on each generation in the Java heap.

We can see Java heap usage and the time (in seconds) spent in Java garbage collection of each new generation, tenured generation, and permanent generation with the -XX:+PrintGCDetails option in the following example:

[GC [DefNew: 3520K->3520K(3520K), 0.0001143 secs][Tenured: 43897K->47295K(47296K), 0.2110999 secs] 47417K->47415K(50816K), [Perm : 17K->17K(12288K)], 0.2115593 secs]
[Times: user=0.22 sys=0.00, real=0.22 secs]

In tenured generation, Java heap usage was 43,897KB before this Java garbage collection. Java heap usage reached 47,295KB after Java garbage collection; 47296K is the size of the high watermark of the tenured generation; 0.2110999 second was spent to collect the tenured generation. Unfortunately we do not see the maximum size of each generation with the -XX:+PrintGCDetails option alone.

With -XX:+PrintGCTimeStamps, we can get a timestamp for each garbage collection like this:

1.393: [GC 1002K->106K(5056K), 0.0001036 secs]

This garbage collection started 1.393 seconds after the JVM started.

The -XX:+PrintHeapAtGC option provides extensive information about each Java garbage collection (see Listing 5).

We can even see the address range of each generation. Unfortunately there's no timestamp for each garbage collection with -XX:+PrintHeapAtGC option alone.

The last option, -XX:-HeapDumpOnOutOfMemoryError allows the JVM to dump the Java heap to a file when an allocation from the Java heap cannot be satisfied or a java.lang.OutOfMemoryError is thrown. This option was introduced in Sun Java 1.4.2 update 12 and Sun Java 5.0 update 7.

If you want to experiment with IBM's Java Virtual Machine, all you need is a -verbosegc command-line option. You do not need any of these: -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC, or -XX:+HeapDumpOnOutOfMemoryError.

Let's take a look at what happened to the class while we talked about Sun JVM's command-line option. We've got java.lang.OutOfMemoryError from TestObjectWYieldFinalizer:

Exception in the thread "main" java.lang.OutOfMemoryError: Java heap space
at java.lang.ref.Finalizer.register(Finalizer.java:72)
at java.lang.Object.<init>(Object.java:20)
at ObjectWYieldFinalizer.<init>(ObjectWYieldFinalizer.java:2)
at TestObjectWYieldFinalizer.main(TestObjectWYieldFinalizer.java:11)

"java.lang.OutOfMemoryError: Java heap space." That means we got Java heap space exhaustion. The JVM could not allocate any more Java heap while running the method java.lang.ref.Finalizer.register(), which is on line 72 of Finalizer.java. Finalizer.java? Of course, we did not write Finalizer.java. That's a part of the JVM. We can also check verbosegc.txt to which we redirected the garbage collection trace (see Listing 6).

About 3.711 seconds after the JVM started, we got java.lang.OutOfMemoryError. The Java heap dump is written to pid124.hprof.

Analysis of Java Garbage Collection Traces
We can use a tool to analyze this trace. The IBM Pattern Modeling and Analysis Tool for Java Garbage Collector (PMAT) is one of top five technologies at alphaWorks. I have implemented patented algorithms to predict future failures related to Java heap exhaustion in this tool. Please refer to United States Patent No. 7,475,214 if you are interested in the algorithms. Although we don't need these algorithms to investigate simple problem like this, you might be able to find situations where you could get some insight from fortune tellers. We can get a copy of the tool here.

PMAT parses verbose garbage collection (GC) trace, analyzes Java heap usage, and recommends possible solutions based on pattern modeling of Java heap usage.

The following features are included:

The tool can also parse Sun's Java garbage collector traces, including the following:

We can start version 3.2 of the tool with a jar file in the download package. (V3.2 was the latest version when this article was written.)

# /usr/java5/bin/java -Xmx200m -jar ga32.jar

The tool provides a headless mode but let's bring up the graphical user interface mode for easy demonstration. We can click on the "N" icon to open Sun's trace file. We can click on "I" for IBM's trace file as seen in Figure 1.

We can see in Figure 2 the analysis result and recommendation virtually instantly.

The analysis tells us that the tenured generation got exhausted and the tool recommends that we increase the Java heap size with the -Xmx command-line option. If it does not help, we can use IBM's HeapAnalyzer to investigate the Java heap dump. If we click on chart icon, we can see what's happening visually in Figure 3.

By default, Java heap usage in tenured generation after garbage collection is shown in red. The X axis represents time. The Y axis represents the size of the Java heap (left) or milliseconds (right).

Each red dot represents each Java garbage collection activity. The red-dotted vertical line represents Java heap exhaustion. We can see that Java heap usage in tenured generation went up and then we had Java heap exhaustion. After that, Java heap usage in tenured generation plateaued all the way to the end of the Java Virtual Machine execution.

By clicking on the "Max Tenured" button, we can check whether tenured generation reached its maximum size at the plateau (see Figure 4).

We can see that Java heap usage in tenured generation reached maximum size. You might have already noticed that increasing the maximum size of tenured generation would only delay the java.lang.OutOfMemoryError. So we do not need to try with a larger -Xmx command-line option. Let's move on and run the IBM HeapAnalyzer to investigate the Java heap dump.

More details about IBM Pattern Modeling and Analysis Tool for Java Garbage Collector is outside of scope of this article. Further information is available in this Webcast replay: "How to analyze verbosegc trace with IBM Pattern Modeling and Analysis Tool for IBM Java Garbage Collector".

Analysis of the Java Heap
The IBM HeapAnalyzer is also one of top five technologies at alphaWorks. It's actually the most popular technology there. HeapAnalyzer commands about 10% of the downloads at the site. You can get a copy of IBM HeapAnalyzer here.

This Java heap dump is about 70MB in size. -Xmx1000m should be enough for IBM HeapAnalyzer to process it. If you get java.lang.OutOfMemoryError from IBM HeapAnalyzer, you need to add more to the JVM with the -Xmx command-line option. Here's a command-line example for a Unix system to start version 3.4 of IBM HeapAnalyzer:

# /usr/java5/bin/java -Xmx1000m -jar ha34.jar

This is an example for Windows system:

C:\java5\bin\java -Xmx1000m -jar ha34.jar

If higher than V3.4 is available, please use that version. V3.4 is the latest version as of January 2009.

Currently there's no headless mode for IBM HeapAnalyzer. The following is the first screen from the tool. We can just click on the folder icon and open the Java heap dump (see Figure 5).

After the Java heap dump is loaded, an analysis window shows up with a Java heap leak suspect as seen in Figure 6.

Java heap usage is 52,053,322 bytes or approximately 49.6MB. Considering that we set -Xmx50m in the command line, it makes sense that the Java heap got exhausted. Unlike gasoline in your car's gas tank, it's virtually impossible to use up the last drop of the Java heap for a couple of reasons. One explanation is that there are 0.4MB of free Java heap but we wanted a 0.5MB Java heap. We would get java.lang.OutOfMemoryError even though we have 0.4MB of free space. Probably 0.4MB of space may not be a single contiguous space anyway.

IBM HeapAnalyzer identifies a leak suspect, java/lang/ref/Finalizer, which is responsible for 51,879,248 bytes (99.665596 %) of Java heap.

51,879,248 (99%) [32] 5 java/lang/ref/Finalizer 0x25783a48

In the reference tree view, the suspect is highlighted in blue. Please note that we use the word, leak suspect, not leak perpetrator, since the tool can't be 100% sure whether this is a root cause of the Java heap leak. That's why we don't want a computer to make decisions under any judicial system.

So, why does IBM HeapAnalyzer think java/lang/ref/Finalizer is a leak suspect in Figure 7?

Here's a clue:

Number of objects with finalize() method                  1,298,247
Number of garbage objects implementing finalize() method  1,298,242

The number of garbage objects implementing the finalize() method is almost the same as the number of objects with a finalize() method. In most cases, the Java heap dump isn't supposed to contain any garbage because by default most of JVMs do garbage collection before generating a heap dump. But we do have garbage objects implementing finalize() method according to HeapAnalyzer's analysis. If you're skeptical about the analysis, let's investigate further to see whether the analysis is correct or not.

We can expand java/lang/ref/Finalizer to see what objects are referenced from java/lang/ref/Finalizer. After a couple of expansions from the reference tree view we realize that java/lang/ref/Finalizer objects are linked like chains.

If we click on one of the java/lang/ref/Finalizers, we can see the properties and values of the object in the window on the right.

java/lang/ref/Finalizer next      0x257838e0
Java/lang/ref/Finalizer prev     0x25783930

The properties "next" and "prev" are variables of the java/lang/ref/Finalizer. They have references to the java/lang/ref/Finalizer. Each java/lang/ref/Finalizer has a reference to a java/lang/ref/Finalizer in the variable "prev" and a reference to a java/lang/ref/Finalizer in the variable "next." We can also find a variable "referent" that has a reference to an ObjectWYieldFinalizer. Does this object look familiar? You're right. That's an instance of the class we just built and ran.

ObjectWYieldFinalizer referent      0x25783900

Almost all of java/lang/ref/Finalizers have references to ObjectWYieldFinalizers as referents. Please note too that java/lang/ref/Finalizer has a reference to a java/lang/ref/ReferenceQueue in the variable "queue." We will come back later to check the variable "queue."

java/lang/ref/ReferenceQueue queue      0x2579a048

Let's take a look at the variable "prev" of the leak suspect java/lang/ref/Finalizer at 0x25783a48. It has a reference to another java/lang/ref/Finalizer. We can click on the icon Tree View to open more reference tree views (see Figure 8).

java/lang/ref/Finalizer prev             0x25783a70
java/lang/ref/ReferenceQueue queue       0x2579a048

java/lang/ref/Finalizer at 0x25783a70 is marked with V (check icon) under the leak suspect java/lang/ref/Finalizer at 0x25783a48. This means java/lang/ref/Finalizer at 0x25783a70 is also referenced from other objects. We can find it under java/lang/ref/ReferenceQueue at 0x2579a048. There's the same chain pattern of java/lang/ref/Finalizer. Here's a something very interesting. The variable "queue" does not have a reference to java/lang/ref/ReferenceQueue. Instead it's pointing to java/lang/ref/ReferenceQueue$Null.

java/lang/ref/ReferenceQueue$Null queue     0x2579b9c8

Is that only for java/lang/ref/Finalizer at 0x25783a70? We can expand java/lang/ref/Finalizer at 0x25783a70 to see what other java/lang/ref/Finalizer objects have in the variable "queue" (see Figure 9).

It's very interesting that other java/lang/ref/Finalizer objects also have 0x2579b9c8 (java/lang/ref/ReferenceQueue$Null) in the variable "queue." Let's find out what java/lang/ref/ReferenceQueue$Null at 0x2579b9c8 is. Select java/lang/ref/ReferenceQueue$Null at 0x2579b9c8, bring up a pop-up menu and select List parents menu as seen in Figure 10.

Here's list of objects that have references to java/lang/ref/ReferenceQueue$Null at 0x2579b9c8. Let's sort them by name by clicking on the name header of the table. Click on it again to sort in reverse order. We can find the class of java/lang/ref/ReferenceQueue at the top of the table. From the detailed information pop-up menu of the class java/lang/ref/ReferenceQueue, we can see that the address 0x2579b9c8 is referenced as the variable "ENQUEUED" (see Figure 11).

java/lang/ref/ReferenceQueue$Null ENQUEUED    0x2579b9c8

Based on the variable name "ENQUEUED," we can guess that any java/lang/ref/Finalizer object with ENQUEUED in the "queue" variable is queued for finalization. Other java/lang/ref/Finalizer objects without ENQUEUED in the "queue" variable are eventually going to be enqueued for finalization. How many java/lang/ref/Finalizer objects do we have in the queue? Probably 1,251,762 according to the variable "queueLength" of java/lang/ref/ReferenceQueue, which means 46,485 java/lang/ref/Finalizer objects need to be enqueued (see Figure 12).

If a java/lang/ref/Finalizer object is enqueued, is it finalized? Not necessarily, according to our investigation. In ObjectWYieldFinalizer, we implemented the finalize() method with Thread.yield(), which means it likely never completes executing the finalize() method. So java/lang/ref/Finalizer objects will stay in the queue and cause the Java heap to leak. The java/lang/ref/Finalizer object itself might be small in size. If we have millions of them, that's not trivial. Furthermore, java/lang/ref/Finalizer doesn't hang around alone, it has a reference to the object that has the finalize() method. So we would have millions of java/lang/ref/Finalizer objects and their referenced objects, millions of objects that have finalize() methods in the Java heap growing and growing. Eventually we would see java.lang.OutOfMemoryError due to Java heap exhaustion.

We have a similar result with ObjectWExceptionFinalizer.

Let's run ObjectWEmptyFinalizer in which we did not implement any code in the finalize() method and ObjectWOFinalizer that did not have any finalize() method on Sun's JVM. Even after several hours, we don't see any java.lang.OutOfMemoryError. -XX:+HeapDumpOnOutOfMemoryError will not create any Java heap dump if there's no java.lang.OutOfMemoryError. Here's another card for that situation. -XX:+HeapDumpOnCtrlBreak will create a Java heap dump on a Control-Break key combination or SIGQUIT signal. This is a way to trigger a Java heap dump on demand. Currently not all of Sun's JVMs support these options. Please refer to the JVM documentation for detailed information.

In Figure 13 there's an analysis of a Java heap dump from ObjectWEmptyFinalizer. Of course, we have to trigger a Java heap dump with a -XX:+HeapDumpOnCtrlBreak command-line option in place since there's no java.lang.OutOfMemoryError.

Java heap usage is only 218,189 bytes. That's why we didn't get any java.lang.OutOfMemoryError. There are only nine objects that have finalize() methods in the Java heap. We had millions of them in the Java heap dump from ObjectWYieldFinalizer. There are chains of java/lang/ref/Finalizer objects but only nine of them exist. Looks like the JVM didn't have any problem completing the finalize() methods of the ObjectWEmptyFinalizer and reclaiming spaces occupied by ObjectWEmptyFinalizer and Finalizers.

Let's try the IBM Java runtime and take a look at the Java garbage collection trace and Java heap dumps. You don't need a -XX:+HeapDumpOnCtrlBreak or -XX:+HeapDumpOnOutOfMemoryError command-line option on an IBM JVM. You can create a Java heap dump on a Control-Break key combination or SIGQUIT signal without any additional command-line options. Here's a Java garbage collection trace from an IBM Java virtual machine. With a -verbosegc option alone, we can get quite a lot of information (see Listing 7).

Figure 14 shows the analysis and recommendation from the IBM Pattern Modeling and Analysis Tool. They're similar.

From chart view, the used tenured area goes up rapidly and reaches the maximum limit (see Figure 15).

The IBM Java runtime provides a Portable Heap Dump (PHD) format of the Java heap dump by default in recent versions. In earlier versions a Text (TXT) format was provided by default. Here's a Java heap dump from ObjectWYieldFinalizer on IBM Java 6. Yes, there's a java.lang.OutOfMemoryError (see Figure 16).

Java heap usage is 52,427,816 bytes, approximately 49.99MB, almost reaching the maximum Java heap size of 50MB. No wonder we got java.lang.OutOfMemoryError. Unfortunately there's no leak suspect in the Java heap dump taken from IBM Java 6. We don't see any java/lang/ref/Finalizer object chains either in the IBM Java 6 heap dump. Let's search for ObjectWYieldFinalizer objects by clicking on search icon and putting ObjectWYieldFinalizer in the search string (see Figure 17).

We have as many as 3,251,653 ObjectWYieldFinalizer objects. They are holding 52,026,464 bytes of Java heap. ObjectWYieldFinalizer objects are not referenced from java/lang/ref/Finalizer objects. They do not have any parents. We see the same pattern in IBM Java 5 runtime as well. It seems that IBM Java 5 and Java 6 implement Finalizers in native code even though I haven't looked at the source code. ObjectWYieldFinalizer object should have been garbage collected but they are still in Java heap. They are not referenced from any Java object, which means they are referenced from native code. That's why I suspect that IBM Java 6 and Java 5 implement Finalizers in native code. Is that a good move? Maybe or maybe not. The efficiency of the native code would be an upside. We have more room in the Java heap since Finalizers use less Java heap thanks to native Finalizers. In the IBM Java 6 heap dump, 3,251,653 ObjectWYieldFinalizer objects were able to fit in 50MB of Java heap whereas Sun's Java 6 could only accommodate 1,298,244 ObjectWYieldFinalizer objects in 50MB of Java heap. But IBM Java 6 and Java 5 would consume native memory to handle native Finalizers. Native memory usage is not limited by the -Xmx command-line option. A downside is that we can no longer keep track of Finalizers in the Java heap dump (see Figure 18).

Let's check out what IBM Java used to be in Java Virtual Machine version 1.4.2. Here's a Java heap dump from ObjectWYieldFinalizer on IBM Java 1.4.2 (see Figure 19).

This looks like the Java heap dump from Sun's Java runtime. We see the same pattern of chained java/lang/ref/Finalizer objects.

Number of garbage objects implementing finalize() method  1,073,276
Number of objects with finalize() method                  1,073,654
Java heap usage                                               52,527,856 bytes

By expanding Finalizer objects, we can confirm that reference structures are almost same as what we saw with Sun's Java heap dump (see Figure 20).

The java/lang/ref/Finalizer object at 0x4f12d78 has a reference to the java/lang/ref/ReferenceQueue object at 0x2872730. The java/lang/ref/Finalizer object at 0x4f12d48 has a reference to java/lang/ref/ReferenceQueue$Null at 0x2869d20, which is probably enqueued for finalization. Unfortunately the IBM Java heap dump (PHD/TXT) does not provide the names of variables or the contents of the variables. So there's no way to find out which Finalizer object is the next Finalizer object from the PHD or TXT format of the Java heap dump.

Analysis of Java Thread Dumps
We can also take a look at this problem from the Java thread's point of view. Let's get a copy of the IBM Thread and Monitor Dump Analyzer for Java from http://www.alphaworks.ibm.com/tech/jca and analyze Java thread dumps.

The Java thread dump at the top, javacore.20081111.081343.3360.txt, is taken from the IBM Java 1.4.2 runtime (see Figure 21).

Another dump at the middle, verbosegc.txt_1, is taken from the Sun Java 6 runtime. The other thread dump at the bottom, javacore.20081111.081932.2172.0003.txt, is taken from the IBM Java 6 runtime.

We can see the Finalizer thread and the Reference Handler thread. We do not see the Reference Handler thread in the IBM Java 6 thread dump though. All Finalizer threads are executing the java.lang.Thread.yield() method, which causes the current thread (Finalizer thread) to pause and allow other thread to run. Reference Handler threads enqueue Finalizer objects for finalization. All the stack traces of the Finalizer thread have runFinalizer() or similar methods. The runFinalizer() method calls the finalize() method in the ObjectWYieldFinalizer object and the finalize() method calls the java.lang.Thread.yield() method. Basically the Finalizer thread paused because of the java.lang.Thread.yield() method.

Conclusion
We ran an experiment on various finalizer implementations in various Java Virtual Machines. We used a handful of tools to investigate the problem from different perspectives. The finalize() method could be used to do cleanup tasks on any system resources before an object is discarded when the object is no longer referenced. We observed that there's risks in using the finalize() method in the current implementation of IBM and Sun Java Virtual Machines. If we want to perform cleanup tasks on objects, we might want to consider finalizers as a last resort and implement our own more predictable cleanup method.

© 2008 SYS-CON Media