Logging Performance Exceptions (Part 1)

You've probably wished you could find out why a certain block of code was occasionally slow in production. Wouldn't it be nice to turn on extra logging only when things were acting up? You can!

With a bit of logging in your code, you can get an output like this:

 [135ms] request share purchase
   [5ms] validate purchase request
   [40ms] check account balances
    [39ms] synchronous balance request
   [30ms] read uncommitted share availability check
   [55ms] queue request
     [30ms] persist message to queue
     [15ms] write audit log

The oddly named hatch-timer tool, will give you a breakdown by putting simple push and pop methods in your code. It's not as fancy as doing it with AOP, but it's trivial to add.

One cool feature is configuring Hatch to only log when your code takes over a certain duration. For example, to log if businessMethod takes 1 second or longer:

   public void businessMethod() {
     TimerStackUtil.enableAndPush("businessMethod");
     ...
     TimerStackUtil.setThreadLocalMetricsLogger(
        new ExceedsDurationMetricsLogger(BasicMetricsLogger.LOGGER,999));
     TimerStackUtil.pop("businessMethod");

Check out the getting started to try it yourself!