Your Java fell into my DTrace!
So I’ve been following with excitement the JVMPI and JVMTI agents prototyped by Jarod Jenson of Aeysis and developed by Kelly O’Hair of Sun (with some helpful guidance from Adam on Team DTrace). The agent exports DTrace probes that correspond to well-known Java phenomena (“method-entry”, “gc-start”, “vm-init”, etc), and while it isn’t a perfect solution from a DTrace perspective (the requirement that one restart the JVM means it’s still more appropriate for developers than for dynamic production use, for example), damn is it a big leap forward. For an example of its power, check out Adam’s blog entry following code flow from Java through native code and into the kernel (and back). Such a view of code flow is without precedent – it is awesome (in all senses of that word) to see the progression through the stack of software abstraction.
Wanting to get in on the fun, I’ve been playing around with it myself. To get a sample program, I downloaded Per Cerderberg’s Java implementation of Tetris. To get to run with the agent, I run it this way:
# export LD_LIBRARY_PATH=/path/to/djvm/build/i386/lib
# java -Xrundjvmti:all -cp $LD_LIBRARY_PATH -jar tetris-1.2-bin.jar
The “-Xrundjvmti” pulls in the JVMTI agent, and the “:all” following it denotes that I want to get DTrace probes for all possible events. (It defaults to less than all events to minimize probe effect.) Running with this agent creates a new provider in the JVM process called djvm. Listing its probes:
# dtrace -l -P 'djvm*'
ID PROVIDER MODULE FUNCTION NAME
4 djvm793 libdjvmti.so gc_finish_worker gc-stats
5 djvm793 libdjvmti.so cbGarbageCollectionFinish gc-finish
6 djvm793 libdjvmti.so cbThreadStart thread-start
7 djvm793 libdjvmti.so _method_exit method-return
8 djvm793 libdjvmti.so cbVMInit vm-init
9 djvm793 libdjvmti.so cbThreadEnd thread-end
10 djvm793 libdjvmti.so cbMonitorContendedEnter monitor-contended-enter
11 djvm793 libdjvmti.so cbMonitorWait monitor-wait
12 djvm793 libdjvmti.so _method_entry method-entry
13 djvm793 libdjvmti.so track_allocation object-alloc
14 djvm793 libdjvmti.so cbMonitorWaited monitor-waited
15 djvm793 libdjvmti.so cbMonitorContendedEntered monitor-contended-entered
16 djvm793 libdjvmti.so cbObjectFree object-free
17 djvm793 libdjvmti.so cbGarbageCollectionStart gc-start
18 djvm793 libdjvmti.so cbObjectFree class-unload
19 djvm793 libdjvmti.so cbVMDeath vm-death
20 djvm793 libdjvmti.so cbClassFileLoadHook class-load
#
I can enable these just like any DTrace probe. For example, if I want to see output whenever a method is entered, I could enable the method-entry probe. This probe has two arguments: the first is a pointer to the class name, and the second is a pointer to the method name. These are both in user-level, so you need to use copyinstr() to get at them. So, to see which methods that Tetris is calling, it’s as simple as:
# dtrace -n djvm793:::method-entry'{printf("called %s.%s\n", copyinstr(arg0), co pyinstr(arg1))}' -q
Just dragging my mouse into the window containing Tetris generates a flurry of output:
called sun/awt/AWTAutoShutdown.notifyToolkitThreadBusy
called sun/awt/AWTAutoShutdown.getInstance
called sun/awt/AWTAutoShutdown.setToolkitBusy
called sun/awt/AWTAutoShutdown.isReadyToShutdown
called java/util/Hashtable.isEmpty
called java/awt/event/MouseEvent.<init>
called java/awt/event/InputEvent.<init>
called sun/reflect/DelegatingMethodAccessorImpl.invoke
called sun/reflect/GeneratedMethodAccessor1.invoke
called java/lang/Boolean.booleanValue
called java/awt/EventQueue.wakeup
called sun/awt/motif/MWindowPeer.handleWindowFocusIn
called java/awt/event/WindowEvent.<init>
called java/awt/event/WindowEvent.<init>
called java/awt/event/ComponentEvent.<init>
called java/awt/AWTEvent.<init>
called java/util/EventObject.<init>
called java/awt/SequencedEvent.<init>
called java/util/EventObject.getSource
called java/awt/AWTEvent.<init>
called java/util/EventObject.<init>
called java/util/LinkedList.add
called java/util/LinkedList.addBefore
called java/util/LinkedList$Entry.<init>
...
This is way too much output to sift through, so let’s instead aggregate on class and method name:
#pragma D option quiet
djvm$1:::method-entry
{
@[strjoin(strjoin(basename(copyinstr(arg0)), "."),
copyinstr(arg1))] = count();
}
END
{
printa("%-70s %8@d\n", @);
}
Running this (providing our pid – 793 – as the argument), fooling around with Tetris for a second or two, and then ^C‘ing gave me this output:
String.equals 1
PlatformFont.makeConvertedMultiFontString 1
String.toCharArray 1
PlatformFont.makeConvertedMultiFontChars 1
CharToByteISO8859_1.getMaxBytesPerChar 1
CharToByteISO8859_1.reset 1
CharToByteConverter.setSubstitutionMode 1
SquareBoard.getBoardHeight 1
X11InputMethod.deactivate 1
ExecutableInputMethodManager.setInputContext 1
SquareBoard$SquareBoardComponent.redrawAll 1
SquareBoard.clear 1
Figure.getRotation 1
InputMethodManager.getInstance 1
Figure.rotateRandom 1
FontDescriptor.isExcluded 1
CharToByteISO8859_1.canConvert 1
PlatformFont$PlatformFontCache.<init> 1
InputContext.deactivateInputMethod 1
...
SquareBoard.access$100 807
AWTEvent.getID 883
Figure.getRelativeY 959
X11Renderer.drawLine 1168
SunGraphics2D.drawLine 1168
Rectangle.intersects 1246
SquareBoard$SquareBoardComponent.paintSquare 1246
SunGraphics2D.getClipBounds 1284
X11Renderer.validate 1352
SurfaceData.getNativeOps 1352
Rectangle.translate 1361
Figure.getRelativeX 1383
Rectangle2D.<init> 1516
RectangularShape.<init> 1516
SurfaceData.isValid 1620
SunGraphics2D.getCompClip 1620
Rectangle.<init> 2839
SquareBoard.access$000 8019
SquareBoard.access$200 8496
That’s a lot of calls to the Rectangle constructor, so a natural question might be “where are calling this constructor?” For this, we can use the djvm provider along with the jstack() action:
djvm$1:::method-entry
/basename(copyinstr(arg0)) == "Rectangle" && copyinstr(arg1) == "<init>"/
{
@[jstack()] = count();
}
Running the above generated a bunch of output, with stack traces sorted in order of popularity; here was the most popular stacktrace:
libdjvmti.so`_method_entry+0x5c
com/sun/tools/dtrace/internal/Tracker._method_entry*
java/awt/Rectangle.<init>*
sun/java2d/SunGraphics2D.getClipBounds*
net/percederberg/tetris/SquareBoard$SquareBoardComponent.paintSquare*
net/percederberg/tetris/SquareBoard$SquareBoardComponent.paintComponent*
net/percederberg/tetris/SquareBoard$SquareBoardComponent.paint
net/percederberg/tetris/SquareBoard$SquareBoardComponent.redraw
net/percederberg/tetris/SquareBoard.update
net/percederberg/tetris/Figure.moveDown
0xf9002a7b
0xf9002a7b
0xf9002a7b
...
Note those Java frames: we can see exactly why we’re creating a new Rectangle. We might have all sorts of questions from the above output. The one that occurred to me was “just how much work do we do from that paint method?” Answering this question is a snap in DTrace using bread-and-butter like thread-locals and aggregations:
#pragma D option quiet
self int follow;
int ttl;
djvm$1:::method-entry
/self->follow/
{
@[basename(copyinstr(arg0)), copyinstr(arg1)] = count();
}
djvm$1:::method-entry,
djvm$1:::method-return
/basename(copyinstr(arg0)) == "SquareBoard$SquareBoardComponent" &&
copyinstr(arg1) == "paint"/
{
ttl += self->follow;
self->follow ^= 1;
}
END
{
normalize(@, ttl);
printa("%35s %35s %8@d\n", @);
}
Running the above for a bit and ^C‘ing generated ~200 lines of output; here are the last 30:
CompositeGlyphMapper getCachedGlyphCode 4
SquareBoard$SquareBoardComponent getDarkerColor 14
SquareBoard$SquareBoardComponent getLighterColor 14
X11Renderer fillRect 15
SunGraphics2D fillRect 15
SquareBoard access$100 19
Color hashCode 28
Color equals 28
Hashtable get 29
Color getRGB 44
SunGraphics2D setColor 44
PixelConverter$Xrgb rgbToPixel 45
SurfaceType pixelFor 45
SurfaceData pixelFor 45
SquareBoard$SquareBoardComponent paintSquare 65
Rectangle intersects 65
SunGraphics2D getClipBounds 66
Rectangle translate 67
RectangularShape <init> 69
Rectangle2D <init> 69
X11Renderer drawLine 115
SunGraphics2D drawLine 115
SurfaceData getNativeOps 130
X11Renderer validate 130
SunGraphics2D getCompClip 134
SurfaceData isValid 134
Rectangle <init> 137
SquareBoard access$000 191
SquareBoard access$200 238
This means that (on average) each call to SquareBoard$SquareBoardComponent’s paint method induced 137 creations of Rectangle. Seeing this, I thought it would be cool to write a little “stat” utility that let me know how many of each kind of object was being constructed on a real-time, per-second basis. Here’s that script:
#pragma D option quiet
djvm$1:::method-entry
/copyinstr(arg1) == "<init>"/
{
@[basename(copyinstr(arg0))] = count();
}
profile:::tick-1sec
{
trunc(@, 20);
printf("%-70s %8s\n", "CLASS", "COUNT");
printa("%-70s %8@d\n", @);
printf("\n");
clear(@);
}
Running the above gives output once per-second. Initially, it didn’t provide any output – but as soon as I moused into the Tetris window, I saw a (small) explosion of mouse-related object construction:
CLASS COUNT
Region 0
RectangularShape 0
Rectangle2D 0
Rectangle 0
LinkedList$ListItr 0
SentEvent 0
LinkedList$Entry 0
WindowEvent 0
InvocationEvent 15
HashMap$Entry 69
ComponentEvent 74
InputEvent 74
MouseEvent 74
WeakReference 78
AWTEvent 79
EventObject 79
Point2D 128
Reference 156
EventQueueItem 158
Point 192
As soon as I move the mouse out of the window, the rates dropped back to zero (as you would hope and expect from a well-behaved app). When I started actually playing Tetris, I saw a different kind of ouput:
CLASS COUNT
Dimension 7
HashMap$Entry 8
EventObject 8
AWTEvent 8
ComponentEvent 8
InputEvent 8
Finalizer 14
AffineTransform 14
Graphics 14
SunGraphics2D 14
Graphics2D 14
FinalReference 14
EventQueueItem 16
KeyEvent 16
WeakReference 24
Region 42
Reference 62
Rectangle2D 105
RectangularShape 105
Rectangle 175
This means that we’re seeing 175 Rectangle creations a second when I’m playing Tetris as fast as my BattleTris-hardened fingers can play. That doesn’t seem so bad, but you can easily see how useful this is going to be on those pathological Java apps!
Needless to say, the ability to peer into a Java app with DTrace is a very exciting development. To catch the fever, download the JVMTI and JVMPI agents, head to your nearest Solaris 10 machine (or download Solaris 10 if there isn’t one), and have at it!