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:
nice post!!! i would like to get more information.
Quite helpful piece of writing, thank you for this article.
Post a Comment