Section 10.3. Inspecting Java Applications with DTrace | Solaris Performance and Tools: DTrace and MDB Techniques for Solaris 10 and OpenSolaris

10.3. Inspecting Java Applications with DTrace

This section presents two sample applications that demonstrate the interaction of the Mustang Java HotSpot Virtual Machine and the Solaris 10 DTrace Framework. The first example, Java2Demo, is bundled with the Mustang release and will already be familiar to most developers. Because the hotspot provider is built into the Mustang VM itself, running the application is all that is required to trigger probe activity. The second example is a custom debugging scenario that uses DTrace to find a troublesome line of native code in a Java Native Interface (JNI) application.

The following script, written in the D programming language, defines the set of probes that DTrace will listen to while the Java2Demo application is running. In this case, the only probes of interest are those related to garbage collection.

#!/usr/sbin/dtrace -Zs #pragma D option quiet self int cnt; dtrace:::BEGIN {         self->cnt == 0;         printf("Ready..\n"); } hotspot$1:::gc-begin /self->cnt == 0/ {         self->tid = tid;         self->cnt++; } hotspot$1:::* /self->cnt != 0 / {         printf("  tid: %d, Probe: %s\n", tid, probename); } hotspot$1:::gc-end {         printf("  tid: %d, D-script exited\n", tid);         exit(0); }

To run this example:

Start the sample application: java -jar Java2Demo.jar.
Note the application's PID (11201 for this example).
Start the D script, passing in the PID as its only argument: hotspot_gc.d 11201.

The following output shows that DTrace prints the thread ID and probe name as each probe fires in response to garbage collection activity in the VM:

Ready..  tid: 4, Probe: gc-begin  tid: 4, Probe: mem-pool-gc-begin  tid: 4, Probe: mem-pool-gc-begin  tid: 4, Probe: mem-pool-gc-begin  tid: 4, Probe: mem-pool-gc-begin  tid: 4, Probe: mem-pool-gc-begin  tid: 4, Probe: mem-pool-gc-end  tid: 4, Probe: mem-pool-gc-end  tid: 4, Probe: mem-pool-gc-end  tid: 4, Probe: mem-pool-gc-end  tid: 4, Probe: mem-pool-gc-end  tid: 4, Probe: mem-pool-gc-begin  tid: 4, Probe: mem-pool-gc-begin  tid: 4, Probe: mem-pool-gc-begin  tid: 4, Probe: mem-pool-gc-begin  tid: 4, Probe: mem-pool-gc-begin  tid: 4, Probe: mem-pool-gc-end  tid: 4, Probe: mem-pool-gc-end  tid: 4, Probe: mem-pool-gc-end  tid: 4, Probe: mem-pool-gc-end  tid: 4, Probe: mem-pool-gc-end  tid: 4, Probe: gc-end  tid: 4, D-script exited

The next script shows the thread ID (tid) and probe name in all probes; class name, method name and signature in the "method-compile-begin" probe; and method name and signature in the compiled-method-load probe:

#!/usr/sbin/dtrace -Zs #pragma D option quiet self int cnt; dtrace:::BEGIN {         self->cnt == 0;         printf("Ready..\n"); } hotspot$1:::method-compile-begin /self->cnt == 0/ {         self->tid = tid;         self->cnt++;         printf(" tid: %d, %21s, %s.%s %s\n", tid, probename,         copyinstr(arg2), copyinstr(arg4), copyinstr(arg6)); } hotspot$1:::method-compile-end /self->cnt > 0/ {         printf(" tid: %d, %21s\n", tid, probename); } hotspot$1:::compiled-method-load /self->cnt > 0/ {         printf(" tid: %d, %21s, %s %s\n", tid, probename,            copyinstr(arg2), copyinstr(arg4)); } hotspot$1:::vm-shutdown {         printf(" tid: %d, %21s\n", tid, probename);         printf(" tid: %d, D-script exited\n", tid);         exit(0); } hotspot$1:::* /self->cnt > 0/ {         printf(" tid: %d, %21s, %s %s\n", tid, probename,            copyinstr(arg2), copyinstr(arg4)); }

Its output shows:

Ready.. tid: 9,  method-compile-begin, sun/java2d/SunGraphics2D.setFont (Ljava/awt/Font;)V tid: 9,  compiled-method-load, setFont (Ljava/awt/Font;)V tid: 9,    method-compile-end tid: 9,  method-compile-begin, sun/java2d/SunGraphics2D validateCompClip tid: 9,  compiled-method-load, validateCompClip ()V tid: 9,    method-compile-end tid: 8,  method-compile-begin, javax/swing/RepaintManager addDirtyRegion0 tid: 8,  compiled-method-load, addDirtyRegion0 (Ljava/awt/Container;IIII)V tid: 8,    method-compile-end tid: 9,  method-compile-begin, java/io/BufferedInputStream read tid: 9,  compiled-method-load, read ()I tid: 9,    method-compile-end tid: 8,  method-compile-begin, java/awt/geom/AffineTransform translate tid: 8,  compiled-method-load, translate (DD)V tid: 8,    method-compile-end tid: 9,  method-compile-begin, sun/awt/X11/Native getInt tid: 9,  compiled-method-load, getInt (J)I tid: 9,    method-compile-end tid: 8,  method-compile-begin, sun/java2d/SunGraphics2D setColor tid: 8,  compiled-method-load, setColor (Ljava/awt/Color;)V tid: 8,    method-compile-end tid: 9,  method-compile-begin, sun/reflect/GeneratedMethodAccessor1 invoke tid: 9,  compiled-method-load, invoke (Ljava/lang/Object;[Ljava/lang/Object;)Ljava/ lang/ Object; tid: 9,    method-compile-end tid: 9,  method-compile-begin, sun/java2d/SunGraphics2D constrain tid: 9,  compiled-method-load, constrain (IIII)V tid: 9,    method-compile-end tid: 8,  method-compile-begin, java/awt/Rectangle setLocation tid: 8,  compiled-method-load, setLocation (II)V tid: 8,    method-compile-end tid: 9,  method-compile-begin, java/awt/Rectangle move tid: 9,  compiled-method-load, move (II)V tid: 9,    method-compile-end tid: 8,  method-compile-begin, java/lang/Number <init> tid: 8,  compiled-method-load, <init> ()V tid: 8,    method-compile-end tid: 8,  method-compile-begin, sun/awt/X11/XToolkit getAWTLock tid: 8,  compiled-method-load, getAWTLock ()Ljava/lang/Object; tid: 8,    method-compile-end tid: 17,           vm-shutdown tid: 17, D-script exited

The next example demonstrates a debugging session with the hotspot_jni provider. Consider, if you will, an application that is suspected to be calling JavaTM Native Interface (JNI) functions from within a critical region. A JNI critical region is the space between calls to JNI methods GetPrimitiveArrayCritical and ReleasePrimitiveArrayCritical. There are some important rules for what is allowed within that space. Chapter 4 of the JNI 5.0 Specification makes it clear that within this region, "Native code should not run for an extended period of time before it calls ReleasePrimitiveArrayCritical." In addition, "Native code must not call other JNI functions, or any system call that may cause the current thread to block and wait for another Java thread."

The following D script will inspect a JNI application for this kind of violation:

#!/usr/sbin/dtrace -Zs #pragma D option quiet self int in_critical_section; dtrace:::BEGIN {         printf("ready..\n"); } hotspot_jni$1:::ReleasePrimitiveArrayCritical_entry {         self->in_critical_section = 0; } hotspot_jni$1:::GetPrimitiveArrayCritical_entry {         self->in_critical_section = 0; } hotspot_jni$1:::* /self->in_critical_section == 1/ {         printf("JNI call %s made from JNI critical region\n", probename); } hotspot_jni$1:::GetPrimitiveArrayCritical_return {         self->in_critical_section = 1; } syscall:::entry /pid == $1 && self->in_critical_section == 1/ {         printf("system call %s made in JNI critical region\n", probefunc); }

Output:

system call brk made in JNI critical section system call brk made in JNI critical section system call ioctl made in JNI critical section system call fstat64 made in JNI critical section JNI call FindClass_entry made from JNI critical region JNI call FindClass_return made from JNI critical region

From this DTrace output, we can see that the probes FindClass_entry and FindClass_return have fired due to a JNI function call within a critical region. The output also shows some system calls related to calling printf() in the JNI critical region. The native code for this application shows the guilty function:

#include "t.h" /*  * Class:     t  * Method:    func  * Signature: ([I)V  */ JNIEXPORT void JNICALL Java_t_func   (JNIEnv *env, jclass clazz, jintArray array) {    int* value = (int*)env->GetPrimitiveArrayCritical(array, NULL);    printf("hello world");    env->FindClass("java/lang/Object");    env->ReleasePrimitiveArrayCritical(array, value, JNI_ABORT); }

10.3.1. Inspecting Applications with the DTrace jstack Action

Mustang is the first release to contain built-in DTrace probes, but support for the DTrace jstack() action was actually first introduced in the JavaTM 2 Platform Standard Edition 5.0 Update Release 1. The DTrace jstack() action prints mixed-mode stack traces including both Java method and native function names. As an example of its use, consider the following application, which periodically sleeps to mimic hanging behavior:

public class dtest{     int method3(int stop){         try{Thread.sleep(500);}         catch(Exception ex){}         return stop++;     }     int method2(int stop){         int result = method3(stop);         return result + 1;     }     int method1(int arg){         int stop=0;         for(int i=1; i>0; i++){             if(i>arg){stop=i=1;}             stop=method2(stop);         }         return stop;     }     public static void main(String[] args) {         new dtest().method1(10000);     } }

To find the cause of the hang, the user would want to know the chain of native and Java method calls in the currently executing thread. The expected chain would be something like:

<chain of initial VM functions> -> dtest.main -> dtest.method1 -> dtest.method2 -> dtest.method3 -> java/lang/Thread.sleep -> <chain of VM sleep functions> -> <Kernel pool functions>

The following D script (usestack.d) uses the DTrace jstack() action to print the stack trace:

#!/usr/sbin/dtrace -s BEGIN { this->cnt = 0; } syscall::pollsys:entry /pid == $1 && tid == 1/ {    this->cnt++;    printf("\n\tTID: %d", tid);    jstack(50); } syscall:::entry /this->cnt == 1/ {    exit(0); }

And the stack trace itself appears as follows:

$ usejstack.d 1344 | c++filt CPU     ID                    FUNCTION:NAME  0    316                    pollsys:entry    TID: 1    libc.so.1'__pollsys+0xa    libc.so.1'poll+0x52    libjvm.so'int os_sleep(long long,int)+0xb4    libjvm.so'int os::sleep(Thread*,long long,int)+0x1ce    libjvm.so'JVM_Sleep+0x1bc    java/lang/Thread.sleep    dtest.method3    dtest.method2    dtest.method1    dtest.main    StubRoutines (1)    libjvm.so'void JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArgu- ments*,Thread*)+0x1b5    libjvm.so'void os::os_exception_wrapper(void(*)(JavaValue*,methodHandle*,JavaCallAr- guments*,Thread*),JavaValue*,methodHandle*,Ja vaCallArguments*,Thread*)+0x18    libjvm.so'void JavaCalls::call(JavaValue*,methodHandle,JavaCallArgu- ments*,Thread*)+0x2d    libjvm.so'void jni_invoke_static(JNIEnv_*,JavaValue*,_jobject*,JNICallType,_ jmethodID*,JNI_ArgumentPush er*,Thread*)+0x214    libjvm.so'jni_CallStaticVoidMethod+0x244    java'main+0x642    StubRoutines (1)

