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