While developing software it is a good habit to keep an eye on performance of specific parts of code. There are obviously many ways to do it – we can for instance benchmark specific methods or modules as part of unit tests, we can use tools like JMeter to simulate larger number of users, we can run a profiler from time to time etc. Despite having all these advanced approaches in reach, sometimes the most convenient (or lazy) way to measure performance is to wrap code with something like this:
long t = System.currentTimeMillis();
doSomething();
System.out.println("took " + (System.currentTimeMillis() - t) + "ms");
There are definitely many cons to this approach – it’s not elegant, the results are scattered all over the log file, it can not be turned off and so on. If you happen to be using Spring Framework or Apache Commons, you might use one of their implementations of StopWatch class (here and here), which is a wrapper with some additional capabilities, like report formatting, providing of statistics etc.
Some time ago I was in a need to use a stop watch for a web application based on Spring. After spending some time with mentioned implementations it became obvious that what I needed was a slightly different mechanism – one that would allow me to see a hierarchical structure of time consumption of individual pieces of code. Something like:
run() : 2753 ms
foo() : 2753 ms
bar() : 417 ms
bang() : 60 ms
bang() : 119 ms
bang() : 238 ms
bar() : 2336 ms
bang() : 477 ms
bang() : 953 ms
bang() : 906 ms
(more…)