diff --git a/dd-java-agent/instrumentation/jboss-classloading/src/test/groovy/JBossClassloadingTest.groovy b/dd-java-agent/instrumentation/jboss-classloading/src/test/groovy/JBossClassloadingTest.groovy index 29b2a73bfb7..de1a9a4c2f6 100644 --- a/dd-java-agent/instrumentation/jboss-classloading/src/test/groovy/JBossClassloadingTest.groovy +++ b/dd-java-agent/instrumentation/jboss-classloading/src/test/groovy/JBossClassloadingTest.groovy @@ -1,7 +1,7 @@ import datadog.trace.agent.test.AgentTestRunner import spock.lang.Timeout -@Timeout(1) +@Timeout(5) class JBossClassloadingTest extends AgentTestRunner { def "delegation property set on module load"() { setup: diff --git a/dd-trace-ot/src/main/java/datadog/opentracing/DDSpan.java b/dd-trace-ot/src/main/java/datadog/opentracing/DDSpan.java index f2f66ff675d..ebadd77606b 100644 --- a/dd-trace-ot/src/main/java/datadog/opentracing/DDSpan.java +++ b/dd-trace-ot/src/main/java/datadog/opentracing/DDSpan.java @@ -19,7 +19,7 @@ import lombok.extern.slf4j.Slf4j; /** - * Represents an in-flight span in the opentracing system. + * Represents a period of time. Associated information is stored in the SpanContext. * *

Spans are created by the {@link DDTracer#buildSpan}. This implementation adds some features * according to the DD agent. @@ -28,31 +28,39 @@ public class DDSpan implements Span { /** The context attached to the span */ - protected final DDSpanContext context; - /** StartTime stores the creation time of the span in milliseconds */ - protected long startTimeMicro; - /** StartTimeNano stores the only the nanoseconds for more accuracy */ - protected long startTimeNano; - /** The duration in nanoseconds computed using the startTimeMicro and startTimeNano */ - protected long durationNano; + private final DDSpanContext context; + + /** Creation time of the span in microseconds. Must be greater than zero. */ + private final long startTimeMicro; + + /** Creation time of span in system relative nanotime (may be negative) */ + private final long startTimeNano; + + /** + * The duration in nanoseconds computed using the startTimeMicro or startTimeNano. Span is + * considered finished when this is set. + */ + private volatile long durationNano; /** - * A simple constructor. Currently, users have + * Spans should be constructed using the builder, not by calling the constructor directly. * - * @param timestampMicro if set, use this time instead of the auto-generated time - * @param context the context + * @param timestampMicro if greater than zero, use this time instead of the current time + * @param context the context used for the span */ - protected DDSpan(final long timestampMicro, final DDSpanContext context) { + DDSpan(final long timestampMicro, final DDSpanContext context) { this.context = context; // record the start time in nano (current milli + nano delta) - if (timestampMicro == 0L) { + if (timestampMicro <= 0L) { this.startTimeMicro = Clock.currentMicroTime(); + this.startTimeNano = Clock.currentNanoTicks(); } else { this.startTimeMicro = timestampMicro; + // timestamp might have come from an external clock, so don't bother with nanotime. + this.startTimeNano = 0; } - this.startTimeNano = Clock.currentNanoTicks(); // track each span of the trace this.context.getTrace().add(this); @@ -60,11 +68,23 @@ protected DDSpan(final long timestampMicro, final DDSpanContext context) { @Override public final void finish() { - finish(Clock.currentMicroTime()); + if (startTimeNano != 0) { + if (durationNano != 0) { + log.debug("Span already finished: {}", this); + } + // no external clock was used, so we can rely on nanotime. + this.durationNano = Math.max(1, Clock.currentNanoTicks() - startTimeNano); + afterFinish(); + } else { + finish(Clock.currentMicroTime()); + } } @Override public final void finish(final long stoptimeMicros) { + if (durationNano != 0) { + log.debug("Span already finished: {}", this); + } // Ensure that duration is at least 1. Less than 1 is possible due to our use of system clock instead of nano time. this.durationNano = Math.max(1, TimeUnit.MICROSECONDS.toNanos(stoptimeMicros - this.startTimeMicro)); diff --git a/dd-trace-ot/src/test/groovy/datadog/opentracing/DDSpanTest.groovy b/dd-trace-ot/src/test/groovy/datadog/opentracing/DDSpanTest.groovy index 25a0e5cf915..2d29df845d3 100644 --- a/dd-trace-ot/src/test/groovy/datadog/opentracing/DDSpanTest.groovy +++ b/dd-trace-ot/src/test/groovy/datadog/opentracing/DDSpanTest.groovy @@ -1,29 +1,34 @@ package datadog.opentracing import datadog.trace.common.sampling.PrioritySampling +import datadog.trace.common.writer.ListWriter import spock.lang.Specification import spock.lang.Timeout +import java.util.concurrent.TimeUnit + @Timeout(1) class DDSpanTest extends Specification { + def writer = new ListWriter() + def tracer = new DDTracer(writer) def "getters and setters"() { setup: final DDSpanContext context = - new DDSpanContext( - 1L, - 1L, - 0L, - "fakeService", - "fakeOperation", - "fakeResource", - PrioritySampling.UNSET, - Collections.emptyMap(), - false, - "fakeType", - null, - null, - null) + new DDSpanContext( + 1L, + 1L, + 0L, + "fakeService", + "fakeOperation", + "fakeResource", + PrioritySampling.UNSET, + Collections. emptyMap(), + false, + "fakeType", + null, + null, + null) final DDSpan span = new DDSpan(1L, context) @@ -70,7 +75,7 @@ class DDSpanTest extends Specification { DDSpan span when: - span = new DDTracer().buildSpan(opName).startManual() + span = tracer.buildSpan(opName).start() then: span.getResourceName() == opName span.getServiceName() == DDTracer.UNASSIGNED_DEFAULT_SERVICE_NAME @@ -79,12 +84,73 @@ class DDSpanTest extends Specification { final String resourceName = "fake" final String serviceName = "myService" span = new DDTracer() - .buildSpan(opName) - .withResourceName(resourceName) - .withServiceName(serviceName) - .startManual() + .buildSpan(opName) + .withResourceName(resourceName) + .withServiceName(serviceName) + .start() then: span.getResourceName() == resourceName span.getServiceName() == serviceName } + + def "duration measured in nanoseconds"() { + setup: + def mod = TimeUnit.MILLISECONDS.toNanos(1) + def builder = tracer.buildSpan("test") + def start = System.nanoTime() + def span = builder.start() + def between = System.nanoTime() + def betweenDur = System.nanoTime() - between + span.finish() + def total = System.nanoTime() - start + + expect: + span.durationNano > betweenDur + span.durationNano < total + span.durationNano % mod > 0 // Very slim chance of a false negative. + } + + def "starting with a timestamp disables nanotime"() { + setup: + def mod = TimeUnit.MILLISECONDS.toNanos(1) + def start = System.currentTimeMillis() + def builder = tracer.buildSpan("test") + .withStartTimestamp(TimeUnit.MILLISECONDS.toMicros(System.currentTimeMillis())) + def span = builder.start() + def between = System.currentTimeMillis() + def betweenDur = System.currentTimeMillis() - between + span.finish() + def total = System.currentTimeMillis() - start + + expect: + span.durationNano >= TimeUnit.MILLISECONDS.toNanos(betweenDur) + span.durationNano <= TimeUnit.MILLISECONDS.toNanos(total) + span.durationNano % mod == 0 + } + + def "stopping with a timestamp disables nanotime"() { + setup: + def mod = TimeUnit.MILLISECONDS.toNanos(1) + def builder = tracer.buildSpan("test") + def start = System.currentTimeMillis() + def span = builder.start() + def between = System.currentTimeMillis() + def betweenDur = System.currentTimeMillis() - between + span.finish(TimeUnit.MILLISECONDS.toMicros(System.currentTimeMillis() + 1)) + def total = System.currentTimeMillis() - start + 1 + + expect: + span.durationNano >= TimeUnit.MILLISECONDS.toNanos(betweenDur) + span.durationNano <= TimeUnit.MILLISECONDS.toNanos(total) + span.durationNano % mod == 0 + } + + def "stopping with a timestamp after start time yeilds a min duration of 1"() { + setup: + def span = tracer.buildSpan("test").start() + span.finish(span.startTimeMicro - 10) + + expect: + span.durationNano == 1 + } } diff --git a/dd-trace-ot/src/test/groovy/datadog/trace/api/writer/DDApiTest.groovy b/dd-trace-ot/src/test/groovy/datadog/trace/api/writer/DDApiTest.groovy index ac9392f7efb..b7de75569b1 100644 --- a/dd-trace-ot/src/test/groovy/datadog/trace/api/writer/DDApiTest.groovy +++ b/dd-trace-ot/src/test/groovy/datadog/trace/api/writer/DDApiTest.groovy @@ -23,7 +23,7 @@ import static ratpack.groovy.test.embed.GroovyEmbeddedApp.ratpack class DDApiTest extends Specification { static mapper = new ObjectMapper(new MessagePackFactory()) - @Timeout(5) + @Timeout(10) // first test takes longer def "sending an empty list of traces returns no errors"() { setup: