CDI instrumentation

If we focus back on the Metrics library, we will find several CDI integrations. The global idea is to decorate the code with some annotation and automatically get the metrics associated with the executed code. Clearly, it will impact your code this way (using https://github.com/astefanutti/metrics-cdi for instance):

@Transactional
@ApplicationScoped
public class QuoteService {
    @PersistenceContext
    private EntityManager entityManager;

    @Timed(name = "create")
    public Quote create(final Quote newQuote) {
        entityManager.persist(newQuote);
        entityManager.flush();
        return newQuote;
    }
}

The @Timed annotation will automatically wrap the method execution in a Metrics timer and will therefore provide the statistics about the execution time of the method. The relevant code of the interceptor associated with the @Timed annotation is very close to this logic:

private Object onInvocation(InvocationContext context) throws Exception {
    Timer.Context time = findTimer(context).time();
    try {
        return context.proceed();
    } finally {
        time.stop();
    }
}

This is exactly what we want to achieve but it has one trap we didn't think about yet: the exception handling. To understand this point, we can compare the code used in the retired project (called Apache Sirona), which had the following differently implemented feature:

protected Object doInvoke(final InvocationContext context) throws Throwable {
    final Context ctx = before(context);
    Throwable error = null;
    try {
        return proceed(context);
    } catch (final Throwable t) {
        error = t;
        throw t;
    } finally {
        if (error == null) {
            ctx.stop();
        } else {
            ctx.stopWithException(error);
        }
    }
}

What is important to see here is that the code path changes in the case of an exception. In terms of statistics, this implies that failures will have a different marker from successful calls in the metrics report. This is important to notice because the execution time of a failure is rarely comparable to a success, even for simple methods. Let's take a simple finder example from our quote manager application and observe this. Here is the line we will investigate:

entityManager.find(Quote.class, id)

A normal call with a valid ID will be around 6 to 7 ms (on my reference machine, with my personal configuration). The EntityManager#find method can take any type for the identifier, so if we pass a wrong type (such as String instead of long ) then the call should compile and execute. Eclipselink will complain with an exception but the performance impact is something interesting: 0 ms! Indeed, this example is very extreme and is a bug, but if you have some rate limiting on an endpoint or some sanity checks at the beginning of the methods, the same impact can be observed.

This means that if the framework you are using is putting all the invocations (with errors or not) in the same bucket, you can have a very good performance but a very slow application, since the average of the success/failure makes the figures look good.