DTrace Topics Java
From Siwiki
Contents |
[edit] DTrace Topics: Java
This article is about DTracing Java, and is part of the DTrace Topics collection. A general understanding of DTrace is assumed knowledge, which can be studied from the DTrace Topics: Intro section.
DTrace is a dynamic troubleshooting and analysis tool first introduced in the Solaris 10 and OpenSolaris operating systems. Java is an object oriented programming language created by Sun. DTracing Java is about observing the operation of Java code using DTrace.
Completion 
Difficulty 
Audience Java developers, application support
[edit] Java and DTrace
In the first release of Solaris 10, DTrace provided a jstack() action to read Java stack traces.
For JDK 1.4.2 and 5.0, prototype DTrace Java providers were released as loadable VM agent libraries, first named “djvm” then “dvm”.
The hotspot DTrace Java provider was integrated in JDK 6.0, ready for immediate use.
[edit] jstack()
jstack() prints a stack trace with Java translations. Since jstack() is a DTrace action, one must pick a probe from a provider to begin using it. Appropriate providers include,
- The profile provider, to sample frequent stack traces. This can identify Java code hot spots.
- The pid provider, to show how Java interacts with user libraries.
- The syscall provider, to determine what Java causes the system to do, such as I/O.
Long Java stack traces can exceed the default string buffers that DTrace has allocated. If you suspect this has happened (DTrace may warn you if it did), you can increase the global tunables jstackframes and jstackstrsize.
[edit] Example #1
The following DTrace one-liner matches all processes with the execname "java", when they call the read() syscall, and prints jstack(). The first line of the output shows that a syscall was entered, followed by user libraries (libc.so.1 through to libmawt.so.4), and then followed by Java classes and Java methods, then back into user libraries (libjvm.so).
# dtrace -n 'syscall::read:entry /execname == "java"/ { jstack(); }'
dtrace: description 'syscall::read:entry ' matched 1 probe
[...]
CPU ID FUNCTION:NAME
0 75943 read:entry
libc.so.1`_read+0x7
libX11.so.4`_X11TransSocketRead+0x25
libX11.so.4`_X11TransRead+0x17
libX11.so.4`_XRead+0x58
libX11.so.4`_XEventsQueued+0x29e
libX11.so.4`XEventsQueued+0x4f
libmawt.so`Java_sun_awt_X11_XlibWrapper_XEventsQueued+0x1f
sun/awt/X11/XlibWrapper.XEventsQueued(JI)I
sun/awt/X11/XToolkit.run(Z)V
sun/awt/X11/XToolkit.run()V
java/lang/Thread.run()V
StubRoutines (1)
libjvm.so`__1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x1a3
libjvm.so`__1cCosUos_exception_wrapper6FpFpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_+0x27
libjvm.so`__1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x2f
libjvm.so`__1cJJavaCallsMcall_virtual6FpnJJavaValue_nLKlassHandle_nMsymbolHandle_4pnRJavaCallArguments_pnGThread__v_+0xc1
libjvm.so`__1cJJavaCallsMcall_virtual6FpnJJavaValue_nGHandle_nLKlassHandle_nMsymbolHandle_5pnGThread__v_+0x7e
libjvm.so`__1cMthread_entry6FpnKJavaThread_pnGThread__v_+0xd2
libjvm.so`__1cKJavaThreadRthread_main_inner6M_v_+0x4c
libjvm.so`__1cKJavaThreadDrun6M_v_+0x196
libjvm.so`java_start+0xd3
libc.so.1`_thr_setup+0x52
libc.so.1`_lwp_start
This is awesome stuff - we can see the layers of the software stack, and how they are interacting. This is invaluable for troubleshooting - it can answer why Java is causing the system to do various tasks.
Note that the above output contained some encoded C++ names; this can be translated using the c++filt tool,
# dtrace -n 'syscall::read:entry /execname == "java"/ { jstack(); }' | c++filt
dtrace: description 'syscall::read:entry ' matched 1 probe
[...]
CPU ID FUNCTION:NAME
0 75943 read:entry
libc.so.1`_read+0x7
libX11.so.4`_X11TransSocketRead+0x25
libX11.so.4`_X11TransRead+0x17
libX11.so.4`_XRead+0x58
libX11.so.4`_XEventsQueued+0x29e
libX11.so.4`XEventsQueued+0x4f
libmawt.so`Java_sun_awt_X11_XlibWrapper_XEventsQueued+0x1f
sun/awt/X11/XlibWrapper.XEventsQueued(JI)I
sun/awt/X11/XToolkit.run(Z)V
sun/awt/X11/XToolkit.run()V
java/lang/Thread.run()V
StubRoutines (1)
libjvm.so`void JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*)+0x1a3
libjvm.so`void os::os_exception_wrapper(void(*)(JavaValue*,methodHandle*,JavaCallArguments*,Thread*),JavaValue*,methodHandle*,JavaCallArguments*,Thread*)+0x27
libjvm.so`void JavaCalls::call(JavaValue*,methodHandle,JavaCallArguments*,Thread*)+0x2f
libjvm.so`void JavaCalls::call_virtual(JavaValue*,KlassHandle,symbolHandle,symbolHandle,JavaCallArguments*,Thread*)+0xc1
libjvm.so`void JavaCalls::call_virtual(JavaValue*,Handle,KlassHandle,symbolHandle,symbolHandle,Thread*)+0x7e
libjvm.so`void thread_entry(JavaThread*,Thread*)+0xd2
libjvm.so`void JavaThread::thread_main_inner()+0x4c
libjvm.so`void JavaThread::run()+0x196
libjvm.so`java_start+0xd3
libc.so.1`_thr_setup+0x52
libc.so.1`_lwp_start
This is a little awkward to use due to pipe buffering between dtrace and c++filt; it may be better to write to a file and c++filt afterwards.
[edit] string table overflow
Translated Java stack traces can breach some string limits producing truncated output and warning messages, for example,
1 79901 read:entry
libc.so.1`_read+0x7
libzip.so`ZFILE_read+0x24
libzip.so`readFully+0x57
libzip.so`readFullyAt+0x44
libzip.so`ZIP_GetEntryDataOffset+0x48
libzip.so`ZIP_Read+0x92
libzip.so`Java_java_util_zip_ZipFile_read+0x52
java/util/zip/ZipFile.read(JJJ[BII)I
java/util/zip/ZipFile.access$1200(JJJ[BII)I
java/util/zip/ZipFile$ZipFileInputStream.read([BII)I
java/util/zip/ZipFile$1.fill()V
java/util/zip/InflaterInputStream.read([BII)I
sun/misc/Resource.getBytes()[B
java/net/URLClassLoader.defineClass(Ljava/lang/String;Lsun/misc/Resource;)Ljava/lang/Class;
java/net/URLClassLoader.access$000(Ljava/net/URLClassLoader;Ljava/lang/String;Lsun/misc/Resource;)Ljava/lang/Class;
java/net/URLClassLoader$1.run()Ljava/lang/Object;
Stub^A
libjvm.so`__1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x1a3
libjvm.so`__1cCosUos_exception_wrapper6FpFpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_+0x27
libjvm.so`__1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x2f
libjvm.so`JVM_DoPrivileged+0x35c
libjava.so`Java_java_security_AccessController_doPrivileged__Ljava_security_PrivilegedExceptionAction_2Ljava_security_AccessControlContext_2+0x2b
0xfb20a578
0xfb202d67
0xfb202d67
0xfb202d67
0xfb202d67
0xfb202d67
0xfb200202
libjvm.so`__1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x1a3
libjvm.so`__1cCosUos_exception_wrapper6FpFpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_+0x27
libjvm.so`__1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x2f
libjvm.so`__1cJJavaCallsMcall_special6FpnJJavaValue_nLKlassHandle_nMsymbolHandle_4pnRJavaCallArguments_pnGThread__v_+0x66
libjvm.so`__1cJJavaCallsMcall_special6FpnJJavaValue_nGHandle_nLKlassHandle_nMsymbolHandle_53pnGThread__v_+0x8e
libjvm.so`__1cQSystemDictionaryTload_instance_class6FnMsymbolHandle_nGHandle_pnGThread__nTinstanceKlassHandle__+0x165
libjvm.so`__1cQSystemDictionarybEresolve_instance_class_or_null6FnMsymbolHandle_nGHandle_2pnGThread__pnMklassOopDesc__+0x514
libjvm.so`__1cQSystemDictionaryPresolve_or_null6FnMsymbolHandle_nGHandle_2pnGThread__pnMklassOopDesc__+0x63
libjvm.so`__1cQSystemDictionaryPresolve_or_fail6FnMsymbolHandle_nGHandle_2bpnGThread__pnMklassOopDesc__+0x2a
libjvm.so`__1cTconstantPoolOopDescNklass_at_impl6FnSconstantPoolHandle_ipnGThread__pnMklassOopDesc__+0x1a1
libjvm.so`__1cSInterpreterRuntimeE_new6FpnKJavaThread_pnTconstantPoolOopDesc_i_v_+0x68
0xfb212ba4
0xfb202ecd
0xfb202ecd
0xfb2033a9
0xfb202ecd
0xfb2033a9
0xfb202ecd
0xfb2033a9
0xfb202ecd
0xfb202ecd
dtrace: 156 jstack()/ustack() string table overflows
This problem can be reduced or eliminated by increasing jstacksize,
# dtrace -x jstackstrsize=2048 ...
[edit] djvm/dvm Provider
If possible, move the application to to JDK 6.0 so that the integrated hotspot provider can be used instead.
If you are stuck on JDK 1.4.2 or 5.0, you can try the djvm/dvm prototype provider. They require command line configuration and the application to be restarted.
They can be downloaded from Prototype Java Provider for JDK 1.4.2 or JDK 5.0
Some examples of its usage are here. Several more examples and all the Java related scripts from the DTraceToolkit back ported to the dvm provider can be found here.
[edit] hotspot Provider
The hotspot provider was integrated into JDK 6.0. You can check what java you are running by default using,
$ java -version java version "1.6.0" Java(TM) SE Runtime Environment (build 1.6.0-b105) Java HotSpot(TM) Server VM (build 1.6.0-b105, mixed mode)
If you have downloaded and added a beta or "early access" version of JDK 6.0, it may appear in a different directory. Try the following command to see what else is available,
$ ls /usr/jdk/instances/*/bin/java /usr/jdk/instances/jdk1.5.0/bin/java /usr/jdk/instances/jdk1.6.0/bin/java
[edit] hotspot Probes
hotspot provides around 500 different probes, including:
| probe name | description |
| class-loaded | A class loaded |
| class-unloaded | A class unloaded |
| method-entry | A method begins |
| method-return | A method completed |
| object-alloc | An object was allocated |
| gc-begin | System wide GC begins |
| gc-end | System wide GC ended |
| thread-start | A thread has started |
| thread-stop | A thread completed |
The method-* probes can degrade performance, and are only enabled with the VM flag ExtendedDTraceProbes.
The full reference for probes and their arguments is: hotspot Probes
[edit] hotspot Example #1
The hotspot provider will be demonstrated by tracing a simple Java program.
The following Greeting.java code may look familiar, many Java tutorials begin with something similar,
$ cat Greeting.java
public class Greeting {
public void greet() {
System.out.println("Hello DTrace!");
}
}
Now the test harness,
$ cat TestGreeting.java
public class TestGreeting {
public static void main(String[] args) {
Greeting hello = new Greeting();
while (true) {
hello.greet();
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
}
}
}
}
Compiling, Executing,
$ javac TestGreeting.java $ java TestGreeting Hello DTrace! Hello DTrace! Hello DTrace! Hello DTrace! ^C
This simple program produces some known events every second, as it writes the "Hello DTrace!" message to the screen.
[edit] jstack()
We will start with jstack() (not hotspot!). We know that this program writes output, ie syscall::write, so we will use that as the probe for our jstack() action,
# dtrace -n 'syscall::write:entry /execname == "java"/ { jstack(); }'
dtrace: description 'syscall::write:entry ' matched 1 probe
[...]
1 79903 write:entry
libc.so.1`_write+0x7
libjvm.so`__1cDhpiFwrite6FipkvI_I_+0xa0
libjvm.so`JVM_Write+0x36
libjava.so`writeBytes+0x154
libjava.so`Java_java_io_FileOutputStream_writeBytes+0x3f
java/io/FileOutputStream.writeBytes([BII)V
java/io/FileOutputStream.write([BII)V
java/io/BufferedOutputStream.flushBuffer()V
java/io/BufferedOutputStream.flush()V
java/io/PrintStream.write([BII)V
sun/nio/cs/StreamEncoder.writeBytes()V
sun/nio/cs/StreamEncoder.implFlushBuffer()V
sun/nio/cs/StreamEncoder.flushBuffer()V
java/io/OutputStreamWriter.flushBuffer()V
java/io/PrintStream.newLine()V
java/io/PrintStream.println(Ljava/lang/String;)V
Greeting.greet()V
TestGreeting.main([Ljava/lang/String;)V
StubRout
libjvm.so`__1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x1a3
libjvm.so`__1cCosUos_exception_wrapper6FpFpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_+0x27
libjvm.so`__1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x2f
libjvm.so`__1cRjni_invoke_static6FpnHJNIEnv__pnJJavaValue_pnI_jobject_nLJNICallType_pnK_jmethodID_pnSJNI_ArgumentPusher_pnGThread__v_+0x1df
libjvm.so`jni_CallStaticVoidMethod+0x15d
java`JavaMain+0xd30
libc.so.1`_thr_setup+0x52
libc.so.1`_lwp_start
The stack begins in the user level libraries libc, libjvm, libjava, then enters Java. Class and method names are visible, for example java/io/FileOutputStream.write.
Study the Java he stack trace carefully,
- Can you find Greeting.greet?
- Who calls Greeting.greet?
- What is above Greeting.greet? How many of these classes do you recognize?
[edit] Listing Probes
The hotspot provider make many probes available to trace Java and JVM events. As root we can list all of the probes available, while the TestGreeting program is running (and making these probes available to see),
# dtrace -ln 'hotspot*:::' ID PROVIDER MODULE FUNCTION NAME 58974 hotspot_jni120546 libjvm.so jni_CallNonvirtualIntMethodA CallNonvirtualIntMethodA-return 58975 hotspot_jni120546 libjvm.so jni_CallNonvirtualIntMethodV CallNonvirtualIntMethodV-entry 58976 hotspot_jni120546 libjvm.so jni_CallNonvirtualIntMethodV CallNonvirtualIntMethodV-return 58977 hotspot_jni120546 libjvm.so jni_CallNonvirtualLongMethod CallNonvirtualLongMethod-entry 58978 hotspot_jni120546 libjvm.so jni_CallNonvirtualLongMethod CallNonvirtualLongMethod-return 58979 hotspot_jni120546 libjvm.so jni_CallNonvirtualLongMethodA CallNonvirtualLongMethodA-entry 58980 hotspot_jni120546 libjvm.so jni_CallNonvirtualLongMethodA CallNonvirtualLongMethodA-return 58981 hotspot_jni120546 libjvm.so jni_CallNonvirtualLongMethodV CallNonvirtualLongMethodV-entry 58982 hotspot_jni120546 libjvm.so jni_CallNonvirtualLongMethodV CallNonvirtualLongMethodV-return 58983 hotspot_jni120546 libjvm.so jni_CallNonvirtualObjectMethod CallNonvirtualObjectMethod-entry 58984 hotspot_jni120546 libjvm.so jni_CallNonvirtualObjectMethod CallNonvirtualObjectMethod-return 58985 hotspot_jni120546 libjvm.so jni_CallNonvirtualObjectMethodA CallNonvirtualObjectMethodA-entry 58986 hotspot_jni120546 libjvm.so jni_CallNonvirtualObjectMethodA CallNonvirtualObjectMethodA-return 58987 hotspot_jni120546 libjvm.so jni_CallNonvirtualObjectMethodV CallNonvirtualObjectMethodV-entry 58988 hotspot_jni120546 libjvm.so jni_CallNonvirtualObjectMethodV CallNonvirtualObjectMethodV-return 58989 hotspot_jni120546 libjvm.so jni_CallNonvirtualShortMethod CallNonvirtualShortMethod-entry 58990 hotspot_jni120546 libjvm.so jni_CallNonvirtualShortMethod CallNonvirtualShortMethod-return 58991 hotspot_jni120546 libjvm.so jni_CallNonvirtualShortMethodA CallNonvirtualShortMethodA-entry 58992 hotspot_jni120546 libjvm.so jni_CallNonvirtualShortMethodA CallNonvirtualShortMethodA-return 58993 hotspot_jni120546 libjvm.so jni_CallNonvirtualShortMethodV CallNonvirtualShortMethodV-entry 58994 hotspot_jni120546 libjvm.so jni_CallNonvirtualShortMethodV CallNonvirtualShortMethodV-return 58995 hotspot_jni120546 libjvm.so jni_CallNonvirtualVoidMethod CallNonvirtualVoidMethod-entry 58996 hotspot_jni120546 libjvm.so jni_CallNonvirtualVoidMethod CallNonvirtualVoidMethod-return 58997 hotspot_jni120546 libjvm.so jni_CallNonvirtualVoidMethodA CallNonvirtualVoidMethodA-entry [...]
Lots of probes. How many probes?
# dtrace -ln 'hotspot*:::' | wc -l
1015
# dtrace -ln 'hotspot*:::' | awk '{print $5}' | sort -u | wc -l
499
Minus the header, that gives 1014 probes. Some of the probe names are listed more than once, as they have more than one entry point in the Java source. awk and sort -u listed unique lines, showing that there were 498 unique probe names.
Now for enabling the probes, this time without the -l for listing,
# dtrace -n 'hotspot*:::' dtrace: description 'hotspot*:::' matched 1014 probes CPU ID FUNCTION:NAME 0 66465 jni_GetArrayLength:GetArrayLength-entry 0 66466 jni_GetArrayLength:GetArrayLength-return 0 66529 jni_GetObjectField:GetObjectField-entry 0 66530 jni_GetObjectField:GetObjectField-return 0 66529 jni_GetObjectField:GetObjectField-entry 0 66530 jni_GetObjectField:GetObjectField-return 0 66475 jni_GetByteArrayRegion:GetByteArrayRegion-entry 0 66476 jni_GetByteArrayRegion:GetByteArrayRegion-return 0 66456 jni_ExceptionOccurred:ExceptionOccurred-entry 0 66457 jni_ExceptionOccurred:ExceptionOccurred-return [...]
The output scrolls rather fast...
[edit] Aggregating Probes
Just aggregating probe names, a simple one-liner, can give a consise insight into Java behaviour. The TestGreeting program is still running, and the following was run for a few seconds,
# dtrace -n 'hotspot*::: { @[probename] = count(); }'
dtrace: description 'hotspot*::: ' matched 1014 probes
^C
ExceptionOccurred-entry 8
ExceptionOccurred-return 8
GetArrayLength-entry 8
GetArrayLength-return 8
GetByteArrayRegion-entry 8
GetByteArrayRegion-return 8
GetObjectField-entry 16
GetObjectField-return 16
Interesting, but some expected probes are missing (eg, method-entry). To see those we need to enable extended probes.
Extended probes are not activated by default as they may degrade performance on busy apps. They can be enabled using,
- An option to java: -XX:+ExtendedDTraceProbes
- An option to jinfo: -flag +ExtendedDTraceProbes
# java -XX:+ExtendedDTraceProbes TestGreeting Hello DTrace! Hello DTrace! Hello DTrace! [...]
and now aggregating,
# dtrace -n 'hotspot*::: { @[probename] = count(); }'
dtrace: description 'hotspot*::: ' matched 1014 probes
^C
ExceptionOccurred-entry 8
ExceptionOccurred-return 8
GetArrayLength-entry 8
GetArrayLength-return 8
GetByteArrayRegion-entry 8
GetByteArrayRegion-return 8
object-alloc 8
GetObjectField-entry 16
GetObjectField-return 16
method-entry 496
method-return 496
Now we see method-entry and method-return, which occurred 496 times while this was tracing (about 4 seconds).
[edit] Tracing Methods
The class and method names can be fetched from the probe arguments. The following (longer) one-liner snoops Java method execution, as the TestGreeting program runs,
# dtrace -qn 'hotspot*:::method-entry { printf("-> %4s.%s\n",
stringof(copyin(arg1, arg2)), stringof(copyin(arg3, arg4))); }'
-> Greeting.greet
-> java/io/PrintStream.println
-> java/io/PrintStream.print
-> java/io/PrintStream.write
-> java/io/PrintStream.ensureOpen
-> java/io/Writer.write
-> java/io/BufferedWriter.write
-> java/io/BufferedWriter.ensureOpen
-> java/io/BufferedWriter.min
-> java/lang/String.getChars
-> java/lang/System.arraycopy
-> java/io/BufferedWriter.flushBuffer
-> java/io/BufferedWriter.ensureOpen
-> java/io/OutputStreamWriter.write
-> sun/nio/cs/StreamEncoder.write
-> sun/nio/cs/StreamEncoder.ensureOpen
-> sun/nio/cs/StreamEncoder.implWrite
-> java/nio/CharBuffer.wrap
-> java/nio/HeapCharBuffer.<init>
-> java/nio/CharBuffer.<init>
-> java/nio/Buffer.<init>
-> java/lang/Object.<init>
-> java/nio/Buffer.limit
-> java/nio/Buffer.position
-> java/nio/Buffer.hasRemaining
-> java/nio/charset/CharsetEncoder.encode
-> sun/nio/cs/US_ASCII$Encoder.encodeLoop
[...]
Awsome! We can see live class.method calls!
If you see no output, try enabling the ExtendedDTraceProbes option first. If you think you see shuffled output, you may be on a multi-CPU server which is dumping CPU buffers every second but not post sorting; you will need to print out the timestamp variable in the DTrace action and post sort (eg, /usr/bin/sort -n).
This output can scroll very fast for busy applications. It may be more appropriate to aggregate method calls.
[edit] Aggregating Methods
The following script, jagg.d, traces and summarizes Java method calls. It uses a DTrace aggregate to print a frequency count,
# ./jagg.d
Tracing... Hit Ctrl-C to end.
^C
Greeting.greet 3
java/io/BufferedWriter.newLine 3
java/io/PrintStream.newLine 3
java/io/PrintStream.print 3
java/io/PrintStream.println 3
java/lang/Thread.sleep 3
java/io/BufferedOutputStream.write 6
java/io/BufferedWriter.flushBuffer 6
java/io/BufferedWriter.min 6
java/io/BufferedWriter.write 6
java/io/FileOutputStream.write 6
java/io/FileOutputStream.writeBytes 6
java/io/OutputStreamWriter.flushBuffer 6
java/io/OutputStreamWriter.write 6
java/io/Writer.write 6
java/lang/Object.<init> 6
java/lang/String.getChars 6
java/lang/String.indexOf 6
[...output truncated...]
java/io/BufferedOutputStream.flush 9
java/io/BufferedOutputStream.flushBuffer 9
java/io/PrintStream.write 9
java/io/BufferedWriter.ensureOpen 12
java/io/PrintStream.ensureOpen 12
java/lang/System.arraycopy 12
java/nio/ByteBuffer.array 12
java/nio/charset/CoderResult.isUnderflow 12
java/nio/Buffer.position 18
java/nio/CharBuffer.arrayOffset 18
java/nio/ByteBuffer.arrayOffset 24
This has summarized the method calls from our TestGreeting program, which is still running. The most frequent methods were called 24 times during this sample. Our Greeting.greet method was called three times.
The source code to jagg.d is,
#!/usr/sbin/dtrace -qs
dtrace:::BEGIN
{
printf("Tracing... Hit Ctrl-C to end.\n");
}
hotspot*:::method-entry
{
this->class = (char *) copyin(arg1, arg2 + 1);
this->class[arg2] = '\0';
this->method = (char *) copyin(arg3, arg4 + 1);
this->method[arg4] = '\0';
@calls[stringof(this->class), stringof(this->method)] = count();
}
dtrace:::END
{
printa("%48s.%-24s %@4d\n", @calls);
}
Note that strings are now manually terminated.
If you run a script which produces long class.method names such as "java/nio/ByteBuffer$EncoarrayOffsetodeArrayLoop.arrayOffsetodeArrayLoop", it is likely that you have string corruption and need to manually terminate the copyin class and methods names, as jagg.d does above.
[edit] Method Flow
With a little scripting, Java method flow tracing can be accomplished. The following simple script, jflow.d, prints an indented flow of class.method calls as they are entered and returned. We are still running our TestGreeting program, and the Greeting.greet class.method can be seen in the output,
# jflow.d
<- java/lang/Thread.sleep
-> Greeting.greet
-> java/io/PrintStream.println
-> java/io/PrintStream.print
-> java/io/PrintStream.write
-> java/io/PrintStream.ensureOpen
<- java/io/PrintStream.ensureOpen
-> java/io/Writer.write
-> java/io/BufferedWriter.write
-> java/io/BufferedWriter.ensureOpen
<- java/io/BufferedWriter.ensureOpen
-> java/io/BufferedWriter.min
<- java/io/BufferedWriter.min
-> java/lang/String.getChars
-> java/lang/System.arraycopy
<- java/lang/System.arraycopy
<- java/lang/String.getChars
<- java/io/BufferedWriter.write
<- java/io/Writer.write
-> java/io/BufferedWriter.flushBuffer
-> java/io/BufferedWriter.ensureOpen
<- java/io/BufferedWriter.ensureOpen
-> java/io/OutputStreamWriter.write
[...]
The jflow.d script was,
#!/usr/sbin/dtrace -s
#pragma D option quiet
hotspot*:::method-entry
{
self->indent++;
printf("%*s %s %s.%s\n", self->indent, "", "->",
stringof(copyin(arg1, arg2)), stringof(copyin(arg3,arg4)));
}
hotspot*:::method-return
{
printf("%*s %s %s.%s\n", self->indent, "", "<-",
stringof(copyin(arg1, arg2)), stringof(copyin(arg3,arg4)));
self->indent--;
}
jflow.d is neat as a demonstration of DTrace Java tracing, but it is too simple for much use in practice. Issues include,
- The profile name "hotspot*" matches all instances of java. This should be "hotspot$target" to match individual java processes when the script is run with "-p PID" or "-c command".
- As with other snooping tools that produce an event driven output, on a multi-CPU server the output may be shuffled.
- The script doesn't account for multi-threaded Java programs. How should indentation be represented when we are switching between threads?
- This will produce a lot of output on anything but trivial software. DTrace scripts that summarize rather than trace are likely to be more useful.
- The script doesn't terminate strings (as with jagg.d).
The purpose of jflow.d is simply to show that we do have this level of observability.
[edit] Stack Flow
DTrace can observe all layers of the software stack, not just the Java method calls in the JVM. The following example demonstrates this capability, and was actually from the prototype provider. This was by Adam Leventhal,
-> java/io/InputStreamReader:read
-> sun/nio/cs/StreamDecoder:read
-> sun/nio/cs/StreamDecoder:read0
-> libc.so.1:malloc
-> libc.so.1:_smalloc
<- libc.so.1:_smalloc
<- libc.so.1:malloc
-> sun/nio/cs/StreamDecoder:read
-> sun/nio/cs/StreamDecoder:ensureOpen
<- sun/nio/cs/StreamDecoder:ensureOpen
-> sun/nio/cs/StreamDecoder$CharsetSD:implRead
-> java/nio/CharBuffer:wrap
-> java/nio/HeapCharBuffer:
-> java/nio/CharBuffer:
-> java/nio/Buffer:
-> libc.so.1:malloc
<- libc.so.1:malloc
-> java/nio/Buffer:position
<- java/nio/Buffer:position
<- java/nio/Buffer:
<- java/nio/CharBuffer:
<- java/nio/HeapCharBuffer:
<- java/nio/CharBuffer:wrap
-> java/nio/charset/CharsetDecoder:decode
-> sun/nio/cs/US_ASCII$Decoder:decodeLoop
-> java/nio/ByteBuffer:hasArray
<- java/nio/ByteBuffer:hasArray
-> java/nio/CharBuffer:hasArray
<- java/nio/CharBuffer:hasArray
-> sun/nio/cs/US_ASCII$Decoder:decodeArrayLoop
[...]
While this extreme level of visibility is unlikely to be common usage, it is valuable that this is at all possible.
This really highlights why DTracing Java is different to other Java debugging and profiling software; DTrace can see all layers of the software stack. No matter where a bug or performance issue is hiding, DTrace has the capability to find it.
[edit] Object Allocation
The creation of a new object can be traced with object-alloc. Here we are back to tracing the TestGreeting program,
# dtrace -qn 'hotspot*:::object-alloc { printf("new %s\n",
stringof(copyin(arg1, arg2))); }'
new java/nio/HeapCharBuffer
new java/nio/HeapCharBuffer
new java/nio/HeapCharBuffer
new java/nio/HeapCharBuffer
[...]
[edit] Method Times
With method-entry and method-return probes, and DTrace's ability to measure nanosecond timestamps, the time to execute methods can be measured. This can help identify bottlenecks in Java code.
Things start to get a little harder. Be aware of,
- overlapping methods
- multiple Java threads executing concurrently
- Java threads context switching off the CPUs
- DTrace overheads at nanosecond resolutions
- recursive methods?
It may be easier to use java -Xrunhprof profiling, which is built into the JVM and doesn't use DTrace. Here I use it on TestGreeting,
$ java -Xrunhprof:cpu=times,monitor=y,msa=y,depth=8,file=prof.txt TestGreeting Hello DTrace! Hello DTrace! Hello DTrace! Hello DTrace! Hello DTrace! Hello DTrace! Hello DTrace! ^C Dumping contended monitor usage ... CPU usage by timing methods ... done. $ $ more prof.txt JAVA PROFILE 1.0.1, created Mon Mar 19 20:41:08 2007 Header for -agentlib:hprof (or -Xrunhprof) ASCII Output (JDK 5.0 JVMTI based) [...verbose output truncated...] CPU TIME (ms) BEGIN (total = 84933) Mon Mar 19 20:41:15 2007 rank self accum count trace method 1 4.32% 4.32% 5 300309 sun.net.www.ParseUtil.decode 2 3.20% 7.53% 1 301011 java.io.FilePermission$1.run 3 2.59% 10.12% 1 300898 sun.net.www.protocol.file.Handler.createFileURLConnection 4 2.41% 12.53% 276 300301 java.lang.StringBuilder.append 5 2.31% 14.84% 1 300409 sun.misc.URLClassPath$JarLoader.getJarFile 6 1.55% 16.39% 6 300428 sun.misc.URLClassPath$3.run 7 1.46% 17.85% 5 300312 java.io.UnixFileSystem.normalize 8 1.13% 18.98% 276 300300 java.lang.AbstractStringBuilder.append 9 1.13% 20.11% 276 300299 java.lang.String.charAt [...] 122 0.15% 62.89% 7 301458 Greeting.greet [...]
Profiling suggests that the Greeting.greet method consumes 0.15% CPU, with the highest being sun.net.www.ParseUtil.decode at 4.32% CPU.
[edit] More Analysis
So far we have seen a few ways to analyse the TestGreeting example program, and used a few different probes directly. There is a lot more which can be done with the hotspot provider, which provides around 500 different probes.
Further directions for analysis include,
- Other hotspot probes
- Other DTrace providers
- Scripting to identify custom events of interest
The possibilities for analysis are near-endless. This is great if you are troubleshooting a known problem – as DTrace should have the power to find it.
[edit] hotspot Shipped Samples
In the /usr/jdk/instances/jdk1.6.0/sample/dtrace/hotspot and /usr/jdk/instances/jdk1.6.0/sample/dtrace/hotspot_jni directories are several shipped sample scripts of DTracing Java using the hotspot provider. These scripts are worth checking out, as their output is quite useful and they are shipped by default.
Since the shipped /usr/jdk/instances/jdk1.6.0/sample/dtrace/hotspot/README.txt file explains these scripts well, the contents of this README has been included as the three following sections,
[edit] README
From README.txt,
This directory contains D scripts which demonstrate usage of 'hotspot' provider probes.
The 'hotspot' provider makes available probes that can be used to track the lifespan of the VM, thread start and stop events, GC and memory pool statistics, method compilations, and monitor activity. With a startup flag, additional probes are enabled which can be used to monitor the running Java program, such as method enter and return probes, and object allocations. All of the hotspot probes originate in the VM library (libjvm.so), so they are also provided from programs which embed the VM.
Many of the probes in the provider have arguments that can be examined to provide further details on the state of the VM. Many of these probes' arguments are opaque IDs which can be used to link probe firings to each other, however strings and other data are also provided. When string values are provided, they are always present as a pair: a pointer to unterminated modified UTF-8 data (see JVM spec: 4.4.7) , and a length value which indicates the extent of that data. Because the string data (even when none of the characters are outside the ASCII range) is not guaranteed to be terminated by a NULL character, it is necessary to use the length-terminated copyinstr() intrinsic to read the string data from the process.
You can find more information about HotSpot probes here.
[edit] Scripts
From README.txt,
The following scripts/samples which demonstrate 'hotspot' probes usage are available:
- class_loading_stat.d
- The script collects statistics about loaded and unloaded Java classes and
- dump current state to stdout every N seconds.
- gc_time_stat.d
- The script measures the duration of a time spent in GC.
- The duration is measured for every memory pool every N seconds.
- hotspot_calls_tree.d
- The script prints calls tree of fired 'hotspot' probes.
- method_compile_stat.d
- The script prints statistics about N methods with largest/smallest
- compilation time every M seconds.
- method_invocation_stat.d
- The script collects statistics about Java method invocations.
- method_invocation_stat_filter.d
- The script collects statistics about Java method invocations.
- You can specify package, class or method name to trace.
- method_invocation_tree.d
- The script prints tree of Java and JNI method invocations.
- monitors.d
- The script traces monitor related probes.
- object_allocation_stat.d
- The script collects statistics about N object allocations every M seconds.
[edit] Running the Scripts
From README.txt,
To run any D script from hotspot directory you can do either:
# dscript.d -c "java ..."
or if you don't have Solaris 10 patch which allows to specify probes that don't yet exist ( Hotspot DTrace probes are defined in libjvm.so and as result they could be not been yet loaded when you try to attach D script to the Java process) do:
# ../helpers/dtrace_helper.d -c "java ..." dscript.d
or if your application is already running you can just simply attach the D script like:
# dscript.d -p JAVA_PID
[edit] Quick Reference
The following is a quick reference for DTracing the Java programming language.
[edit] Providers
| Provider | Relavence |
| hotspot | Tracing JVM events including Java method execution for JDK 1.6 |
| dvm/djvm | Tracing JVM events including Java method execution for JDK 1.4.2 and JDK 1.5 |
| profile | Sampling Java execution at fixed rates |
| syscall | Tracing system calls that Java code caused |
| pid | Tracing raw JVM operation |
[edit] Probes
| Probe | Description |
| hotspot*:::method-entry | A method begins (needs VM flag ExtendedDTraceProbes) |
| hotspot*:::method-returns | A method completes (needs VM flag ExtendedDTraceProbes) |
| hotspot*:::object-alloc | An object was created (needs VM flag ExtendedDTraceProbes) |
| hotspot*:::gc-begin | System wide GC begins |
| hotspot*:::gc-ends | System wide GC ended |
| hotspot*:::thread-start | A thread begins execution |
| hotspot*:::thread-stop | A thread completes |
This is a small selection from about 500 probes available.
[edit] Capabilities
| Capability | Exists | Format | Example |
| Function entries | yes | Probe: hotspot:::method-entry | # dtrace -qn 'hotspot*:::method-entry { printf("%s.%s\n",
stringof(copyin(arg1, arg2)), stringof(copyin(arg3, arg4))); }' |
| Function entry arguments | no[1] | ||
| Function returns | yes | Probe: hotspot:::method-return | # dtrace -qn 'hotspot*:::method-entry { printf("%s.%s\n",
stringof(copyin(arg1, arg2)), stringof(copyin(arg3, arg4))); }' |
| Function return value | no[1] | ||
| Function instructions | no[1] | ||
| Stack traces | yes | Action: jstack() | dtrace -n 'syscall::read:entry /pid == $target/ { jstack(); }' -p PID |
[1] this can probably be achieved with some effort using the pid provider to examine raw JVM execution.
[edit] Resources
Links for DTrace and Java,
- hotspot Probes Guide
- /usr/jdk/instances/jdk1.6.0/sample/dtrace/hotspot has some sample scripts
- Search the Internet for “DTrace Java”, in particular are articles written by, Adam Leventhal, Jarod Jenson and Kelly O'Hair.
[edit] References
References used while creating this site,
- /usr/jdk/instances/jdk1.6.0/sample/dtrace/hotspot/README.txt
- http://java.sun.com/javase/6/docs/technotes/guides/vm/dtrace.html
