Add start/end time to RequestListener
MODIFY
instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java
instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java
@@ -15,8 +15,10 @@ import io.opentelemetry.api.trace.Tracer;
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 class Instrumenter<REQUEST, RESPONSE> {
.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 class Instrumenter<REQUEST, RESPONSE> {
Context context = parentContext;
+ if (!requestListeners.isEmpty()) {
+ long startNanos = getNanos(startTime);
for (RequestListener requestListener : requestListeners) {
- context = requestListener.start(context, attributes);
+ context = requestListener.start(context, attributes, startNanos);
+ }
}
spanBuilder.setAllAttributes(attributes);
@@ -177,8 +184,16 @@ public class Instrumenter<REQUEST, RESPONSE> {
Attributes attributes = attributesBuilder;
span.setAllAttributes(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);
+ requestListener.end(context, attributes, endNanos);
+ }
}
StatusCode statusCode = spanStatusExtractor.extract(request, response, error);
@@ -186,10 +201,17 @@ public class Instrumenter<REQUEST, RESPONSE> {
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();
+ }
}

MODIFY
instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/RequestListener.java
instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/RequestListener.java
@@ -10,9 +10,9 @@ import io.opentelemetry.context.Context;
/**
* 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);
}

MODIFY
instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetrics.java
instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetrics.java
@@ -60,16 +60,14 @@ public final class HttpClientMetrics implements RequestListener {
}
@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 final class HttpClientMetrics implements RequestListener {
return;
}
duration.record(
- (System.nanoTime() - state.startTimeNanos()) / NANOS_PER_MS,
+ (endNanos - state.startTimeNanos()) / NANOS_PER_MS,
applyDurationView(state.startAttributes()));
}

MODIFY
instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetrics.java
instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetrics.java
@@ -70,17 +70,16 @@ public final class HttpServerMetrics implements RequestListener {
}
@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 final class HttpServerMetrics implements RequestListener {
}
activeRequests.add(-1, applyActiveRequestsView(state.startAttributes()));
duration.record(
- (System.nanoTime() - state.startTimeNanos()) / NANOS_PER_MS,
+ (endNanos - state.startTimeNanos()) / NANOS_PER_MS,
applyDurationView(state.startAttributes()));
}

MODIFY
instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetricsTest.java
instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetricsTest.java
@@ -14,6 +14,7 @@ import io.opentelemetry.instrumentation.api.instrumenter.RequestListener;
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 @@ class HttpClientMetricsTest {
.put("http.status_code", 200)
.build();
- Context context1 = listener.start(Context.current(), requestAttributes);
+ Context context1 = listener.start(Context.current(), requestAttributes, nanos(100));
Collection<MetricData> 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 @@ class HttpClientMetricsTest {
.hasDoubleHistogram()
.points()
.satisfiesExactly(
- point -> {
- assertThat(point.getSum()).isPositive();
+ 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));
- }));
+ attributeEntry("net.host.port", 1234L))));
- listener.end(context2, responseAttributes);
+ listener.end(context2, responseAttributes, nanos(300));
metrics = meterProvider.collectAllMetrics();
assertThat(metrics).hasSize(1);
@@ -86,6 +86,10 @@ class HttpClientMetricsTest {
.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);
}
}

MODIFY
instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetricsTest.java
instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetricsTest.java
@@ -14,6 +14,7 @@ import io.opentelemetry.instrumentation.api.instrumenter.RequestListener;
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 @@ class HttpServerMetricsTest {
.put("http.status_code", 200)
.build();
- Context context1 = listener.start(Context.current(), requestAttributes);
+ Context context1 = listener.start(Context.current(), requestAttributes, nanos(100));
Collection<MetricData> metrics = meterProvider.collectAllMetrics();
assertThat(metrics).hasSize(1);
@@ -65,7 +66,7 @@ class HttpServerMetricsTest {
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 @@ class HttpServerMetricsTest {
.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 @@ class HttpServerMetricsTest {
.hasDoubleHistogram()
.points()
.satisfiesExactly(
- point -> {
- assertThat(point.getSum()).isPositive();
+ 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));
- }));
+ attributeEntry("net.host.port", 1234L))));
- listener.end(context2, responseAttributes);
+ listener.end(context2, responseAttributes, nanos(300));
metrics = meterProvider.collectAllMetrics();
assertThat(metrics).hasSize(2);
@@ -129,6 +129,10 @@ class HttpServerMetricsTest {
.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);
}
}

Add start/end time to RequestListener (#4155)