Use nanotime for additional clock resolution
If a start or stop timestamp on a span is provided, the nanotime is ignored.
MODIFY
dd-java-agent/instrumentation/jboss-classloading/src/test/groovy/JBossClassloadingTest.groovy
dd-java-agent/instrumentation/jboss-classloading/src/test/groovy/JBossClassloadingTest.groovy
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:

MODIFY
dd-trace-ot/src/main/java/datadog/opentracing/DDSpan.java
dd-trace-ot/src/main/java/datadog/opentracing/DDSpan.java
@@ -19,7 +19,7 @@ import java.util.concurrent.TimeUnit;
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.
*
* <p>Spans are created by the {@link DDTracer#buildSpan}. This implementation adds some features
* according to the DD agent.
@@ -28,31 +28,39 @@ import lombok.extern.slf4j.Slf4j;
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 @@ public class DDSpan implements Span {
@Override
public final void finish() {
+ 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));

MODIFY
dd-trace-ot/src/test/groovy/datadog/opentracing/DDSpanTest.groovy
dd-trace-ot/src/test/groovy/datadog/opentracing/DDSpanTest.groovy
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:
@@ -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
@@ -82,9 +87,70 @@ class DDSpanTest extends Specification {
.buildSpan(opName)
.withResourceName(resourceName)
.withServiceName(serviceName)
- .startManual()
+ .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
+ }
}

MODIFY
dd-trace-ot/src/test/groovy/datadog/trace/api/writer/DDApiTest.groovy
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:

Use nanotime for additional clock resolution

If a start or stop timestamp on a span is provided, the nanotime is ignored.