[improvement] Tracer spans are inexpensive for unsampled operations (#…

…180) ## Before this PR Operations which are fast in the common case were infeasible to trace because regardless of the trace rate, span creation performance was worse than the operation being measured. ``` Benchmark (observability) Mode Cnt Score Error Units TracingBenchmark.nestedSpans SAMPLE avgt 3 39710.354 ± 36443.873 ns/op TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 3425.430 ± 3215.533 MB/sec TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 41560.021 ± 0.434 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 3444.571 ± 3116.221 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 41795.982 ± 7880.516 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.386 ± 2.219 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 4.741 ± 30.088 B/op TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 137.000 counts TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 87.000 ms TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 19958.082 ± 6584.116 ns/op TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 3506.264 ± 1147.188 MB/sec TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.011 ± 0.230 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 3547.447 ± 1525.303 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21666.731 ± 4251.611 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.383 ± 0.331 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 2.341 ± 1.300 B/op TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 139.000 counts TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 86.000 ms TracingBenchmark.nestedSpans UNDECIDED avgt 3 22570.008 ± 7874.344 ns/op TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 3590.635 ± 1268.870 MB/sec TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 24792.658 ± 44.976 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 3674.586 ± 3668.504 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 25360.986 ± 16430.980 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.217 ± 2.148 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.509 ± 15.297 B/op TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 90.000 counts TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 58.000 ms ``` ## After this PR Added `Tracer.fastStartSpan` which can effectively no-op for unsampled operations. ``` Benchmark (observability) Mode Cnt Score Error Units TracingBenchmark.nestedSpans SAMPLE avgt 3 37969.436 ± 25282.797 ns/op TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 3475.679 ± 2277.025 MB/sec TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40360.062 ± 1.751 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 3511.677 ± 2743.986 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 40771.767 ± 7164.960 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.384 ± 0.428 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 4.451 ± 2.688 B/op TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 148.000 counts TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 88.000 ms TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 908.402 ± 79.755 ns/op TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2820.275 ± 290.026 MB/sec TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 784.001 ± 0.011 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2834.984 ± 293.831 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 788.123 ± 162.926 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.223 ± 1.492 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 0.062 ± 0.416 B/op TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 126.000 counts TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 77.000 ms TracingBenchmark.nestedSpans UNDECIDED avgt 3 1254.746 ± 233.856 ns/op TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2945.625 ± 514.073 MB/sec TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 1130.854 ± 22.743 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2993.199 ± 1125.922 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 1149.047 ± 258.339 B/op TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.279 ± 0.890 MB/sec TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 0.107 ± 0.355 B/op TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 135.000 counts TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 81.000 ms ```
palantir · Jun 24, 2019 · 4178047 · 4178047
1 parent ce236e3
commit 4178047
Show file tree

Hide file tree

Showing 18 changed files with 424 additions and 171 deletions.
diff --git a/.gitignore b/.gitignore
@@ -19,6 +19,7 @@ bin/
 .idea/
 out/
 generated_src/
+generated_testSrc/
 
 # Codegen
 .generated

diff --git a/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java b/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java
@@ -16,6 +16,7 @@
 
 package com.palantir.tracing;
 
+import com.google.common.util.concurrent.Runnables;
 import java.util.concurrent.TimeUnit;
 import org.openjdk.jmh.annotations.Benchmark;
 import org.openjdk.jmh.annotations.BenchmarkMode;
