In my previous post, I discussed how jmap can be used to view the contents of the Java heap. Jmap is a wonderful utility for viewing heap utilization at a specific point in time, but it’s not the best utiltiy for answer questions like “which call stack is allocating objects of type foo?", or “how many objects are being allocated per second?", or “what is the average size of allocated objects?". To answer these types of questions, we need to look to a more thorough instrumentation framework.
One such framework is the DTrace hotspot provider which was introduced in Java 6, and provides a number of probes to dynamically instrument Java applications. These probes allow you to observe thread behavior, garbage collection, method calls, class loader activity, monitor contention and object allocation. The probe to observe object allocation is rightfully named “object-alloc,” and contains several arguments (since the probe arguments are documented extremely well in the Java community, I won’t describe them here) that can be used to understand how the heap is being used.
To use the object-alloc probe, you will need to start the JVM with the “-XX:+DTraceAllocProbes” option, or run the jinfo utility to enable it at runtime (enabling it at runtime is preferred):
$ jinfo -XX:+DTraceAllocProbespgrep java``
Once the object-alloc probe is enabled, you can begin prodding your application to see what it’s doing. If you are seeing lots of garbage collection events in jconsole, jstat or your garbage collection logs, the object allocation probe can be used to display object allocations by object type, the number of objects being allocated, and the size of these allocations. The newobjects.d DTrace script provides the necessary probe definitions to display this information:
$ newobjects.d
Class Objects created Bytes Allocated
[I 112 16064
Wasteful 17943 287088
java/lang/StringBuilder 17943 287088
java/lang/String 17943 430632
[C 107658 52393560
Class Objects created Bytes Allocated
[I 121 18520
Wasteful 19541 312656
java/lang/StringBuilder 19541 312656
java/lang/String 19542 469008
[C 117252 57062640
If you see tons of object allocations, you can use the DTrace quantize() action to create a histogram with object counts or object sizes. The objectsize.d DTrace script shows how to create a distribution that is keyed on object size:
$ objectsize.d
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@ 95897
32 |@@@@ 31965
64 | 1
128 |@@@@ 32157
256 |@@@@ 31965
512 |@@@@@@@@@ 63932
1024 |@@@@ 31967
2048 | 0
Once we know how many objects are being allocated, it would useful to see which Java call stacks are responsible for allocating these objects. To generate a list of Java calls stacks with the number of objects allocated per call stack, we can run the whoallocatecount.d DTrace script:
$ whoallocatecount.d
< ..... >
libjvm.so`__1cNSharedRuntimeTdtrace_object_alloc6FpnHoopDesc__i_+0x4f
Wasteful.main([Ljava/lang/String;)V
StubRoutines (1)
libjvm.so`_pnGThread__v_+0x1a3
libjvm.so`jni_CallStaticVoidMethod+0x15d
java`JavaMain+0xd30
libc.so.1`_thr_setup+0x52
libc.so.1`_lwp_start
5678
In the output above (which was cleaned up to make it easy to view), we can see that 5678 objects where allocated by the main() method in the Wasteful class. If you would prefer to see call stacks by bytes allocated, you can run the whoallocatebybytes.d script:
$ whoallocatebytes.d
< ..... >
libjvm.so`__1cNSharedRuntimeTdtrace_object_alloc6FpnHoopDesc__i_+0x4f
Wasteful.main([Ljava/lang/String;)V
StubRoutines (1)
libjvm.so`_pnGThread__v_+0x1a3
libjvm.so`jni_CallStaticVoidMethod+0x15d
java`JavaMain+0xd30
libc.so.1`_thr_setup+0x52
libc.so.1`_lwp_start
817632
The hotspot provider is an incredible debugging tool, and it’s pretty amazing what you can do with just one probe!! If you decide to use these probes in production, be somewhat cautious. Selectively enable probes, and do so only for the duration of your troubleshooting session. Be safe, be careful, and most of all, have fun! Niiiiiiice!