From 592527cf58bab62335e9b16f122aea7e6e71d317 Mon Sep 17 00:00:00 2001 From: Idel Pivnitskiy Date: Fri, 24 Sep 2021 11:27:33 -0500 Subject: [PATCH] LifecycleObservers: log `responseTime` and `totalTime` (#1843) Motivation: Because the connections are full-duplex and request/response can be processed independently, a server may respond much earlier than it finishes processing of the request payload body. Modifications: - Rename `duration` to `totalTime`; - Add `responseTime`; Result: `LoggingHttpLifecycleObserver` and `LoggingGrpcLifecycleObserver` log `responseTime` and `totalTime`. --- .../utils/LoggingGrpcLifecycleObserver.java | 20 ++++++++++++------ .../utils/LoggingHttpLifecycleObserver.java | 21 +++++++++++++------ 2 files changed, 29 insertions(+), 12 deletions(-) diff --git a/servicetalk-grpc-utils/src/main/java/io/servicetalk/grpc/utils/LoggingGrpcLifecycleObserver.java b/servicetalk-grpc-utils/src/main/java/io/servicetalk/grpc/utils/LoggingGrpcLifecycleObserver.java index 07d3691704..2e21490b50 100644 --- a/servicetalk-grpc-utils/src/main/java/io/servicetalk/grpc/utils/LoggingGrpcLifecycleObserver.java +++ b/servicetalk-grpc-utils/src/main/java/io/servicetalk/grpc/utils/LoggingGrpcLifecycleObserver.java @@ -74,6 +74,7 @@ private static final class LoggingGrpcExchangeObserver implements GrpcExchangeOb private int responseTrailersCount; @Nullable private GrpcStatusCode grpcStatus; + private long responseTimeMs; @Nullable private Object responseResult; @@ -150,18 +151,21 @@ public void onGrpcStatus(final GrpcStatus status) { public void onResponseComplete() { assert responseResult == null; assert responseMetaData != null; + responseTimeMs = durationMs(startTime); responseResult = Result.complete; } @Override public void onResponseError(final Throwable cause) { assert responseResult == null; + responseTimeMs = durationMs(startTime); responseResult = cause; } @Override public void onResponseCancel() { assert responseResult == null; + responseTimeMs = durationMs(startTime); responseResult = Result.cancelled; } @@ -180,22 +184,22 @@ public void onExchangeFinally() { logger.log("connection={} " + "request=\"{} {} {}\" requestHeadersCount={} requestSize={} requestTrailersCount={} requestResult={} " + "responseCode={} responseHeadersCount={} responseSize={} responseTrailersCount={} grpcStatus={} " + - "responseResult={} duration={}ms", + "responseResult={} responseTime={}ms totalTime={}ms", connInfo == null ? "unknown" : connInfo, requestMetaData.method(), requestMetaData.requestTarget(), requestMetaData.version(), requestMetaData.headers().size(), requestSize, requestTrailersCount, requestResult, responseMetaData.status().code(), responseMetaData.headers().size(), responseSize, - responseTrailersCount, grpcStatus, unwrapResult(responseResult), - NANOSECONDS.toMillis(nanoTime() - startTime), combine(responseResult, requestResult)); + responseTrailersCount, grpcStatus, unwrapResult(responseResult), responseTimeMs, durationMs(startTime), + combine(responseResult, requestResult)); } else { logger.log("connection={} " + "request=\"{} {} {}\" requestHeadersCount={} requestSize={} requestTrailersCount={} requestResult={} " + - "responseResult={} duration={}ms", + "responseResult={} responseTime={}ms totalTime={}ms", connInfo == null ? "unknown" : connInfo, requestMetaData.method(), requestMetaData.requestTarget(), requestMetaData.version(), requestMetaData.headers().size(), requestSize, requestTrailersCount, requestResult, - unwrapResult(responseResult), - NANOSECONDS.toMillis(nanoTime() - startTime), combine(responseResult, requestResult)); + unwrapResult(responseResult), responseTimeMs, durationMs(startTime), + combine(responseResult, requestResult)); } } @@ -204,6 +208,10 @@ private static Object unwrapResult(@Nullable Object result) { return result instanceof Throwable ? Result.error : result; } + private static long durationMs(final long startTime) { + return NANOSECONDS.toMillis(nanoTime() - startTime); + } + private enum Result { complete, error, cancelled } diff --git a/servicetalk-http-utils/src/main/java/io/servicetalk/http/utils/LoggingHttpLifecycleObserver.java b/servicetalk-http-utils/src/main/java/io/servicetalk/http/utils/LoggingHttpLifecycleObserver.java index 50ecc76c97..8be3531c46 100644 --- a/servicetalk-http-utils/src/main/java/io/servicetalk/http/utils/LoggingHttpLifecycleObserver.java +++ b/servicetalk-http-utils/src/main/java/io/servicetalk/http/utils/LoggingHttpLifecycleObserver.java @@ -70,6 +70,7 @@ private static final class LoggingHttpExchangeObserver implements HttpExchangeOb private HttpResponseMetaData responseMetaData; private long responseSize; private int responseTrailersCount; + private long responseTimeMs; @Nullable private Object responseResult; @@ -140,18 +141,21 @@ public void onResponseTrailers(final HttpHeaders trailers) { public void onResponseComplete() { assert responseResult == null; assert responseMetaData != null; + responseTimeMs = durationMs(startTime); responseResult = Result.complete; } @Override public void onResponseError(final Throwable cause) { assert responseResult == null; + responseTimeMs = durationMs(startTime); responseResult = cause; } @Override public void onResponseCancel() { assert responseResult == null; + responseTimeMs = durationMs(startTime); responseResult = Result.cancelled; } @@ -166,26 +170,27 @@ public void onExchangeFinally() { // It's possible that request can be cancelled before transport subscribed to its payload body requestResult = Result.cancelled; } + assert responseResult != null; if (responseMetaData != null) { logger.log("connection={} " + "request=\"{} {} {}\" requestHeadersCount={} requestSize={} requestTrailersCount={} requestResult={} " + "responseCode={} responseHeadersCount={} responseSize={} responseTrailersCount={} responseResult={} " + - "duration={}ms", + "responseTime={}ms totalTime={}ms", connInfo == null ? "unknown" : connInfo, requestMetaData.method(), requestMetaData.requestTarget(), requestMetaData.version(), requestMetaData.headers().size(), requestSize, requestTrailersCount, requestResult, responseMetaData.status().code(), responseMetaData.headers().size(), responseSize, - responseTrailersCount, unwrapResult(responseResult), - NANOSECONDS.toMillis(nanoTime() - startTime), combine(responseResult, requestResult)); + responseTrailersCount, unwrapResult(responseResult), responseTimeMs, durationMs(startTime), + combine(responseResult, requestResult)); } else { logger.log("connection={} " + "request=\"{} {} {}\" requestHeadersCount={} requestSize={} requestTrailersCount={} requestResult={} " + - "responseResult={} duration={}ms", + "responseResult={} responseTime={}ms totalTime={}ms", connInfo == null ? "unknown" : connInfo, requestMetaData.method(), requestMetaData.requestTarget(), requestMetaData.version(), requestMetaData.headers().size(), requestSize, requestTrailersCount, requestResult, - unwrapResult(responseResult), - NANOSECONDS.toMillis(nanoTime() - startTime), combine(responseResult, requestResult)); + unwrapResult(responseResult), responseTimeMs, durationMs(startTime), + combine(responseResult, requestResult)); } } @@ -194,6 +199,10 @@ private static Object unwrapResult(@Nullable Object result) { return result instanceof Throwable ? Result.error : result; } + private static long durationMs(final long startTime) { + return NANOSECONDS.toMillis(nanoTime() - startTime); + } + private enum Result { complete, error, cancelled }