Collect timings related with TLS handshake

[Leewongi0731]

Motivation:

Collect the timings related with TLS handshake. If a request was the first in a connection, armeria could also provide it in a RequestLog to tell a user that the request timing has been affected by TLS handshake.

Modifications:

• Add TLS handshake related field in ClientConnectionTimings
• Add TLS handshake duration metric field at MetricCollectingClient
• Start collecting the TLS handshake timer in the case below.
  • If the client is enabled as TCP fast open in the first request, start the timer before the TCP connection.
  • start the timer when netty calls SslHandler.channelActive()

Result:

• Closes Collect timings related with TLS handshake and protocol upgrade #3647

[github-actions]

🔍 Build Scan® (commit: 43eca15)

Job name	Status	Build Scan®
build-windows-latest-jdk-19	✅	https://ge.armeria.dev/s/ch7tpdqlqmh6u
build-self-hosted-unsafe-jdk-8	✅	https://ge.armeria.dev/s/pxczxoqz7shf6
build-self-hosted-unsafe-jdk-19-snapshot-blockhound	✅	https://ge.armeria.dev/s/l6pwhyqgjf5ku
build-self-hosted-unsafe-jdk-17-min-java-17-coverage	✅	https://ge.armeria.dev/s/nfk24356rofpu
build-self-hosted-unsafe-jdk-17-min-java-11	✅	https://ge.armeria.dev/s/m63yyh7w2rvrq
build-self-hosted-unsafe-jdk-17-leak	✅	https://ge.armeria.dev/s/ivmsuqx7uzfpm
build-self-hosted-unsafe-jdk-11	✅	https://ge.armeria.dev/s/lcplfewunk2as
build-macos-12-jdk-19	✅	https://ge.armeria.dev/s/756u4aui7sdee

[jrhee17]

Looks good overall! Left some minor comments! 👍

[Leewongi0731]

Additionally, shouldn't the check condition at the bottom be >0 instead of >=0??

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

  Line 84 in 3033fea

  checkState(socketConnectStartTimeMicros >= 0, "socketConnectStart() is not called yet.");

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

  Line 135 in 3033fea

  checkState(pendingAcquisitionStartTimeMicros >= 0, "pendingAcquisitionStart() is not called yet.");

[minwoox]

Additionally, shouldn't the check condition at the bottom be >0 instead of >=0??

Oops, I think so. 😓

[jrhee17]

Looks almost done! Left some minor comments 👍

[Leewongi0731]

Oops, I think so. 😓

If find a bug while working on a different �issue like this, should I make and work on a separate issue ticket or fix it together in this PR?

[jrhee17]

Forgot to mention this, but it is probably more useful if users can view this timing by default when they add a MetricCollectingClient.

e.g.

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

Lines 118 to 134 in 0d5b520

	if (timings != null) {
	metrics.connectionAcquisitionDuration().record(timings.connectionAcquisitionDurationNanos(),
	TimeUnit.NANOSECONDS);
	final long dnsResolutionDurationNanos = timings.dnsResolutionDurationNanos();
	if (dnsResolutionDurationNanos >= 0) {
	metrics.dnsResolutionDuration().record(dnsResolutionDurationNanos, TimeUnit.NANOSECONDS);
	}
	final long socketConnectDurationNanos = timings.socketConnectDurationNanos();
	if (socketConnectDurationNanos >= 0) {
	metrics.socketConnectDuration().record(socketConnectDurationNanos, TimeUnit.NANOSECONDS);
	}
	final long pendingAcquisitionDurationNanos = timings.pendingAcquisitionDurationNanos();
	if (pendingAcquisitionDurationNanos >= 0) {
	metrics.pendingAcquisitionDuration().record(pendingAcquisitionDurationNanos,
	TimeUnit.NANOSECONDS);
	}
	}

[jrhee17]

should I make and work on a separate issue ticket or fix it together in this PR?

It's your choice, but I prefer that it be handled separately

[Leewongi0731]

It's your choice, but I prefer that it be handled separately

Okay, I will make new issue and new PR!!

[minwoox]

Looks really great!
Thanks, @Leewongi0731! 👍 👍 👍

[jrhee17]

Very nicely done. Thanks @Leewongi0731 🙇 👍 🙇

[trustin]

Nice job, @Leewongi0731! Let's merge once @minwoox's comment about deduplication is addressed.

[minwoox]

Great job, @Leewongi0731! 😊