Fix ApiCallDuration so that it measures the whole API call

Author: alextwoods

.changes/next-release/bugfix-AWSSDKforJavav2-a1b2c3d.json

@@ -0,0 +1,6 @@
+{
+    "type": "bugfix",
+    "category": "AWS SDK for Java v2",
+    "contributor": "",
+    "description": "Fix `ApiCallDuration` so that it measures the whole API call. It previously started after marshalling had already completed, and on asynchronous clients it also started after endpoint resolution, auth scheme resolution, request compression and checksum computation, and so understated the reported duration. The metric is now measured identically for synchronous and asynchronous clients and matches the documented formula. Reported `ApiCallDuration` values will increase but do not reflect changes in actual round-trip latency."
+}

core/sdk-core/pom.xml

@@ -267,8 +267,15 @@
                 <artifactId>japicmp-maven-plugin</artifactId>
                 <configuration>
                     <parameter>
+                        <!-- Note: this list replaces, rather than appends to, the <excludes> in the root pom, so the
+                             root pom's *.internal.* exclusion does not apply here. Internal classes removed from
+                             sdk-core therefore have to be listed individually. -->
                         <excludes>
                             <exclude>software.amazon.awssdk.core.spi.identity.AuthSchemeOptionsResolver#resolve(software.amazon.awssdk.core.SdkRequest)</exclude>
+                            <!-- API_CALL_DURATION moved out of the request pipeline into the client handlers, so that
+                                 the measured window can enclose marshalling. -->
+                            <exclude>software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage</exclude>
+                            <exclude>software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncApiCallMetricCollectionStage</exclude>
                         </excludes>
                     </parameter>
                 </configuration>

core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseAsyncClientHandler.java

@@ -17,6 +17,7 @@
 
 import static software.amazon.awssdk.utils.FunctionalUtils.runAndLogError;
 
+import java.time.Duration;
 import java.util.Optional;
 import java.util.concurrent.CompletableFuture;
 import java.util.function.Function;
@@ -50,6 +51,7 @@
 import software.amazon.awssdk.http.SdkHttpFullRequest;
 import software.amazon.awssdk.http.SdkHttpFullResponse;
 import software.amazon.awssdk.metrics.MetricCollector;
+import software.amazon.awssdk.metrics.NoOpMetricCollector;
 import software.amazon.awssdk.utils.CompletableFutureUtils;
 import software.amazon.awssdk.utils.Logger;
 
