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!


Technorati tags:

Posted on April 18, 2005 at 10:29 pm by bmc · Permalink
In: Solaris

6 Responses

Subscribe to comments via RSS

  1. Written by Robert Milkowski
    on April 19, 2005 at 1:41 am
    Permalink

    Wow! I think our developers will be happy, very happy! Thanks guys!

  2. Written by Dan Price
    on April 19, 2005 at 2:15 am
    Permalink

    So when is BattleTris (suitably enhanced with DTrace probes) going to be open source? :)

    Seriously, I wept to read this article. At a minimum, this is going to drastically change the game for the folks who have to deploy what the Java developers toss over the wall.

  3. Written by Jeff
    on April 19, 2005 at 7:13 am
    Permalink

    Awesome, I can’t wait to check some of this stuff out… Step one: Get a machine running Solaris10! *trys to figure out how*

  4. Written by Anonymous
    on April 26, 2005 at 9:22 am
    Permalink

    The only problem I see here is that BattleTris isn’t actually available for download.

  5. Written by The Alethiometer
    on June 28, 2005 at 9:29 am
    Permalink

    [Trackback] Good turn out last night at the OpenSolaris BoF at
    JavaOne . There was a ton of interest about
    DTrace supporting Java .
    Unfortunately, we only had 1 hour. They had to kick us out because the
    GlassFish BoF was in the same
    room following us….

Subscribe to comments via RSS