Sunday, June 24, 2007

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:
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

1 comment:

Laurent said...

About your TestStringBuffer :

Your code is quite misleading as it is wrong.

It is true that the += operator is quite memory hungry as it creates a new StringBuffer instance since it is replaced by the VM as :

str1 += str2 is equivalent to doing the following:

str1 = new StringBuilder().append(str1).append(str2).toString();

(cf: http://stackoverflow.com/questions/693597/is-there-a-difference-between-string-concat-and-the-operator-in-java)

I ran your code and was really stunned that such code could create an overflow so fast.

After a while i saw that your code has a simple flaw :
in the case of a stringBuffer, you don't do "s += s", doubling your string size for every iteration.

In fact, you append the same String to your buffer : sb.append(s);
The String buffer increases but not your String s !

Therefore the correct code would be to initialize your buffer correctly :
StringBuffer sb = new StringBuffer();

Then to append to the same String correctly :
s = sb.append(s).toString();
or if you prefer :
sb.append(sb.toString());


This in turn creates the exact same response. On my machine, after only 21 iterations both fail.

Laurent B.