The command line shows that the output from this script was piped to the c++filt utility, which demangles C++ mangled names making the output easier to read. The DTrace header output shows that the CPU number is 0, the probe number is 316, the thread ID (TID) is 1, and the probe name is pollsys:entry, where pollsys is the name of the system call. The stack trace frames appear from top to bottom in the following order: two system call frames, three VM frames, five Java method frames, and the remaining frames are VMframes.

It is also worth noting that the DTrace jstack action will run on older releases, such as the Java 2 Platform, Standard Edition version 1.4.2, but hexadecimal addresses will appear instead of Java method names. Such addresses are of little use to application developers.

10.3.2. Adding Probes to Pre-Mustang Releases

In addition to the jstack() action, it is also possible for pre-Mustang users to add DTrace probes to their release with the help of VM Agents. A VM agent is a shared library that is dynamically loaded into the VM at startup.

VM agents are available for the following releases:

For The Java 2 Platform, Standard Edition, version 1.4.2, there is a dvmpi agent that uses the Java Virtual Machine Profiler Interface (JVMPI).
For The Java 2 Platform Standard Edition 5.0, there is a dvmti agent that uses the JVM Tool Interface (JVM TI).

To obtain the agents, visit the DVM java.net project website at

https://solaris10-dtrace-vm-agents.dev.java.net/

