Find the execution time of a code block using DropWizard timers

Question

I went through this question DropWizard Metrics Meters vs Timers and understood the concept of timers. But is there a way that I can log the execution time of a code block, each time it is called? I do not want the mean rate and stuff of this timer as this method is not called that frequently but takes a considerable amount of time when called. So is there a way that I can print the execution time of each call? Also how can I get answers for the below questions

How can I investigate the reason for the spikes in the values?
How will I know when the Max time event occurred so that I can go through the logs and see the possible reasons?

Any help would be much appreciated.

score 0 · Answer 1 · edited May 14 '20 at 17:54

I don't know if there is a way to get the timer context object, but I have another idea. You said this method is called not so often. Why not use DynamicFeature and print the execution time of the container?

Below I will show you how this can be implemented. I'm not sure if this works, I just coded it without any test, so please try it and change it if needed. If the ExecutionTimeFilter needs a split in two seperate classes due to the implemented interfaces, then change it accordingly.

Step 1: Create Filter

@Provider
public class ExecutionTimeFilter implements ContainerRequestFilter, ContainerResponseFilter {
    public static final String EXECUTION_TIME_HEADER = "X-Execution-Time";

    @Override
    public void filter(ContainerRequestContext requestContext) throws IOException {
        requestContext.getHeaders().add(EXECUTION_TIME_HEADER, ZonedDateTime.now().toString());
    }

        @Override
    public void filter(ContainerRequestContext requestContext, ContainerResponseContext responseContext) throws IOException {
        ZonedDateTime executionStartHeader = ZonedDateTime.parse(requestContext.getHeaderString(EXECUTION_TIME_HEADER));
        Duration executionTime = Duration.between(executionStartHeader, ZonedDateTime.now());
        //you can also print some url informations or whatever you need; check out the informations from both mehtod params
        System.out.println("The execution time was:" + executionTime);
    }
}

Step 2: Create DynamicFeature

@Provider
public class ExecutionTimeFeature implements DynamicFeature {
    @Override
    public void configure(ResourceInfo resourceInfo, FeatureContext context) {
        if (resourceInfo.getResourceMethod().getAnnotation(ExecutionTime.class) != null) {
            context.register(ExecutionTimeFilter.class);
        }
    }
}

Step 3: Create Annotation

@Target({ ElementType.METHOD })
@Retention(RetentionPolicy.RUNTIME)
public @interface ExecutionTime {
}

Step 4: Annotate your resource

@GET
@ExecutionTime
public String getExcpensiveCalculation(@QueryParam("number") @DefaultValue("1") IntegerParam number) {
    return getCalculation(number);
}

Step 5: Register Feature

environment.jersey().register(ExecutionTimeFeature.class);

References:Dropwizard Dynamic Feature with Filters

I don't know why your answer was downvoted; but yours served a perfect template for me, when I did not want to use complex metering of Dropwizard. — Madhur Bhaiya, May 14 '20 at 17:53

Iurii Ant · Answer 2 · 2019-01-19T14:45:38.197

For reporting exact code block execution time, one can use Counter.

It can keep cumulative time value that can be transformed to spikes on a graph by taking the derivative. See Graphite's derivative(..) function as an example (take care, this is not 'true' derivative, just value difference).

This approach does not suit for frequent events though, not very scalable. In the case of high load, Timers fit better.

Simple java helper:

    timed(String metricName, Runnable body) {
        Counter counter = metricsRegistry.counter(metricName);
        long t = System.currentTimeMillis();
        try {
            body.run();
        finally {
            counter.inc(System.currentTimeMillis() - t);
        }
    }

Find the execution time of a code block using DropWizard timers

2 Answers2