If at any point in your coding life you had to measure some component performance, chances are that you came across Perf4J at some point. To quote from their own website:

Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()

There are of course other ways to measure timings of components execution, however, I found Perf4J to be rather neat as it plugs into Log4J, Apache Logging, JDK Logging and a whole bunch of others. It also has a bunch of tools you can use to analyze the output and generate some interesting stats analysis or even graphs. Basically, if you haven’t looked into it by now, do so! 😉

Anyways, apart from trying to promote this framework, there’s (at least) another point I’m trying to make, regarding usage: unfortunately, the standard example shown in Perf4J’s developer how-to is not ideal (booooo!). They basically suggest the following pattern to using this framework:

// Create the LoggingStopWatch to start timing. This constructor takes the tag
// name, which identifies the code block being timed. Note that usually you
// will want to instantiate one of the subclasses of LoggingStopWatch, such as
// a Log4JStopWatch or CommonsLogStopWatch depending on your preferred
// logging framework.
StopWatch stopWatch = new LoggingStopWatch("codeBlock1");
 
// Execute the code block - this is just a dummy call to pause execution for
// 0-1 second.
Thread.sleep((long)(Math.random() * 1000L));
 
// Stop the StopWatch and log it. LoggingStopWatches automatically log their
// timing statements when one of the stop() or lap() methods are called.
stopWatch.stop();

At first glance all is good — we create a stop watch which starts automatically and when we’re done processing we stop it. This will trigger a record to be written somewhere — be it console, or in a log file or the likes if you decide to use (as suggested) something like LoggingStopWatch, Log4JStopWatch etc. There is however, a subtle problem with this approach – and it’s not far from Schroedinger’s Cat problem: in order to measure the timing, we have to create an instance of StopWatch! This instance gets used, it produces the output (timing) and then it gets thrown in the deep hole of the garbage collection 🙁 Which means every time this method gets called, we increase the pressure on the GC! If this is a method that gets called thousands of times a second, you got a few thousands of instances of StopWatch waiting to be GC’d! And the next thing you know, your JVM freezes for a fraction of a second to recollect these, which in a high-throughput application is not acceptable, needless to point out!

You can of course start thinking of using a single instance of StopWatch (static final) — however, these instances are not thread safe for once, and secondly, how can you correlate a start() to a stop() when calls to each will come in random order due to the very nature of multi-threaded apps???

So in order to avoid that issue, you can use a mixed approach and throw in a ThreadLocal:

public class C {
 private static final ThreadLocal<StopWatch> WATCH = new ThreadLocal<StopWatch>() {
  @Override protected StopWatch initialValue() {
   return new Log4JStopWatch("abc");//let's assume we're going to use Log4J here
  }
 }
 
 //...
 
 void methodToMeasure() {
  WATCH.get().start();
  try {
 
   //...
 
  } finally {
   WATCH.get().stop()
  }
 }
}

Voila! Each thread now gets its own instance, so need to to worry about multi-threading inside the StopWatch and correlating each stop() correctly to a start() call. Also, no need to worry about object creation either — the number of StopWatch instances will be equals to the number of threads in your application using class C above — so even if you have 1,000 threads in your app, it’s better to have 1,000 instances of StopWatch rather than 1,000 instances of StopWatch created and destroyed every second!

Simple, right?