Collect timings related with TLS handshake

core/src/main/java/com/linecorp/armeria/client/HttpChannelPool.java

@@ -72,6 +72,7 @@
 import io.netty.handler.proxy.Socks4ProxyHandler;
 import io.netty.handler.proxy.Socks5ProxyHandler;
 import io.netty.handler.ssl.SslContext;
+import io.netty.util.AttributeKey;
 import io.netty.util.concurrent.Future;
 import io.netty.util.concurrent.Promise;
 import reactor.core.scheduler.NonBlocking;
@@ -81,6 +82,9 @@ final class HttpChannelPool implements AsyncCloseable {
     private static final Logger logger = LoggerFactory.getLogger(HttpChannelPool.class);
     private static final Channel[] EMPTY_CHANNELS = new Channel[0];
 
+    static final AttributeKey<ClientConnectionTimingsBuilder> TIMINGS_BUILDER_KEY =
+            AttributeKey.valueOf(HttpChannelPool.class, "TIMINGS_BUILDER_KEY");
+
     private final HttpClientFactory clientFactory;
     private final EventLoop eventLoop;
     private final AsyncCloseableSupport closeable = AsyncCloseableSupport.of(this::closeAsync);
@@ -350,7 +354,7 @@ private void connect(SessionProtocol desiredProtocol, SerializationFormat serial
 
         // Create a new connection.
         final Promise<Channel> sessionPromise = eventLoop.newPromise();
-        connect(remoteAddress, desiredProtocol, serializationFormat, key, sessionPromise);
+        connect(remoteAddress, desiredProtocol, serializationFormat, key, sessionPromise, timingsBuilder);
 
         if (sessionPromise.isDone()) {
             notifyConnect(desiredProtocol, key, sessionPromise, promise, timingsBuilder);
@@ -371,8 +375,8 @@ private void connect(SessionProtocol desiredProtocol, SerializationFormat serial
      */
     void connect(SocketAddress remoteAddress, SessionProtocol desiredProtocol,
                  SerializationFormat serializationFormat,
-                 PoolKey poolKey, Promise<Channel> sessionPromise) {
-
+                 PoolKey poolKey, Promise<Channel> sessionPromise,
+                 @Nullable ClientConnectionTimingsBuilder timingsBuilder) {
         final Bootstrap bootstrap;
         try {
             bootstrap = bootstraps.get(remoteAddress, desiredProtocol, serializationFormat);
@@ -391,6 +395,10 @@ void connect(SocketAddress remoteAddress, SessionProtocol desiredProtocol,
                 final Channel channel = registerFuture.channel();
                 configureProxy(channel, poolKey.proxyConfig, desiredProtocol);
 
+                if (desiredProtocol.isTls() && timingsBuilder != null) {
+                    channel.attr(TIMINGS_BUILDER_KEY).set(timingsBuilder);
+                }
+
                 // should be invoked right before channel.connect() is invoked as defined in javadocs
                 clientFactory.channelPipelineCustomizer().accept(channel.pipeline());
 

core/src/main/java/com/linecorp/armeria/client/HttpClientPipelineConfigurator.java

@@ -17,6 +17,7 @@
 package com.linecorp.armeria.client;
 
 import static com.google.common.base.MoreObjects.firstNonNull;
+import static com.linecorp.armeria.client.HttpChannelPool.TIMINGS_BUILDER_KEY;
 import static com.linecorp.armeria.common.SessionProtocol.H1;
 import static com.linecorp.armeria.common.SessionProtocol.H1C;
 import static com.linecorp.armeria.common.SessionProtocol.H2;
@@ -49,6 +50,7 @@
 import com.linecorp.armeria.common.RequestTarget;
 import com.linecorp.armeria.common.SessionProtocol;
 import com.linecorp.armeria.common.annotation.Nullable;
+import com.linecorp.armeria.common.logging.ClientConnectionTimingsBuilder;
 import com.linecorp.armeria.common.util.Exceptions;
 import com.linecorp.armeria.common.util.SystemInfo;
 import com.linecorp.armeria.internal.client.DecodedHttpResponse;
@@ -216,17 +218,18 @@ private void configureAsHttps(Channel ch, SocketAddress remoteAddr) {
         assert isHttps();
 
         final ChannelPipeline p = ch.pipeline();
-        final SslHandler sslHandler;
+        final SSLEngine sslEngine;
         if (remoteAddr instanceof InetSocketAddress) {
             final InetSocketAddress raddr = (InetSocketAddress) remoteAddr;
-            sslHandler = sslCtx.newHandler(ch.alloc(),
-                                           raddr.getHostString(),
-                                           raddr.getPort());
+            sslEngine = sslCtx.newEngine(ch.alloc(),
+                                         raddr.getHostString(),
+                                         raddr.getPort());
         } else {
             assert remoteAddr instanceof DomainSocketAddress : remoteAddr;
-            sslHandler = sslCtx.newHandler(ch.alloc());
+            sslEngine = sslCtx.newEngine(ch.alloc());
         }
-
+        final ClientConnectionTimingsBuilder timingsBuilder = ch.attr(TIMINGS_BUILDER_KEY).get();
+        final SslHandler sslHandler = new ClientSslHandler(sslEngine, timingsBuilder);
         p.addLast(configureSslHandler(sslHandler));
         p.addLast(TrafficLoggingHandler.CLIENT);
         p.addLast(new ChannelInboundHandlerAdapter() {
@@ -457,6 +460,25 @@ private static boolean isHttp2Protocol(SslHandler sslHandler) {
         return ApplicationProtocolNames.HTTP_2.equals(sslHandler.applicationProtocol());
     }
 
+    /**
+     * A handler that collects the ssl related metric.
+     */
+    private static final class ClientSslHandler extends SslHandler {
+        private final ClientConnectionTimingsBuilder timingsBuilder;
+
+        ClientSslHandler(SSLEngine engine, ClientConnectionTimingsBuilder timingsBuilder) {
+            super(engine);
+            this.timingsBuilder = timingsBuilder;
+        }
+
+        @Override
+        public void channelActive(ChannelHandlerContext ctx) throws Exception {
+            timingsBuilder.tlsHandshakeStart();
+            super.channelActive(ctx);
+            handshakeFuture().addListener(future -> timingsBuilder.tlsHandshakeEnd());
+        }
+    }
+
     /**
      * A handler that triggers the cleartext upgrade to HTTP/2 by sending an initial HTTP request.
      */

core/src/main/java/com/linecorp/armeria/client/HttpSessionHandler.java

@@ -523,9 +523,10 @@ public void channelInactive(ChannelHandlerContext ctx) throws Exception {
             }
             if (proxyDestinationAddress != null) {
                 channelPool.connect(proxyDestinationAddress, retryProtocol, serializationFormat,
-                                    poolKey, sessionPromise);
+                                    poolKey, sessionPromise, null);
             } else {
-                channelPool.connect(remoteAddress, retryProtocol, serializationFormat, poolKey, sessionPromise);
+                channelPool.connect(remoteAddress, retryProtocol, serializationFormat, poolKey, sessionPromise,
+                                    null);
             }
         } else {
             // Fail all pending responses.

core/src/main/java/com/linecorp/armeria/common/logging/ClientConnectionTimings.java

@@ -41,6 +41,8 @@ public final class ClientConnectionTimings {
     private final long dnsResolutionDurationNanos;
     private final long socketConnectStartTimeMicros;
     private final long socketConnectDurationNanos;
+    private final long tlsHandshakeStartTimeMicros;
+    private final long tlsHandshakeDurationNanos;
     private final long pendingAcquisitionStartTimeMicros;
     private final long pendingAcquisitionDurationNanos;
 
@@ -54,13 +56,16 @@ public static ClientConnectionTimingsBuilder builder() {
     ClientConnectionTimings(long connectionAcquisitionStartTimeMicros, long connectionAcquisitionDurationNanos,
                             long dnsResolutionStartTimeMicros, long dnsResolutionDurationNanos,
                             long socketConnectStartTimeMicros, long socketConnectDurationNanos,
+                            long tlsHandshakeStartTimeMicros, long tlsHandshakeDurationNanos,
                             long pendingAcquisitionStartTimeMicros, long pendingAcquisitionDurationNanos) {
         this.connectionAcquisitionStartTimeMicros = connectionAcquisitionStartTimeMicros;
         this.connectionAcquisitionDurationNanos = connectionAcquisitionDurationNanos;
         this.dnsResolutionStartTimeMicros = dnsResolutionStartTimeMicros;
         this.dnsResolutionDurationNanos = dnsResolutionDurationNanos;
         this.socketConnectStartTimeMicros = socketConnectStartTimeMicros;
         this.socketConnectDurationNanos = socketConnectDurationNanos;
+        this.tlsHandshakeStartTimeMicros = tlsHandshakeStartTimeMicros;
+        this.tlsHandshakeDurationNanos = tlsHandshakeDurationNanos;
         this.pendingAcquisitionStartTimeMicros = pendingAcquisitionStartTimeMicros;
         this.pendingAcquisitionDurationNanos = pendingAcquisitionDurationNanos;
     }
@@ -103,10 +108,7 @@ public long dnsResolutionStartTimeMicros() {
      * @return the start time, or {@code -1} if there was no action to resolve a domain name.
      */
     public long dnsResolutionStartTimeMillis() {
-        if (dnsResolutionStartTimeMicros >= 0) {
-            return TimeUnit.MICROSECONDS.toMillis(dnsResolutionStartTimeMicros);
-        }
-        return -1;
+        return toMillis(dnsResolutionStartTimeMicros);
     }
 
     /**
@@ -133,10 +135,7 @@ public long socketConnectStartTimeMicros() {
      * @return the start time, or {@code -1} if there was no action to connect to a remote peer.
      */
     public long socketConnectStartTimeMillis() {
-        if (socketConnectStartTimeMicros >= 0) {
-            return TimeUnit.MICROSECONDS.toMillis(socketConnectStartTimeMicros);
-        }
-        return -1;
+        return toMillis(socketConnectStartTimeMicros);
     }
 
     /**
@@ -148,6 +147,33 @@ public long socketConnectDurationNanos() {
         return socketConnectDurationNanos;
     }
 
+    /**
+     * Returns the time when the client started to TLS handshake, in microseconds since the epoch.
+     *
+     * @return the start time, or {@code -1} if there was no action to TLS handshake.
+     */
+    public long tlsHandshakeStartTimeMicros() {
+        return tlsHandshakeStartTimeMicros;
+    }
+
+    /**
+     * Returns the time when the client started to TLS handshake, in milliseconds since the epoch.
+     *
+     * @return the start time, or {@code -1} if there was no action to TLS handshake.
+     */
+    public long tlsHandshakeStartTimeMillis() {
+        return toMillis(tlsHandshakeStartTimeMicros);
+    }
+
+    /**
+     * Returns the duration which was taken to TLS handshake, in nanoseconds.
+     *
+     * @return the duration, or {@code -1} if there was no action to TLS handshake.
+     */
+    public long tlsHandshakeDurationNanos() {
+        return tlsHandshakeDurationNanos;
+    }
+
     /**
      * Returns the time when the client started to wait for the completion of an existing connection attempt,
      * in microseconds since the epoch.
@@ -165,10 +191,7 @@ public long pendingAcquisitionStartTimeMicros() {
      * @return the start time, or {@code -1} if there was no action to get a pending connection.
      */
     public long pendingAcquisitionStartTimeMillis() {
-        if (pendingAcquisitionStartTimeMicros >= 0) {
-            return TimeUnit.MICROSECONDS.toMillis(pendingAcquisitionStartTimeMicros);
-        }
-        return -1;
+        return toMillis(pendingAcquisitionStartTimeMicros);
     }
 
     /**
@@ -203,6 +226,14 @@ public String toString() {
             buf.append(", socketConnectDuration=");
             TextFormatter.appendElapsed(buf, socketConnectDurationNanos);
         }
+
+        if (tlsHandshakeDurationNanos >= 0) {
+            buf.append(", tlsHandshakeStartTime=");
+            TextFormatter.appendEpochMicros(buf, tlsHandshakeStartTimeMicros);
+            buf.append(", tlsHandshakeDuration=");
+            TextFormatter.appendElapsed(buf, tlsHandshakeDurationNanos);
+        }
+
         if (pendingAcquisitionDurationNanos >= 0) {
             buf.append(", pendingAcquisitionStartTime=");
             TextFormatter.appendEpochMicros(buf, pendingAcquisitionStartTimeMicros);
@@ -212,4 +243,11 @@ public String toString() {
         buf.append('}');
         return buf.toString();
     }
+
+    private static long toMillis(long micro) {
+        if (micro >= 0) {
+            return TimeUnit.MICROSECONDS.toMillis(micro);
+        }
+        return -1;
+    }
 }

core/src/main/java/com/linecorp/armeria/common/logging/ClientConnectionTimingsBuilder.java

@@ -32,6 +32,10 @@ public final class ClientConnectionTimingsBuilder {
 
     private final long connectionAcquisitionStartTimeMicros;
     private final long connectionAcquisitionStartNanos;
+    private long tlsHandshakeStartTimeMicros;
+    private long tlsHandshakeStartNanos;
+    private long tlsHandshakeEndNanos;
+    private boolean tlsHandshakeEndSet;
     private long dnsResolutionEndNanos;
     private boolean dnsResolutionEndSet;
 
@@ -84,6 +88,28 @@ public ClientConnectionTimingsBuilder socketConnectEnd() {
         return this;
     }
 
+    /**
+     * Sets the time when the client started to TLS handshake to a remote peer.
+     */
+    public ClientConnectionTimingsBuilder tlsHandshakeStart() {
+        tlsHandshakeStartTimeMicros = SystemInfo.currentTimeMicros();
+        tlsHandshakeStartNanos = System.nanoTime();
+        return this;
+    }
+
+    /**
+     * Sets the time when the client ended to TLS handshake to a remote peer.
+     *
+     * @throws IllegalStateException if {@link #tlsHandshakeStart()} is not invoked before calling this.
+     */
+    public ClientConnectionTimingsBuilder tlsHandshakeEnd() {
+        checkState(tlsHandshakeStartTimeMicros > 0, "tlsHandshakeStart() is not called yet.");
+        checkState(!tlsHandshakeEndSet, "tlsHandshakeEnd() is already called.");
+        tlsHandshakeEndNanos = System.nanoTime();
+        tlsHandshakeEndSet = true;
+        return this;
+    }
+
     /**
      * Sets the time when the client started to wait for the completion of an existing connection attempt
      * in order to use one connection for HTTP/2.
@@ -127,6 +153,8 @@ public ClientConnectionTimings build() {
                 dnsResolutionEndSet ? dnsResolutionEndNanos - connectionAcquisitionStartNanos : -1,
                 socketConnectEndSet ? socketConnectStartTimeMicros : -1,
                 socketConnectEndSet ? socketConnectEndNanos - socketConnectStartNanos : -1,
+                tlsHandshakeEndSet ? tlsHandshakeStartTimeMicros : -1,
+                tlsHandshakeEndSet ? tlsHandshakeEndNanos - tlsHandshakeStartNanos : -1,
                 pendingAcquisitionEndSet ? pendingAcquisitionStartTimeMicros : -1,
                 pendingAcquisitionEndSet ? pendingAcquisitionEndNanos - pendingAcquisitionStartNanos : -1);
     }

core/src/main/java/com/linecorp/armeria/internal/common/metric/RequestMetricSupport.java

@@ -126,6 +126,10 @@ private static void onResponse(
             if (socketConnectDurationNanos >= 0) {
                 metrics.socketConnectDuration().record(socketConnectDurationNanos, TimeUnit.NANOSECONDS);
             }
+            final long tlsHandshakeDurationNanos = timings.tlsHandshakeDurationNanos();
+            if (tlsHandshakeDurationNanos >= 0) {
+                metrics.tlsHandshakeDuration().record(tlsHandshakeDurationNanos, TimeUnit.NANOSECONDS);
+            }
             final long pendingAcquisitionDurationNanos = timings.pendingAcquisitionDurationNanos();
             if (pendingAcquisitionDurationNanos >= 0) {
                 metrics.pendingAcquisitionDuration().record(pendingAcquisitionDurationNanos,
@@ -204,6 +208,8 @@ private interface ClientRequestMetrics extends RequestMetrics {
 
         Timer socketConnectDuration();
 
+        Timer tlsHandshakeDuration();
+
         Timer pendingAcquisitionDuration();
 
         Counter writeTimeouts();
@@ -299,6 +305,7 @@ private static class DefaultClientRequestMetrics
         private final Timer connectionAcquisitionDuration;
         private final Timer dnsResolutionDuration;
         private final Timer socketConnectDuration;
+        private final Timer tlsHandshakeDuration;
         private final Timer pendingAcquisitionDuration;
 
         private final Counter writeTimeouts;
@@ -328,6 +335,9 @@ private static class DefaultClientRequestMetrics
             socketConnectDuration = newTimer(
                     parent, idPrefix.name("socket.connect.duration"), idPrefix.tags(),
                     distributionStatisticConfig);
+            tlsHandshakeDuration = newTimer(
+                    parent, idPrefix.name("tls.handshake.duration"), idPrefix.tags(),
+                    distributionStatisticConfig);
             pendingAcquisitionDuration = newTimer(
                     parent, idPrefix.name("pending.acquisition.duration"), idPrefix.tags(),
                     distributionStatisticConfig);
@@ -360,6 +370,11 @@ public Timer socketConnectDuration() {
             return socketConnectDuration;
         }
 
+        @Override
+        public Timer tlsHandshakeDuration() {
+            return tlsHandshakeDuration;
+        }
+
         @Override
         public Timer pendingAcquisitionDuration() {
             return pendingAcquisitionDuration;