Wednesday, February 21, 2007

The Stopwatch Idiom

A favorite tool of mine is the "Stopwatch". It is a simple, all-purpose timer. The timer starts in the constructor and stops in the log() method.

For example:


public ObjectInfo exampleMethod() {
final String whoAmI = "exampleMethod ";

ObjectInfo result = null;

Stopwatch stopwatch = new Stopwatch();

result = someRemoteService.getInfo();

logger.info( stopwatch.log(whoAmI) ) ;

return result;
}

Output to log:

21-Feb-2007-21:30.05 exampleMethod completed in 0.234 seconds

This tool is easy to write, and can be used (a) temporarily, for pinpointing performance problems or (b) general logging, especially on client-server boundaries. If the whoAmI variable is used intelligently, then a simple grep of the log file can yield muchos infos. Clearly, one can learn how long a method took, but one can also gather stats on how many times a method was called. It is almost guaranteed that this tool will surprise you with new information.

Some thoughts:
  • Note that this trick works best when there is a single-point of return in the method. Much, much more to come on this one.
  • The keen reader will certainly ask: what about aspects?! To me the answer is, as usual, the KISS principle. There is certainly a time and place for the space-age gadgetry of aspects, but not here. To me it is just painful to take a simple idea like this and go overkill with something like aspects.
  • However, I do think that using something like Spring to set a "threshold" value on the Stopwatch is very useful. i.e. The stopwatch log() method would take the logging stream as a parameter, but not perform the log unless the time taken was greater than the given threshold (e.g. 1 second).

2 comments:

  1. nice post!!! i would like to get more information.

    ReplyDelete
  2. Quite helpful piece of writing, thank you for this article.

    ReplyDelete