@@ -47,13 +48,13 @@
 @SuppressWarnings({"checkstyle:hideutilityclassconstructor", "checkstyle:VisibilityModifier"})
 public class TracingBenchmark {
 
-    private static final Runnable nestedSpans = createnestedSpan(100);
+    private static final Runnable nestedSpans = createNestedSpan(100);
 
     @SuppressWarnings("ImmutableEnumChecker")
     public enum BenchmarkObservability {
         SAMPLE(AlwaysSampler.INSTANCE),
         DO_NOT_SAMPLE(() -> false),
-        UNDECIDED(new RandomSampler(0.1f));
+        UNDECIDED(new RandomSampler(0.01f));
 
         private final TraceSampler traceSampler;
 
@@ -87,20 +88,19 @@ public static void nestedSpans() {
         nestedSpans.run();
     }
 
-    private static Runnable createnestedSpan(int depth) {
-        if (depth == 0) {
-            return () -> {
-            };
+    private static Runnable createNestedSpan(int depth) {
+        if (depth <= 0) {
+            return Runnables.doNothing();
         } else {
-            return wrapWithSpan(createnestedSpan(depth - 1));
+            return wrapWithSpan("benchmark-span-" + depth, createNestedSpan(depth - 1));
         }
     }
 
-    private static Runnable wrapWithSpan(Runnable toBenNested) {
+    private static Runnable wrapWithSpan(String operation, Runnable next) {
         return () -> {
+            Tracer.fastStartSpan(operation);
             try {
-                Tracer.startSpan("span");
-                toBenNested.run();
+                next.run();
             } finally {
                 Tracer.fastCompleteSpan();
             }

diff --git a/tracing-jaxrs/src/test/java/com/palantir/tracing/jaxrs/JaxRsTracersTest.java b/tracing-jaxrs/src/test/java/com/palantir/tracing/jaxrs/JaxRsTracersTest.java
@@ -18,6 +18,7 @@
 
 import static org.assertj.core.api.Assertions.assertThat;
 
+import com.palantir.tracing.AlwaysSampler;
 import com.palantir.tracing.Tracer;
 import java.io.ByteArrayOutputStream;
 import javax.ws.rs.core.StreamingOutput;
@@ -26,22 +27,58 @@
 public final class JaxRsTracersTest {
 
     @Test
-    public void testWrappingStreamingOutput_streamingOutputTraceIsIsolated() throws Exception {
-        Tracer.startSpan("outside");
+    public void testWrappingStreamingOutput_streamingOutputTraceIsIsolated_sampled() throws Exception {
+        Tracer.setSampler(AlwaysSampler.INSTANCE);
+        Tracer.getAndClearTrace();
+
+        Tracer.fastStartSpan("outside");
         StreamingOutput streamingOutput = JaxRsTracers.wrap(os -> {
-            Tracer.startSpan("inside"); // never completed
+            Tracer.fastStartSpan("inside"); // never completed
         });
         streamingOutput.write(new ByteArrayOutputStream());
         assertThat(Tracer.completeSpan().get().getOperation()).isEqualTo("outside");
     }
 
     @Test
-    public void testWrappingStreamingOutput_traceStateIsCapturedAtConstructionTime() throws Exception {
-        Tracer.startSpan("before-construction");
+    public void testWrappingStreamingOutput_streamingOutputTraceIsIsolated_unsampled() throws Exception {
+        Tracer.setSampler(() -> false);
+        Tracer.getAndClearTrace();
+
+        Tracer.fastStartSpan("outside");
+        StreamingOutput streamingOutput = JaxRsTracers.wrap(os -> {
+            Tracer.fastStartSpan("inside"); // never completed
+        });
+        streamingOutput.write(new ByteArrayOutputStream());
+        assertThat(Tracer.hasTraceId()).isTrue();
+        Tracer.fastCompleteSpan();
+        assertThat(Tracer.hasTraceId()).isFalse();
+    }
+
+    @Test
+    public void testWrappingStreamingOutput_traceStateIsCapturedAtConstructionTime_sampled() throws Exception {
+        Tracer.setSampler(AlwaysSampler.INSTANCE);
+        Tracer.getAndClearTrace();
+
+        Tracer.fastStartSpan("before-construction");
         StreamingOutput streamingOutput = JaxRsTracers.wrap(os -> {
             assertThat(Tracer.completeSpan().get().getOperation()).isEqualTo("streaming-output");
         });
-        Tracer.startSpan("after-construction");
+        Tracer.fastStartSpan("after-construction");
+        streamingOutput.write(new ByteArrayOutputStream());
+    }
+
+    @Test
+    public void testWrappingStreamingOutput_traceStateIsCapturedAtConstructionTime_unsampled() throws Exception {
+        Tracer.setSampler(() -> false);
+        Tracer.getAndClearTrace();
+
+        Tracer.fastStartSpan("before-construction");
+        StreamingOutput streamingOutput = JaxRsTracers.wrap(os -> {
+            assertThat(Tracer.hasTraceId()).isTrue();
+            Tracer.fastCompleteSpan();
+            assertThat(Tracer.hasTraceId()).isFalse();
+        });
+        Tracer.fastStartSpan("after-construction");
         streamingOutput.write(new ByteArrayOutputStream());
     }
 }
diff --git a/tracing-jersey/src/main/java/com/palantir/tracing/jersey/TraceEnrichingFilter.java b/tracing-jersey/src/main/java/com/palantir/tracing/jersey/TraceEnrichingFilter.java
@@ -68,14 +68,14 @@ public void filter(ContainerRequestContext requestContext) throws IOException {
         if (Strings.isNullOrEmpty(traceId)) {
             // HTTP request did not indicate a trace; initialize trace state and create a span.
             Tracer.initTrace(getObservabilityFromHeader(requestContext), Tracers.randomId());
-            Tracer.startSpan(operation, SpanType.SERVER_INCOMING);
+            Tracer.fastStartSpan(operation, SpanType.SERVER_INCOMING);
         } else {
             Tracer.initTrace(getObservabilityFromHeader(requestContext), traceId);
             if (spanId == null) {
-                Tracer.startSpan(operation, SpanType.SERVER_INCOMING);
+                Tracer.fastStartSpan(operation, SpanType.SERVER_INCOMING);
             } else {
                 // caller's span is this span's parent.
-                Tracer.startSpan(operation, spanId, SpanType.SERVER_INCOMING);
+                Tracer.fastStartSpan(operation, spanId, SpanType.SERVER_INCOMING);
             }
         }
 

diff --git a/tracing-servlet/src/test/java/com/palantir/tracing/servlet/LeakedTraceFilterTest.java b/tracing-servlet/src/test/java/com/palantir/tracing/servlet/LeakedTraceFilterTest.java
@@ -103,7 +103,7 @@ public void doFilter(ServletRequest request, ServletResponse response, FilterCha
                         throws IOException, ServletException {
                     // Open a span to simulate a thread from another request
                     // leaving bad data without the leaked trace filter applied.
-                    Tracer.startSpan("previous request leaked");
+                    Tracer.fastStartSpan("previous request leaked");
                     chain.doFilter(request, response);
                 }
 
@@ -140,7 +140,7 @@ public void destroy() {}
             env.servlets().addServlet("alwaysLeaks", new HttpServlet() {
                 @Override
                 protected void service(HttpServletRequest req, HttpServletResponse resp) {
-                    Tracer.startSpan("leaky");
+                    Tracer.fastStartSpan("leaky");
                     resp.addHeader("Leaky-Invoked", "true");
                 }
             }).addMapping("/leaky");

diff --git a/tracing-undertow/src/main/java/com/palantir/tracing/undertow/TracedOperationHandler.java b/tracing-undertow/src/main/java/com/palantir/tracing/undertow/TracedOperationHandler.java
@@ -103,10 +103,10 @@ private void initializeTraceFromExisting(HeaderMap headers, String traceId) {
         Tracer.initTrace(getObservabilityFromHeader(headers), traceId);
         String spanId = headers.getFirst(SPAN_ID); // nullable
         if (spanId == null) {
-            Tracer.startSpan(operation, SpanType.SERVER_INCOMING);
+            Tracer.fastStartSpan(operation, SpanType.SERVER_INCOMING);
         } else {
             // caller's span is this span's parent.
-            Tracer.startSpan(operation, spanId, SpanType.SERVER_INCOMING);
+            Tracer.fastStartSpan(operation, spanId, SpanType.SERVER_INCOMING);
         }
     }
 
@@ -115,7 +115,7 @@ private String initializeNewTrace(HeaderMap headers) {
         // HTTP request did not indicate a trace; initialize trace state and create a span.
         String newTraceId = Tracers.randomId();
         Tracer.initTrace(getObservabilityFromHeader(headers), newTraceId);
-        Tracer.startSpan(operation, SpanType.SERVER_INCOMING);
+        Tracer.fastStartSpan(operation, SpanType.SERVER_INCOMING);
         return newTraceId;
     }
 

diff --git a/tracing/src/main/java/com/palantir/tracing/AsyncTracer.java b/tracing/src/main/java/com/palantir/tracing/AsyncTracer.java
@@ -62,7 +62,7 @@ public AsyncTracer(String operation) {
      */
     public AsyncTracer(Optional<String> operation) {
         this.operation = operation.orElse(DEFAULT_OPERATION);
-        Tracer.startSpan(this.operation + "-enqueue");
+        Tracer.fastStartSpan(this.operation + "-enqueue");
         deferredTrace = Tracer.copyTrace().get();
         Tracer.fastDiscardSpan(); // span will completed in the deferred execution
     }
@@ -76,7 +76,7 @@ public <T, E extends Throwable> T withTrace(Tracers.ThrowingCallable<T, E> inner
         Tracer.setTrace(deferredTrace);
         // Finish the enqueue span
         Tracer.fastCompleteSpan();
-        Tracer.startSpan(operation + "-run");
+        Tracer.fastStartSpan(operation + "-run");
         try {
             return inner.call();
         } finally {

diff --git a/tracing/src/main/java/com/palantir/tracing/CloseableTracer.java b/tracing/src/main/java/com/palantir/tracing/CloseableTracer.java
@@ -44,7 +44,7 @@ public static CloseableTracer startSpan(String operation) {
      * labeled with the provided operation.
      */
     public static CloseableTracer startSpan(String operation, SpanType spanType) {
-        Tracer.startSpan(operation, spanType);
+        Tracer.fastStartSpan(operation, spanType);
         return INSTANCE;
     }
 

diff --git a/tracing/src/main/java/com/palantir/tracing/DeferredTracer.java b/tracing/src/main/java/com/palantir/tracing/DeferredTracer.java
@@ -104,11 +104,11 @@ public <T, E extends Throwable> T withTrace(Tracers.ThrowingCallable<T, E> inner
 
         Optional<Trace> originalTrace = Tracer.copyTrace();
 
-        Tracer.setTrace(new Trace(isObservable, traceId));
+        Tracer.setTrace(Trace.of(isObservable, traceId));
         if (parentSpanId != null) {
-            Tracer.startSpan(operation, parentSpanId, SpanType.LOCAL);
+            Tracer.fastStartSpan(operation, parentSpanId, SpanType.LOCAL);
         } else {
-            Tracer.startSpan(operation);
+            Tracer.fastStartSpan(operation);
         }
 
         try {