Use nanotime for additional clock resolution

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:

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.
  *
  * <p>Spans are created by the {@link DDTracer#buildSpan}. This implementation adds some features
  * according to the DD agent.
@@ -28,43 +28,63 @@
 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);
   }
 
   @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));

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.<String, String>emptyMap(),
-            false,
-            "fakeType",
-            null,
-            null,
-            null)
+      new DDSpanContext(
+        1L,
+        1L,
+        0L,
+        "fakeService",
+        "fakeOperation",
+        "fakeResource",
+        PrioritySampling.UNSET,
+        Collections.<String, String> 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
+  }
 }

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: