The Observation Deck

Search
Close this search box.

Month: April 2005

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:

It has been a bit horrifying to watch the BitKeeper saga unfold. Not that it’s surprising of course that Larry rescinded the BK Linux license; if you know Larry or even know of him, you know that Larry’s tragic flaws — hypersensitivity, volatility and vindictiveness — made this an inevitability of sorts.1 So the horrifying bit has not been the act itself, but rather the specific reason that Larry cited when rescinding the license: he seems to have taken issue with Tridge’s attempt to reverse engineer the BitKeeper protocols. This rankles; I (like many engineers, I suspect) view reverse engineering as a Natural Right. That is, I believe that we are endowed with certain unalienable Rights, and that among these are Life, Liberty and the pursuit of Understanding how the hell something works (or doesn’t, as is frequently the case). Perhaps perversely to some, it is my strong belief in the right to reverse engineer that leads me to my equally strong belief in the responsibility of government to establish a system of patents: if you use my product, you have the right to take it apart and understand its inner workings, but I have the right to protect my intellectual property by patenting the novel mechanism that represents a non-obvious advance in the state of the art. That is, it should be the protection afforded by patents — and not the obfuscation inherent in a running system — that prevents the rip-off artists.2 My belief reflects the fact that nearly all applications of reverse engineering do not in any way violate anyone’s intellectual property — and the act itself and alone can never violate intellectual property.

I believe strongly in reverse engineering in particular, but it plays an especially critical role in the development of software: in my experience, when developing a layer in the stack of software abstraction, you always need to understand at least one layer below you and you often need to understand at least one layer above you — and reverse engineering is often the primary means to achieve this understanding. More generally, software is usually reverse engineered to work around oversights or blunders, or to simply understand a software system sufficiently well to interoperate with it. It is in part out of the recognition of the importance of reverse engineering in software development and integration that we developed DTrace — a tool which many regard as the ne plus ultra of software reverse engineering.

Returning to the case at hand, if BitMover believes that Tridge violated one of its patents, fine — BitMover should sue for infringement.3 But to rescind the free BK license simply because someone dared to even understand how it works is just…cowardly. In doing this, BitMover is exhibiting classic Bad ISV Behavior: they are devoting their efforts to preserving their natural monopoly (such as it is) over their own users — joining the fetid ranks of the ISVs that have demanded that we disable DTrace for their application. And it adds insult to injury for Torvalds to condemn Tridge for “ruining it for everyone.” Tridge “ruined it for everyone” just like Rosa Parks and Helen Gahagan Douglas and Nathan Hale and anyone else who ever took a stand for what was right. And I don’t mean this comparison to diminish the courage that it took these others to stand up to tyranny, but rather to underscore the degree that I believe that reverse engineering is a Natural Right. So I, for one, hope that Tridge continues to reverse engineer BitKeeper — and I would be honored if DTrace helped him do it.


1 I actually like Larry — he’s sharp, forthright, and engaged and he can be very sweet — but I do view him as ultimately tragic…

2 I also believe that patents have gotten way out of hand, and that the proliferation of bad software patents represents a serious problem — but that doesn’t change my feelings about patents in the abstract.

3 Of course, BitMover is unlikely to do this, for several reasons. First, it seems highly unlikely that Tridge has violated any BitMover patents if he has only reverse engineered the protocol. Second, even if he has somehow managed to violate a patent, there’s the little problem of damages to BitMover — or rather, the lack of such damages; if there aren’t damages, treble damages still amount to nothing. Third, even if there were enormous damages, who would pay them Suing Tridge is not likely to be terribly gratifying; I can’t imagine that his pockets are deep enough to even pay the substantial expense of just prosecuting patent infringement. And both Tridge and OSDL claim that the work was done in his spare time; if it wasn’t done using OSDL equipment, there isn’t much of a case to be made against OSDL. Finally, there is a more practical reason that BitMover is unlikely to sue for patent infringement: suing a well-known White Knight in the open source world for patent infringement would likely cause several megacorps with large patent portfolios to carefully review both their patents on SCM and the prior art in same. If BitMover is lucky, this would only result in a deluge of amicus briefs; if BitMover is unlucky, it would find itself buried in enough counter-litigation to destroy the company.

Recent Posts

November 26, 2023
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

Archives