Add "ChannelAcquireDuration" metric for apache-client

The time taken to acquire a new channel from a channel pool can be both
non-trivial and highly variable, depending upon whether a new connection
needs to be established, and depending upon the overhead of new
connection establishment (including TLS handshakes).

The same metric was recently added for netty-nio-client:
aws#2903

Author: Bennett Lynch

.changes/next-release/feature-ApacheHTTPClient-2ecc813.json

@@ -0,0 +1,6 @@
+{
+    "category": "Apache HTTP Client", 
+    "contributor": "", 
+    "type": "feature", 
+    "description": "Add \"ConcurrencyAcquireDuration\" metric for apache-client"
+}

http-client-spi/src/main/java/software/amazon/awssdk/http/HttpMetric.java

@@ -109,15 +109,13 @@ public final class HttpMetric {
      * The time taken to acquire a channel from the connection pool.
      *
      * <p>For HTTP/1 operations, a channel is equivalent to a TCP connection. For HTTP/2 operations, a channel is equivalent to
-     * an HTTP/2 stream channel. For both protocols, the time to acquire a new concurrency permit may include the following:
+     * an HTTP/2 stream channel. For both protocols, the time to acquire a new channel may include the following:
      * <ol>
      *     <li>Awaiting a concurrency permit, as restricted by the client's max concurrency configuration.</li>
      *     <li>The time to establish a new connection, depending on whether an existing connection is available in the pool or
      *     not.</li>
      *     <li>The time taken to perform a TLS handshake/negotiation, if TLS is enabled.</li>
      * </ol>
-     *
-     * <p>Note: This metric is currently only supported in 'netty-nio-client'.
      */
     public static final SdkMetric<Duration> CONCURRENCY_ACQUIRE_DURATION =
         metric("ConcurrencyAcquireDuration", Duration.class, MetricLevel.INFO);

http-clients/apache-client/src/main/java/software/amazon/awssdk/http/apache/ApacheHttpClient.java

@@ -81,6 +81,7 @@
 import software.amazon.awssdk.http.apache.internal.DefaultConfiguration;
 import software.amazon.awssdk.http.apache.internal.SdkProxyRoutePlanner;
 import software.amazon.awssdk.http.apache.internal.conn.ClientConnectionManagerFactory;
+import software.amazon.awssdk.http.apache.internal.conn.ClientConnectionRequestFactory;
 import software.amazon.awssdk.http.apache.internal.conn.IdleConnectionReaper;
 import software.amazon.awssdk.http.apache.internal.conn.SdkConnectionKeepAliveStrategy;
 import software.amazon.awssdk.http.apache.internal.conn.SdkTlsSocketFactory;
@@ -230,7 +231,7 @@ public ExecutableHttpRequest prepareRequest(HttpExecuteRequest request) {
         return new ExecutableHttpRequest() {
             @Override
             public HttpExecuteResponse call() throws IOException {
-                HttpExecuteResponse executeResponse = execute(apacheRequest);
+                HttpExecuteResponse executeResponse = execute(apacheRequest, metricCollector);
                 collectPoolMetric(metricCollector);
                 return executeResponse;
             }
@@ -249,10 +250,15 @@ public void close() {
         cm.shutdown();
     }
 
-    private HttpExecuteResponse execute(HttpRequestBase apacheRequest) throws IOException {
+    private HttpExecuteResponse execute(HttpRequestBase apacheRequest, MetricCollector metricCollector) throws IOException {
         HttpClientContext localRequestContext = ApacheUtils.newClientContext(requestConfig.proxyConfiguration());
-        HttpResponse httpResponse = httpClient.execute(apacheRequest, localRequestContext);
-        return createResponse(httpResponse, apacheRequest);
+        ClientConnectionRequestFactory.THREAD_LOCAL_REQUEST_METRIC_COLLECTOR.set(metricCollector);
+        try {
+            HttpResponse httpResponse = httpClient.execute(apacheRequest, localRequestContext);
+            return createResponse(httpResponse, apacheRequest);
+        } finally {
+            ClientConnectionRequestFactory.THREAD_LOCAL_REQUEST_METRIC_COLLECTOR.remove();
+        }
     }
 
     private HttpRequestBase toApacheRequest(HttpExecuteRequest request) {

http-clients/apache-client/src/main/java/software/amazon/awssdk/http/apache/internal/conn/ClientConnectionRequestFactory.java

@@ -20,13 +20,24 @@
 import java.lang.reflect.InvocationTargetException;
 import java.lang.reflect.Method;
 import java.lang.reflect.Proxy;
+import java.time.Duration;
+import java.time.Instant;
 import org.apache.http.conn.ConnectionRequest;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import software.amazon.awssdk.annotations.SdkInternalApi;
+import software.amazon.awssdk.http.HttpMetric;
+import software.amazon.awssdk.http.apache.ApacheHttpClient;
+import software.amazon.awssdk.metrics.MetricCollector;
 
 @SdkInternalApi
-final class ClientConnectionRequestFactory {
+public final class ClientConnectionRequestFactory {
+
+    /**
+     * {@link ThreadLocal}, request-level {@link MetricCollector}, set and removed by {@link ApacheHttpClient}.
+     */
+    public static final ThreadLocal<MetricCollector> THREAD_LOCAL_REQUEST_METRIC_COLLECTOR = new ThreadLocal<>();
+    
     private static final Logger log = LoggerFactory.getLogger(ClientConnectionRequestFactory.class);
     private static final Class<?>[] INTERFACES = {
             ConnectionRequest.class,
@@ -69,22 +80,27 @@ private static class Handler implements InvocationHandler {
         @Override
         public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
             try {
-                // TODO v2 service metrics
-                //                if ("get".equals(method.getName())) {
-                //                    ServiceLatencyProvider latencyProvider = new ServiceLatencyProvider(
-                //                            AWSServiceMetrics.HttpClientGetConnectionTime);
-                //                    try {
-                //                        return method.invoke(orig, args);
-                //                    } finally {
-                //                        AwsSdkMetrics.getServiceMetricCollector()
-                //                                .collectLatency(latencyProvider.endTiming());
-                //                    }
-                //                }
-                return method.invoke(orig, args);
+                Instant startGet = null;
+                if ("get".equals(method.getName())) {
+                    startGet = Instant.now();
+                }
+                try {
+                    return method.invoke(orig, args);
+                } finally {
+                    if (startGet != null) {
+                        recordGetTime(startGet);
+                    }
+                }
             } catch (InvocationTargetException e) {
                 log.debug("", e);
                 throw e.getCause();
             }
         }
+
+        private void recordGetTime(Instant startGet) {
+            Duration elapsed = Duration.between(startGet, Instant.now());
+            MetricCollector metricCollector = THREAD_LOCAL_REQUEST_METRIC_COLLECTOR.get();
+            metricCollector.reportMetric(HttpMetric.CONCURRENCY_ACQUIRE_DURATION, elapsed);
+        }
     }
 }

http-clients/apache-client/src/test/java/software/amazon/awssdk/http/apache/ApacheMetricsTest.java

@@ -0,0 +1,99 @@
+/*
+ * Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License").
+ * You may not use this file except in compliance with the License.
+ * A copy of the License is located at
+ *
+ *  http://aws.amazon.com/apache2.0
+ *
+ * or in the "license" file accompanying this file. This file is distributed
+ * on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either
+ * express or implied. See the License for the specific language governing
+ * permissions and limitations under the License.
+ */
+
+package software.amazon.awssdk.http.apache;
+
+import static com.github.tomakehurst.wiremock.client.WireMock.aResponse;
+import static com.github.tomakehurst.wiremock.client.WireMock.any;
+import static com.github.tomakehurst.wiremock.client.WireMock.urlMatching;
+import static org.assertj.core.api.Assertions.assertThat;
+import static software.amazon.awssdk.http.HttpMetric.CONCURRENCY_ACQUIRE_DURATION;
+
+import com.github.tomakehurst.wiremock.WireMockServer;
+import java.io.IOException;
+import org.junit.After;
+import org.junit.AfterClass;
+import org.junit.Before;
+import org.junit.BeforeClass;
+import org.junit.Rule;
+import org.junit.Test;
+import org.junit.rules.ExpectedException;
+import software.amazon.awssdk.http.HttpExecuteRequest;
+import software.amazon.awssdk.http.HttpExecuteResponse;
+import software.amazon.awssdk.http.SdkHttpClient;
+import software.amazon.awssdk.http.SdkHttpFullRequest;
+import software.amazon.awssdk.http.SdkHttpMethod;
+import software.amazon.awssdk.http.SdkHttpRequest;
+import software.amazon.awssdk.metrics.MetricCollection;
+import software.amazon.awssdk.metrics.MetricCollector;
+
+
+public class ApacheMetricsTest {
+    private static WireMockServer wireMockServer;
+    private SdkHttpClient client;
+
+    @Rule
+    public ExpectedException thrown = ExpectedException.none();
+
+    @BeforeClass
+    public static void setUp() throws IOException {
+        wireMockServer = new WireMockServer();
+        wireMockServer.start();
+    }
+
+    @Before
+    public void methodSetup() {
+        wireMockServer.stubFor(any(urlMatching(".*")).willReturn(aResponse().withStatus(200).withBody("{}")));
+    }
+
+    @AfterClass
+    public static void teardown() throws IOException {
+        wireMockServer.stop();
+    }
+
+    @After
+    public void methodTeardown() {
+        if (client != null) {
+            client.close();
+        }
+        client = null;
+    }
+
+    @Test
+    public void defaultTlsKeyManagersProviderIsSystemPropertyProvider() throws IOException {
+        client = ApacheHttpClient.create();
+        MetricCollector collector = MetricCollector.create("test");
+        makeRequestWithMetrics(client, collector);
+
+        MetricCollection collection = collector.collect();
+
+        assertThat(collection.metricValues(CONCURRENCY_ACQUIRE_DURATION).get(0)).isPositive();
+    }
+
+    private HttpExecuteResponse makeRequestWithMetrics(SdkHttpClient httpClient, MetricCollector metricCollector) throws IOException {
+        SdkHttpRequest httpRequest = SdkHttpFullRequest.builder()
+                                                       .method(SdkHttpMethod.GET)
+                                                       .protocol("http")
+                                                       .host("localhost:" + wireMockServer.port())
+                                                       .build();
+
+        HttpExecuteRequest request = HttpExecuteRequest.builder()
+                                                       .request(httpRequest)
+                                                       .metricCollector(metricCollector)
+                                                       .build();
+
+        return httpClient.prepareRequest(request).call();
+    }
+}