Troubleshooting JVM, Part I

Part of my job is to provide support for the famous issue tracker JIRA. Sometimes, we will have to look into client's stack traces and thread dumps to troubleshoot some memory or locking issues which usually caused by third-party plug-ins, Lucene, etc.

One of the excellent articles I came across is "Of Thread dumps and stack traces" written by Rajiv Shivane. There are also some people who have given me some good pointers, like, Jed (one of my co-workers, the memory guy) who pointed me to "JDK 1.5 - Trouble-shooting and Diagnostic Guide" and Rob who lent me the book "Inside the Java 2 Virtual Machine". Some other good reads that you shouldn't miss are:

• "An Introduction to Java Stack Traces" by Calvin Austin
• "Troubleshooting Guide for Java SE 6 with HotSpot VM" by Sun Microsystems

Anyway, I spent some time in the weekend to play around with java, jmap and jhat.

Note: jhat 1.1 doesn't recognize 64-bit dump, simply download JDK 1.6 and use the jhat 2.0 which shipped together with it.

I will go through an java.lang.OutOfMemoryError: Java heap space test I have done and give as detailed information as I can. I have demonstrated this to some people earlier on at work using one of the classic examples: String vs. StringBuffer.

public class TestStringBuffer{

public static void main(String[] args)
throws Exception{

StringBuffer sb = new StringBuffer();
String s = "foobar";
String which = args[1];

for(int i = 0; i < Integer.parseInt(args[0]); i++){
if(which.equals("sb"))
sb.append(s);
else
s += s;

System.out.println(System.currentTimeMillis() + ": " + i);
Thread.currentThread().sleep(500);
}
}
}

Using the StringBuffer way, the program remains alright even after 10K of iterations. However, it dies immediately with String concatenation around 23th iteration. Before we look deeper into this, here are two interesting JVM startup parameters that you would like to know:

• -XX:+HeapDumpOnOutOfMemoryError, requests HotSpot to generate a binary dump when it runs out of memory.
• -Xmx1024m, allocates 1GB of heap space

The jmap utility can be used to produce snapshot of the currently running JVM process. The jhat utility does something similar however in a post-mortem manner.

For instance, running jmap on the StringBuffer case:

yclian@kate:~/devels/test/java$ $JAVA_HOME/bin/jmap -histo 29237
Attaching to process ID 29237, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 1.5.0_09-b03
Iterating over heap. This may take a while...
Unknown oop at 0x00002b7df8296da0
Oop's klass is null
Object Histogram:

Size    Count   Class description
-------------------------------------------------------
500112  4121    * ConstMethodKlass
433192  4121    * MethodKlass
303824  283     * ConstantPoolKlass
269816  6117    * SymbolKlass
214688  265     * ConstantPoolCacheKlass
183776  283     * InstanceKlassKlass
108768  1044    char[]
83368   455     byte[]
61248   348     java.lang.Class
52096   462     java.lang.Object[]
31400   785     java.lang.String
29168   413     short[]
19584   295     int[]
18720   36      * ObjArrayKlassKlass
15048   213     java.lang.Object[]
7616    136     java.nio.HeapCharBuffer
4592    82      java.nio.HeapByteBuffer
4160    8       * TypeArrayKlassKlass
2784    58      java.util.Hashtable$Entry
2248    31      java.lang.String[]
2128    14      java.util.HashMap$Entry[]
2080    65      java.lang.StringBuilder
2064    10      java.util.Hashtable$Entry[]
2000    10      * KlassKlass
1792    14      java.lang.reflect.Field
1320    11      java.lang.reflect.Constructor
1056    22      java.util.Locale
1040    2       * ArrayKlassKlass
936     9       java.net.URL
864     6       java.lang.Thread
768     12      java.util.HashMap
736     23      java.io.File
696     21      java.lang.Class[]
672     12      java.io.ObjectStreamField
672     21      java.lang.StringBuffer
...
Heap traversal took 2.054 seconds.

And for the String case:

yclian@kate:~/devels/test/java$ $JAVA_HOME/bin/jmap -histo 29336
Attaching to process ID 29336, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 1.5.0_09-b03
Iterating over heap. This may take a while...
Object Histogram:

Size    Count   Class description
-------------------------------------------------------
906039672       578     char[]
501216  4132    * ConstMethodKlass
434336  4132    * MethodKlass
304728  284     * ConstantPoolKlass
270328  6127    * SymbolKlass
214688  265     * ConstantPoolCacheKlass
184336  284     * InstanceKlassKlass
71072   351     byte[]
61424   349     java.lang.Class
51216   446     java.lang.Object[]
28960   411     short[]
22520   563     java.lang.String
19088   291     int[]
18720   36      * ObjArrayKlassKlass
13784   202     java.lang.Object[]
4160    8       * TypeArrayKlassKlass
2736    57      java.util.Hashtable$Entry
2128    14      java.util.HashMap$Entry[]
2000    10      * KlassKlass
1936    27      java.lang.String[]
1536    12      java.lang.reflect.Field
1344    7       java.util.Hashtable$Entry[]
1320    11      java.lang.reflect.Constructor
1056    22      java.util.Locale
1040    2       * ArrayKlassKlass
864     6       java.lang.Thread
768     12      java.util.HashMap
728     7       java.net.URL
672     12      java.io.ObjectStreamField
640     10      java.util.LinkedHashMap$Entry
448     8       java.lang.ref.SoftReference
448     7       java.lang.ref.Finalizer
432     9       java.util.HashMap$Entry
384     6       java.util.Hashtable
360     9       java.util.Vector
352     10      java.lang.Class[]
288     3       java.util.jar.JarFile
272     17      java.lang.Object
264     7       java.io.ObjectStreamField[]
256     8       java.io.ExpiringCache$Entry
240     3       sun.nio.cs.UTF_8$Encoder
240     3       java.nio.DirectByteBuffer
216     3       sun.misc.Cleaner
208     2       sun.nio.cs.StreamEncoder$CharsetSE
200     5       java.util.ArrayList
192     3       sun.misc.URLClassPath$JarLoader
176     2       java.io.ExpiringCache$1
160     4       sun.reflect.NativeConstructorAccessorImpl
152     4       java.lang.reflect.Constructor[]
152     1       java.lang.ThreadLocal$ThreadLocalMap$Entry[]
152     1       java.lang.reflect.Method
144     3       java.lang.OutOfMemoryError
...
Heap traversal took 1.323 seconds.

char[], 108768 vs. 906039672. Clear example why String concatenation should be discouraged ;-). The histogram is very useful in identifying memory leakage as it shows you the size and number of instances created for a specific object type. jhat also allows you to generate some other information such as heap summary and permgen statistics, run it with the -h parameter for more information.

Let's examine the binary heap dump produced by the OutOfMemoryError using jhat.

java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid29613.hprof ...
Heap dump file created [403190555 bytes in 31.321 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space

jhat is one of the best tools comes together with JVM. It starts a HTTP server and provides you a simple interface which enables you to inspect the heap dump with your favorite browser.


Since we were talking about histogram, we will look into histogram again using the jhat interface.

Class	Instance Count	Total Size
class [C	564	402716036
class [B	350	67135
class java.lang.Class	336	48384
class [S	411	25126
class [I	291	16760
class [Ljava.lang.Object;	202	12168
class java.lang.String	552	11040
class [Ljava.util.HashMap$Entry;	14	2016
class [Ljava.lang.String;	27	1720
class java.util.Hashtable$Entry	57	1596
class [Ljava.util.Hashtable$Entry;	7	1288
class java.lang.reflect.Constructor	8	776
class java.lang.Thread	6	744
class java.util.Locale	22	704
class java.net.URL	7	616
class java.util.HashMap	12	576
class java.io.ObjectStreamField	12	444
class java.util.LinkedHashMap$Entry	10	440
class java.lang.ref.Finalizer	7	336
class java.lang.ref.SoftReference	8	320
class java.util.Hashtable	6	288
class java.util.HashMap$Entry	9	252
class java.util.jar.JarFile	3	222
class [Ljava.io.ObjectStreamField;	7	208
class java.util.Vector	9	180
class java.nio.DirectByteBuffer	3	168
class sun.misc.Cleaner	3	168
class [Ljava.lang.Class;	7	152

So, it actually produces something similar with what we have seen earlier. Except the slightly different use of notation, e.g. class [C, class [B, etc. Just if you are unsure:

• class [C is char[]
• class [B is byte[]
• class [Z is boolean[]
  
• class [S is short[]
• class [I is int[]
• class [J is long[]
• class [D is double[]
  
• class [Lpackage.ClassName is package.ClassName[]
• class [[Lpackage.ClassName is package.ClassName[][]

And therefore, don't be panicked when you see ([[ID[Ljava/lang/String)Z in the stack trace next time. It is simply just boolean foo(int[][], double, String[]).

Clicking into one of the hyper-links (of course, it works just on my machine), for instance, class [C will bring me to a page as captured in the screenshot below:


The page gives you more details of the class, such as: loader, subclasses, static/instance data members, instances, references, etc.

I will end this blog entry at this point and I would expect you to spend some time to do some research on it too :-). When I start writing again for Part II, I will be sharing some thread dump tips that I have collected.

- yc, dumped