Stop Watches Anyone? (Or "About Continuous Profiling")
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)
final StopWatch stopWatch = StopWatch.create(delegate.getClass(), String.format("read/%s/%s", itemClass.getName(), extension(file)));
return delegate.readMetadataItem(file, itemClass);
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.
(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)