Merge pull request #54 from DataDog/tyler/jmh

Add JMH tooling and try using queues instead

dd-trace/dd-trace.gradle

@@ -1,6 +1,7 @@
 plugins {
   id 'groovy'
   id "com.github.johnrengelman.shadow" version "2.0.1"
+  id "me.champeau.gradle.jmh" version "0.4.4"
 }
 
 description = 'dd-trace'
@@ -32,6 +33,7 @@ dependencies {
   testCompile group: 'org.spockframework', name: 'spock-core', version: '1.0-groovy-2.4'
   testCompile group: 'org.codehaus.groovy', name: 'groovy-all', version: '2.4.4'
   testCompile group: 'io.ratpack', name: 'ratpack-groovy-test', version: '1.4.6'
+  jmh 'commons-io:commons-io:2.4'
 }
 
 shadowJar {
@@ -46,3 +48,29 @@ shadowJar {
   relocate 'org.reflections', 'dd.deps.org.reflections'
   relocate 'org.yaml', 'dd.deps.org.yaml'
 }
+
+jmh {
+  timeUnit = 'us' // Output time unit. Available time units are: [m, s, ms, us, ns].
+  benchmarkMode = ['thrpt', 'avgt']
+  timeOnIteration = '1s'
+  iterations = 1 // Number of measurement iterations to do.
+//  fork = 2 // How many times to forks a single benchmark. Use 0 to disable forking altogether
+  jvmArgs = []
+  failOnError = true // Should JMH fail immediately if any benchmark had experienced the unrecoverable error?
+  warmup = '2s' // Time to spend at each warmup iteration.
+  warmupIterations = 1 // Number of warmup iterations to do.
+//  warmupForks = 0 // How many warmup forks to make for a single benchmark. 0 to disable warmup forks.
+
+//  profilers = ['stack']
+  // Use profilers to collect additional data. Supported profilers: [cl, comp, gc, stack, perf, perfnorm, perfasm, xperf, xperfasm, hs_cl, hs_comp, hs_gc, hs_rt, hs_thr]
+
+//  humanOutputFile = project.file("${project.buildDir}/reports/jmh/human.txt") // human-readable output file
+//  operationsPerInvocation = 10 // Operations per invocation.
+//  synchronizeIterations = false // Synchronize iterations?
+//  timeout = '1s' // Timeout for benchmark iteration.
+//  includeTests = true
+  // Allows to include test sources into generate JMH jar, i.e. use it when benchmarks depend on the test classes.
+
+  duplicateClassesStrategy = 'fail'
+  jmhVersion = '1.19' // Specifies JMH version
+}

dd-trace/src/jmh/java/com/datadoghq/trace/DDTraceBenchmark.java

@@ -0,0 +1,59 @@
+package com.datadoghq.trace;
+
+import com.datadoghq.trace.writer.ListWriter;
+import io.opentracing.ActiveSpan;
+import io.opentracing.Span;
+import io.opentracing.Tracer;
+import org.openjdk.jmh.annotations.Benchmark;
+import org.openjdk.jmh.annotations.Scope;
+import org.openjdk.jmh.annotations.State;
+
+public class DDTraceBenchmark {
+  public static String SPAN_NAME = "span-benchmark";
+
+  @State(Scope.Thread)
+  public static class TraceState {
+    public ListWriter traceCollector = new ListWriter();
+    public Tracer tracer = new DDTracer(traceCollector);
+    public ActiveSpan activeSpan = tracer.buildSpan(SPAN_NAME).startActive();
+  }
+
+  @Benchmark
+  public Object testBuildSpan(final TraceState state) {
+    return state.tracer.buildSpan(SPAN_NAME);
+  }
+
+  @Benchmark
+  public Object testBuildStartSpan(final TraceState state) {
+    return state.tracer.buildSpan(SPAN_NAME).startManual();
+  }
+
+  @Benchmark
+  public Object testFullSpan(final TraceState state) {
+    final Span span = state.tracer.buildSpan(SPAN_NAME).startManual();
+    span.finish();
+    return span;
+  }
+
+  @Benchmark
+  public Object testBuildStartSpanActive(final TraceState state) {
+    return state.tracer.buildSpan(SPAN_NAME).startActive();
+  }
+
+  @Benchmark
+  public Object testFullActiveSpan(final TraceState state) {
+    final ActiveSpan activeSpan = state.tracer.buildSpan(SPAN_NAME).startActive();
+    activeSpan.deactivate();
+    return activeSpan;
+  }
+
+  @Benchmark
+  public Object testContinuationCapture(final TraceState state) {
+    return state.activeSpan.capture();
+  }
+
+  @Benchmark
+  public Object testContinuationActivate(final TraceState state) {
+    return state.activeSpan.capture().activate();
+  }
+}

dd-trace/src/jmh/reports/2017-07-18.using-array-copy.txt

@@ -0,0 +1,15 @@
+Benchmark                                   Mode  Cnt    Score    Error   Units
+DDTraceBenchmark.testBuildSpan             thrpt   10  124.480 ±  6.190  ops/us
+DDTraceBenchmark.testBuildStartSpan        thrpt   10    0.542 ±  0.210  ops/us
+DDTraceBenchmark.testBuildStartSpanActive  thrpt   10    0.433 ±  0.136  ops/us
+DDTraceBenchmark.testContinuationActivate  thrpt   10    1.408 ±  0.701  ops/us
+DDTraceBenchmark.testContinuationCapture   thrpt   10   77.598 ± 16.400  ops/us
+DDTraceBenchmark.testFullActiveSpan        thrpt   10    1.348 ±  0.935  ops/us
+DDTraceBenchmark.testFullSpan              thrpt   10    0.976 ±  1.515  ops/us
+DDTraceBenchmark.testBuildSpan              avgt   10    0.009 ±  0.003   us/op
+DDTraceBenchmark.testBuildStartSpan         avgt   10    2.287 ±  0.937   us/op
+DDTraceBenchmark.testBuildStartSpanActive   avgt   10    2.548 ±  1.400   us/op
+DDTraceBenchmark.testContinuationActivate   avgt   10    0.744 ±  0.192   us/op
+DDTraceBenchmark.testContinuationCapture    avgt   10    0.013 ±  0.003   us/op
+DDTraceBenchmark.testFullActiveSpan         avgt   10    1.039 ±  0.564   us/op
+DDTraceBenchmark.testFullSpan               avgt   10    1.789 ±  1.174   us/op

dd-trace/src/jmh/reports/2017-07-18.using-linked-queue.txt

@@ -0,0 +1,15 @@
+Benchmark                                   Mode  Cnt    Score    Error   Units
+DDTraceBenchmark.testBuildSpan             thrpt   10  124.865 ±  3.206  ops/us
+DDTraceBenchmark.testBuildStartSpan        thrpt   10    0.595 ±  0.250  ops/us
+DDTraceBenchmark.testBuildStartSpanActive  thrpt   10    0.390 ±  0.142  ops/us
+DDTraceBenchmark.testContinuationActivate  thrpt   10    1.478 ±  0.575  ops/us
+DDTraceBenchmark.testContinuationCapture   thrpt   10   81.097 ± 13.030  ops/us
+DDTraceBenchmark.testFullActiveSpan        thrpt   10    1.365 ±  1.032  ops/us
+DDTraceBenchmark.testFullSpan              thrpt   10    0.484 ±  0.246  ops/us
+DDTraceBenchmark.testBuildSpan              avgt   10    0.008 ±  0.001   us/op
+DDTraceBenchmark.testBuildStartSpan         avgt   10    2.406 ±  0.950   us/op
+DDTraceBenchmark.testBuildStartSpanActive   avgt   10    2.943 ±  1.512   us/op
+DDTraceBenchmark.testContinuationActivate   avgt   10    0.620 ±  0.223   us/op
+DDTraceBenchmark.testContinuationCapture    avgt   10    0.012 ±  0.001   us/op
+DDTraceBenchmark.testFullActiveSpan         avgt   10    1.496 ±  1.948   us/op
+DDTraceBenchmark.testFullSpan               avgt   10    2.112 ±  1.857   us/op

dd-trace/src/main/java/com/datadoghq/trace/DDBaseSpan.java

@@ -4,9 +4,9 @@ import com.fasterxml.jackson.annotation.JsonGetter;
 import com.fasterxml.jackson.annotation.JsonIgnore;
 import io.opentracing.BaseSpan;
 import java.util.HashMap;
-import java.util.List;
 import java.util.Map;
 import java.util.Map.Entry;
+import java.util.Queue;
 import java.util.concurrent.TimeUnit;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
@@ -65,10 +65,10 @@ public abstract class DDBaseSpan<S extends BaseSpan> implements BaseSpan<S> {
 
     // warn if one of the parent's children is not finished
     if (this.isRootSpan()) {
-      final List<DDBaseSpan<?>> spans = this.context().getTrace();
+      final Queue<DDBaseSpan<?>> spans = this.context().getTrace();
 
       for (final DDBaseSpan<?> span : spans) {
-        if (((DDBaseSpan<?>) span).getDurationNano() == 0L) {
+        if (span.getDurationNano() == 0L) {
           logger.warn(
               "{} - The parent span is marked as finished but this span isn't. You have to close each children.",
               this);
@@ -90,7 +90,7 @@ public abstract class DDBaseSpan<S extends BaseSpan> implements BaseSpan<S> {
       return false;
     }
     // First item of the array AND tracer set
-    final DDBaseSpan<?> first = context().getTrace().get(0);
+    final DDBaseSpan<?> first = context().getTrace().peek();
     return first.context().getSpanId() == this.context().getSpanId()
         && this.context.getTracer() != null;
   }

dd-trace/src/main/java/com/datadoghq/trace/DDSpanContext.java

@@ -8,7 +8,8 @@ import java.util.Collections;
 import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
-import java.util.concurrent.CopyOnWriteArrayList;
+import java.util.Queue;
+import java.util.concurrent.ConcurrentLinkedQueue;
 
 /**
  * SpanContext represents Span state that must propagate to descendant Spans and across process
@@ -40,7 +41,7 @@ public class DDSpanContext implements io.opentracing.SpanContext {
   /** The type of the span. If null, the Datadog Agent will report as a custom */
   private String spanType;
   /** The collection of all span related to this one */
-  private final List<DDBaseSpan<?>> trace;
+  private final Queue<DDBaseSpan<?>> trace;
   /** Each span have an operation name describing the current span */
   private String operationName;
 
@@ -61,7 +62,7 @@ public class DDSpanContext implements io.opentracing.SpanContext {
       final boolean errorFlag,
       final String spanType,
       final Map<String, Object> tags,
-      final List<DDBaseSpan<?>> trace,
+      final Queue<DDBaseSpan<?>> trace,
       final DDTracer tracer) {
 
     this.traceId = traceId;
@@ -84,7 +85,7 @@ public class DDSpanContext implements io.opentracing.SpanContext {
 
     if (trace == null) {
       // TODO: figure out better concurrency model.
-      this.trace = new CopyOnWriteArrayList<>(); // must be thread safe!
+      this.trace = new ConcurrentLinkedQueue<>();
     } else {
       this.trace = trace;
     }
@@ -150,7 +151,7 @@ public class DDSpanContext implements io.opentracing.SpanContext {
   }
 
   @JsonIgnore
-  public List<DDBaseSpan<?>> getTrace() {
+  public Queue<DDBaseSpan<?>> getTrace() {
     return this.trace;
   }
 

dd-trace/src/main/java/com/datadoghq/trace/DDTracer.java

@@ -18,6 +18,7 @@ import java.util.Collections;
 import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
+import java.util.Queue;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -32,6 +33,12 @@ public class DDTracer extends ThreadLocalActiveSpanSource implements io.opentrac
     CURRENT_VERSION = version != null ? version : "unknown";
   }
 
+  public static final String UNASSIGNED_DEFAULT_SERVICE_NAME = "unnamed-java-app";
+  public static final Writer UNASSIGNED_WRITER = new LoggingWriter();
+  public static final Sampler UNASSIGNED_SAMPLER = new AllSampler();
+
+  private static final Logger logger = LoggerFactory.getLogger(DDTracer.class);
+
   /** Writer is an charge of reporting traces and spans to the desired endpoint */
   private final Writer writer;
   /** Sampler defines the sampling policy in order to reduce the number of traces for instance */
@@ -43,13 +50,8 @@ public class DDTracer extends ThreadLocalActiveSpanSource implements io.opentrac
   /** Span context decorators */
   private final Map<String, List<DDSpanContextDecorator>> spanContextDecorators = new HashMap<>();
 
-  private static final Logger logger = LoggerFactory.getLogger(DDTracer.class);
   private final CodecRegistry registry;
 
-  public static final String UNASSIGNED_DEFAULT_SERVICE_NAME = "unnamed-java-app";
-  public static final Writer UNASSIGNED_WRITER = new LoggingWriter();
-  public static final Sampler UNASSIGNED_SAMPLER = new AllSampler();
-
   /** Default constructor, trace/spans are logged, no trace/span dropped */
   public DDTracer() {
     this(UNASSIGNED_WRITER);
@@ -131,12 +133,12 @@ public class DDTracer extends ThreadLocalActiveSpanSource implements io.opentrac
    *
    * @param trace a list of the spans related to the same trace
    */
-  public void write(final List<DDBaseSpan<?>> trace) {
+  public void write(final Queue<DDBaseSpan<?>> trace) {
     if (trace.isEmpty()) {
       return;
     }
-    if (this.sampler.sample(trace.get(0))) {
+    if (this.sampler.sample(trace.peek())) {
-      this.writer.write(trace);
+      this.writer.write(new ArrayList<>(trace));
     }
   }
 
@@ -293,7 +295,7 @@ public class DDTracer extends ThreadLocalActiveSpanSource implements io.opentrac
       final long spanId = generateNewId();
       final long parentSpanId;
       final Map<String, String> baggage;
-      final List<DDBaseSpan<?>> parentTrace;
+      final Queue<DDBaseSpan<?>> parentTrace;
 
       final DDSpanContext context;
       SpanContext parentContext = this.parent;

dd-trace/src/test/java/com/datadoghq/trace/DDTracerTest.java

@@ -9,7 +9,8 @@ import static org.mockito.Mockito.when;
 import com.datadoghq.trace.sampling.RateSampler;
 import com.datadoghq.trace.writer.Writer;
 import java.util.ArrayList;
-import java.util.List;
+import java.util.LinkedList;
+import java.util.Queue;
 import org.junit.Test;
 
 public class DDTracerTest {
@@ -24,7 +25,7 @@ public class DDTracerTest {
     // Rate 0.5
     when(sampler.sample(any(DDSpan.class))).thenReturn(true).thenReturn(false);
 
-    final List<DDBaseSpan<?>> spans = new ArrayList<>();
+    final Queue<DDBaseSpan<?>> spans = new LinkedList<>();
     spans.add(span);
     spans.add(span);
     spans.add(span);
@@ -35,6 +36,6 @@ public class DDTracerTest {
     tracer.write(spans);
 
     verify(sampler, times(2)).sample(span);
-    verify(writer, times(1)).write(spans);
+    verify(writer, times(1)).write(new ArrayList<>(spans));
   }
 }

dd-trace/src/test/java/com/datadoghq/trace/writer/impl/DDAgentWriterTest.java

@@ -40,7 +40,7 @@ public class DDAgentWriterTest {
     parent.finish();
 
     //Create DDWriter
-    traces.add(parent.context().getTrace());
+    traces.add(new ArrayList<>(parent.context().getTrace()));
     mockedAPI = mock(DDApi.class);
     when(mockedAPI.sendTraces(traces)).thenReturn(true);
     ddAgentWriter = new DDAgentWriter(mockedAPI);
@@ -49,7 +49,7 @@ public class DDAgentWriterTest {
 
   @Test
   public void testWrite() throws Exception {
-    ddAgentWriter.write(parent.context().getTrace());
+    ddAgentWriter.write(new ArrayList<>(parent.context().getTrace()));
     Thread.sleep(500);
     verify(mockedAPI).sendTraces(traces);
   }
@@ -58,7 +58,7 @@ public class DDAgentWriterTest {
   public void testClose() throws Exception {
     ddAgentWriter.close();
 
-    ddAgentWriter.write(parent.context().getTrace());
+    ddAgentWriter.write(new ArrayList<>(parent.context().getTrace()));
     Thread.sleep(500);
     verifyNoMoreInteractions(mockedAPI);
   }