[client-v2] httpcomponents.httpclient.connect.time does not include the TCP connect or the TLS handshake

Read client-v2/src/main/java/com/clickhouse/client/api/internal/HttpAPIClientHelper.java around MeteredManagedHttpClientConnectionFactory.createConnection, then trace the connection manager's connect() path and the suggested operator or manager hooks. Check MetricsTest.testConnectionTime in client-v2/src/test/java/com/clickhouse/client/metrics/MetricsTest.java. Done means new connections record DNS, TCP and TLS setup time, reused connections add no sample, and the test verifies the behavior.

Description

The Micrometer gauge httpcomponents.httpclient.connect.time is documented as "Running average connection establishment time" (client.mdx#L1081). It does not measure connection establishment. It measures only the construction of the Java connection object. The DNS lookup, the TCP connect and the TLS handshake occur after the measured call. For a new connection the gauge shows 0-2 ms, also when the connect takes hundreds of milliseconds.

MeteredManagedHttpClientConnectionFactory.createConnection(Socket) times super.createConnection(socket). Apache HttpClient 5 calls this method with socket == null. It does this when it leases a pool entry that has no connection (PoolingHttpClientConnectionManager.java:443 in httpclient5 5.6.4), or at the start of connect() (:535). After that, connectionOperator.connect(...) (:547) resolves the host, opens the socket and does the TLS upgrade (DefaultHttpClientConnectionOperator.connect). The factory does not wrap that call. httpclient5 5.2.1 was the version when the metric was added (605d50687). It has the same call order, so the metric has never included the connect. This is not a regression.

Related facts:

• The only test of the value, MetricsTest.testConnectionTime, is disabled with the comment "Disabled because we can't assume the time is greater than 0" (MetricsTest.java#L124-L126).
• The factory records whole milliseconds (System.currentTimeMillis()), and getTime() returns an integer-millisecond average. Thus a sub-millisecond value shows as 0.

The same factory has a different defect in #3253: that issue is about how long the recorded values are kept, and this issue is about what the value measures.

Found by automated analysis of the client while working on #3253. Verified against a live server, not by inspection only.

Steps to reproduce

1. Put a local TLS proxy in front of ClickHouse. The proxy waits 300 ms before it does the TLS handshake, so each new connection needs 300 ms or more to become usable.
2. Build a Client with registerClientMetrics(new SimpleMeterRegistry(), "repro"), endpoint https://127.0.0.1:<proxy port>, and setConnectionTTL(1, ChronoUnit.MILLIS), so that each request opens a new connection.
3. Run SELECT 1 several times. Read the gauge after each request. Compare with a run that reuses one connection (no TTL).
4. Optional: set a jdb breakpoint on HttpAPIClientHelper$MeteredManagedHttpClientConnectionFactory.createConnection(java.net.Socket). Then examine socket and the stack.

Error Log or Exception StackTrace

No exception. In the output below, proxy accepts is the number of TCP connections that the proxy accepted during the request. factory recorded is the content of the factory queue before the gauge read.

=== TLS, 300 ms handshake delay, connection_ttl = 1 ms (new connection per request)
req 1: request wall time=864 ms, proxy accepts=1, factory recorded=[70] ms, gauge connect.time=70.0
req 2: request wall time=396 ms, proxy accepts=1, factory recorded=[1] ms, gauge connect.time=1.0
req 3: request wall time=347 ms, proxy accepts=1, factory recorded=[2] ms, gauge connect.time=2.0
req 4: request wall time=423 ms, proxy accepts=1, factory recorded=[1] ms, gauge connect.time=1.0
req 5: request wall time=409 ms, proxy accepts=1, factory recorded=[1] ms, gauge connect.time=1.0
=== TLS, 300 ms handshake delay, default config (connection reused)
req 1: request wall time=441 ms, proxy accepts=1, factory recorded=[3] ms, gauge connect.time=3.0
req 2: request wall time=12 ms, proxy accepts=0, factory recorded=[] ms, gauge connect.time=0.0
req 3: request wall time=16 ms, proxy accepts=0, factory recorded=[] ms, gauge connect.time=0.0
req 4: request wall time=53 ms, proxy accepts=0, factory recorded=[] ms, gauge connect.time=0.0
req 5: request wall time=11 ms, proxy accepts=0, factory recorded=[] ms, gauge connect.time=0.0
=== plain HTTP direct, connection_ttl = 1 ms (new connection per request)
req 1: request wall time=18 ms, proxy accepts=0, factory recorded=[0] ms, gauge connect.time=0.0
req 2: request wall time=7 ms, proxy accepts=0, factory recorded=[0] ms, gauge connect.time=0.0
req 3: request wall time=9 ms, proxy accepts=0, factory recorded=[1] ms, gauge connect.time=1.0

A new connection adds 330-410 ms to the request (347-423 ms, against 11-16 ms on a reused connection), but the gauge shows 1-2 ms. The 70 ms on the first request is class loading on first use.

jdb at the breakpoint, first request:

main[1] print socket
 socket = null
main[1] print ConnectTimeRepro.accepted
 ConnectTimeRepro.accepted = "0"
main[1] where
  [1] com.clickhouse.client.api.internal.HttpAPIClientHelper$MeteredManagedHttpClientConnectionFactory.createConnection (HttpAPIClientHelper.java:1,303)
  [2] com.clickhouse.client.api.internal.HttpAPIClientHelper$MeteredManagedHttpClientConnectionFactory.createConnection (HttpAPIClientHelper.java:1,293)
  [3] org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager$3.get (PoolingHttpClientConnectionManager.java:443)
  [4] org.apache.hc.client5.http.impl.classic.InternalExecRuntime.acquireEndpoint (InternalExecRuntime.java:111)
  [5] org.apache.hc.client5.http.impl.classic.ConnectExec.execute (ConnectExec.java:127)
  ...
  [20] com.clickhouse.client.api.internal.HttpAPIClientHelper.doExecuteRequest (HttpAPIClientHelper.java:821)

The factory runs during the pool lease (acquireEndpoint). At that time there is no socket and the proxy has not accepted a TCP connection.

Expected Behaviour

For a new connection, httpcomponents.httpclient.connect.time includes the time to establish it: DNS lookup, TCP connect and TLS handshake, as the docs say. In the reproduction above, it shows approximately 300 ms or more for each new TLS connection, not 1-2 ms.

Root cause (main 0946034a2):

• HttpAPIClientHelper.java#L1302-L1310: createConnection(Socket) times only super.createConnection(socket). HttpClient calls it with null before the connect.
• httpclient5 5.6.4 PoolingHttpClientConnectionManager: createConnection(null) at lines 443 (lease) and 535 (connect()), then connectionOperator.connect(...) at line 547, which does the DNS lookup, socket.connect and the TLS upgrade.
• MicrometerLoader.java#L55-L60: the gauge (description "The running average connection creation time.").

Suggested fix:

• Measure the connect step, not the connection factory. Two possible ways:

  • Override connect(ConnectionEndpoint, TimeValue, HttpContext) in a PoolingHttpClientConnectionManager subclass, and time super.connect(...).
  • Wrap the HttpClientConnectionOperator, and time its connect(...). PoolingHttpClientConnectionManagerBuilder.createConnectionOperator(...) is protected.

  Both ways include the DNS lookup, the TCP connect and the TLS handshake for direct routes.

• Measure with System.nanoTime() and keep sub-millisecond precision, or use a Micrometer Timer instead of an integer-millisecond gauge.

• Contrast case that must not change: a request on a reused pooled connection adds no sample.

• #3253 changes the same class. It can be useful to fix both together.

• Re-enable testConnectionTime, or add a test with a delayed endpoint. Also make the descriptions agree ("establishment" in the docs, "creation" in MicrometerLoader).

Code Example

// Classpath: client-v2 + dependencies + micrometer-core. /tmp/proxy.p12: self-signed key, SAN ip:127.0.0.1.
// Proxy: wait 300 ms, then do the TLS handshake, then forward bytes to ClickHouse HTTP.
SSLServerSocket ss = (SSLServerSocket) serverCtx.getServerSocketFactory()
        .createServerSocket(0, 50, InetAddress.getLoopbackAddress());
// for each accepted SSLSocket s (own thread):
//     Thread.sleep(300); s.startHandshake(); Socket up = new Socket("clickhouse", 8123); pipe(s <-> up);

SimpleMeterRegistry reg = new SimpleMeterRegistry();
try (Client client = new Client.Builder()
        .addEndpoint("https://127.0.0.1:" + ss.getLocalPort())
        .setUsername("default").setPassword("...")
        .setSSLContext(trustAllContext).setSSLMode(SSLMode.TRUST)
        .setConnectionTTL(1, ChronoUnit.MILLIS)          // new connection for each request
        .registerClientMetrics(reg, "repro")
        .build()) {
    Gauge gauge = reg.find("httpcomponents.httpclient.connect.time").gauge();
    for (int i = 1; i <= 5; i++) {
        long t0 = System.nanoTime();
        try (QueryResponse r = client.query("SELECT 1").get(30, TimeUnit.SECONDS)) { }
        long ms = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - t0);
        Thread.sleep(5);                                  // let the TTL expire
        System.out.printf("req %d: request wall time=%d ms, gauge connect.time=%.1f%n", i, ms, gauge.value());
    }
}

Configuration

Client Configuration

new Client.Builder()
        .addEndpoint("https://127.0.0.1:<proxy port>")
        .setSSLContext(trustAllContext).setSSLMode(SSLMode.TRUST)
        .setConnectionTTL(1, ChronoUnit.MILLIS)
        .registerClientMetrics(new SimpleMeterRegistry(), "repro")
        .build();

Environment

• Cloud
• Client version: client-v2 0.12.0-rc1-SNAPSHOT (main 0946034a2), httpclient5 5.6.4, micrometer-core 1.17.1
• Language version: OpenJDK 17.0.20.1 (Temurin)
• OS: Linux (Ubuntu 22.04 container)

ClickHouse Server

• ClickHouse Server version: 26.9.1.1629
• ClickHouse Server non-default settings, if any: none that apply
• CREATE TABLE statements for tables involved: none (SELECT 1)
• Sample data for all these tables: n/a