10.3. Inspecting Java Applications with DTraceThis 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:
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 ActionMustang 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 ReleasesIn 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:
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:
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:
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. |