and follow the "Documents and Files" link. The file dvm.zip contains both binary and source code versions of the agent libraries.

The following diagram shows an abbreviated view of the resulting directory structure once dvm.zip has been extracted:

          build   make   src    test             |        ---------------------          |      |     |      |         amd64  i386  sparc  sparcv9          |      |     |      |         lib    lib   lib    lib

Each lib directory contains the pre-built binaries dvmti.jar, libdvmpi.so, and libdvmti.so. If you prefer to compile the libraries yourself, the included README file contains all necessary instructions.

Once unzipped, the VM must be able to find the native libraries on the filesystem. This can be accomplished either by copying the libraries into the release with the other shared libraries, or by using a platform-specific mechanism to help a process find it, such as LD_LIBRARY_PATH. In addition, the agent library itself must be able to find all the external symbols that it needs. The ldd utility can be used to verify that a native library knows how to find all required externals.

Both agents accept options to limit the probes that are available, and default to the least possible performance impact. To enable the agents for use in your own applications, run the java command with one of the following additional options:

-Xrundvmpi
-Xrundvmti (for defaults)
-Xrundvmpi:all
-Xrundvmti:all (for all probes)

For additional options, consult the DVM agent README. Both agents have their limitations, but dvmpi has more, and we recommend using the Java Standard Edition 5.0 Development Kit (JDK 5.0) and the dvmti agent if possible.

When using the agent-based approach, keep in mind that:

The dvmpi agent uses JVMPI and only works with one collector. JVMPI has historically been an unstable, experimental interface, and there is a performance penalty associated with using it. JVMPI only works with JDK 5.0 and earlier.
The dvmti agent uses JVM TI and only works with JDK 5.0 and later. It works with all collectors, has little performance impact for most probes, and is a formal and much more stable interface.
Both agents have some performance penalty for method entry/exit and object alloc/free, less so with the dvmti agent.
The dvmti agent uses BCI (byte code instrumentation), and therefore adds bytecodes to methods (if method entry/exit or object alloc/free probes are active).
Enabling the allocation event for the JVMTI agent creates an overhead even when DTrace is not attached, and the JVMPI agent severely impacts performance and limits deployment to the serial collector.

Section C.1 provides a D script for testing DVM probes. The DVM agent provider interface, shown in Section C.2, lists all probes provided by dvmpi and dvmti.