DTracing Java

DTrace has cast light on parts of the system that were previously only dimly illuminated by previous tools, but there have been some parts of the system frustratingly left in the dark. The prevalent example is Java. Java has been relatively unobservable with DTrace; the jstack() action has offered a narrow beam of light into interactions between Java code and the rest of the system, but we really need is Java probes in the DTrace framework.

DTrace users really want to be able to trace Java methods in the same way they can trace C function calls in the application (or in the kernel). We haven’t quite reached that Xanadu yet, but Kelly O’Hair (with the inspiration and prodding of Jarod Jenson) has created JVMPI and JVMTI agents export the instrumentation provided by those frameworks into DTrace.

For example, examining the size of Java allocations is now a snap. The object-alloc probe fires every time an object gets allocated, and one of the arguments is the size.

# dtrace -n 'djvm$target:::object-alloc{ @ = quantize(arg1) }' -p `pgrep -n java`
dtrace: description 'djvm$target:::object-alloc' matched 1 probe
^C
value  ------------- Distribution ------------- count
4 |                                         0
8 |                                         43
16 |@@@@@@@@@@@@@@@@@                        18771
32 |@@@@@@@@@@@@@@@@                         17482
64 |@@@@@                                    5292
128 |@                                        1486
256 |                                         106
512 |                                         165
1024 |                                         319
2048 |                                         149
4096 |                                         48
8192 |                                         0
16384 |                                         1
32768 |                                         1
65536 |                                         0

One of the most troublesome areas when dealing with production Java code seems to be around garbage collection. There are two probes — that fire at the start and end of a GC run — that can be used, for example, to look for latency spikes in garbage collection:

bash-3.00# dtrace -s /dev/stdin -p `pgrep -n java`
djvm$target:::gc-start
{
self->ts = vtimestamp;
}
djvm$target:::gc-finish
/self->ts/
{
@ = quantize(vtimestamp - self->ts);
self->ts = 0;
}
dtrace: script '/dev/stdin' matched 2 probes
^C
value  ------------- Distribution ------------- count
16777216 |                                         0
33554432 |@@                                       1
67108864 |@@@@@@                                   3
134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@         16
268435456 |                                         0

Let’s say there’s some itermittent problem where GC takes a long time. This sort of script can help you identify the standard behavior and the outliers, and other DTrace facility — notably speculative tracing — will let you drill down on the source of the problem (“I care about these events only when the GC run takes more than 10ms?).

One of the most exciting moments early on with DTrace was observing the flow of control from a user-land function through a system call and into the kernel — as far as I know we were seeing something that hadn’t been done before (Bryan‘s last example in this blog post demonstrates this). Here’s a script that instruments a particular Java method (java.io.InputStreamReader.read()) and follows the thread of control from that method call through Java, libc, the system call table, and the kernel — and back out:

