From 4bc32e6358c2f49cb83eee858b4ec489d0d67c90 Mon Sep 17 00:00:00 2001 From: Andy Wilkinson Date: Fri, 23 Nov 2018 20:16:05 +0000 Subject: [PATCH] Use a HandlerInterceptor for timing long tasks Closes gh-15204 --- .../WebMvcMetricsAutoConfiguration.java | 37 +++- .../WebMvcMetricsAutoConfigurationTests.java | 18 ++ .../LongTaskTimingHandlerInterceptor.java | 156 ++++++++++++++ .../web/servlet/WebMvcMetricsFilter.java | 150 ++++---------- ...LongTaskTimingHandlerInterceptorTests.java | 192 ++++++++++++++++++ .../web/servlet/WebMvcMetricsFilterTests.java | 17 +- 6 files changed, 433 insertions(+), 137 deletions(-) create mode 100644 spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptor.java create mode 100644 spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptorTests.java diff --git a/spring-boot-project/spring-boot-actuator-autoconfigure/src/main/java/org/springframework/boot/actuate/autoconfigure/metrics/web/servlet/WebMvcMetricsAutoConfiguration.java b/spring-boot-project/spring-boot-actuator-autoconfigure/src/main/java/org/springframework/boot/actuate/autoconfigure/metrics/web/servlet/WebMvcMetricsAutoConfiguration.java index a64036b673d..2c6aef80025 100644 --- a/spring-boot-project/spring-boot-actuator-autoconfigure/src/main/java/org/springframework/boot/actuate/autoconfigure/metrics/web/servlet/WebMvcMetricsAutoConfiguration.java +++ b/spring-boot-project/spring-boot-actuator-autoconfigure/src/main/java/org/springframework/boot/actuate/autoconfigure/metrics/web/servlet/WebMvcMetricsAutoConfiguration.java @@ -27,6 +27,7 @@ import org.springframework.boot.actuate.autoconfigure.metrics.MetricsProperties. import org.springframework.boot.actuate.autoconfigure.metrics.OnlyOnceLoggingDenyMeterFilter; import org.springframework.boot.actuate.autoconfigure.metrics.export.simple.SimpleMetricsExportAutoConfiguration; import org.springframework.boot.actuate.metrics.web.servlet.DefaultWebMvcTagsProvider; +import org.springframework.boot.actuate.metrics.web.servlet.LongTaskTimingHandlerInterceptor; import org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter; import org.springframework.boot.actuate.metrics.web.servlet.WebMvcTagsProvider; import org.springframework.boot.autoconfigure.AutoConfigureAfter; @@ -41,8 +42,9 @@ import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Configuration; import org.springframework.core.Ordered; import org.springframework.core.annotation.Order; -import org.springframework.web.context.WebApplicationContext; import org.springframework.web.servlet.DispatcherServlet; +import org.springframework.web.servlet.config.annotation.InterceptorRegistry; +import org.springframework.web.servlet.config.annotation.WebMvcConfigurer; /** * {@link EnableAutoConfiguration Auto-configuration} for instrumentation of Spring Web @@ -75,11 +77,10 @@ public class WebMvcMetricsAutoConfiguration { @Bean public FilterRegistrationBean webMvcMetricsFilter( - MeterRegistry registry, WebMvcTagsProvider tagsProvider, - WebApplicationContext context) { + MeterRegistry registry, WebMvcTagsProvider tagsProvider) { Server serverProperties = this.properties.getWeb().getServer(); - WebMvcMetricsFilter filter = new WebMvcMetricsFilter(context, registry, - tagsProvider, serverProperties.getRequestsMetricName(), + WebMvcMetricsFilter filter = new WebMvcMetricsFilter(registry, tagsProvider, + serverProperties.getRequestsMetricName(), serverProperties.isAutoTimeRequests()); FilterRegistrationBean registration = new FilterRegistrationBean<>( filter); @@ -98,4 +99,30 @@ public class WebMvcMetricsAutoConfiguration { this.properties.getWeb().getServer().getMaxUriTags(), filter); } + @Bean + public MetricsWebMvcConfigurer metricsWebMvcConfigurer(MeterRegistry meterRegistry, + WebMvcTagsProvider tagsProvider) { + return new MetricsWebMvcConfigurer(meterRegistry, tagsProvider); + } + + static class MetricsWebMvcConfigurer implements WebMvcConfigurer { + + private final MeterRegistry meterRegistry; + + private final WebMvcTagsProvider tagsProvider; + + MetricsWebMvcConfigurer(MeterRegistry meterRegistry, + WebMvcTagsProvider tagsProvider) { + this.meterRegistry = meterRegistry; + this.tagsProvider = tagsProvider; + } + + @Override + public void addInterceptors(InterceptorRegistry registry) { + registry.addInterceptor(new LongTaskTimingHandlerInterceptor( + this.meterRegistry, this.tagsProvider)); + } + + } + } diff --git a/spring-boot-project/spring-boot-actuator-autoconfigure/src/test/java/org/springframework/boot/actuate/autoconfigure/metrics/web/servlet/WebMvcMetricsAutoConfigurationTests.java b/spring-boot-project/spring-boot-actuator-autoconfigure/src/test/java/org/springframework/boot/actuate/autoconfigure/metrics/web/servlet/WebMvcMetricsAutoConfigurationTests.java index 354f6671cda..fd5d11d9e03 100644 --- a/spring-boot-project/spring-boot-actuator-autoconfigure/src/test/java/org/springframework/boot/actuate/autoconfigure/metrics/web/servlet/WebMvcMetricsAutoConfigurationTests.java +++ b/spring-boot-project/spring-boot-actuator-autoconfigure/src/test/java/org/springframework/boot/actuate/autoconfigure/metrics/web/servlet/WebMvcMetricsAutoConfigurationTests.java @@ -33,6 +33,7 @@ import org.junit.Test; import org.springframework.boot.actuate.autoconfigure.metrics.MetricsAutoConfiguration; import org.springframework.boot.actuate.autoconfigure.metrics.web.TestController; import org.springframework.boot.actuate.metrics.web.servlet.DefaultWebMvcTagsProvider; +import org.springframework.boot.actuate.metrics.web.servlet.LongTaskTimingHandlerInterceptor; import org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter; import org.springframework.boot.actuate.metrics.web.servlet.WebMvcTagsProvider; import org.springframework.boot.autoconfigure.AutoConfigurations; @@ -47,6 +48,7 @@ import org.springframework.core.Ordered; import org.springframework.test.web.servlet.MockMvc; import org.springframework.test.web.servlet.request.MockMvcRequestBuilders; import org.springframework.test.web.servlet.setup.MockMvcBuilders; +import org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping; import static org.assertj.core.api.Assertions.assertThat; import static org.springframework.test.web.servlet.result.MockMvcResultMatchers.status; @@ -140,6 +142,22 @@ public class WebMvcMetricsAutoConfigurationTests { }); } + @Test + @SuppressWarnings("rawtypes") + public void longTaskTimingInterceptorIsRegistered() { + this.contextRunner + .withUserConfiguration(TestController.class, + MeterRegistryConfiguration.class) + .withConfiguration(AutoConfigurations.of(MetricsAutoConfiguration.class, + WebMvcAutoConfiguration.class)) + .run((context) -> { + assertThat(context.getBean(RequestMappingHandlerMapping.class)) + .extracting("interceptors").element(0).asList() + .extracting((item) -> (Class) item.getClass()) + .contains(LongTaskTimingHandlerInterceptor.class); + }); + } + private MeterRegistry getInitializedMeterRegistry( AssertableWebApplicationContext context) throws Exception { assertThat(context).hasSingleBean(FilterRegistrationBean.class); diff --git a/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptor.java b/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptor.java new file mode 100644 index 00000000000..357b5588e98 --- /dev/null +++ b/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptor.java @@ -0,0 +1,156 @@ +/* + * Copyright 2012-2018 the original author or authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.springframework.boot.actuate.metrics.web.servlet; + +import java.lang.reflect.AnnotatedElement; +import java.util.ArrayList; +import java.util.Collection; +import java.util.Collections; +import java.util.List; +import java.util.Set; + +import javax.servlet.http.HttpServletRequest; +import javax.servlet.http.HttpServletResponse; + +import io.micrometer.core.annotation.Timed; +import io.micrometer.core.instrument.LongTaskTimer; +import io.micrometer.core.instrument.MeterRegistry; +import io.micrometer.core.instrument.Tag; + +import org.springframework.core.annotation.AnnotationUtils; +import org.springframework.web.method.HandlerMethod; +import org.springframework.web.servlet.HandlerInterceptor; + +/** + * A {@link HandlerInterceptor} that supports Micrometer's long task timers configured on + * a handler using {@link Timed} with {@link Timed#longTask()} set to {@code true}. + * + * @author Andy Wilkinson + * @since 2.0.7 + */ +public class LongTaskTimingHandlerInterceptor implements HandlerInterceptor { + + private final MeterRegistry registry; + + private final WebMvcTagsProvider tagsProvider; + + /** + * Creates a new {@ode LongTaskTimingHandlerInterceptor} that will create + * {@link LongTaskTimer LongTaskTimers} using the given registry. Timers will be + * tagged using the given {@code tagsProvider}. + * @param registry the registry + * @param tagsProvider the tags provider + */ + public LongTaskTimingHandlerInterceptor(MeterRegistry registry, + WebMvcTagsProvider tagsProvider) { + this.registry = registry; + this.tagsProvider = tagsProvider; + } + + @Override + public boolean preHandle(HttpServletRequest request, HttpServletResponse response, + Object handler) throws Exception { + LongTaskTimingContext timingContext = LongTaskTimingContext.get(request); + if (timingContext == null) { + startAndAttachTimingContext(request, handler); + } + return true; + } + + @Override + public void afterCompletion(HttpServletRequest request, HttpServletResponse response, + Object handler, Exception ex) throws Exception { + if (!request.isAsyncStarted()) { + stopLongTaskTimers(LongTaskTimingContext.get(request)); + } + } + + private void startAndAttachTimingContext(HttpServletRequest request, Object handler) { + Set annotations = getTimedAnnotations(handler); + Collection longTaskTimerSamples = getLongTaskTimerSamples( + request, handler, annotations); + LongTaskTimingContext timingContext = new LongTaskTimingContext( + longTaskTimerSamples); + timingContext.attachTo(request); + } + + private Collection getLongTaskTimerSamples( + HttpServletRequest request, Object handler, Set annotations) { + List samples = new ArrayList<>(); + annotations.stream().filter(Timed::longTask).forEach((annotation) -> { + Iterable tags = this.tagsProvider.getLongRequestTags(request, handler); + LongTaskTimer.Builder builder = LongTaskTimer.builder(annotation).tags(tags); + LongTaskTimer timer = builder.register(this.registry); + samples.add(timer.start()); + }); + return samples; + } + + private Set getTimedAnnotations(Object handler) { + if (!(handler instanceof HandlerMethod)) { + return Collections.emptySet(); + } + return getTimedAnnotations((HandlerMethod) handler); + } + + private Set getTimedAnnotations(HandlerMethod handler) { + Set timed = findTimedAnnotations(handler.getMethod()); + if (timed.isEmpty()) { + return findTimedAnnotations(handler.getBeanType()); + } + return timed; + } + + private Set findTimedAnnotations(AnnotatedElement element) { + return AnnotationUtils.getDeclaredRepeatableAnnotations(element, Timed.class); + } + + private void stopLongTaskTimers(LongTaskTimingContext timingContext) { + for (LongTaskTimer.Sample sample : timingContext.getLongTaskTimerSamples()) { + sample.stop(); + } + } + + /** + * Context object attached to a request to retain information across the multiple + * interceptor calls that happen with async requests. + */ + static class LongTaskTimingContext { + + private static final String ATTRIBUTE = LongTaskTimingContext.class.getName(); + + private final Collection longTaskTimerSamples; + + LongTaskTimingContext(Collection longTaskTimerSamples) { + this.longTaskTimerSamples = longTaskTimerSamples; + } + + Collection getLongTaskTimerSamples() { + return this.longTaskTimerSamples; + } + + void attachTo(HttpServletRequest request) { + request.setAttribute(ATTRIBUTE, this); + } + + static LongTaskTimingContext get(HttpServletRequest request) { + return (LongTaskTimingContext) request.getAttribute(ATTRIBUTE); + } + + } + +} diff --git a/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilter.java b/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilter.java index 08cd9e83174..b99125c0ae5 100644 --- a/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilter.java +++ b/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilter.java @@ -18,28 +18,21 @@ package org.springframework.boot.actuate.metrics.web.servlet; import java.io.IOException; import java.lang.reflect.AnnotatedElement; -import java.util.ArrayList; -import java.util.Collection; import java.util.Collections; -import java.util.List; import java.util.Set; import java.util.function.Supplier; import javax.servlet.FilterChain; import javax.servlet.ServletException; import javax.servlet.http.HttpServletRequest; -import javax.servlet.http.HttpServletRequestWrapper; import javax.servlet.http.HttpServletResponse; import io.micrometer.core.annotation.Timed; -import io.micrometer.core.instrument.LongTaskTimer; import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.Tag; import io.micrometer.core.instrument.Timer; import io.micrometer.core.instrument.Timer.Builder; import io.micrometer.core.instrument.Timer.Sample; -import org.apache.commons.logging.Log; -import org.apache.commons.logging.LogFactory; import org.springframework.context.ApplicationContext; import org.springframework.core.annotation.AnnotationUtils; @@ -47,10 +40,7 @@ import org.springframework.http.HttpStatus; import org.springframework.web.filter.OncePerRequestFilter; import org.springframework.web.method.HandlerMethod; import org.springframework.web.servlet.DispatcherServlet; -import org.springframework.web.servlet.HandlerExecutionChain; import org.springframework.web.servlet.HandlerMapping; -import org.springframework.web.servlet.handler.HandlerMappingIntrospector; -import org.springframework.web.servlet.handler.MatchableHandlerMapping; import org.springframework.web.util.NestedServletException; /** @@ -63,10 +53,6 @@ import org.springframework.web.util.NestedServletException; */ public class WebMvcMetricsFilter extends OncePerRequestFilter { - private static final Log logger = LogFactory.getLog(WebMvcMetricsFilter.class); - - private final ApplicationContext context; - private final MeterRegistry registry; private final WebMvcTagsProvider tagsProvider; @@ -75,8 +61,6 @@ public class WebMvcMetricsFilter extends OncePerRequestFilter { private final boolean autoTimeRequests; - private volatile HandlerMappingIntrospector introspector; - /** * Create a new {@link WebMvcMetricsFilter} instance. * @param context the source application context @@ -84,11 +68,26 @@ public class WebMvcMetricsFilter extends OncePerRequestFilter { * @param tagsProvider the tags provider * @param metricName the metric name * @param autoTimeRequests if requests should be automatically timed + * @deprecated since 2.0.7 in favor of + * {@link #WebMvcMetricsFilter(MeterRegistry, WebMvcTagsProvider, String, boolean)} */ + @Deprecated public WebMvcMetricsFilter(ApplicationContext context, MeterRegistry registry, WebMvcTagsProvider tagsProvider, String metricName, boolean autoTimeRequests) { - this.context = context; + this(registry, tagsProvider, metricName, autoTimeRequests); + } + + /** + * Create a new {@link WebMvcMetricsFilter} instance. + * @param registry the meter registry + * @param tagsProvider the tags provider + * @param metricName the metric name + * @param autoTimeRequests if requests should be automatically timed + * @since 2.0.7 + */ + public WebMvcMetricsFilter(MeterRegistry registry, WebMvcTagsProvider tagsProvider, + String metricName, boolean autoTimeRequests) { this.registry = registry; this.tagsProvider = tagsProvider; this.metricName = metricName; @@ -110,45 +109,9 @@ public class WebMvcMetricsFilter extends OncePerRequestFilter { private void filterAndRecordMetrics(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws IOException, ServletException { - Object handler; - try { - handler = getHandler(request); - } - catch (Exception ex) { - logger.debug("Unable to time request", ex); - filterChain.doFilter(request, response); - return; - } - filterAndRecordMetrics(request, response, filterChain, handler); - } - - private Object getHandler(HttpServletRequest request) throws Exception { - HttpServletRequest wrapper = new UnmodifiableAttributesRequestWrapper(request); - for (HandlerMapping mapping : getMappingIntrospector().getHandlerMappings()) { - HandlerExecutionChain chain = mapping.getHandler(wrapper); - if (chain != null) { - if (mapping instanceof MatchableHandlerMapping) { - return chain.getHandler(); - } - return null; - } - } - return null; - } - - private HandlerMappingIntrospector getMappingIntrospector() { - if (this.introspector == null) { - this.introspector = this.context.getBean(HandlerMappingIntrospector.class); - } - return this.introspector; - } - - private void filterAndRecordMetrics(HttpServletRequest request, - HttpServletResponse response, FilterChain filterChain, Object handler) - throws IOException, ServletException { TimingContext timingContext = TimingContext.get(request); if (timingContext == null) { - timingContext = startAndAttachTimingContext(request, handler); + timingContext = startAndAttachTimingContext(request); } try { filterChain.doFilter(request, response); @@ -159,24 +122,19 @@ public class WebMvcMetricsFilter extends OncePerRequestFilter { // TimingContext that was attached to the first) Throwable exception = (Throwable) request .getAttribute(DispatcherServlet.EXCEPTION_ATTRIBUTE); - record(timingContext, response, request, handler, exception); + record(timingContext, response, request, exception); } } catch (NestedServletException ex) { response.setStatus(HttpStatus.INTERNAL_SERVER_ERROR.value()); - record(timingContext, response, request, handler, ex.getCause()); + record(timingContext, response, request, ex.getCause()); throw ex; } } - private TimingContext startAndAttachTimingContext(HttpServletRequest request, - Object handler) { - Set annotations = getTimedAnnotations(handler); + private TimingContext startAndAttachTimingContext(HttpServletRequest request) { Timer.Sample timerSample = Timer.start(this.registry); - Collection longTaskTimerSamples = getLongTaskTimerSamples( - request, handler, annotations); - TimingContext timingContext = new TimingContext(annotations, timerSample, - longTaskTimerSamples); + TimingContext timingContext = new TimingContext(timerSample); timingContext.attachTo(request); return timingContext; } @@ -200,31 +158,23 @@ public class WebMvcMetricsFilter extends OncePerRequestFilter { return AnnotationUtils.getDeclaredRepeatableAnnotations(element, Timed.class); } - private Collection getLongTaskTimerSamples( - HttpServletRequest request, Object handler, Set annotations) { - List samples = new ArrayList<>(); - annotations.stream().filter(Timed::longTask).forEach((annotation) -> { - Iterable tags = this.tagsProvider.getLongRequestTags(request, handler); - LongTaskTimer.Builder builder = LongTaskTimer.builder(annotation).tags(tags); - LongTaskTimer timer = builder.register(this.registry); - samples.add(timer.start()); - }); - return samples; - } - private void record(TimingContext timingContext, HttpServletResponse response, - HttpServletRequest request, Object handlerObject, Throwable exception) { + HttpServletRequest request, Throwable exception) { + Object handlerObject = request + .getAttribute(HandlerMapping.BEST_MATCHING_HANDLER_ATTRIBUTE); + Set annotations = getTimedAnnotations(handlerObject); Timer.Sample timerSample = timingContext.getTimerSample(); Supplier> tags = () -> this.tagsProvider.getTags(request, response, handlerObject, exception); - for (Timed annotation : timingContext.getAnnotations()) { - stop(timerSample, tags, Timer.builder(annotation, this.metricName)); - } - if (timingContext.getAnnotations().isEmpty() && this.autoTimeRequests) { - stop(timerSample, tags, Timer.builder(this.metricName)); + if (annotations.isEmpty()) { + if (this.autoTimeRequests) { + stop(timerSample, tags, Timer.builder(this.metricName)); + } } - for (LongTaskTimer.Sample sample : timingContext.getLongTaskTimerSamples()) { - sample.stop(); + else { + for (Timed annotation : annotations) { + stop(timerSample, tags, Timer.builder(annotation, this.metricName)); + } } } @@ -241,31 +191,16 @@ public class WebMvcMetricsFilter extends OncePerRequestFilter { private static final String ATTRIBUTE = TimingContext.class.getName(); - private final Set annotations; - private final Timer.Sample timerSample; - private final Collection longTaskTimerSamples; - - TimingContext(Set annotations, Sample timerSample, - Collection longTaskTimerSamples) { - this.annotations = annotations; + TimingContext(Sample timerSample) { this.timerSample = timerSample; - this.longTaskTimerSamples = longTaskTimerSamples; - } - - public Set getAnnotations() { - return this.annotations; } public Timer.Sample getTimerSample() { return this.timerSample; } - public Collection getLongTaskTimerSamples() { - return this.longTaskTimerSamples; - } - public void attachTo(HttpServletRequest request) { request.setAttribute(ATTRIBUTE, this); } @@ -276,21 +211,4 @@ public class WebMvcMetricsFilter extends OncePerRequestFilter { } - /** - * An {@link HttpServletRequestWrapper} that prevents modification of the request's - * attributes. - */ - private static final class UnmodifiableAttributesRequestWrapper - extends HttpServletRequestWrapper { - - private UnmodifiableAttributesRequestWrapper(HttpServletRequest request) { - super(request); - } - - @Override - public void setAttribute(String name, Object value) { - } - - } - } diff --git a/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptorTests.java b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptorTests.java new file mode 100644 index 00000000000..036e6f82e49 --- /dev/null +++ b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptorTests.java @@ -0,0 +1,192 @@ +/* + * Copyright 2012-2018 the original author or authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.springframework.boot.actuate.metrics.web.servlet; + +import java.util.concurrent.Callable; +import java.util.concurrent.CompletableFuture; +import java.util.concurrent.CyclicBarrier; +import java.util.concurrent.atomic.AtomicReference; + +import io.micrometer.core.annotation.Timed; +import io.micrometer.core.instrument.Clock; +import io.micrometer.core.instrument.MeterRegistry; +import io.micrometer.core.instrument.MockClock; +import io.micrometer.core.instrument.simple.SimpleConfig; +import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; + +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; +import org.springframework.context.annotation.Import; +import org.springframework.test.context.junit4.SpringRunner; +import org.springframework.test.context.web.WebAppConfiguration; +import org.springframework.test.web.servlet.MockMvc; +import org.springframework.test.web.servlet.MvcResult; +import org.springframework.test.web.servlet.setup.MockMvcBuilders; +import org.springframework.web.bind.annotation.GetMapping; +import org.springframework.web.bind.annotation.PathVariable; +import org.springframework.web.bind.annotation.RequestMapping; +import org.springframework.web.bind.annotation.RestController; +import org.springframework.web.context.WebApplicationContext; +import org.springframework.web.servlet.config.annotation.EnableWebMvc; +import org.springframework.web.servlet.config.annotation.InterceptorRegistry; +import org.springframework.web.servlet.config.annotation.WebMvcConfigurer; +import org.springframework.web.util.NestedServletException; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatExceptionOfType; +import static org.assertj.core.api.Assertions.fail; +import static org.springframework.test.web.servlet.request.MockMvcRequestBuilders.asyncDispatch; +import static org.springframework.test.web.servlet.request.MockMvcRequestBuilders.get; +import static org.springframework.test.web.servlet.result.MockMvcResultMatchers.request; +import static org.springframework.test.web.servlet.result.MockMvcResultMatchers.status; + +/** + * Tests for {@link LongTaskTimingHandlerInterceptor}. + * + * @author Andy Wilkinson + */ +@RunWith(SpringRunner.class) +@WebAppConfiguration +public class LongTaskTimingHandlerInterceptorTests { + + @Autowired + private SimpleMeterRegistry registry; + + @Autowired + private WebApplicationContext context; + + @Autowired + private CyclicBarrier callableBarrier; + + private MockMvc mvc; + + @Before + public void setUpMockMvc() { + this.mvc = MockMvcBuilders.webAppContextSetup(this.context).build(); + } + + @Test + public void asyncRequestThatThrowsUncheckedException() throws Exception { + MvcResult result = this.mvc.perform(get("/api/c1/completableFutureException")) + .andExpect(request().asyncStarted()).andReturn(); + assertThat(this.registry.get("my.long.request.exception").longTaskTimer() + .activeTasks()).isEqualTo(1); + assertThatExceptionOfType(NestedServletException.class) + .isThrownBy(() -> this.mvc.perform(asyncDispatch(result))) + .withRootCauseInstanceOf(RuntimeException.class); + assertThat(this.registry.get("my.long.request.exception").longTaskTimer() + .activeTasks()).isEqualTo(0); + } + + @Test + public void asyncCallableRequest() throws Exception { + AtomicReference result = new AtomicReference<>(); + Thread backgroundRequest = new Thread(() -> { + try { + result.set(this.mvc.perform(get("/api/c1/callable/10")) + .andExpect(request().asyncStarted()).andReturn()); + } + catch (Exception ex) { + fail("Failed to execute async request", ex); + } + }); + backgroundRequest.start(); + this.callableBarrier.await(); + assertThat(this.registry.get("my.long.request").tags("region", "test") + .longTaskTimer().activeTasks()).isEqualTo(1); + this.callableBarrier.await(); + backgroundRequest.join(); + this.mvc.perform(asyncDispatch(result.get())).andExpect(status().isOk()); + assertThat(this.registry.get("my.long.request").tags("region", "test") + .longTaskTimer().activeTasks()).isEqualTo(0); + } + + @Configuration + @EnableWebMvc + @Import(Controller1.class) + static class MetricsInterceptorConfiguration { + + @Bean + Clock micrometerClock() { + return new MockClock(); + } + + @Bean + SimpleMeterRegistry simple(Clock clock) { + return new SimpleMeterRegistry(SimpleConfig.DEFAULT, clock); + } + + @Bean + CyclicBarrier callableBarrier() { + return new CyclicBarrier(2); + } + + @Bean + WebMvcConfigurer handlerInterceptorConfigurer(MeterRegistry meterRegistry) { + return new WebMvcConfigurer() { + + @Override + public void addInterceptors(InterceptorRegistry registry) { + registry.addInterceptor(new LongTaskTimingHandlerInterceptor( + meterRegistry, new DefaultWebMvcTagsProvider())); + } + + }; + } + + } + + @RestController + @RequestMapping("/api/c1") + static class Controller1 { + + @Autowired + private CyclicBarrier callableBarrier; + + @Timed + @Timed(value = "my.long.request", extraTags = { "region", + "test" }, longTask = true) + @GetMapping("/callable/{id}") + public Callable asyncCallable(@PathVariable Long id) throws Exception { + this.callableBarrier.await(); + return () -> { + try { + this.callableBarrier.await(); + } + catch (InterruptedException ex) { + throw new RuntimeException(ex); + } + return id.toString(); + }; + } + + @Timed + @Timed(value = "my.long.request.exception", longTask = true) + @GetMapping("/completableFutureException") + CompletableFuture asyncCompletableFutureException() { + return CompletableFuture.supplyAsync(() -> { + throw new RuntimeException("boom"); + }); + } + + } + +} diff --git a/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilterTests.java b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilterTests.java index f86847881bb..7b53c255690 100644 --- a/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilterTests.java +++ b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilterTests.java @@ -219,39 +219,24 @@ public class WebMvcMetricsFilterTests { // once the mapping completes, we can gather information about status, etc. this.callableBarrier.await(); MockClock.clock(this.registry).add(Duration.ofSeconds(2)); - // while the mapping is running, it contributes to the activeTasks count - assertThat(this.registry.get("my.long.request").tags("region", "test") - .longTaskTimer().activeTasks()).isEqualTo(1); this.callableBarrier.await(); backgroundRequest.join(); this.mvc.perform(asyncDispatch(result.get())).andExpect(status().isOk()); assertThat(this.registry.get("http.server.requests").tags("status", "200") .tags("uri", "/api/c1/callable/{id}").timer().totalTime(TimeUnit.SECONDS)) .isEqualTo(2L); - // once the async dispatch is complete, it should no longer contribute to the - // activeTasks count - assertThat(this.registry.get("my.long.request").tags("region", "test") - .longTaskTimer().activeTasks()).isEqualTo(0); } @Test public void asyncRequestThatThrowsUncheckedException() throws Exception { MvcResult result = this.mvc.perform(get("/api/c1/completableFutureException")) .andExpect(request().asyncStarted()).andReturn(); - // once the async dispatch is complete, it should no longer contribute to the - // activeTasks count - assertThat(this.registry.get("my.long.request.exception").longTaskTimer() - .activeTasks()).isEqualTo(1); assertThatExceptionOfType(NestedServletException.class) .isThrownBy(() -> this.mvc.perform(asyncDispatch(result))) .withRootCauseInstanceOf(RuntimeException.class); assertThat(this.registry.get("http.server.requests") .tags("uri", "/api/c1/completableFutureException").timer().count()) .isEqualTo(1); - // once the async dispatch is complete, it should no longer contribute to the - // activeTasks count - assertThat(this.registry.get("my.long.request.exception").longTaskTimer() - .activeTasks()).isEqualTo(0); } @Test @@ -375,7 +360,7 @@ public class WebMvcMetricsFilterTests { @Bean WebMvcMetricsFilter webMetricsFilter(MeterRegistry registry, WebApplicationContext ctx) { - return new WebMvcMetricsFilter(ctx, registry, new DefaultWebMvcTagsProvider(), + return new WebMvcMetricsFilter(registry, new DefaultWebMvcTagsProvider(), "http.server.requests", true); }