@@ -70,7 +72,7 @@ protected BaseAsyncClientHandler(SdkClientConfiguration clientConfiguration,
     public <InputT extends SdkRequest, OutputT extends SdkResponse> CompletableFuture<OutputT> execute(
         ClientExecutionParams<InputT, OutputT> executionParams) {
 
-        return measureApiCallSuccess(executionParams, () -> {
+        return measureApiCall(executionParams, () -> {
             // Running beforeExecution interceptors and modifyRequest interceptors.
             ExecutionContext executionContext = invokeInterceptorsAndCreateExecutionContext(executionParams);
 
@@ -86,7 +88,7 @@ public <InputT extends SdkRequest, OutputT extends SdkResponse, ReturnT> Complet
         ClientExecutionParams<InputT, OutputT> executionParams,
         AsyncResponseTransformer<OutputT, ReturnT> asyncResponseTransformer) {
 
-        return measureApiCallSuccess(executionParams, () -> {
+        return measureApiCall(executionParams, () -> {
             if (executionParams.getCombinedResponseHandler() != null) {
                 // There is no support for catching errors in a body for streaming responses. Our codegen must never
                 // attempt to do this.
@@ -232,7 +234,9 @@ private <InputT extends SdkRequest, OutputT extends SdkResponse, ReturnT> Comple
                        new AsyncAfterTransmissionInterceptorCallingResponseHandler<>(asyncResponseHandler,
                                                                                      executionContext));
 
+            SdkHttpFullRequest requestForMetrics = marshalled;
             CompletableFuture<ReturnT> exceptionTranslatedFuture = invokeFuture.handle((resp, err) -> {
+                reportServiceEndpointMetric(executionContext, requestForMetrics);
                 if (err != null) {
                     throw ThrowableUtils.failure(err);
                 }
@@ -288,27 +292,46 @@ private <InputT extends SdkRequest, OutputT> CompletableFuture<OutputT> invoke(
                      .execute(responseHandler);
     }
 
-    private <T> CompletableFuture<T> measureApiCallSuccess(ClientExecutionParams<?, ?> executionParams,
-                                                           Supplier<CompletableFuture<T>> apiCall) {
+    /**
+     * Measure {@link CoreMetric#API_CALL_DURATION} and report {@link CoreMetric#API_CALL_SUCCESSFUL} for the whole API
+     * call.
+     *
+     * <p>The window deliberately encloses everything the SDK does for the call, marshalling included, and closes when
+     * the returned future completes. Measuring inside the request pipeline is not an option: the pipeline's input is the
+     * already-marshalled request, so no arrangement of pipeline stages can enclose marshalling. Measuring here also
+     * keeps the window identical to the synchronous client's.
+     */
+    private <T> CompletableFuture<T> measureApiCall(ClientExecutionParams<?, ?> executionParams,
+                                                    Supplier<CompletableFuture<T>> apiCall) {
+        MetricCollector metricCollector = executionParams.getMetricCollector();
+        if (metricCollector == null || metricCollector instanceof NoOpMetricCollector) {
+            // Nothing will consume these metrics, so don't pay for the clock reads or the extra future.
+            try {
+                return apiCall.get();
+            } catch (Exception e) {
+                return CompletableFutureUtils.failedFuture(e);
+            }
+        }
+
+        long callStart = System.nanoTime();
         try {
             CompletableFuture<T> apiCallResult = apiCall.get();
             CompletableFuture<T> outputFuture =
-                apiCallResult.whenComplete((r, t) -> reportApiCallSuccess(executionParams, t == null));
+                apiCallResult.whenComplete((r, t) -> reportApiCallMetrics(metricCollector, callStart, t == null));
 
             // Preserve cancellations on the output future, by passing cancellations of the output future to the api call future.
             CompletableFutureUtils.forwardExceptionTo(outputFuture, apiCallResult);
 
             return outputFuture;
         } catch (Exception e) {
-            reportApiCallSuccess(executionParams, false);
+            reportApiCallMetrics(metricCollector, callStart, false);
             return CompletableFutureUtils.failedFuture(e);
         }
     }
 
-    private void reportApiCallSuccess(ClientExecutionParams<?, ?> executionParams, boolean value) {
-        MetricCollector metricCollector = executionParams.getMetricCollector();
-        if (metricCollector != null) {
-            metricCollector.reportMetric(CoreMetric.API_CALL_SUCCESSFUL, value);
-        }
+    private void reportApiCallMetrics(MetricCollector metricCollector, long callStartNanoTime, boolean successful) {
+        long durationNanos = System.nanoTime() - callStartNanoTime;
+        metricCollector.reportMetric(CoreMetric.API_CALL_SUCCESSFUL, successful);
+        metricCollector.reportMetric(CoreMetric.API_CALL_DURATION, Duration.ofNanos(durationNanos));
     }
 }

core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseClientHandler.java

@@ -90,6 +90,22 @@ static <InputT extends SdkRequest, OutputT> InterceptorContext finalizeSdkHttpFu
         return runModifyHttpRequestAndHttpContentInterceptors(executionContext);
     }
 
+    /**
+     * Report the {@link CoreMetric#SERVICE_ENDPOINT} metric for a completed request execution.
+     *
+     * <p>This must run after the request pipeline, so that {@code EndpointResolutionStage} and the signer have applied
+     * their changes to the HTTP request held by the interceptor context. {@code fallbackRequest} is used only when the
+     * interceptor context does not hold a full request, which can happen when the execution failed before the pipeline
+     * updated it.
+     */
+    static void reportServiceEndpointMetric(ExecutionContext executionContext, SdkHttpFullRequest fallbackRequest) {
+        SdkHttpRequest finalRequest = executionContext.interceptorContext().httpRequest();
+        MetricUtils.collectServiceEndpointMetrics(executionContext.metricCollector(),
+                                                 finalRequest instanceof SdkHttpFullRequest
+                                                 ? (SdkHttpFullRequest) finalRequest
+                                                 : fallbackRequest);
+    }
+
     private static void runBeforeMarshallingInterceptors(ExecutionContext executionContext) {
         executionContext.interceptorChain().beforeMarshalling(executionContext.interceptorContext(),
                                                               executionContext.executionAttributes());

core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseSyncClientHandler.java

@@ -15,6 +15,7 @@
 
 package software.amazon.awssdk.core.internal.handler;
 
+import java.time.Duration;
 import java.util.Optional;
 import java.util.function.Supplier;
 import software.amazon.awssdk.annotations.SdkInternalApi;
@@ -41,6 +42,7 @@
 import software.amazon.awssdk.http.SdkHttpFullRequest;
 import software.amazon.awssdk.http.SdkHttpFullResponse;
 import software.amazon.awssdk.metrics.MetricCollector;
+import software.amazon.awssdk.metrics.NoOpMetricCollector;
 
 @SdkInternalApi
 public abstract class BaseSyncClientHandler extends BaseClientHandler implements SyncClientHandler {
@@ -57,7 +59,7 @@ public <InputT extends SdkRequest, OutputT extends SdkResponse, ReturnT> ReturnT
         ClientExecutionParams<InputT, OutputT> executionParams,
         ResponseTransformer<OutputT, ReturnT> responseTransformer) {
 
-        return measureApiCallSuccess(executionParams, () -> {
+        return measureApiCall(executionParams, () -> {
             // Running beforeExecution interceptors and modifyRequest interceptors.
             ExecutionContext executionContext = invokeInterceptorsAndCreateExecutionContext(executionParams);
 
@@ -71,7 +73,7 @@ public <InputT extends SdkRequest, OutputT extends SdkResponse, ReturnT> ReturnT
     public <InputT extends SdkRequest, OutputT extends SdkResponse> OutputT execute(
         ClientExecutionParams<InputT, OutputT> executionParams) {
 
-        return measureApiCallSuccess(executionParams, () -> {
+        return measureApiCall(executionParams, () -> {
             // Running beforeExecution interceptors and modifyRequest interceptors.
             ExecutionContext executionContext = invokeInterceptorsAndCreateExecutionContext(executionParams);
 
@@ -170,28 +172,42 @@ private <InputT extends SdkRequest, OutputT, ReturnT> ReturnT doExecute(
         }
 
         SdkClientConfiguration clientConfiguration = resolveRequestConfiguration(executionParams);
-        return invoke(clientConfiguration,
-                      marshalled,
-                      inputT,
-                      executionContext,
-                      responseHandler);
+        try {
+            return invoke(clientConfiguration,
+                          marshalled,
+                          inputT,
+                          executionContext,
+                          responseHandler);
+        } finally {
+            reportServiceEndpointMetric(executionContext, marshalled);
+        }
     }
 
-    private <T> T measureApiCallSuccess(ClientExecutionParams<?, ?> executionParams, Supplier<T> thingToMeasureSuccessOf) {
+    /**
+     * Measure {@link CoreMetric#API_CALL_DURATION} and report {@link CoreMetric#API_CALL_SUCCESSFUL} for the whole API
+     * call.
+     *
+     * <p>The window deliberately encloses everything the SDK does for the call, marshalling included. Measuring inside
+     * the request pipeline is not an option: the pipeline's input is the already-marshalled request, so no arrangement
+     * of pipeline stages can enclose marshalling.
+     */
+    private <T> T measureApiCall(ClientExecutionParams<?, ?> executionParams, Supplier<T> apiCall) {
+        MetricCollector metricCollector = executionParams.getMetricCollector();
+        if (metricCollector == null || metricCollector instanceof NoOpMetricCollector) {
+            // Nothing will consume these metrics, so don't pay for the clock reads.
+            return apiCall.get();
+        }
+
+        long callStart = System.nanoTime();
         try {
-            T result = thingToMeasureSuccessOf.get();
-            reportApiCallSuccess(executionParams, true);
+            T result = apiCall.get();
+            metricCollector.reportMetric(CoreMetric.API_CALL_SUCCESSFUL, true);
             return result;
         } catch (Exception e) {
-            reportApiCallSuccess(executionParams, false);
+            metricCollector.reportMetric(CoreMetric.API_CALL_SUCCESSFUL, false);
             throw e;
-        }
-    }
-
-    private void reportApiCallSuccess(ClientExecutionParams<?, ?> executionParams, boolean value) {
-        MetricCollector metricCollector = executionParams.getMetricCollector();
-        if (metricCollector != null) {
-            metricCollector.reportMetric(CoreMetric.API_CALL_SUCCESSFUL, value);
+        } finally {
+            metricCollector.reportMetric(CoreMetric.API_CALL_DURATION, Duration.ofNanos(System.nanoTime() - callStart));
         }
     }
 

core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/AmazonAsyncHttpClient.java

@@ -33,7 +33,6 @@
 import software.amazon.awssdk.core.internal.http.pipeline.stages.ApplyTransactionIdStage;
 import software.amazon.awssdk.core.internal.http.pipeline.stages.ApplyUserAgentStage;
 import software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncApiCallAttemptMetricCollectionStage;
-import software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncApiCallMetricCollectionStage;
 import software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncApiCallTimeoutTrackingStage;
 import software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncBeforeTransmissionExecutionInterceptorsStage;
 import software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncExecutionFailureExceptionReportingStage;
@@ -214,8 +213,10 @@ public <OutputT> CompletableFuture<OutputT> execute(
                                         .then(async(() -> new UnwrapResponseContainer<>()))
                                         .then(async(() -> new AfterExecutionInterceptorsStage<>()))
                                         .wrappedWith(AsyncExecutionFailureExceptionReportingStage::new)
-                                        .wrappedWith(AsyncApiCallTimeoutTrackingStage::new)
-                                        .wrappedWith(AsyncApiCallMetricCollectionStage::new)::build)::build)
+                                        // Note: API_CALL_DURATION is measured by BaseAsyncClientHandler, not here. A
+                                        // stage here could not enclose marshalling, and nesting it on this inner
+                                        // builder previously also excluded the request-mutation stages above.
+                                        .wrappedWith(AsyncApiCallTimeoutTrackingStage::new)::build)::build)
                         .build(httpClientDependencies)
                         .execute(request, createRequestExecutionDependencies());
             } catch (RuntimeException e) {

core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/AmazonSyncHttpClient.java

@@ -30,7 +30,6 @@
 import software.amazon.awssdk.core.internal.http.pipeline.stages.AfterTransmissionExecutionInterceptorsStage;
 import software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage;
 import software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage;
-import software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage;
 import software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage;
 import software.amazon.awssdk.core.internal.http.pipeline.stages.ApplyTransactionIdStage;
 import software.amazon.awssdk.core.internal.http.pipeline.stages.ApplyUserAgentStage;
@@ -206,7 +205,8 @@ public <OutputT> OutputT execute(HttpResponseHandler<Response<OutputT>> response
                                          .wrappedWith(RetryableStage::new)::build)
                                .wrappedWith(StreamManagingStage::new)
                                .wrappedWith(ApiCallTimeoutTrackingStage::new)::build)
-                               .wrappedWith((deps, wrapped) -> new ApiCallMetricCollectionStage<>(wrapped))
+                    // Note: API_CALL_DURATION is measured by BaseSyncClientHandler, not here. The pipeline's input is
+                    // the already-marshalled request, so a stage here cannot enclose marshalling.
                     .then(() -> new UnwrapResponseContainer<>())
                     .then(() -> new AfterExecutionInterceptorsStage<>())
                     .wrappedWith(ExecutionFailureExceptionReportingStage::new)