Fabrizio Giudici is a Senior Java Architect with a long Java experience in the industrial field. He runs Tidalwave, his own consultancy company, and has contributed to Java success stories in a number of fields, including Formula One. Fabrizio often appears as a speaker at international Java conferences such as JavaOne and Devoxx and is member of JUG Milano and the NetBeans Dream Team. Fabrizio is a DZone MVB and is not an employee of DZone and has posted 67 posts at DZone. You can read more from them at their website. View Full User Profile

Stop Watches Anyone? (Or "About Continuous Profiling")

06.18.2008
| 9524 views |
  • submit to reddit

For these reasons I'm thinking of a very simple API. Here it is an example: I have a class which is responsible for importing a piece of metadata, represented by its class, from an image; and the following is the decorator which triggers the stop watches:

public class ImageBridgeStopWatchDecorator implements ImageBridge
{
private final ImageBridgeImpl delegate = new ImageBridgeImpl();

public <T> T readMetadataItem (final File file, final Class<T> itemClass)
throws IOException
{
final StopWatch stopWatch = StopWatch.create(delegate.getClass(), String.format("read/%s/%s", itemClass.getName(), extension(file)));

try
{
return delegate.readMetadataItem(file, itemClass);
}
finally
{
stopWatch.stop();
}
}
}

As you can see, a StopWatch is just created (and automatically started) and defined with a name, which is composed by the class it refers to and a hierarchical name, part of which is context dependant (the extension of the file name in this case). This is an example of the data that can be collected:

STATS: it/tidalwave/bluemarine/metadata/importer/MetadataImporter/process/ALL            [ 155 samples]: acc:     1.38/    0.01/    0.06/    0.01 msec, ela: 96549.59/  225.20/ 2781.93/  622.90 msec (val/min/max/avg)
STATS: it/tidalwave/bluemarine/metadata/importer/MetadataImporter/process/image/crw [ 8 samples]: acc: 3151.33/ 102.31/ 1134.09/ 393.92 msec, ela: 4396.07/ 225.18/ 1336.43/ 549.51 msec (val/min/max/avg)
STATS: it/tidalwave/bluemarine/metadata/importer/MetadataImporter/process/image/dng [ 10 samples]: acc: 6413.12/ 345.50/ 1541.62/ 641.31 msec, ela: 18840.89/ 996.86/ 2781.86/ 1884.09 msec (val/min/max/avg)
STATS: it/tidalwave/bluemarine/metadata/importer/MetadataImporter/process/image/jpeg [ 63 samples]: acc: 18608.76/ 104.39/ 583.07/ 295.38 msec, ela: 30141.81/ 309.16/ 915.03/ 478.44 msec (val/min/max/avg)
STATS: it/tidalwave/bluemarine/metadata/importer/MetadataImporter/process/image/mrw [ 10 samples]: acc: 3076.36/ 272.67/ 419.63/ 307.64 msec, ela: 4089.75/ 370.50/ 518.07/ 408.97 msec (val/min/max/avg)
STATS: it/tidalwave/bluemarine/metadata/importer/MetadataImporter/process/image/nef [ 59 samples]: acc: 26909.63/ 293.88/ 759.67/ 456.10 msec, ela: 37054.66/ 440.88/ 1118.92/ 628.05 msec (val/min/max/avg)
STATS: it/tidalwave/bluemarine/metadata/importer/MetadataImporter/process/image/srf [ 2 samples]: acc: 709.45/ 247.23/ 462.23/ 354.73 msec, ela: 1120.44/ 445.31/ 675.14/ 560.22 msec (val/min/max/avg)
STATS: it/tidalwave/bluemarine/metadata/importer/MetadataImporter/process/image/tiff [ 3 samples]: acc: 355.54/ 109.47/ 134.61/ 118.51 msec, ela: 902.77/ 258.22/ 333.88/ 300.92 msec (val/min/max/avg)

