Skip to content

Commit

Permalink
use seconds instead of milliseconds; add duration extension
Browse files Browse the repository at this point in the history
  • Loading branch information
aajtodd committed Jun 29, 2023
1 parent b979988 commit 9eb1e0d
Show file tree
Hide file tree
Showing 7 changed files with 62 additions and 30 deletions.
3 changes: 3 additions & 0 deletions runtime/observability/telemetry-api/api/telemetry-api.api
Original file line number Diff line number Diff line change
Expand Up @@ -137,6 +137,9 @@ public final class aws/smithy/kotlin/runtime/telemetry/metrics/Histogram$Default
public static synthetic fun record$default (Laws/smithy/kotlin/runtime/telemetry/metrics/Histogram;Ljava/lang/Number;Laws/smithy/kotlin/runtime/util/Attributes;Laws/smithy/kotlin/runtime/telemetry/context/Context;ILjava/lang/Object;)V
}

public final class aws/smithy/kotlin/runtime/telemetry/metrics/HistogramKt {
}

public abstract interface class aws/smithy/kotlin/runtime/telemetry/metrics/Meter {
public abstract fun createAsyncUpDownCounter (Ljava/lang/String;Lkotlin/jvm/functions/Function1;Ljava/lang/String;Ljava/lang/String;)Laws/smithy/kotlin/runtime/telemetry/metrics/AsyncMeasurementHandle;
public abstract fun createDoubleGauge (Ljava/lang/String;Lkotlin/jvm/functions/Function1;Ljava/lang/String;Ljava/lang/String;)Laws/smithy/kotlin/runtime/telemetry/metrics/AsyncMeasurementHandle;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -5,9 +5,11 @@

package aws.smithy.kotlin.runtime.telemetry.metrics

import aws.smithy.kotlin.runtime.InternalApi
import aws.smithy.kotlin.runtime.telemetry.context.Context
import aws.smithy.kotlin.runtime.util.Attributes
import aws.smithy.kotlin.runtime.util.emptyAttributes
import kotlin.time.Duration

public interface Histogram<T : Number> {
/**
Expand All @@ -25,3 +27,17 @@ public interface Histogram<T : Number> {
}
public typealias LongHistogram = Histogram<Long>
public typealias DoubleHistogram = Histogram<Double>

/**
* Record a duration in seconds using millisecond precision.
*
* @param value the duration to record
* @param attributes attributes to associate with this measurement
* @param context (Optional) trace context to associate with this measurement
*/
@InternalApi
public fun DoubleHistogram.recordSeconds(value: Duration, attributes: Attributes = emptyAttributes(), context: Context? = null) {
val ms = value.inWholeMilliseconds.toDouble()
val sec = ms / 1000
record(sec, attributes, context)
}
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ import aws.smithy.kotlin.runtime.telemetry.logging.LoggerProvider
import aws.smithy.kotlin.runtime.telemetry.logging.MessageSupplier
import aws.smithy.kotlin.runtime.telemetry.logging.getLogger
import aws.smithy.kotlin.runtime.telemetry.logging.logger
import aws.smithy.kotlin.runtime.telemetry.metrics.recordSeconds
import aws.smithy.kotlin.runtime.telemetry.telemetryProvider
import aws.smithy.kotlin.runtime.telemetry.trace.SpanStatus
import aws.smithy.kotlin.runtime.telemetry.trace.recordException
Expand Down Expand Up @@ -100,7 +101,7 @@ internal class HttpEngineEventListener(
metrics.acquiredConnections = pool.connectionCount().toLong()
metrics.idleConnections = pool.idleConnectionCount().toLong()
connectStart?.let {
metrics.connectionAcquireDuration.record(it.elapsedNow().inWholeMilliseconds)
metrics.connectionAcquireDuration.recordSeconds(it.elapsedNow())
}

val connId = System.identityHashCode(connection)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -7,8 +7,8 @@ package aws.smithy.kotlin.runtime.http.engine.internal
import aws.smithy.kotlin.runtime.InternalApi
import aws.smithy.kotlin.runtime.io.Closeable
import aws.smithy.kotlin.runtime.telemetry.TelemetryProvider
import aws.smithy.kotlin.runtime.telemetry.metrics.DoubleHistogram
import aws.smithy.kotlin.runtime.telemetry.metrics.LongAsyncMeasurement
import aws.smithy.kotlin.runtime.telemetry.metrics.LongHistogram
import aws.smithy.kotlin.runtime.util.Attributes
import aws.smithy.kotlin.runtime.util.attributesOf
import kotlinx.atomicfu.atomic
Expand Down Expand Up @@ -42,13 +42,14 @@ public class HttpClientMetrics(
private val _connectionsLimit = atomic(0L)
private val _idleConnections = atomic(0L)
private val _acquiredConnections = atomic(0L)
private val _requestConcurrencyLimit = atomic(0L)
private val _queuedRequests = atomic(0L)
private val _inFlightRequests = atomic(0L)

/**
* The amount of time it takes to acquire a connection from the pool
*/
public val connectionAcquireDuration: LongHistogram = meter.createLongHistogram(
public val connectionAcquireDuration: DoubleHistogram = meter.createDoubleHistogram(
"smithy.client.http.connections.acquire_duration",
"ms",
"The amount of time requests take to acquire a connection from the pool",
Expand All @@ -57,7 +58,7 @@ public class HttpClientMetrics(
/**
* The amount of time a request spent queued waiting to be executed by the HTTP client
*/
public val concurrencyQueuedDuration: LongHistogram = meter.createLongHistogram(
public val concurrencyQueuedDuration: DoubleHistogram = meter.createDoubleHistogram(
"smithy.client.http.concurrency.queued_duration",
"ms",
"The amount of time a requests spent queued waiting to be executed by the HTTP client",
Expand All @@ -77,13 +78,12 @@ public class HttpClientMetrics(
"Current state of connections (idle, acquired)",
)

// TODO - enable?
// private val concurrencyLimitHandle = meter.createAsyncUpDownCounter(
// "smithy.client.http.concurrency.limit",
// { it.record(_connectionsLimit.value) },
// "{connection}",
// "Max connections configured for the HTTP client",
// )
private val concurrencyLimitHandle = meter.createAsyncUpDownCounter(
"smithy.client.http.concurrency.limit",
{ it.record(_requestConcurrencyLimit.value) },
"{request}",
"Max concurrent requests configured for the HTTP client",
)

private val concurrencyHandle = meter.createAsyncUpDownCounter(
"smithy.client.http.concurrency.usage",
Expand All @@ -101,6 +101,15 @@ public class HttpClientMetrics(
_connectionsLimit.update { value }
}

/**
* The maximum number of concurrent requests configured for the client
*/
public var requestConcurrencyLimit: Long
get() = _requestConcurrencyLimit.value
set(value) {
_requestConcurrencyLimit.update { value }
}

/**
* The number of idle (warm) connections in the pool right now
*/
Expand Down Expand Up @@ -183,5 +192,6 @@ public class HttpClientMetrics(
connectionLimitHandle.stop()
connectionUsageHandle.stop()
concurrencyHandle.stop()
concurrencyLimitHandle.stop()
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ import aws.smithy.kotlin.runtime.client.ResponseInterceptorContext
import aws.smithy.kotlin.runtime.http.operation.OperationMetrics
import aws.smithy.kotlin.runtime.http.request.HttpRequest
import aws.smithy.kotlin.runtime.http.response.HttpResponse
import aws.smithy.kotlin.runtime.telemetry.metrics.recordSeconds
import aws.smithy.kotlin.runtime.util.attributesOf
import kotlin.time.ExperimentalTime
import kotlin.time.TimeMark
Expand All @@ -35,7 +36,6 @@ internal class OperationTelemetryInterceptor(
private var callStart: TimeMark? = null
private var serializeStart: TimeMark? = null
private var deserializeStart: TimeMark? = null
private var signingStart: TimeMark? = null
private var transmitStart: TimeMark? = null

private val perRpcAttributes = attributesOf {
Expand All @@ -48,11 +48,11 @@ internal class OperationTelemetryInterceptor(
}

override fun readAfterExecution(context: ResponseInterceptorContext<Any, Any, HttpRequest?, HttpResponse?>) {
val callDuration = callStart?.elapsedNow()?.inWholeMilliseconds ?: return
val callDuration = callStart?.elapsedNow() ?: return

// TODO - total requests?

metrics.rpcCallDuration.record(callDuration, perRpcAttributes, metrics.provider.contextManager.current())
metrics.rpcCallDuration.recordSeconds(callDuration, perRpcAttributes, metrics.provider.contextManager.current())

context.protocolRequest?.body?.contentLength?.let {
metrics.rpcRequestSize.record(it, perRpcAttributes, metrics.provider.contextManager.current())
Expand All @@ -68,25 +68,25 @@ internal class OperationTelemetryInterceptor(
}

override fun readAfterSerialization(context: ProtocolRequestInterceptorContext<Any, HttpRequest>) {
val serializeDuration = serializeStart?.elapsedNow()?.inWholeMilliseconds ?: return
metrics.serializationDuration.record(serializeDuration, perRpcAttributes, metrics.provider.contextManager.current())
val serializeDuration = serializeStart?.elapsedNow() ?: return
metrics.serializationDuration.recordSeconds(serializeDuration, perRpcAttributes, metrics.provider.contextManager.current())
}

override fun readBeforeDeserialization(context: ProtocolResponseInterceptorContext<Any, HttpRequest, HttpResponse>) {
deserializeStart = timeSource.markNow()
}

override fun readAfterDeserialization(context: ResponseInterceptorContext<Any, Any, HttpRequest, HttpResponse>) {
val deserializeDuration = deserializeStart?.elapsedNow()?.inWholeMilliseconds ?: return
metrics.deserializationDuration.record(deserializeDuration, perRpcAttributes, metrics.provider.contextManager.current())
val deserializeDuration = deserializeStart?.elapsedNow() ?: return
metrics.deserializationDuration.recordSeconds(deserializeDuration, perRpcAttributes, metrics.provider.contextManager.current())
}

override fun readBeforeTransmit(context: ProtocolRequestInterceptorContext<Any, HttpRequest>) {
transmitStart = timeSource.markNow()
}

override fun readAfterTransmit(context: ProtocolResponseInterceptorContext<Any, HttpRequest, HttpResponse>) {
val serviceCallDuration = transmitStart?.elapsedNow()?.inWholeMilliseconds ?: return
metrics.serviceCallDuration.record(serviceCallDuration, perRpcAttributes, metrics.provider.contextManager.current())
val serviceCallDuration = transmitStart?.elapsedNow() ?: return
metrics.serviceCallDuration.recordSeconds(serviceCallDuration, perRpcAttributes, metrics.provider.contextManager.current())
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ package aws.smithy.kotlin.runtime.http.operation

import aws.smithy.kotlin.runtime.InternalApi
import aws.smithy.kotlin.runtime.telemetry.TelemetryProvider
import aws.smithy.kotlin.runtime.telemetry.metrics.DoubleHistogram
import aws.smithy.kotlin.runtime.telemetry.metrics.LongHistogram

/**
Expand All @@ -24,13 +25,13 @@ public class OperationMetrics(
val None: OperationMetrics = OperationMetrics("NoOp", TelemetryProvider.None)
}

public val rpcCallDuration: LongHistogram = meter.createLongHistogram("smithy.client.duration", "ms", "Overall call duration including retries")
public val rpcCallDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.duration", "s", "Overall call duration including retries")
public val rpcRequestSize: LongHistogram = meter.createLongHistogram("smithy.client.request.size", "By", "Size of the serialized request message")
public val rpcResponseSize: LongHistogram = meter.createLongHistogram("smithy.client.response.size", "By", "Size of the serialized response message")
public val serviceCallDuration: LongHistogram = meter.createLongHistogram("smithy.client.service_call_duration", "ms", "The time it takes to connect to the service, send the request, and receive the HTTP status code and headers from the response")
public val serializationDuration: LongHistogram = meter.createLongHistogram("smithy.client.serialization_duration", "ms", "The time it takes to serialize a request message body")
public val deserializationDuration: LongHistogram = meter.createLongHistogram("smithy.client.deserialization_duration", "ms", "The time it takes to deserialize a response message body")
public val resolveEndpointDuration: LongHistogram = meter.createLongHistogram("smithy.client.resolve_endpoint_duration", "ms", "The time it takes to resolve an endpoint for a request")
public val resolveIdentityDuration: LongHistogram = meter.createLongHistogram("smithy.client.auth.resolve_identity_duration", "ms", "The time it takes to resolve an identity for signing a request")
public val signingDuration: LongHistogram = meter.createLongHistogram("smithy.client.auth.signing_duration", "ms", "The time it takes to sign a request")
public val serviceCallDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.service_call_duration", "s", "The time it takes to connect to the service, send the request, and receive the HTTP status code and headers from the response")
public val serializationDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.serialization_duration", "s", "The time it takes to serialize a request message body")
public val deserializationDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.deserialization_duration", "s", "The time it takes to deserialize a response message body")
public val resolveEndpointDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.resolve_endpoint_duration", "s", "The time it takes to resolve an endpoint for a request")
public val resolveIdentityDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.auth.resolve_identity_duration", "s", "The time it takes to resolve an identity for signing a request")
public val signingDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.auth.signing_duration", "s", "The time it takes to sign a request")
}
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,7 @@ import aws.smithy.kotlin.runtime.retries.policy.StandardRetryPolicy
import aws.smithy.kotlin.runtime.telemetry.logging.debug
import aws.smithy.kotlin.runtime.telemetry.logging.logger
import aws.smithy.kotlin.runtime.telemetry.logging.trace
import aws.smithy.kotlin.runtime.telemetry.metrics.recordSeconds
import aws.smithy.kotlin.runtime.util.attributesOf
import aws.smithy.kotlin.runtime.util.merge
import kotlin.coroutines.coroutineContext
Expand Down Expand Up @@ -280,7 +281,7 @@ internal class AuthHandler<Input, Output>(
val identity = measureTimedValue {
identityProvider.resolve(authOption.attributes)
}.let {
request.context.operationMetrics.resolveIdentityDuration.record(it.duration.inWholeMilliseconds, schemeAttr)
request.context.operationMetrics.resolveIdentityDuration.recordSeconds(it.duration, schemeAttr)
it.value
}

Expand All @@ -290,7 +291,7 @@ internal class AuthHandler<Input, Output>(
val endpoint = measureTimedValue {
endpointResolver.resolve(resolveEndpointReq)
}.let {
request.context.operationMetrics.resolveEndpointDuration.record(it.duration.inWholeMilliseconds, request.context.operationAttributes)
request.context.operationMetrics.resolveEndpointDuration.recordSeconds(it.duration, request.context.operationAttributes)
it.value
}
coroutineContext.debug<AuthHandler<*, *>> { "resolved endpoint: $endpoint" }
Expand All @@ -309,7 +310,7 @@ internal class AuthHandler<Input, Output>(
measureTime {
authScheme.signer.sign(signingRequest)
}.let {
request.context.operationMetrics.signingDuration.record(it.inWholeMilliseconds, schemeAttr)
request.context.operationMetrics.signingDuration.recordSeconds(it, schemeAttr)
}

interceptors.readAfterSigning(modified.subject.immutableView())
Expand Down

0 comments on commit 9eb1e0d

Please sign in to comment.