X

DTracing Java

Guest Author

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 <- %s:%s\\n", self->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 <= %s\\n", self->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 <- %s:%s\\n", self->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 <- %s:%s\\n", self->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<- 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
...<- sun/nio/cs/US_ASCII$Decoder:decodeArrayLoop<- sun/nio/cs/US_ASCII$Decoder:decodeLoop
-> java/nio/charset/CoderResult:isUnderflow<- java/nio/charset/CoderResult:isUnderflow<- java/nio/charset/CharsetDecoder:decode
-> java/nio/charset/CoderResult:isUnderflow<- java/nio/charset/CoderResult:isUnderflow
-> java/nio/Buffer:position<- java/nio/Buffer:position
-> sun/nio/cs/StreamDecoder$CharsetSD:readBytes
-> java/nio/HeapByteBuffer:compact
...<- 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<- genunix:pre_syscall
=> read
-> genunix:read32<- genunix:read32
-> genunix:read
-> genunix:getf
-> genunix:set_active_fd<- genunix:set_active_fd<- genunix:getf
-> genunix:nbl_need_check<- genunix:nbl_need_check
-> genunix:fop_rwlock<- genunix:fop_rwlock
-> nfs:nfs4_rwlock
-> nfs:nfs_rw_enter_sig<- nfs:nfs_rw_enter_sig<- nfs:nfs4_rwlock
-> genunix:fop_read<- genunix:fop_read
-> nfs:nfs4_read
... ... ...<- nfs:nfs4_read
-> genunix:fop_rwunlock<- genunix:fop_rwunlock
-> nfs:nfs4_rwunlock<- nfs:nfs4_rwunlock
-> nfs:nfs_rw_exit<- nfs:nfs_rw_exit
-> genunix:releasef
-> genunix:clear_active_fd<- genunix:clear_active_fd
-> genunix:cv_broadcast<- genunix:cv_broadcast<- genunix:releasef<- genunix:read<= read
-> genunix:post_syscall<- genunix:post_syscall<- libc.so.1:_read<- libc.so.1:read<- java/io/FileInputStream:read
-> java/nio/Buffer:position<- java/nio/Buffer:position
-> java/nio/Buffer:flip<- java/nio/Buffer:flip
-> java/nio/Buffer:remaining<- java/nio/Buffer:remaining<- sun/nio/cs/StreamDecoder$CharsetSD:readBytes
-> 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
...<- sun/nio/cs/US_ASCII$Decoder:decodeArrayLoop<- sun/nio/cs/US_ASCII$Decoder:decodeLoop
-> java/nio/charset/CoderResult:isOverflow<- java/nio/charset/CoderResult:isOverflow<- java/nio/charset/CharsetDecoder:decode
-> java/nio/charset/CoderResult:isUnderflow<- java/nio/charset/CoderResult:isUnderflow
-> java/nio/charset/CoderResult:isOverflow<- java/nio/charset/CoderResult:isOverflow
-> java/nio/Buffer:position<- 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 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:

Join the discussion

Comments ( 4 )
  • guest Monday, April 18, 2005
    It'd be nice if it could also output the time spent in each function and java method...
  • MrBenchmark Monday, April 18, 2005
    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 ?
  • Adam Leventhal Tuesday, April 19, 2005
    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
  • Dan Price Tuesday, April 19, 2005
    My god, it's full of stars...
    Nice work, guys.
Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.Captcha
Oracle

Integrated Cloud Applications & Platform Services