#pragma D option quiet
djvm$target:::method-entry
/copyinstr(arg0) == "java/io/InputStreamReader" && copyinstr(arg1) == "read"/
{
self->interested = 1;
self->indent = 0;
}
djvm$target:::method-entry
/self->interested/
{
self->indent += 2;
printf("%*s -> %s:%s\n", self->indent, "",
copyinstr(arg0), copyinstr(arg1));
}
djvm$target:::method-return
/self->interested/
{
printf("%*s indent, "",
copyinstr(arg0), copyinstr(arg1));
self->indent -= 2;
}
syscall:::entry
/self->interested/
{
self->indent += 2;
printf("%*s => %s\n", self->indent, "", probefunc);
}
syscall:::return
/self->interested/
{
printf("%*s indent, "", probefunc);
self->indent -= 2;
}
pid$target:libc.so.1::entry
/self->interested/
{
self->indent += 2;
printf("%*s -> %s:%s\n", self->indent, "", probemod, probefunc);
}
pid$target:libc.so.1::return
/self->interested/
{
printf("%*s indent, "", probemod, probefunc);
self->indent -= 2;
}
fbt:::entry
/self->interested/
{
self->indent += 2;
printf("%*s -> %s:%s\n", self->indent, "", probemod, probefunc);
}
fbt:::return
/self->interested/
{
printf("%*s indent, "", probemod, probefunc);
self->indent -= 2;
}
djvm$target:::method-return
/copyinstr(arg0) == "java/io/InputStreamReader" && copyinstr(arg1) == "read" &&
self->interested/
{
self->interested = 0;
exit(0);
}

Not especially beautiful — I had to hand roll my own flowindent — but the results are pretty spectacular. I’ve uploaded the whole shebang, but here’s an abbreviated version:

-> 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
 sun/nio/cs/StreamDecoder:read
-> 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
 java/nio/Buffer:position
<- java/nio/Buffer:position
<- java/nio/Buffer:
<- java/nio/CharBuffer:
<- java/nio/HeapCharBuffer:
 java/nio/charset/CharsetDecoder:decode
-> sun/nio/cs/US_ASCII$Decoder:decodeLoop
-> java/nio/ByteBuffer:hasArray
 java/nio/CharBuffer:hasArray
 sun/nio/cs/US_ASCII$Decoder:decodeArrayLoop
...
<- sun/nio/cs/US_ASCII$Decoder:decodeArrayLoop
 java/nio/charset/CoderResult:isUnderflow
<- java/nio/charset/CoderResult:isUnderflow
 java/nio/charset/CoderResult:isUnderflow
 java/nio/Buffer:position
 sun/nio/cs/StreamDecoder$CharsetSD:readBytes
-> java/nio/HeapByteBuffer:compact
...
 java/io/FileInputStream:read
-> libc.so.1:read
-> libc.so.1:_read
-> genunix:pre_syscall
-> genunix:syscall_mstate
<- genunix:syscall_mstate
 read
-> genunix:read32
 genunix:read
-> genunix:getf
-> genunix:set_active_fd
<- genunix:set_active_fd
 genunix:nbl_need_check
 genunix:fop_rwlock
 nfs:nfs4_rwlock
-> nfs:nfs_rw_enter_sig
<- nfs:nfs_rw_enter_sig
 genunix:fop_read
 nfs:nfs4_read
... ... ...
 genunix:fop_rwunlock
 nfs:nfs4_rwunlock
 nfs:nfs_rw_exit
 genunix:releasef
-> genunix:clear_active_fd
 genunix:cv_broadcast
<- genunix:cv_broadcast
<- genunix:releasef
<- genunix:read
 genunix:post_syscall
<- genunix:post_syscall
<- libc.so.1:_read
<- libc.so.1:read
 java/nio/Buffer:position
 java/nio/Buffer:flip
 java/nio/Buffer:remaining
<- java/nio/Buffer:remaining
 java/nio/charset/CharsetDecoder:decode
-> sun/nio/cs/US_ASCII$Decoder:decodeLoop
-> java/nio/ByteBuffer:hasArray
 java/nio/CharBuffer:hasArray
 sun/nio/cs/US_ASCII$Decoder:decodeArrayLoop
...
<- sun/nio/cs/US_ASCII$Decoder:decodeArrayLoop
 java/nio/charset/CoderResult:isOverflow
<- java/nio/charset/CoderResult:isOverflow
 java/nio/charset/CoderResult:isUnderflow
 java/nio/charset/CoderResult:isOverflow
 java/nio/Buffer:position
 java/nio/Buffer:position
<- java/nio/Buffer:position
<- sun/nio/cs/StreamDecoder$CharsetSD:implRead
<- sun/nio/cs/StreamDecoder:read
<- sun/nio/cs/StreamDecoder:read0
<- sun/nio/cs/StreamDecoder:read
<- java/io/InputStreamReader:read

To me that’s pretty exciting. From a unified framework, we’re able to follow a single thread of control across multiple languages, privilege modes, and execution environments using multiple instrumtation methodologies to get one clear and bright view of that’s going on. Obviously, having all method entries and returns coming from two probes isn’t ideal and — in the fullness of time — we hope to have much better and more tightly integrated support Java in DTrace, but this is a first step and you can use it today. The performance impact can be pretty hefty depending on how you invoke the agent, so while this may or may not be applicable in production, this should be a huge benefit for developers (including, apparently, our own in-house Java developers — care to explain all the calls to mutex_trylock(3c)?).

I encourage you to check out Kelly’s DTrace/Java Agents and feel free to comment about your experiences.


Technorati tag:

Posted on April 18, 2005 at 5:00 pm by ahl · Permalink
In: DTrace

4 Responses

Subscribe to comments via RSS

  1. Written by Anonymous
    on April 18, 2005 at 6:15 pm
    Permalink

    It’d be nice if it could also output the time spent in each function and java method…

  2. Written by MrBenchmark
    on April 18, 2005 at 8:46 pm
    Permalink

    This calls to malloc (libc) are fairly interesting and would benefit being timed to weight them on the overall GC. I assume an output for the 1.5.0 jvm. correct ?

  3. Written by Adam Leventhal
    on April 19, 2005 at 12:12 am
    Permalink

    Capt. 69.238.229.71,

    Indeed getting the time spent in each method or function would be useful — and with DTrace it’s trivial. All you have to do is record a timestamp (or vtimestamp) at each method or function entry, save it in a thread-local associative arrary, and print out the difference on the way out. In fact, this is a <em>very</em> common use of DTrace. Forgive me if it sounds trite, but I’ll leave this as an exercise for the reader.

    Mr. Benchmark,

    Again, printing out timing information is easy because these java probes are first class citizens in the DTrace framework — you can do all the usual DTrace-ish things with them. This example was with 1.5, and the agents should also work with 1.4.2 (and possibly earlier versions, but you’re very much on your own there).

    Adam

  4. Written by Dan Price
    on April 19, 2005 at 12:52 am
    Permalink

    My god, it’s full of stars…
    Nice work, guys.

Subscribe to comments via RSS