From 89f1094476b8a404871f591cdb2e6e8dd7870259 Mon Sep 17 00:00:00 2001 From: Mateusz Rzeszutek Date: Fri, 17 Sep 2021 16:01:08 +0200 Subject: [PATCH] Add start/end time to RequestListener --- .../api/instrumenter/Instrumenter.java | 36 ++++++++++++++---- .../api/instrumenter/RequestListener.java | 20 +++++++--- .../instrumenter/http/HttpClientMetrics.java | 10 ++--- .../instrumenter/http/HttpServerMetrics.java | 9 ++--- .../http/HttpClientMetricsTest.java | 38 ++++++++++--------- .../http/HttpServerMetricsTest.java | 38 ++++++++++--------- 6 files changed, 93 insertions(+), 58 deletions(-) diff --git a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java index 4143a0408dcd..191350398ac2 100644 --- a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java +++ b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java @@ -15,8 +15,10 @@ import io.opentelemetry.context.Context; import io.opentelemetry.instrumentation.api.InstrumentationVersion; import io.opentelemetry.instrumentation.api.internal.SupportabilityMetrics; +import java.time.Instant; import java.util.ArrayList; import java.util.List; +import java.util.concurrent.TimeUnit; import org.checkerframework.checker.nullness.qual.Nullable; // TODO(anuraaga): Need to define what are actually useful knobs, perhaps even providing a @@ -127,8 +129,10 @@ public Context start(Context parentContext, REQUEST request) { .setSpanKind(spanKind) .setParent(parentContext); + Instant startTime = null; if (startTimeExtractor != null) { - spanBuilder.setStartTimestamp(startTimeExtractor.extract(request)); + startTime = startTimeExtractor.extract(request); + spanBuilder.setStartTimestamp(startTime); } SpanLinksBuilder spanLinksBuilder = new SpanLinksBuilderImpl(spanBuilder); @@ -144,8 +148,11 @@ public Context start(Context parentContext, REQUEST request) { Context context = parentContext; - for (RequestListener requestListener : requestListeners) { - context = requestListener.start(context, attributes); + if (!requestListeners.isEmpty()) { + long startNanos = getNanos(startTime); + for (RequestListener requestListener : requestListeners) { + context = requestListener.start(context, attributes, startNanos); + } } spanBuilder.setAllAttributes(attributes); @@ -177,8 +184,16 @@ public void end( Attributes attributes = attributesBuilder; span.setAllAttributes(attributes); - for (RequestListener requestListener : requestListeners) { - requestListener.end(context, attributes); + Instant endTime = null; + if (endTimeExtractor != null) { + endTime = endTimeExtractor.extract(request, response, error); + } + + if (!requestListeners.isEmpty()) { + long endNanos = getNanos(endTime); + for (RequestListener requestListener : requestListeners) { + requestListener.end(context, attributes, endNanos); + } } StatusCode statusCode = spanStatusExtractor.extract(request, response, error); @@ -186,10 +201,17 @@ public void end( span.setStatus(statusCode); } - if (endTimeExtractor != null) { - span.end(endTimeExtractor.extract(request, response, error)); + if (endTime != null) { + span.end(endTime); } else { span.end(); } } + + private static long getNanos(@Nullable Instant time) { + if (time == null) { + return System.nanoTime(); + } + return TimeUnit.SECONDS.toNanos(time.getEpochSecond()) + time.getNano(); + } } diff --git a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/RequestListener.java b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/RequestListener.java index eaa56295ac01..1a4697ae6290 100644 --- a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/RequestListener.java +++ b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/RequestListener.java @@ -10,9 +10,9 @@ /** * A listener of the start and end of a request. Instrumented libraries will call {@link - * #start(Context, Attributes)} as early as possible in the processing of a request and {@link - * #end(Context, Attributes)} as late as possible when finishing the request. These correspond to - * the start and end of a span when tracing. + * #start(Context, Attributes, long)} as early as possible in the processing of a request and {@link + * #end(Context, Attributes, long)} as late as possible when finishing the request. These correspond + * to the start and end of a span when tracing. */ public interface RequestListener { @@ -20,9 +20,17 @@ public interface RequestListener { * Listener method that is called at the start of a request. If any state needs to be kept between * the start and end of the request, e.g., an in-progress span, it should be added to the passed * in {@link Context} and returned. + * + * @param startNanos The nanosecond timestamp marking the start of the request. Can be used to + * compute the duration of the entire operation. */ - Context start(Context context, Attributes startAttributes); + Context start(Context context, Attributes startAttributes, long startNanos); - /** Listener method that is called at the end of a request. */ - void end(Context context, Attributes endAttributes); + /** + * Listener method that is called at the end of a request. + * + * @param endNanos The nanosecond timestamp marking the end of the request. Can be used to compute + * the duration of the entire operation. + */ + void end(Context context, Attributes endAttributes, long endNanos); } diff --git a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetrics.java b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetrics.java index 85fb64621c0e..e17db01a1f7e 100644 --- a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetrics.java +++ b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetrics.java @@ -60,16 +60,14 @@ private HttpClientMetrics(Meter meter) { } @Override - public Context start(Context context, Attributes startAttributes) { - long startTimeNanos = System.nanoTime(); - + public Context start(Context context, Attributes startAttributes, long startNanos) { return context.with( HTTP_CLIENT_REQUEST_METRICS_STATE, - new AutoValue_HttpClientMetrics_State(startAttributes, startTimeNanos)); + new AutoValue_HttpClientMetrics_State(startAttributes, startNanos)); } @Override - public void end(Context context, Attributes endAttributes) { + public void end(Context context, Attributes endAttributes, long endNanos) { State state = context.get(HTTP_CLIENT_REQUEST_METRICS_STATE); if (state == null) { logger.debug( @@ -77,7 +75,7 @@ public void end(Context context, Attributes endAttributes) { return; } duration.record( - (System.nanoTime() - state.startTimeNanos()) / NANOS_PER_MS, + (endNanos - state.startTimeNanos()) / NANOS_PER_MS, applyDurationView(state.startAttributes())); } diff --git a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetrics.java b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetrics.java index 401e33284cc0..e80acb002890 100644 --- a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetrics.java +++ b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetrics.java @@ -70,17 +70,16 @@ private HttpServerMetrics(Meter meter) { } @Override - public Context start(Context context, Attributes startAttributes) { - long startTimeNanos = System.nanoTime(); + public Context start(Context context, Attributes startAttributes, long startNanos) { activeRequests.add(1, applyActiveRequestsView(startAttributes)); return context.with( HTTP_SERVER_REQUEST_METRICS_STATE, - new AutoValue_HttpServerMetrics_State(startAttributes, startTimeNanos)); + new AutoValue_HttpServerMetrics_State(startAttributes, startNanos)); } @Override - public void end(Context context, Attributes endAttributes) { + public void end(Context context, Attributes endAttributes, long endNanos) { State state = context.get(HTTP_SERVER_REQUEST_METRICS_STATE); if (state == null) { logger.debug( @@ -89,7 +88,7 @@ public void end(Context context, Attributes endAttributes) { } activeRequests.add(-1, applyActiveRequestsView(state.startAttributes())); duration.record( - (System.nanoTime() - state.startTimeNanos()) / NANOS_PER_MS, + (endNanos - state.startTimeNanos()) / NANOS_PER_MS, applyDurationView(state.startAttributes())); } diff --git a/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetricsTest.java b/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetricsTest.java index 5094e48476eb..d31bdd9c0675 100644 --- a/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetricsTest.java +++ b/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetricsTest.java @@ -14,6 +14,7 @@ import io.opentelemetry.sdk.metrics.SdkMeterProvider; import io.opentelemetry.sdk.metrics.data.MetricData; import java.util.Collection; +import java.util.concurrent.TimeUnit; import org.junit.jupiter.api.Test; class HttpClientMetricsTest { @@ -41,17 +42,17 @@ void collectsMetrics() { .put("http.status_code", 200) .build(); - Context context1 = listener.start(Context.current(), requestAttributes); + Context context1 = listener.start(Context.current(), requestAttributes, nanos(100)); Collection metrics = meterProvider.collectAllMetrics(); assertThat(metrics).isEmpty(); - Context context2 = listener.start(Context.current(), requestAttributes); + Context context2 = listener.start(Context.current(), requestAttributes, nanos(150)); metrics = meterProvider.collectAllMetrics(); assertThat(metrics).isEmpty(); - listener.end(context1, responseAttributes); + listener.end(context1, responseAttributes, nanos(250)); metrics = meterProvider.collectAllMetrics(); assertThat(metrics).hasSize(1); @@ -63,19 +64,18 @@ void collectsMetrics() { .hasDoubleHistogram() .points() .satisfiesExactly( - point -> { - assertThat(point.getSum()).isPositive(); - assertThat(point) - .attributes() - .containsOnly( - attributeEntry("http.host", "host"), - attributeEntry("http.method", "GET"), - attributeEntry("http.scheme", "https"), - attributeEntry("net.host.name", "localhost"), - attributeEntry("net.host.port", 1234L)); - })); - - listener.end(context2, responseAttributes); + point -> + assertThat(point) + .hasSum(150 /* millis */) + .attributes() + .containsOnly( + attributeEntry("http.host", "host"), + attributeEntry("http.method", "GET"), + attributeEntry("http.scheme", "https"), + attributeEntry("net.host.name", "localhost"), + attributeEntry("net.host.port", 1234L)))); + + listener.end(context2, responseAttributes, nanos(300)); metrics = meterProvider.collectAllMetrics(); assertThat(metrics).hasSize(1); @@ -86,6 +86,10 @@ void collectsMetrics() { .hasName("http.client.duration") .hasDoubleHistogram() .points() - .satisfiesExactly(point -> assertThat(point.getSum()).isPositive())); + .satisfiesExactly(point -> assertThat(point).hasSum(300 /* millis */))); + } + + private static long nanos(int millis) { + return TimeUnit.MILLISECONDS.toNanos(millis); } } diff --git a/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetricsTest.java b/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetricsTest.java index 43c071852d62..895ad85fbce2 100644 --- a/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetricsTest.java +++ b/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetricsTest.java @@ -14,6 +14,7 @@ import io.opentelemetry.sdk.metrics.SdkMeterProvider; import io.opentelemetry.sdk.metrics.data.MetricData; import java.util.Collection; +import java.util.concurrent.TimeUnit; import org.junit.jupiter.api.Test; class HttpServerMetricsTest { @@ -41,7 +42,7 @@ void collectsMetrics() { .put("http.status_code", 200) .build(); - Context context1 = listener.start(Context.current(), requestAttributes); + Context context1 = listener.start(Context.current(), requestAttributes, nanos(100)); Collection metrics = meterProvider.collectAllMetrics(); assertThat(metrics).hasSize(1); @@ -65,7 +66,7 @@ void collectsMetrics() { attributeEntry("http.method", "GET"), attributeEntry("http.scheme", "https")))); - Context context2 = listener.start(Context.current(), requestAttributes); + Context context2 = listener.start(Context.current(), requestAttributes, nanos(150)); metrics = meterProvider.collectAllMetrics(); assertThat(metrics).hasSize(1); @@ -78,7 +79,7 @@ void collectsMetrics() { .points() .satisfiesExactly(point -> assertThat(point).hasValue(2))); - listener.end(context1, responseAttributes); + listener.end(context1, responseAttributes, nanos(250)); metrics = meterProvider.collectAllMetrics(); assertThat(metrics).hasSize(2); @@ -98,19 +99,18 @@ void collectsMetrics() { .hasDoubleHistogram() .points() .satisfiesExactly( - point -> { - assertThat(point.getSum()).isPositive(); - assertThat(point) - .attributes() - .containsOnly( - attributeEntry("http.host", "host"), - attributeEntry("http.method", "GET"), - attributeEntry("http.scheme", "https"), - attributeEntry("net.host.name", "localhost"), - attributeEntry("net.host.port", 1234L)); - })); - - listener.end(context2, responseAttributes); + point -> + assertThat(point) + .hasSum(150 /* millis */) + .attributes() + .containsOnly( + attributeEntry("http.host", "host"), + attributeEntry("http.method", "GET"), + attributeEntry("http.scheme", "https"), + attributeEntry("net.host.name", "localhost"), + attributeEntry("net.host.port", 1234L)))); + + listener.end(context2, responseAttributes, nanos(300)); metrics = meterProvider.collectAllMetrics(); assertThat(metrics).hasSize(2); @@ -129,6 +129,10 @@ void collectsMetrics() { .hasName("http.server.duration") .hasDoubleHistogram() .points() - .satisfiesExactly(point -> assertThat(point.getSum()).isPositive())); + .satisfiesExactly(point -> assertThat(point).hasSum(300 /* millis */))); + } + + private static long nanos(int millis) { + return TimeUnit.MILLISECONDS.toNanos(millis); } }