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`.
apple · Sep 24, 2021 · 592527c · 592527c
1 parent b9a7318
commit 592527c
Show file tree

Hide file tree

Showing 2 changed files with 29 additions and 12 deletions.
diff --git a/...talk-grpc-utils/src/main/java/io/servicetalk/grpc/utils/LoggingGrpcLifecycleObserver.java b/...talk-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/...talk-http-utils/src/main/java/io/servicetalk/http/utils/LoggingHttpLifecycleObserver.java b/...talk-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
         }