Fix ApiCallDuration so that it measures the whole API call (#7338)

* Fix `ApiCallDuration` so that it measures the whole API call

* Cleanups

* PR Feedback

* Minor cleanups

* Cleanups + fix apiCallTimeout docs.

Author: alextwoods

.changes/next-release/bugfix-AWSSDKforJavav2-c3201a9.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

@@ -255,7 +255,10 @@
                 <artifactId>japicmp-maven-plugin</artifactId>
                 <configuration>
                     <parameter>
-                        <excludes>
+                        <!-- combine.children="append" keeps the root pom's excludes, notably the *.internal.* wildcard.
+                             Without it Maven replaces the parent's list with this one, and deleting any internal
+                             sdk-core class fails the japicmp gate. -->
+                        <excludes combine.children="append">
                             <exclude>software.amazon.awssdk.core.spi.identity.AuthSchemeOptionsResolver#resolve(software.amazon.awssdk.core.SdkRequest)</exclude>
                         </excludes>
                     </parameter>

core/sdk-core/src/main/java/software/amazon/awssdk/core/client/config/ClientOverrideConfiguration.java

@@ -288,6 +288,9 @@ public Optional<ScheduledExecutorService> scheduledExecutorService() {
      * execution except for marshalling. This includes request handler execution, all HTTP requests including retries,
      * unmarshalling, etc. This value should always be positive, if present.
      *
+     * <p>Because this window is narrower than the API call as a whole, the reported
+     * {@link software.amazon.awssdk.core.metrics.CoreMetric#API_CALL_DURATION} metric can exceed this timeout.
+     *
      * <p>The api call timeout feature doesn't have strict guarantees on how quickly a request is aborted when the
      * timeout is breached. The typical case aborts the request within a few milliseconds but there may occasionally be
      * requests that don't get aborted until several seconds after the timer has been breached. Because of this, the client
@@ -613,6 +616,9 @@ default Builder retryStrategy(Consumer<RetryStrategy.Builder<?, ?>> configurator
          * entire client execution except for marshalling. This includes request handler execution, all HTTP requests including
          * retries, unmarshalling, etc. This value should always be positive, if present.
          *
+         * <p>Because this window is narrower than the API call as a whole, the reported
+         * {@link software.amazon.awssdk.core.metrics.CoreMetric#API_CALL_DURATION} metric can exceed this timeout.
+         *
          * <p>The api call timeout feature doesn't have strict guarantees on how quickly a request is aborted when the
          * timeout is breached. The typical case aborts the request within a few milliseconds but there may occasionally be
          * requests that don't get aborted until several seconds after the timer has been breached. Because of this, the client

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,10 @@ private <InputT extends SdkRequest, OutputT extends SdkResponse, ReturnT> Comple
                        new AsyncAfterTransmissionInterceptorCallingResponseHandler<>(asyncResponseHandler,
                                                                                      executionContext));
 
+            // Captured because the requestBody branch above may reassign 'marshalled', leaving it not effectively final.
+            SdkHttpFullRequest requestForMetrics = marshalled;
             CompletableFuture<ReturnT> exceptionTranslatedFuture = invokeFuture.handle((resp, err) -> {
+                reportServiceEndpointMetric(executionContext, requestForMetrics);
                 if (err != null) {
                     throw ThrowableUtils.failure(err);
                 }
@@ -288,27 +293,49 @@ 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. A null collector
+            // is treated the same as NoOp: when the params carry none, the collector that AwsExecutionContextBuilder
+            // substitutes into the ExecutionContext is never handed to a publisher, so anything reported to it is
+            // discarded.
+            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,44 @@ 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. A null collector is treated the same
+            // as NoOp: when the params carry none, the collector that AwsExecutionContextBuilder substitutes into the
+            // ExecutionContext is never handed to a publisher, so anything reported to it is discarded.
+            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,8 @@ 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
+                                        .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,7 @@ 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
                     .then(() -> new UnwrapResponseContainer<>())
                     .then(() -> new AfterExecutionInterceptorsStage<>())
                     .wrappedWith(ExecutionFailureExceptionReportingStage::new)