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

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

Posted by Robert Milkowski on April 18, 2005 at 06:41 PM PDT #

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.

Posted by Dan Price on April 18, 2005 at 07:15 PM PDT #

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

Posted by Jeff on April 19, 2005 at 12:13 AM PDT #

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

Posted by guest on April 26, 2005 at 02:22 AM PDT #

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

Posted by The Alethiometer on June 28, 2005 at 02:29 AM PDT #

Post a Comment:
Comments are closed for this entry.
About

bmc

Search

Top Tags
Categories
Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today