Add metrics related to request timeout (#1589)

Motivation: It would be nice if we provide request timeout metrics by default. Modifications: - Add counters - `timeouts{cause=RequestTimeoutException}` (server-side) - `timeouts{cause=WriteTimeoutException}` (client-side) - `timeouts{cause=ResponseTimeoutException}` (client-side) - Add `ServiceRequestContext.isTimedOut()` - Deprecate `RequestContext.isTimedOut()` Result: - More metrics - Close #1580
line · Feb 14, 2019 · ff46158 · ff46158
1 parent 547013b
commit ff46158
Show file tree

Hide file tree

Showing 10 changed files with 246 additions and 71 deletions.
diff --git a/core/src/main/java/com/linecorp/armeria/client/metric/MetricCollectingClient.java b/core/src/main/java/com/linecorp/armeria/client/metric/MetricCollectingClient.java
@@ -69,7 +69,7 @@ Function<Client<I, O>, MetricCollectingClient<I, O>> newDecorator(
 
     @Override
     public O execute(ClientRequestContext ctx, I req) throws Exception {
-        RequestMetricSupport.setup(ctx, meterIdPrefixFunction);
+        RequestMetricSupport.setup(ctx, meterIdPrefixFunction, false);
         return delegate().execute(ctx, req);
     }
 }
diff --git a/core/src/main/java/com/linecorp/armeria/common/AbstractRequestContext.java b/core/src/main/java/com/linecorp/armeria/common/AbstractRequestContext.java
@@ -27,6 +27,7 @@
 import java.util.function.Function;
 
 import com.linecorp.armeria.common.util.SafeCloseable;
+import com.linecorp.armeria.server.DefaultServiceRequestContext;
 
 import io.netty.channel.ChannelFutureListener;
 import io.netty.channel.EventLoop;
@@ -151,7 +152,10 @@ public boolean isTimedOut() {
     /**
      * Marks this {@link RequestContext} as having been timed out. Any callbacks created with
      * {@code makeContextAware} that are run after this will be failed with {@link CancellationException}.
+     *
+     * @deprecated Use {@link DefaultServiceRequestContext#setTimedOut()}.
      */
+    @Deprecated
     public void setTimedOut() {
         timedOut = true;
     }

diff --git a/core/src/main/java/com/linecorp/armeria/common/RequestContext.java b/core/src/main/java/com/linecorp/armeria/common/RequestContext.java
@@ -439,7 +439,10 @@ default <T> CompletableFuture<T> makeContextAware(CompletableFuture<T> future) {
     /**
      * Returns whether this {@link RequestContext} has been timed-out (e.g., when the corresponding request
      * passes a deadline).
+     *
+     * @deprecated Use {@link ServiceRequestContext#isTimedOut()}.
      */
+    @Deprecated
     boolean isTimedOut();
 
     /**

diff --git a/core/src/main/java/com/linecorp/armeria/internal/metric/RequestMetricSupport.java b/core/src/main/java/com/linecorp/armeria/internal/metric/RequestMetricSupport.java
@@ -22,12 +22,15 @@
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.LongAdder;
 
+import com.linecorp.armeria.client.ResponseTimeoutException;
+import com.linecorp.armeria.client.WriteTimeoutException;
 import com.linecorp.armeria.common.RequestContext;
 import com.linecorp.armeria.common.RpcResponse;
 import com.linecorp.armeria.common.logging.RequestLog;
 import com.linecorp.armeria.common.logging.RequestLogAvailability;
 import com.linecorp.armeria.common.metric.MeterIdPrefix;
 import com.linecorp.armeria.common.metric.MeterIdPrefixFunction;
+import com.linecorp.armeria.server.RequestTimeoutException;
 
 import io.micrometer.core.instrument.Counter;
 import io.micrometer.core.instrument.DistributionSummary;
@@ -44,18 +47,18 @@ public final class RequestMetricSupport {
     private static final AttributeKey<Boolean> ATTR_REQUEST_METRICS_SET =
             AttributeKey.valueOf(Boolean.class, "REQUEST_METRICS_SET");
 
-    public static void setup(RequestContext ctx, MeterIdPrefixFunction meterIdPrefixFunction) {
+    public static void setup(RequestContext ctx, MeterIdPrefixFunction meterIdPrefixFunction, boolean server) {
         if (ctx.hasAttr(ATTR_REQUEST_METRICS_SET)) {
             return;
         }
         ctx.attr(ATTR_REQUEST_METRICS_SET).set(true);
 
-        ctx.log().addListener(log -> onRequest(log, meterIdPrefixFunction),
+        ctx.log().addListener(log -> onRequest(log, meterIdPrefixFunction, server),
                               RequestLogAvailability.REQUEST_HEADERS,
                               RequestLogAvailability.REQUEST_CONTENT);
     }
 
-    private static void onRequest(RequestLog log, MeterIdPrefixFunction meterIdPrefixFunction) {
+    private static void onRequest(RequestLog log, MeterIdPrefixFunction meterIdPrefixFunction, boolean server) {
         final RequestContext ctx = log.context();
         final MeterRegistry registry = ctx.meterRegistry();
         final MeterIdPrefix activeRequestsId = meterIdPrefixFunction.activeRequestPrefix(registry, log)
@@ -67,18 +70,43 @@ private static void onRequest(RequestLog log, MeterIdPrefixFunction meterIdPrefi
                         reg.gauge(prefix.name(), prefix.tags(),
                                   new ActiveRequestMetrics(), ActiveRequestMetrics::doubleValue));
         activeRequestMetrics.increment();
-        ctx.log().addListener(requestLog -> onResponse(requestLog, meterIdPrefixFunction, activeRequestMetrics),
+        ctx.log().addListener(requestLog -> {
+                                  onResponse(requestLog, meterIdPrefixFunction, server);
+                                  activeRequestMetrics.decrement();
+                              },
                               RequestLogAvailability.COMPLETE);
     }
 
     private static void onResponse(RequestLog log, MeterIdPrefixFunction meterIdPrefixFunction,
-                                   ActiveRequestMetrics activeRequestMetrics) {
+                                   boolean server) {
         final RequestContext ctx = log.context();
         final MeterRegistry registry = ctx.meterRegistry();
         final MeterIdPrefix idPrefix = meterIdPrefixFunction.apply(registry, log);
-        final RequestMetrics metrics = MicrometerUtil.register(
-                registry, idPrefix, RequestMetrics.class, DefaultRequestMetrics::new);
 
+        if (server) {
+            final ServiceRequestMetrics metrics = MicrometerUtil.register(registry, idPrefix,
+                                                                          ServiceRequestMetrics.class,
+                                                                          DefaultServiceRequestMetrics::new);
+            updateMetrics(log, metrics);
+            if (log.responseCause() instanceof RequestTimeoutException) {
+                metrics.requestTimeouts().increment();
+            }
+            return;
+        }
+
+        final ClientRequestMetrics metrics = MicrometerUtil.register(registry, idPrefix,
+                                                                     ClientRequestMetrics.class,
+                                                                     DefaultClientRequestMetrics::new);
+        updateMetrics(log, metrics);
+        final Throwable responseCause = log.responseCause();
+        if (responseCause instanceof WriteTimeoutException) {
+            metrics.writeTimeouts().increment();
+        } else if (responseCause instanceof ResponseTimeoutException) {
+            metrics.responseTimeouts().increment();
+        }
+    }
+
+    private static void updateMetrics(RequestLog log, RequestMetrics metrics) {
         if (log.requestCause() != null) {
             metrics.failure().increment();
             return;
@@ -95,8 +123,6 @@ private static void onResponse(RequestLog log, MeterIdPrefixFunction meterIdPref
         } else {
             metrics.failure().increment();
         }
-
-        activeRequestMetrics.decrement();
     }
 
     private static boolean isSuccess(RequestLog log) {
@@ -136,9 +162,19 @@ private interface RequestMetrics {
         Timer totalDuration();
     }
 
+    private interface ClientRequestMetrics extends RequestMetrics {
+        Counter writeTimeouts();
+
+        Counter responseTimeouts();
+    }
+
+    private interface ServiceRequestMetrics extends RequestMetrics {
+        Counter requestTimeouts();
+    }
+
     private static final class ActiveRequestMetrics extends LongAdder {}
 
-    private static final class DefaultRequestMetrics implements RequestMetrics {
+    private abstract static class AbstractRequestMetrics implements RequestMetrics {
 
         private final Counter success;
         private final Counter failure;
@@ -148,7 +184,7 @@ private static final class DefaultRequestMetrics implements RequestMetrics {
         private final DistributionSummary responseLength;
         private final Timer totalDuration;
 
-        DefaultRequestMetrics(MeterRegistry parent, MeterIdPrefix idPrefix) {
+        AbstractRequestMetrics(MeterRegistry parent, MeterIdPrefix idPrefix) {
             final String requests = idPrefix.name("requests");
             success = parent.counter(requests, idPrefix.tags("result", "success"));
             failure = parent.counter(requests, idPrefix.tags("result", "failure"));
@@ -200,4 +236,45 @@ public Timer totalDuration() {
             return totalDuration;
         }
     }
+
+    private static class DefaultClientRequestMetrics
+            extends AbstractRequestMetrics implements ClientRequestMetrics {
+
+        private final Counter writeTimeouts;
+        private final Counter responseTimeouts;
+
+        DefaultClientRequestMetrics(MeterRegistry parent, MeterIdPrefix idPrefix) {
+            super(parent, idPrefix);
+            final String timeouts = idPrefix.name("timeouts");
+            writeTimeouts = parent.counter(timeouts, idPrefix.tags("cause", "WriteTimeoutException"));
+            responseTimeouts = parent.counter(timeouts, idPrefix.tags("cause", "ResponseTimeoutException"));
+        }
+
+        @Override
+        public Counter writeTimeouts() {
+            return writeTimeouts;
+        }
+
+        @Override
+        public Counter responseTimeouts() {
+            return responseTimeouts;
+        }
+    }
+
+    private static class DefaultServiceRequestMetrics
+            extends AbstractRequestMetrics implements ServiceRequestMetrics {
+
+        private final Counter requestTimeouts;
+
+        DefaultServiceRequestMetrics(MeterRegistry parent, MeterIdPrefix idPrefix) {
+            super(parent, idPrefix);
+            requestTimeouts = parent.counter(idPrefix.name("timeouts"),
+                                             idPrefix.tags("cause", "RequestTimeoutException"));
+        }
+
+        @Override
+        public Counter requestTimeouts() {
+            return requestTimeouts;
+        }
+    }
 }
diff --git a/core/src/main/java/com/linecorp/armeria/server/DefaultServiceRequestContext.java b/core/src/main/java/com/linecorp/armeria/server/DefaultServiceRequestContext.java
@@ -24,6 +24,7 @@
 import java.time.Duration;
 import java.util.Iterator;
 import java.util.Map;
+import java.util.concurrent.CancellationException;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.atomic.AtomicReferenceFieldUpdater;
 
@@ -405,6 +406,15 @@ public void setRequestTimeoutHandler(Runnable requestTimeoutHandler) {
         this.requestTimeoutHandler = requireNonNull(requestTimeoutHandler, "requestTimeoutHandler");
     }
 
+    /**
+     * Marks this {@link ServiceRequestContext} as having been timed out. Any callbacks created with
+     * {@code makeContextAware} that are run after this will be failed with {@link CancellationException}.
+     */
+    @Override
+    public void setTimedOut() {
+        super.setTimedOut();
+    }
+
     @Override
     public long maxRequestLength() {
         return maxRequestLength;

diff --git a/core/src/main/java/com/linecorp/armeria/server/ServiceRequestContext.java b/core/src/main/java/com/linecorp/armeria/server/ServiceRequestContext.java
@@ -37,6 +37,7 @@
 import com.linecorp.armeria.common.MediaType;
 import com.linecorp.armeria.common.Request;
 import com.linecorp.armeria.common.RequestContext;
+import com.linecorp.armeria.common.Response;
 
 import io.netty.handler.codec.Headers;
 import io.netty.util.AsciiString;
@@ -178,19 +179,22 @@ default MediaType negotiatedProduceType() {
     Logger logger();
 
     /**
-     * Returns the amount of time allowed until receiving the current {@link Request} completely.
+     * Returns the amount of time allowed until receiving the current {@link Request} and sending
+     * the corresponding {@link Response} completely.
      * This value is initially set from {@link ServerConfig#defaultRequestTimeoutMillis()}.
      */
     long requestTimeoutMillis();
 
     /**
-     * Sets the amount of time allowed until receiving the current {@link Request} completely.
+     * Sets the amount of time allowed until receiving the current {@link Request} and sending
+     * the corresponding {@link Response} completely.
      * This value is initially set from {@link ServerConfig#defaultRequestTimeoutMillis()}.
      */
     void setRequestTimeoutMillis(long requestTimeoutMillis);
 
     /**
-     * Sets the amount of time allowed until receiving the current {@link Request} completely.
+     * Sets the amount of time allowed until receiving the current {@link Request} and sending
+     * the corresponding {@link Response} completely.
      * This value is initially set from {@link ServerConfig#defaultRequestTimeoutMillis()}.
      */
     void setRequestTimeout(Duration requestTimeout);
@@ -212,6 +216,13 @@ default MediaType negotiatedProduceType() {
      */
     void setRequestTimeoutHandler(Runnable requestTimeoutHandler);
 
+    /**
+     * Returns whether this {@link ServiceRequestContext} has been timed-out (e.g., when the
+     * corresponding request passes a deadline).
+     */
+    @Override
+    boolean isTimedOut();
+
     /**
      * Returns the maximum length of the current {@link Request}.
      * This value is initially set from {@link ServerConfig#defaultMaxRequestLength()}.

diff --git a/core/src/main/java/com/linecorp/armeria/server/metric/MetricCollectingService.java b/core/src/main/java/com/linecorp/armeria/server/metric/MetricCollectingService.java
@@ -71,7 +71,7 @@ Function<Service<I, O>, MetricCollectingService<I, O>> newDecorator(
 
     @Override
     public O serve(ServiceRequestContext ctx, I req) throws Exception {
-        RequestMetricSupport.setup(ctx, meterIdPrefixFunction);
+        RequestMetricSupport.setup(ctx, meterIdPrefixFunction, true);
         return delegate().serve(ctx, req);
     }
 }
diff --git a/core/src/test/java/com/linecorp/armeria/common/RequestContextTest.java b/core/src/test/java/com/linecorp/armeria/common/RequestContextTest.java
@@ -362,14 +362,6 @@ public void unintentionalNestedContexts() throws Exception {
         }
     }
 
-    @Test
-    public void timedOut() {
-        final AbstractRequestContext ctx = createContext();
-        assertThat(ctx.isTimedOut()).isFalse();
-        ctx.setTimedOut();
-        assertThat(ctx.isTimedOut()).isTrue();
-    }
-
     private void assertDepth(int expectedDepth) {
         assertThat(ctxStack).hasSize(expectedDepth);
     }