Adam Leventhal's blog

Search
Close this search box.

Month: April 2005

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:

A long-time DTrace user was recently examining an ugly C++ application, and this obvious DTrace invocation to trace the 15th argument (zero-indexed) to a particularly ugly function:

# dtrace -n pid123::foobar:entry'{ trace(arg15); }'
dtrace: invalid probe specifier pid380863:::entry{ trace(arg15); }: in action list:
failed to resolve arg15: Unknown variable name

As described in the Solaris Dynamic Tracing Guide we actually only provide access to arguments 0-9. I suppose you could call this a design oversight, but really it reflects our bias about software — no one’s going to want to call your function if it has a bazillion arguments.

But — as with most things pertaining to C++ — sometimes you just have to hold your nose and get it working. If you need to trace arguments past arg9 in functions you’re observing with the pid provider, here’s how you can do it:

x86 this->argN = *(uint32_t *)copyin(uregs[R_SP] + sizeof (uint32_t) * (this->N + 1), sizeof (uint32_t));
x86-64/AMD64 this->argN = *(uint64_t *)copyin(uregs[R_SP] + sizeof (uint64_t) * (this->N - 5), sizeof (uint64_t));
SPARC 32-bit this->argN = *(uint32_t *)copyin(uregs[R_SP] + sizeof (uint32_t) * (this->N + 17), sizeof (uint32_t));
SPARC 64-bit this->argN = *(uint64_t *)copyin(uregs[R_SP] + 0x7ff + sizeof (uint64_t) * (this->N + 16), sizeof (uint64_t));

Note that for SPARC (32-bit and 64-bit) as well as AMD64, these formulas only work for arguments past the sixth — but then you should probably be using arg0 .. arg9 when you can.

UPDATE

The methods above only apply for integer arguments; while I think it will work for 32-bit x86, the other architectures can pass floating-point arguments in registers as well as on the stack. Perhaps a future entry will discuss floating-point arguments if anyone cares.

There are a couple of gotchas I neglected to mention. On AMD64 if the argument is less that 64-bits (e.g. an int), the compiler can leave garbage in the upper bits meaning that you have to cast the variable to the appropriate type in DTrace (e.g. trace((int)this->argN)). On both 32-bit architectures, 64-bit arguments are passed in 2 of these 32-bit arguments; to get the full 64-bit value, just shift and or the two arguments together (e.g. ((this->arg13 <arg14) or ((this->arg14 <arg13) for SPARC and x86 respectively). Even for arguments that you can get with the built-in variables, you will need to mash together 64-bit arguments on 32-bit architectures (except on the SPARCv8+ ABI which can pass the first 6 arguments in 64-bit registers).


Technorati tag:

Recent Posts

January 22, 2024
January 13, 2024
December 29, 2023
February 12, 2017
December 18, 2016
August 9, 2016

Archives

Archives