As you can see, the data has been segmented by the MIME type of the image, which is very important for me since different codecs are triggered and very different performance are shown (for instance, look at the awful figures about the DNG format). The StopWatch collects the number of invocations, the elapsed and accumulated times, as well as max/min and average. The precision is nanoseconds (by means of System.nanoTime()). At the moment the data are just collected in memory and dumped at the end of the test, but there's also a specific API to access them as JavaBeans, so I can put them in test assertions. If a function all of a sudden becomes slower, a test will fail (of course there are problems here, such as being sure that the CI server is not overloaded by other tasks, otherwise collected times will be artificially too long).

Enhancements could be to make the data available through JMX, so a JConsole could easily track them in real time, if needed. So far I've seen that the impact of StopWatches is very small in my tests, and in any case they could be disabled by configuration (in this case a dummy StopWatch class would be returned every time by the create() method).

What do you think? I'd like to hear from you about this, since continuous profiling is something new for me. In particular, I'd like to know whether there is an existing simple StopWatch API with the features described in the example above, before I go on and develop my own one. Also, any suggestion and best practice would be appreciated.

 

Published at DZone with permission of Fabrizio Giudici, author and DZone MVB.

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)

Comments

Geertjan Wielenga replied on Wed, 2008/06/18 - 8:24am

Great article. Thanks!

Fabrizio Giudici replied on Wed, 2008/06/18 - 8:39am

BTW, comments were broken for a few hours. I'm kindly asking people that tried to comment and failed to retry now. Thanks.

Tim Boudreau replied on Wed, 2008/06/18 - 9:05am

Have you looked at the Timers API in NetBeans? I think it still maybe in "friend" mode (i.e. only JARs that it knows about can call it, but you can get added to the list), since it's not in the officialjavadoc. If you're using a dev build, you can pull up aRun Time Watches window (not present in release builds).The team redoing the Java editor created this for doingexactly the kind of continuous profiling it sounds like you're talking about. I don't know for sure that it'sapplicable, but I think it might be - and should below-overhead.I don't know too much about it, but it sounds like itmight be what you're looking for - it's all about collecting timings for things that should remain fast at runtime.  

Not the same as a unit test for performance regression (hard to do on all platforms, particularly with imaging where you're dealing with platform and hardware specific stuff, but still a worth goal and doable in the abstract).

Our biggest effort in NetBeans 6.1 was not improving performance, but finding ways to make sure that someone cannot commit a change that regresses performance and not know it.  It's a hard problem.

Jan Lahoda in Prague is, AFAIK, the author of the Timers API and its UI.  I'll point him at this thread.

-Tim 

Vincent DABURON replied on Wed, 2008/06/18 - 3:54pm

Hello,

When i see your statistique : msec (val/min/max/avg), i remeber the "Java Application Monitor" API or JAMON V1.0

http://jamonapi.sourceforge.net/

 

Please Fabrisio, have a look to the JAMON API before create a new API.

If there is something missing, may be Steve Souza the principal support of JAMOM could add your feature?

 

If you want to add a junit timed performance, you can use the JunitPerf API.

http://clarkware.com/software/JUnitPerf.html

Like this :

For example, to create a timed test that waits for the completion of the ExampleTestCase.testOneSecondResponse() method and then fails if the elapsed time exceeded 1 second, use:

long maxElapsedTime = 1000;
Test testCase = new ExampleTestCase("testOneSecondResponse");
Test timedTest = new TimedTest(testCase, maxElapsedTime);

 

Vincent D.

 

 

William Louth replied on Sun, 2008/07/20 - 7:31am

Jamon is incredibly slow but that is relatively to what you are doing and what you expect. 

StopWatches are so 80's.  

Is all about resource metering and billing a concept very applicable to our present and future - cloud computing.

There is already an API that slows this problem: JXInsight Probes Open API 

Matt Coleman replied on Thu, 2012/04/26 - 12:49am

i appreciate the information you are sharing here guys,.we at graphic artist buffalo are constatly lookin out for new platforms

Mateo Gomez replied on Fri, 2012/04/27 - 2:07am in response to: William Louth

it slow at it is..too bad mexican dessert

Mateo Gomez replied on Fri, 2012/04/27 - 2:08am

mexican dessert appreciates netbean platforms very much

Matt Coleman replied on Tue, 2012/06/19 - 2:03am

i love stopwatches especially the ones we had in the 80's and 90's..brings back childhood memories..this is great by the way

graphic designer buffalo

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.