HttpRequestMethodNotSupportedException prevents timing in WebMvcMetricsFilter

[izeye]

This was originally reported in micrometer-metrics/micrometer#1011.

HttpRequestMethodNotSupportedException prevents timing in WebMvcMetricsFilter and a simple fix seems to be just ignoring HttpRequestMethodNotSupportedException in filterAndRecordMetrics() and using null handler but I'm opening an issue in case there's a better approach for it. If ignoring HttpRequestMethodNotSupportedException is a right approach, I can create a PR for it.

Here is a sample project to reproduce it: https://github.com/izeye/sample-micrometer-spring-boot/tree/micrometer-gh-1011-2.1.0

Reproduction steps as follows:

• Run the application.
• Open http://localhost:8080/login in a web browser.
• Submit anything.

[wilkinsona]

Thanks for the report, @izeye, but, ideally, I think this should be tackled in Spring MVC. The javadoc for HandlerMapping.getHandler(HttpServletRequest) currently says that it "returns null if no match was found. This is not an error". It also says that it will throw an exception "if there is an internal error". I would expect an unsupported HTTP request method to result in null being returned as it is not an internal error.

Can you please open a Spring Framework JIRA ticket for this and comment here with a link to it? I'll close this one for now. We can re-open it if necessary depending on the outcome of the Framework issue.

[izeye]

@wilkinsona Thanks for the quick feedback! I created https://jira.spring.io/browse/SPR-17518

[wilkinsona]

SPR-17518 has resulted in the addition of a new request attribute that makes the handler available. We need to rework WebMvcMetricsFilter to use it rather than HandlerMappingIntrospector.

[bclozel]

Great! This will avoid duplicate handler lookups and improve runtime performance when actuator is enabled.

[wilkinsona]

The new request attribute for the handler works nicely for standard request timings, but, unfortunately, does not work for long task timers.

There is only a single long task timer per registry for each unique combination of name and tags. The name comes from the value attribute of the @Timed annotation on the handler so the handler is needed to look up any existing timer. A long task timer keeps track of the number of active tasks so it has to be updated when the request is received which is before the handler is available as a request attribute. In short, Micrometer's current design means that it does not appear to be possible to support long task timers using the current Filter-based model without duplicating the handler lookups.

I wonder if we should move support for long task timers into a HandlerInterceptor. The timing would no longer include the time taken to reach the dispatcher servlet, look up the handler, and initiate the dispatch, but it would avoid the performance hit of the duplicate lookup. Arguably, it would also bring what's timed closer to what's annotated with @Timed which I find more intuitive.

What do you think, @bclozel and @jkschneider?

[bclozel]

I agree - while in general we should measure response times as broadly as possible, moving the @Timed support seems to solve two problems in one shot:

• solving the performance issue with mapping twice
• measuring @Timed more precisely and in line with developers' expectations.