From be99318ad27273a62667c38c5f14d80de3699e6b Mon Sep 17 00:00:00 2001 From: Jon Schneider Date: Thu, 18 May 2017 16:42:26 -0500 Subject: [PATCH] Add longTask to @Timed (fixes #8) --- .../metrics/instrument/LongTaskTimer.java | 3 +- .../metrics/instrument/annotation/Timed.java | 3 + .../instrument/annotation/TimedSet.java | 10 ++ .../instrument/internal/TimedUtils.java | 48 ++++++ .../scheduling/MetricsSchedulingAspect.java | 41 +++-- .../simple/SimpleMeterRegistry.java | 8 + .../web/DefaultWebMetricsTagProvider.java | 37 +++-- .../instrument/web/RouterFunctionMetrics.java | 2 +- .../instrument/web/WebMetricsTagProvider.java | 27 +++- .../web/WebfluxMetricsWebFilter.java | 4 +- .../web/WebmvcMetricsHandlerInterceptor.java | 93 +++++++---- .../MetricsSchedulingAspectTest.java | 34 +++- .../WebmvcMetricsHandlerInterceptorTest.java | 149 ++++++++++-------- 13 files changed, 329 insertions(+), 130 deletions(-) create mode 100644 src/main/java/org/springframework/metrics/instrument/annotation/TimedSet.java create mode 100644 src/main/java/org/springframework/metrics/instrument/internal/TimedUtils.java diff --git a/src/main/java/org/springframework/metrics/instrument/LongTaskTimer.java b/src/main/java/org/springframework/metrics/instrument/LongTaskTimer.java index 17fec6b3e6..702430d38e 100644 --- a/src/main/java/org/springframework/metrics/instrument/LongTaskTimer.java +++ b/src/main/java/org/springframework/metrics/instrument/LongTaskTimer.java @@ -15,7 +15,6 @@ */ package org.springframework.metrics.instrument; -import java.util.concurrent.Callable; import java.util.function.Consumer; public interface LongTaskTimer extends Meter { @@ -25,7 +24,7 @@ public interface LongTaskTimer extends Meter { * @param f Function to execute and measure the execution time. * @return The return value of `f`. */ - default T record(Callable f) throws Exception { + default T recordThrowable(ThrowableCallable f) throws Throwable { long id = start(); try { return f.call(); diff --git a/src/main/java/org/springframework/metrics/instrument/annotation/Timed.java b/src/main/java/org/springframework/metrics/instrument/annotation/Timed.java index 9df295ad9b..7a0ebfd953 100644 --- a/src/main/java/org/springframework/metrics/instrument/annotation/Timed.java +++ b/src/main/java/org/springframework/metrics/instrument/annotation/Timed.java @@ -19,9 +19,12 @@ @Target({ElementType.TYPE, ElementType.METHOD}) @Documented +@Repeatable(TimedSet.class) @Retention(RetentionPolicy.RUNTIME) public @interface Timed { String value() default ""; String[] extraTags() default {}; + + boolean longTask() default false; } diff --git a/src/main/java/org/springframework/metrics/instrument/annotation/TimedSet.java b/src/main/java/org/springframework/metrics/instrument/annotation/TimedSet.java new file mode 100644 index 0000000000..19ec042430 --- /dev/null +++ b/src/main/java/org/springframework/metrics/instrument/annotation/TimedSet.java @@ -0,0 +1,10 @@ +package org.springframework.metrics.instrument.annotation; + +import java.lang.annotation.*; + +@Target({ElementType.TYPE, ElementType.METHOD}) +@Documented +@Retention(RetentionPolicy.RUNTIME) +public @interface TimedSet { + Timed[] value(); +} diff --git a/src/main/java/org/springframework/metrics/instrument/internal/TimedUtils.java b/src/main/java/org/springframework/metrics/instrument/internal/TimedUtils.java new file mode 100644 index 0000000000..da76903bd0 --- /dev/null +++ b/src/main/java/org/springframework/metrics/instrument/internal/TimedUtils.java @@ -0,0 +1,48 @@ +package org.springframework.metrics.instrument.internal; + +import org.springframework.metrics.instrument.annotation.Timed; +import org.springframework.metrics.instrument.annotation.TimedSet; + +import java.lang.reflect.Method; +import java.util.Arrays; +import java.util.Collections; +import java.util.Set; +import java.util.function.Predicate; +import java.util.stream.Stream; + +import static java.util.Arrays.stream; +import static java.util.Collections.emptySet; +import static java.util.Collections.singleton; +import static java.util.Comparator.comparing; +import static java.util.stream.Collectors.toSet; +import static java.util.stream.Stream.empty; +import static java.util.stream.Stream.of; + +/** + * @author Jon Schneider + */ +public class TimedUtils { + public static Stream findTimed(Class clazz) { + Timed t = clazz.getAnnotation(Timed.class); + if(t != null) + return of(t); + + TimedSet ts = clazz.getAnnotation(TimedSet.class); + if(ts != null) + return stream(ts.value()).sorted(comparing(Timed::value)); + + return empty(); + } + + public static Stream findTimed(Method m) { + Timed t = m.getAnnotation(Timed.class); + if(t != null) + return of(t); + + TimedSet ts = m.getAnnotation(TimedSet.class); + if(ts != null) + return stream(ts.value()).sorted(comparing(Timed::value)); + + return empty(); + } +} diff --git a/src/main/java/org/springframework/metrics/instrument/scheduling/MetricsSchedulingAspect.java b/src/main/java/org/springframework/metrics/instrument/scheduling/MetricsSchedulingAspect.java index f1d04a6543..b2a1f2a65f 100644 --- a/src/main/java/org/springframework/metrics/instrument/scheduling/MetricsSchedulingAspect.java +++ b/src/main/java/org/springframework/metrics/instrument/scheduling/MetricsSchedulingAspect.java @@ -1,19 +1,26 @@ package org.springframework.metrics.instrument.scheduling; +import com.google.common.base.Functions; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.annotation.Around; import org.aspectj.lang.annotation.Aspect; import org.aspectj.lang.reflect.MethodSignature; +import org.springframework.metrics.instrument.LongTaskTimer; import org.springframework.metrics.instrument.MeterRegistry; +import org.springframework.metrics.instrument.Tags; +import org.springframework.metrics.instrument.Timer; import org.springframework.metrics.instrument.annotation.Timed; +import org.springframework.metrics.instrument.internal.TimedUtils; import java.lang.reflect.Method; +import java.util.Map; +import java.util.stream.Collectors; @Aspect public class MetricsSchedulingAspect { - protected final Log logger = LogFactory.getLog(MetricsSchedulingAspect.class); + private static final Log logger = LogFactory.getLog(MetricsSchedulingAspect.class); private final MeterRegistry registry; @@ -24,7 +31,6 @@ public MetricsSchedulingAspect(MeterRegistry registry) { @Around("execution (@org.springframework.scheduling.annotation.Scheduled * *.*(..))") public Object timeScheduledOperation(ProceedingJoinPoint pjp) throws Throwable { Method method = ((MethodSignature) pjp.getSignature()).getMethod(); - String signature = pjp.getSignature().toShortString(); if (method.getDeclaringClass().isInterface()) { @@ -37,18 +43,31 @@ public Object timeScheduledOperation(ProceedingJoinPoint pjp) throws Throwable { } } - Timed timed = method.getAnnotation(Timed.class); + Map timedAnnots = TimedUtils.findTimed(method) + .filter(t -> !t.value().isEmpty()) + .collect(Collectors.toMap(Timed::longTask, Functions.identity())); - if (timed == null) { - logger.debug("Skipping metrics timing on " + signature + ": no @Timed annotation is present on the method"); - return pjp.proceed(); - } + Timed shortTaskTimerAnnot = timedAnnots.get(false); + Timer shortTaskTimer = null; + if(shortTaskTimerAnnot != null) + shortTaskTimer = registry.timer(shortTaskTimerAnnot.value(), Tags.tagList(shortTaskTimerAnnot.extraTags())); + + Timed longTaskTimerAnnot = timedAnnots.get(true); + LongTaskTimer longTaskTimer = null; + if(longTaskTimerAnnot != null) + longTaskTimer = registry.longTaskTimer(longTaskTimerAnnot.value(), Tags.tagList(longTaskTimerAnnot.extraTags())); - if (timed.value().isEmpty()) { - logger.warn("Unable to perform metrics timing on " + signature + ": @Timed annotation must have a value used to name the metric"); - return pjp.proceed(); + if(shortTaskTimer != null && longTaskTimer != null) { + final Timer finalTimer = shortTaskTimer; + return longTaskTimer.recordThrowable(() -> finalTimer.recordThrowable(pjp::proceed)); + } + else if(shortTaskTimer != null) { + return shortTaskTimer.recordThrowable(pjp::proceed); + } + else if(longTaskTimer != null) { + return longTaskTimer.recordThrowable(pjp::proceed); } - return registry.timer(timed.value()).recordThrowable(pjp::proceed); + return pjp.proceed(); } } diff --git a/src/main/java/org/springframework/metrics/instrument/simple/SimpleMeterRegistry.java b/src/main/java/org/springframework/metrics/instrument/simple/SimpleMeterRegistry.java index fc2f137836..14f79ee7d0 100644 --- a/src/main/java/org/springframework/metrics/instrument/simple/SimpleMeterRegistry.java +++ b/src/main/java/org/springframework/metrics/instrument/simple/SimpleMeterRegistry.java @@ -94,4 +94,12 @@ private Meter storeId(MeterId id, Meter m) { idMap.put(m, id); return m; } + + /** + * Clear the registry of all registered meters and their values. + */ + public void clear() { + meterMap.clear(); + idMap.clear(); + } } diff --git a/src/main/java/org/springframework/metrics/instrument/web/DefaultWebMetricsTagProvider.java b/src/main/java/org/springframework/metrics/instrument/web/DefaultWebMetricsTagProvider.java index c8cfbfcfab..627804bf63 100644 --- a/src/main/java/org/springframework/metrics/instrument/web/DefaultWebMetricsTagProvider.java +++ b/src/main/java/org/springframework/metrics/instrument/web/DefaultWebMetricsTagProvider.java @@ -67,9 +67,28 @@ public Stream clientHttpRequestTags(HttpRequest request, Tag.of("clientName", host)); } + @Override + public Stream httpLongRequestTags(HttpServletRequest request, Object handler) { + Stream.Builder tags = Stream.builder(); + + tags.add(Tag.of("method", request.getMethod())); + + String uri = (String) request.getAttribute(HandlerMapping.BEST_MATCHING_PATTERN_ATTRIBUTE); + if (uri == null) { + uri = request.getPathInfo(); + } + if (!StringUtils.hasText(uri)) { + uri = "/"; + } + uri = sanitizeUrlTemplate(uri.substring(1)); + tags.add(Tag.of("uri", uri.isEmpty() ? "root" : uri)); + + return tags.build(); + } + @Override public Stream httpRequestTags(HttpServletRequest request, - HttpServletResponse response, Object handler, String caller) { + HttpServletResponse response, Object handler) { Stream.Builder tags = Stream.builder(); tags.add(Tag.of("method", request.getMethod())); @@ -90,15 +109,11 @@ public Stream httpRequestTags(HttpServletRequest request, tags.add(Tag.of("exception", exception.getClass().getSimpleName())); } - if (caller != null) { - tags.add(Tag.of("caller", caller)); - } - return tags.build(); } @Override - public Stream httpRequestTags(ServerWebExchange exchange, Throwable exception, String caller) { + public Stream httpRequestTags(ServerWebExchange exchange, Throwable exception) { Stream.Builder tags = Stream.builder(); ServerHttpRequest request = exchange.getRequest(); @@ -120,15 +135,11 @@ public Stream httpRequestTags(ServerWebExchange exchange, Throwable excepti tags.add(Tag.of("exception", exception.getClass().getSimpleName())); } - if (caller != null) { - tags.add(Tag.of("caller", caller)); - } - return tags.build(); } @Override - public Stream httpRequestTags(ServerRequest request, ServerResponse response, String uri, Throwable exception, String caller) { + public Stream httpRequestTags(ServerRequest request, ServerResponse response, String uri, Throwable exception) { Stream.Builder tags = Stream.builder(); tags.add(Tag.of("method", request.method().toString())); @@ -144,10 +155,6 @@ public Stream httpRequestTags(ServerRequest request, ServerResponse respons tags.add(Tag.of("exception", exception.getClass().getSimpleName())); } - if (caller != null) { - tags.add(Tag.of("caller", caller)); - } - return tags.build(); } diff --git a/src/main/java/org/springframework/metrics/instrument/web/RouterFunctionMetrics.java b/src/main/java/org/springframework/metrics/instrument/web/RouterFunctionMetrics.java index 224a066959..b26560ce0a 100644 --- a/src/main/java/org/springframework/metrics/instrument/web/RouterFunctionMetrics.java +++ b/src/main/java/org/springframework/metrics/instrument/web/RouterFunctionMetrics.java @@ -48,7 +48,7 @@ public HandlerFilterFunction timer(String name, return next .handle(request) .doOnSuccess(response -> { - Stream allTags = Stream.concat(tags, tagProvider.httpRequestTags(request, response, "", null, null)); + Stream allTags = Stream.concat(tags, tagProvider.httpRequestTags(request, response, "", null)); registry.timer(name, allTags).record(System.nanoTime() - start, TimeUnit.NANOSECONDS); }); }; diff --git a/src/main/java/org/springframework/metrics/instrument/web/WebMetricsTagProvider.java b/src/main/java/org/springframework/metrics/instrument/web/WebMetricsTagProvider.java index 51f42ff414..5dbe291e83 100644 --- a/src/main/java/org/springframework/metrics/instrument/web/WebMetricsTagProvider.java +++ b/src/main/java/org/springframework/metrics/instrument/web/WebMetricsTagProvider.java @@ -36,6 +36,8 @@ */ public interface WebMetricsTagProvider { /** + * Supplies default tags to timers monitoring RestTemplate requests. + * * @param request RestTemplate client HTTP request * @param response may be null in the event of a client error * @return a map of tags added to every client HTTP request metric @@ -46,7 +48,18 @@ default Stream clientHttpRequestTags(HttpRequest request, } /** - * Supplies default tags to the Web MVC server programming model + * Supplies default tags to long task timers monitoring the Web MVC server programming model. + * + * @param request HTTP request + * @param handler the request method that is responsible for handling the request + * @return a map of tags added to every Spring MVC HTTP request metric + */ + default Stream httpLongRequestTags(HttpServletRequest request, Object handler) { + return Stream.empty(); + } + + /** + * Supplies default tags to the Web MVC server programming model. * * @param request HTTP request * @param response HTTP response @@ -54,31 +67,29 @@ default Stream clientHttpRequestTags(HttpRequest request, * @return a map of tags added to every Spring MVC HTTP request metric */ default Stream httpRequestTags(HttpServletRequest request, - HttpServletResponse response, Object handler, String caller) { + HttpServletResponse response, Object handler) { return Stream.empty(); } /** - * Supplies default tags to the WebFlux annotation-based server programming model + * Supplies default tags to the WebFlux annotation-based server programming model. * @param exchange * @param exception - * @param caller * @return */ - default Stream httpRequestTags(ServerWebExchange exchange, Throwable exception, String caller) { + default Stream httpRequestTags(ServerWebExchange exchange, Throwable exception) { return Stream.empty(); } /** - * Supplies default tags to the WebFlux functional server programming model + * Supplies default tags to the WebFlux functional server programming model. * @param request * @param response * @param uri * @param exception - * @param caller * @return */ - default Stream httpRequestTags(ServerRequest request, ServerResponse response, String uri, Throwable exception, String caller) { + default Stream httpRequestTags(ServerRequest request, ServerResponse response, String uri, Throwable exception) { return Stream.empty(); } } diff --git a/src/main/java/org/springframework/metrics/instrument/web/WebfluxMetricsWebFilter.java b/src/main/java/org/springframework/metrics/instrument/web/WebfluxMetricsWebFilter.java index 1af8f1589a..662e26fba7 100644 --- a/src/main/java/org/springframework/metrics/instrument/web/WebfluxMetricsWebFilter.java +++ b/src/main/java/org/springframework/metrics/instrument/web/WebfluxMetricsWebFilter.java @@ -47,11 +47,11 @@ public Mono filter(ServerWebExchange exchange, WebFilterChain chain) { Mono filtered = chain.filter(exchange); return filtered .doOnSuccess(done -> - registry.timer(metricName, tagProvider.httpRequestTags(exchange, null, null)) + registry.timer(metricName, tagProvider.httpRequestTags(exchange, null)) .record(System.nanoTime() - start, TimeUnit.NANOSECONDS) ) .doOnError(t -> - registry.timer(metricName, tagProvider.httpRequestTags(exchange, t, null)) + registry.timer(metricName, tagProvider.httpRequestTags(exchange, t)) .record(System.nanoTime() - start, TimeUnit.NANOSECONDS) ); } diff --git a/src/main/java/org/springframework/metrics/instrument/web/WebmvcMetricsHandlerInterceptor.java b/src/main/java/org/springframework/metrics/instrument/web/WebmvcMetricsHandlerInterceptor.java index 2679d1bb36..0ebb384ec1 100644 --- a/src/main/java/org/springframework/metrics/instrument/web/WebmvcMetricsHandlerInterceptor.java +++ b/src/main/java/org/springframework/metrics/instrument/web/WebmvcMetricsHandlerInterceptor.java @@ -21,6 +21,7 @@ import org.springframework.metrics.instrument.Tag; import org.springframework.metrics.instrument.Timer; import org.springframework.metrics.instrument.annotation.Timed; +import org.springframework.metrics.instrument.internal.TimedUtils; import org.springframework.web.context.request.RequestContextHolder; import org.springframework.web.method.HandlerMethod; import org.springframework.web.servlet.handler.HandlerInterceptorAdapter; @@ -28,10 +29,16 @@ import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; import java.lang.reflect.Method; +import java.util.Collections; +import java.util.Map; +import java.util.Set; +import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.TimeUnit; +import java.util.stream.Collectors; import java.util.stream.IntStream; import java.util.stream.Stream; +import static java.util.stream.Collectors.toSet; import static org.springframework.web.context.request.RequestAttributes.SCOPE_REQUEST; /** @@ -48,6 +55,8 @@ public class WebmvcMetricsHandlerInterceptor extends HandlerInterceptorAdapter { private final WebMetricsTagProvider provider; private final String metricName; + private final Map longTaskTimerIds = new ConcurrentHashMap<>(); + public WebmvcMetricsHandlerInterceptor(MeterRegistry registry, WebMetricsTagProvider provider, String metricName) { @@ -59,6 +68,14 @@ public WebmvcMetricsHandlerInterceptor(MeterRegistry registry, @Override public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception { + longTaskTimed(handler).forEach(t -> { + if(t.value().isEmpty()) { + logger.warn("Unable to perform metrics timing on " + ((HandlerMethod) handler).getShortLogMessage() + ": @Timed annotation must have a value used to name the metric"); + return; + } + longTaskTimerIds.put(t, registry.longTaskTimer(t.value(), provider.httpLongRequestTags(request, handler)).start()); + }); + RequestContextHolder.getRequestAttributes().setAttribute(TIMING_REQUEST_ATTRIBUTE, System.nanoTime(), SCOPE_REQUEST); return super.preHandle(request, response, handler); @@ -82,40 +99,62 @@ private void recordMetric(HttpServletRequest request, HttpServletResponse respon Object handler, Long startTime) { long endTime = System.nanoTime(); - if (handler instanceof HandlerMethod) { - - Timed timed = ((HandlerMethod) handler).getMethod().getAnnotation(Timed.class); - if (timed == null) { - timed = ((HandlerMethod) handler).getBeanType().getAnnotation(Timed.class); + // complete any LongTaskTimer tasks running for this method + longTaskTimed(handler).forEach(t -> { + if(!t.value().isEmpty()) { + registry.longTaskTimer(t.value(), provider.httpLongRequestTags(request, handler)).stop(longTaskTimerIds.remove(t)); } + }); - if (timed != null) { - String name = metricName; - if (!timed.value().isEmpty()) { - name = timed.value(); - } + // record Timer values + timed(handler).forEach(t -> { + String name = metricName; + if (!t.value().isEmpty()) { + name = t.value(); + } - Stream tags = provider.httpRequestTags(request, response, handler, null); - String[] extraTags = timed.extraTags(); - if (extraTags.length > 0) { - if (extraTags.length % 2 != 0) { - if (logger.isErrorEnabled()) { - Method method = ((HandlerMethod) handler).getMethod(); - String target = method.getDeclaringClass().getName() + "." + method.getName(); - logger.error("@Timed extraTags array on method " + target + " size must be even, it is a set of key=value pairs"); - } - } else { - Stream extraTagsStream = IntStream.range(0, extraTags.length / 2) - .mapToObj(i -> Tag.of(extraTags[i], extraTags[i + 1])); - tags = Stream.concat(tags, extraTagsStream); + Stream tags = provider.httpRequestTags(request, response, handler); + String[] extraTags = t.extraTags(); + if (extraTags.length > 0) { + if (extraTags.length % 2 != 0) { + if (logger.isErrorEnabled()) { + Method method = ((HandlerMethod) handler).getMethod(); + String target = method.getDeclaringClass().getName() + "." + method.getName(); + logger.error("@Timed extraTags array on method " + target + " size must be even, it is a set of key=value pairs"); } + } else { + Stream extraTagsStream = IntStream.range(0, extraTags.length / 2) + .mapToObj(i -> Tag.of(extraTags[i], extraTags[i + 1])); + tags = Stream.concat(tags, extraTagsStream); } + } - Timer timer = registry.timer(name, tags); - if (timer != null) { - timer.record(endTime - startTime, TimeUnit.NANOSECONDS); - } + Timer timer = registry.timer(name, tags); + if (timer != null) { + timer.record(endTime - startTime, TimeUnit.NANOSECONDS); } + }); + } + + private Set longTaskTimed(Object m) { + if(!(m instanceof HandlerMethod)) + return Collections.emptySet(); + + Set timed = TimedUtils.findTimed(((HandlerMethod) m).getMethod()).filter(Timed::longTask).collect(toSet()); + if (timed.isEmpty()) { + return TimedUtils.findTimed(((HandlerMethod) m).getBeanType()).filter(Timed::longTask).collect(toSet()); + } + return timed; + } + + private Set timed(Object m) { + if(!(m instanceof HandlerMethod)) + return Collections.emptySet(); + + Set timed = TimedUtils.findTimed(((HandlerMethod) m).getMethod()).filter(t -> !t.longTask()).collect(toSet()); + if (timed.isEmpty()) { + return TimedUtils.findTimed(((HandlerMethod) m).getBeanType()).filter(t -> !t.longTask()).collect(toSet()); } + return timed; } } diff --git a/src/test/java/org/springframework/metrics/instrument/scheduling/MetricsSchedulingAspectTest.java b/src/test/java/org/springframework/metrics/instrument/scheduling/MetricsSchedulingAspectTest.java index 42c3a76dec..376dc8fdba 100644 --- a/src/test/java/org/springframework/metrics/instrument/scheduling/MetricsSchedulingAspectTest.java +++ b/src/test/java/org/springframework/metrics/instrument/scheduling/MetricsSchedulingAspectTest.java @@ -7,28 +7,44 @@ import org.springframework.boot.test.context.SpringBootTest; import org.springframework.context.annotation.Bean; import org.springframework.metrics.boot.EnableMetrics; +import org.springframework.metrics.instrument.LongTaskTimer; import org.springframework.metrics.instrument.MeterRegistry; import org.springframework.metrics.instrument.Timer; import org.springframework.metrics.instrument.annotation.Timed; import org.springframework.metrics.instrument.simple.SimpleMeterRegistry; +import org.springframework.scheduling.TaskScheduler; import org.springframework.scheduling.annotation.EnableScheduling; import org.springframework.scheduling.annotation.Scheduled; +import org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler; import org.springframework.test.context.junit.jupiter.SpringExtension; +import java.util.concurrent.CountDownLatch; + import static org.assertj.core.api.Assertions.assertThat; @ExtendWith(SpringExtension.class) @SpringBootTest class MetricsSchedulingAspectTest { + static CountDownLatch observeLongTaskLatch = new CountDownLatch(1); + @Autowired MeterRegistry registry; @Test void scheduledIsInstrumented() { assertThat(registry.findMeter(Timer.class, "beeper")) - .containsInstanceOf(Timer.class) .hasValueSatisfying(t -> assertThat(t.count()).isEqualTo(1)); + + assertThat(registry.findMeter(LongTaskTimer.class, "longBeep")) + .hasValueSatisfying(t -> assertThat(t.activeTasks()).isEqualTo(1)); + + // make sure longBeep continues running until we have a chance to observe it in the active state + observeLongTaskLatch.countDown(); + + // now the long beeper has contributed to the beep count as well + assertThat(registry.findMeter(Timer.class, "beeper")) + .hasValueSatisfying(t -> assertThat(t.count()).isEqualTo(2)); } @SpringBootApplication @@ -40,6 +56,22 @@ MeterRegistry registry() { return new SimpleMeterRegistry(); } + @Bean + TaskScheduler scheduler() { + ThreadPoolTaskScheduler scheduler = new ThreadPoolTaskScheduler(); + // this way, executing longBeep doesn't block the short tasks from running + scheduler.setPoolSize(5); + return scheduler; + } + + @Timed("beeper") + @Timed(value = "longBeep", longTask = true) + @Scheduled(fixedRate = 1000) + void longBeep() throws InterruptedException { + observeLongTaskLatch.await(); + System.out.println("beep"); + } + @Timed("beeper") @Scheduled(fixedRate = 1000) void beep1() { diff --git a/src/test/java/org/springframework/metrics/instrument/web/WebmvcMetricsHandlerInterceptorTest.java b/src/test/java/org/springframework/metrics/instrument/web/WebmvcMetricsHandlerInterceptorTest.java index a88f641a81..4c164df807 100644 --- a/src/test/java/org/springframework/metrics/instrument/web/WebmvcMetricsHandlerInterceptorTest.java +++ b/src/test/java/org/springframework/metrics/instrument/web/WebmvcMetricsHandlerInterceptorTest.java @@ -1,12 +1,12 @@ /** * Copyright 2017 Pivotal Software, Inc. - * + *

* 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 - * + *

+ * 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. @@ -15,37 +15,42 @@ */ package org.springframework.metrics.instrument.web; +import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.Disabled; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.ExtendWith; -import org.mockito.ArgumentCaptor; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.boot.autoconfigure.SpringBootApplication; import org.springframework.boot.test.autoconfigure.web.servlet.WebMvcTest; -import org.springframework.boot.test.mock.mockito.MockBean; +import org.springframework.context.annotation.Bean; import org.springframework.http.HttpStatus; import org.springframework.metrics.boot.EnableMetrics; +import org.springframework.metrics.instrument.LongTaskTimer; import org.springframework.metrics.instrument.MeterRegistry; -import org.springframework.metrics.instrument.Tag; +import org.springframework.metrics.instrument.Timer; import org.springframework.metrics.instrument.annotation.Timed; -import org.springframework.metrics.instrument.simple.SimpleTimer; +import org.springframework.metrics.instrument.simple.SimpleMeterRegistry; +import org.springframework.scheduling.annotation.Async; +import org.springframework.scheduling.annotation.EnableAsync; +import org.springframework.test.annotation.DirtiesContext; import org.springframework.test.context.ContextConfiguration; import org.springframework.test.context.junit.jupiter.SpringExtension; import org.springframework.test.web.servlet.MockMvc; +import org.springframework.test.web.servlet.MvcResult; import org.springframework.web.bind.annotation.*; import org.springframework.web.servlet.ModelAndView; import javax.servlet.http.HttpServletRequest; -import java.util.List; -import java.util.stream.Collectors; -import java.util.stream.Stream; +import java.util.concurrent.Callable; +import java.util.concurrent.CompletableFuture; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.Future; import static org.assertj.core.api.Assertions.assertThat; -import static org.mockito.ArgumentMatchers.any; -import static org.mockito.ArgumentMatchers.anyString; -import static org.mockito.ArgumentMatchers.eq; -import static org.mockito.Mockito.*; +import static org.assertj.core.api.Assertions.assertThatCode; +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; @ExtendWith(SpringExtension.class) @@ -53,93 +58,97 @@ @WebMvcTest({WebmvcMetricsHandlerInterceptorTest.Controller1.class, WebmvcMetricsHandlerInterceptorTest.Controller2.class}) class WebmvcMetricsHandlerInterceptorTest { @Autowired - private - MockMvc mvc; + private MockMvc mvc; - @MockBean - private - MeterRegistry registry; + @Autowired + private SimpleMeterRegistry registry; + + static CountDownLatch longRequestCountDown = new CountDownLatch(1); + + @AfterEach + void clearRegistry() { + registry.clear(); + } @Test void metricsGatheredWhenMethodIsTimed() throws Exception { - SimpleTimer timer = expectTimer(); mvc.perform(get("/api/c1/10")).andExpect(status().isOk()); - assertTags( - Tag.of("status", "200"), Tag.of("uri", "api_c1_-id-"), // default tags provided by WebMetricsTagProvider - Tag.of("public", "true") // extra tags provided via @Timed - ); - assertThat(timer.count()).isEqualTo(1); + assertThat(registry.findMeter(Timer.class, "http_server_requests", "status", "200", "uri", "api_c1_-id-", "public", "true")) + .hasValueSatisfying(t -> assertThat(t.count()).isEqualTo(1)); } @SuppressWarnings("unchecked") @Test void metricsNotGatheredWhenRequestMappingIsNotTimed() throws Exception { mvc.perform(get("/api/c1/untimed/10")).andExpect(status().isOk()); - verify(registry, never()).timer(anyString(), any(Stream.class)); + assertThat(registry.findMeter(Timer.class, "http_server_requests")).isEmpty(); } @Test void metricsGatheredWhenControllerIsTimed() throws Exception { - SimpleTimer timer = expectTimer(); mvc.perform(get("/api/c2/10")).andExpect(status().isOk()); - assertTags(Tag.of("status", "200")); - assertThat(timer.count()).isEqualTo(1); + assertThat(registry.findMeter(Timer.class, "http_server_requests", "status", "200")) + .hasValueSatisfying(t -> assertThat(t.count()).isEqualTo(1)); } @Test void metricsGatheredWhenClientRequestBad() throws Exception { - SimpleTimer timer = expectTimer(); mvc.perform(get("/api/c1/oops")).andExpect(status().is4xxClientError()); - assertTags(Tag.of("status", "400"), Tag.of("uri", "api_c1_-id-")); - assertThat(timer.count()).isEqualTo(1); + assertThat(registry.findMeter(Timer.class, "http_server_requests", "status", "400")) + .hasValueSatisfying(t -> assertThat(t.count()).isEqualTo(1)); } @Test void metricsGatheredWhenUnhandledError() throws Exception { - SimpleTimer timer = expectTimer(); - try { - mvc.perform(get("/api/c1/unhandledError/10")).andExpect(status().isOk()); - } catch (Exception e) { - } - assertTags(Tag.of("exception", "RuntimeException"), Tag.of("status", "200"), Tag.of("uri", "api_c1_unhandledError_-id-")); - assertThat(timer.count()).isEqualTo(1); + assertThatCode(() -> mvc.perform(get("/api/c1/unhandledError/10")).andExpect(status().isOk())) + .hasCauseInstanceOf(RuntimeException.class); + assertThat(registry.findMeter(Timer.class, "http_server_requests", "exception", "RuntimeException")) + .hasValueSatisfying(t -> assertThat(t.count()).isEqualTo(1)); + } + + @Test + void metricsGatheredForLongRunningRequestMapping() throws Exception { + MvcResult result = mvc.perform(get("/api/c1/long/10")) + .andExpect(request().asyncStarted()) + .andReturn(); + + // while the mapping is running, it contributes to the activeTasks count + assertThat(registry.findMeter(LongTaskTimer.class, "my_long_request")) + .hasValueSatisfying(t -> assertThat(t.activeTasks()).isEqualTo(1)); + + // once the mapping completes, we can gather information about status, etc. + longRequestCountDown.countDown(); + + mvc.perform(asyncDispatch(result)).andExpect(status().isOk()); + + assertThat(registry.findMeter(Timer.class, "http_server_requests", "status", "200")) + .hasValueSatisfying(t -> assertThat(t.count()).isEqualTo(1)); } @Test - /* FIXME */ @Disabled("ErrorMvcAutoConfiguration is blowing up on SPEL evaluation of 'timestamp'") + /* FIXME */ + @Disabled("ErrorMvcAutoConfiguration is blowing up on SPEL evaluation of 'timestamp'") void metricsGatheredWhenHandledError() throws Exception { - SimpleTimer timer = expectTimer(); mvc.perform(get("/api/c1/error/10")).andExpect(status().is4xxClientError()); - assertTags(Tag.of("status", "422"), Tag.of("uri", "api_c1_error_-id-")); - assertThat(timer.count()).isEqualTo(1); + assertThat(registry.findMeter(Timer.class, "http_server_requests", "status", "422")) + .hasValueSatisfying(t -> assertThat(t.count()).isEqualTo(1)); } @Test void metricsGatheredWhenRegexEndpoint() throws Exception { - SimpleTimer timer = expectTimer(); mvc.perform(get("/api/c1/regex/.abc")).andExpect(status().isOk()); - assertTags(Tag.of("status", "200"), Tag.of("uri", "api_c1_regex_-id-")); - assertThat(timer.count()).isEqualTo(1); - } - - @SuppressWarnings("unchecked") - private void assertTags(Tag... match) { - ArgumentCaptor tags = ArgumentCaptor.forClass(Stream.class); - verify(registry).timer(anyString(), tags.capture()); - assertThat((List) tags.getValue().collect(Collectors.toList())).contains((Object[]) match); - } - - private SimpleTimer expectTimer() { - SimpleTimer timer = new SimpleTimer("http_server_requests"); - - //noinspection unchecked - when(registry.timer(eq("http_server_requests"), any(Stream.class))).thenReturn(timer); - return timer; + assertThat(registry.findMeter(Timer.class, "http_server_requests", "uri", "api_c1_regex_-id-")) + .hasValueSatisfying(t -> assertThat(t.count()).isEqualTo(1)); } @SpringBootApplication @EnableMetrics - static class App {} + static class App { + @Bean + MeterRegistry registry() { + return new SimpleMeterRegistry(); + } + } @RestController @RequestMapping("/api/c1") @@ -150,6 +159,20 @@ public String successfulWithExtraTags(@PathVariable Long id) { return id.toString(); } + @Timed // contains dimensions for status, etc. that can't be known until after the response is sent + @Timed(value = "my_long_request", longTask = true) // in progress metric + @GetMapping("/long/{id}") + public Callable takesLongTimeToSatisfy(@PathVariable Long id) { + return () -> { + try { + longRequestCountDown.await(); + } catch (InterruptedException e) { + throw new RuntimeException(e); + } + return id.toString(); + }; + } + @GetMapping("/untimed/{id}") public String successfulButUntimed(@PathVariable Long id) { return id.toString();