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).