The Observation Deck

Close this search box.

Your Java fell into my DTrace!

April 18, 2005

So I’ve been following with excitement the
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
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
For an example of its power, check out
blog entry
following code flow from Java through
native code and into the kernel (and back). Such a view of code flow is
— 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
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                  gc_finish_worker gc-stats
5    djvm793         cbGarbageCollectionFinish gc-finish
6    djvm793                     cbThreadStart thread-start
7    djvm793                      _method_exit method-return
8    djvm793                          cbVMInit vm-init
9    djvm793                       cbThreadEnd thread-end
10    djvm793           cbMonitorContendedEnter monitor-contended-enter
11    djvm793                     cbMonitorWait monitor-wait
12    djvm793                     _method_entry method-entry
13    djvm793                  track_allocation object-alloc
14    djvm793                   cbMonitorWaited monitor-waited
15    djvm793         cbMonitorContendedEntered monitor-contended-entered
16    djvm793                      cbObjectFree object-free
17    djvm793          cbGarbageCollectionStart gc-start
18    djvm793                      cbObjectFree class-unload
19    djvm793                         cbVMDeath vm-death
20    djvm793               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
@[strjoin(strjoin(basename(copyinstr(arg0)), "."),
copyinstr(arg1))] = count();
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

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:

/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:`_method_entry+0x5c

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;
@[basename(copyinstr(arg0)), copyinstr(arg1)] = count();
/basename(copyinstr(arg0)) == "SquareBoard$SquareBoardComponent" &&
copyinstr(arg1) == "paint"/
ttl += self->follow;
self->follow ^= 1;
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
/copyinstr(arg1) == "<init>"/
@[basename(copyinstr(arg0))] = count();
trunc(@, 20);
printf("%-70s %8s\n", "CLASS", "COUNT");
printa("%-70s %8@d\n", @);

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
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:

6 Responses

  1. 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.

  2. [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….

Leave a Reply

Recent Posts

November 18, 2023
November 27, 2022
October 11, 2020
July 31, 2019
December 16, 2018
September 18, 2018
December 21, 2016
September 30, 2016
September 26, 2016
September 13, 2016
July 29, 2016
December 17, 2015
September 16, 2015
January 6, 2015
November 10, 2013
September 3, 2013
June 7, 2012
September 15, 2011
August 15, 2011
March 9, 2011
September 24, 2010
August 11, 2010
July 30, 2010
July 25, 2010
March 10, 2010
November 26, 2009
February 19, 2009
February 2, 2009
November 10, 2008
November 3, 2008
September 3, 2008
July 18, 2008
June 30, 2008
May 31, 2008
March 16, 2008
December 18, 2007
December 5, 2007
November 11, 2007
November 8, 2007
September 6, 2007
August 21, 2007
August 2, 2007
July 11, 2007
May 20, 2007
March 19, 2007
October 12, 2006
August 17, 2006
August 7, 2006
May 1, 2006
December 13, 2005
November 16, 2005
September 13, 2005
September 9, 2005
August 21, 2005
August 16, 2005