From 9ab758a0009ddeb1e2bdcc320264f60e0f52f0ee Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Thu, 20 Jun 2019 11:38:15 -0400 Subject: [PATCH 01/12] Split Tracer into Sampled+Unsampled types --- .../palantir/tracing/TracingBenchmark.java | 2 +- .../tracing/jaxrs/JaxRsTracersTest.java | 41 +++- .../com/palantir/tracing/DeferredTracer.java | 2 +- .../main/java/com/palantir/tracing/Trace.java | 175 ++++++++++++++---- .../java/com/palantir/tracing/Tracer.java | 19 +- .../tracing/AsyncSlf4jSpanObserverTest.java | 2 + .../com/palantir/tracing/AsyncTracerTest.java | 7 + .../palantir/tracing/CloseableTracerTest.java | 1 + .../java/com/palantir/tracing/TraceTest.java | 4 +- .../java/com/palantir/tracing/TracerTest.java | 41 +++- .../com/palantir/tracing/TracersTest.java | 1 + 11 files changed, 245 insertions(+), 50 deletions(-) diff --git a/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java b/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java index 31bcc19f9..f57eda981 100644 --- a/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java +++ b/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java @@ -99,7 +99,7 @@ private static Runnable createnestedSpan(int depth) { private static Runnable wrapWithSpan(Runnable toBenNested) { return () -> { try { - Tracer.startSpan("span"); + Tracer.fastStartSpan("span"); toBenNested.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 index 081625f1a..62b36f83d 100644 --- 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,7 +27,10 @@ public final class JaxRsTracersTest { @Test - public void testWrappingStreamingOutput_streamingOutputTraceIsIsolated() throws Exception { + public void testWrappingStreamingOutput_streamingOutputTraceIsIsolated_sampled() throws Exception { + Tracer.setSampler(AlwaysSampler.INSTANCE); + Tracer.getAndClearTrace(); + Tracer.startSpan("outside"); StreamingOutput streamingOutput = JaxRsTracers.wrap(os -> { Tracer.startSpan("inside"); // never completed @@ -36,7 +40,25 @@ public void testWrappingStreamingOutput_streamingOutputTraceIsIsolated() throws } @Test - public void testWrappingStreamingOutput_traceStateIsCapturedAtConstructionTime() throws Exception { + public void testWrappingStreamingOutput_streamingOutputTraceIsIsolated_unsampled() throws Exception { + Tracer.setSampler(() -> false); + Tracer.getAndClearTrace(); + + Tracer.startSpan("outside"); + StreamingOutput streamingOutput = JaxRsTracers.wrap(os -> { + Tracer.startSpan("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.startSpan("before-construction"); StreamingOutput streamingOutput = JaxRsTracers.wrap(os -> { assertThat(Tracer.completeSpan().get().getOperation()).isEqualTo("streaming-output"); @@ -44,4 +66,19 @@ public void testWrappingStreamingOutput_traceStateIsCapturedAtConstructionTime() Tracer.startSpan("after-construction"); streamingOutput.write(new ByteArrayOutputStream()); } + + @Test + public void testWrappingStreamingOutput_traceStateIsCapturedAtConstructionTime_unsampled() throws Exception { + Tracer.setSampler(() -> false); + Tracer.getAndClearTrace(); + + Tracer.startSpan("before-construction"); + StreamingOutput streamingOutput = JaxRsTracers.wrap(os -> { + assertThat(Tracer.hasTraceId()).isTrue(); + Tracer.fastCompleteSpan(); + assertThat(Tracer.hasTraceId()).isFalse(); + }); + Tracer.startSpan("after-construction"); + streamingOutput.write(new ByteArrayOutputStream()); + } } diff --git a/tracing/src/main/java/com/palantir/tracing/DeferredTracer.java b/tracing/src/main/java/com/palantir/tracing/DeferredTracer.java index 5f81369a1..73474b859 100644 --- a/tracing/src/main/java/com/palantir/tracing/DeferredTracer.java +++ b/tracing/src/main/java/com/palantir/tracing/DeferredTracer.java @@ -104,7 +104,7 @@ public T withTrace(Tracers.ThrowingCallable inner Optional originalTrace = Tracer.copyTrace(); - Tracer.setTrace(new Trace(isObservable, traceId)); + Tracer.setTrace(Trace.of(isObservable, traceId)); if (parentSpanId != null) { Tracer.startSpan(operation, parentSpanId, SpanType.LOCAL); } else { diff --git a/tracing/src/main/java/com/palantir/tracing/Trace.java b/tracing/src/main/java/com/palantir/tracing/Trace.java index dbc8db4e3..cd5f40a99 100644 --- a/tracing/src/main/java/com/palantir/tracing/Trace.java +++ b/tracing/src/main/java/com/palantir/tracing/Trace.java @@ -18,8 +18,12 @@ import static com.palantir.logsafe.Preconditions.checkArgument; +import com.google.common.base.Strings; +import com.palantir.logsafe.SafeArg; +import com.palantir.logsafe.exceptions.SafeIllegalStateException; import com.palantir.tracing.api.OpenSpan; import com.palantir.tracing.api.SpanObserver; +import com.palantir.tracing.api.SpanType; import java.util.ArrayDeque; import java.util.Deque; import java.util.Optional; @@ -28,62 +32,169 @@ * Represents a trace as an ordered list of non-completed spans. Supports adding and removing of spans. This class is * not thread-safe and is intended to be used in a thread-local context. */ -public final class Trace { +public abstract class Trace { - private final Deque stack; - private final boolean isObservable; private final String traceId; - private Trace(ArrayDeque stack, boolean isObservable, String traceId) { - checkArgument(!traceId.isEmpty(), "traceId must be non-empty"); - - this.stack = stack; - this.isObservable = isObservable; + private Trace(String traceId) { + checkArgument(!Strings.isNullOrEmpty(traceId), "traceId must be non-empty"); this.traceId = traceId; } - Trace(boolean isObservable, String traceId) { - this(new ArrayDeque<>(), isObservable, traceId); - } + abstract void startSpan(String operation, SpanType type); - void push(OpenSpan span) { - stack.push(span); - } + abstract void push(OpenSpan span); - Optional top() { - return stack.isEmpty() ? Optional.empty() : Optional.of(stack.peekFirst()); - } + abstract Optional top(); - Optional pop() { - return stack.isEmpty() ? Optional.empty() : Optional.of(stack.pop()); - } + abstract Optional pop(); - boolean isEmpty() { - return stack.isEmpty(); - } + abstract boolean isEmpty(); /** * True iff the spans of this trace are to be observed by {@link SpanObserver span obververs} upon {@link * Tracer#completeSpan span completion}. */ - boolean isObservable() { - return isObservable; - } + abstract boolean isObservable(); /** * The globally unique non-empty identifier for this call trace. */ - String getTraceId() { + final String getTraceId() { return traceId; } /** Returns a copy of this Trace which can be independently mutated. */ - Trace deepCopy() { - return new Trace(new ArrayDeque<>(stack), isObservable, traceId); + abstract Trace deepCopy(); + + static Trace of(boolean isObservable, String traceId) { + return isObservable ? new Sampled(traceId) : new Unsampled(traceId); + } + + private static final class Sampled extends Trace { + + private final Deque stack; + + private Sampled(ArrayDeque stack, String traceId) { + super(traceId); + this.stack = stack; + } + + private Sampled(String traceId) { + this(new ArrayDeque<>(), traceId); + } + + @Override + void startSpan(String operation, SpanType type) { + Optional prevState = top(); + final OpenSpan span; + // Avoid lambda allocation in hot paths + if (prevState.isPresent()) { + span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.of(prevState.get().getSpanId())); + } else { + span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.empty()); + } + push(span); + } + + @Override + void push(OpenSpan span) { + stack.push(span); + } + + @Override + Optional top() { + return stack.isEmpty() ? Optional.empty() : Optional.of(stack.peekFirst()); + } + + @Override + Optional pop() { + return stack.isEmpty() ? Optional.empty() : Optional.of(stack.pop()); + } + + @Override + boolean isEmpty() { + return stack.isEmpty(); + } + + @Override + boolean isObservable() { + return true; + } + + @Override + Trace deepCopy() { + return new Sampled(new ArrayDeque<>(stack), getTraceId()); + } + + @Override + public String toString() { + return "Trace{stack=" + stack + ", isObservable=true, traceId='" + getTraceId() + "'}"; + } } - @Override - public String toString() { - return "Trace{stack=" + stack + ", isObservable=" + isObservable + ", traceId='" + traceId + "'}"; + private static final class Unsampled extends Trace { + private int depth; + + private Unsampled(int depth, String traceId) { + super(traceId); + this.depth = depth; + validateDepth(); + } + + private Unsampled(String traceId) { + this(0, traceId); + } + + @Override + void startSpan(String operation, SpanType type) { + depth++; + } + + @Override + void push(OpenSpan span) { + depth++; + } + + @Override + Optional top() { + return Optional.empty(); + } + + @Override + Optional pop() { + validateDepth(); + if (depth > 0) { + depth--; + } + return Optional.empty(); + } + + @Override + boolean isEmpty() { + validateDepth(); + return depth <= 0; + } + + @Override + boolean isObservable() { + return false; + } + + @Override + Trace deepCopy() { + return new Unsampled(depth, getTraceId()); + } + + private void validateDepth() { + if (depth < 0) { + throw new SafeIllegalStateException("Unexpected negative depth", SafeArg.of("depth", depth)); + } + } + + @Override + public String toString() { + return "Trace{depth=" + depth + ", isObservable=false, traceId='" + getTraceId() + "'}"; + } } } diff --git a/tracing/src/main/java/com/palantir/tracing/Tracer.java b/tracing/src/main/java/com/palantir/tracing/Tracer.java index c3d217d89..83943f507 100644 --- a/tracing/src/main/java/com/palantir/tracing/Tracer.java +++ b/tracing/src/main/java/com/palantir/tracing/Tracer.java @@ -68,7 +68,7 @@ private Tracer() {} private static Trace createTrace(Observability observability, String traceId) { checkArgument(!Strings.isNullOrEmpty(traceId), "traceId must be non-empty"); boolean observable = shouldObserve(observability); - return new Trace(observable, traceId); + return Trace.of(observable, traceId); } private static boolean shouldObserve(Observability observability) { @@ -133,6 +133,20 @@ public static OpenSpan startSpan(String operation) { return startSpanInternal(operation, SpanType.LOCAL); } + /** + * Like {@link #startSpan(String, SpanType)}, but does not return an {@link OpenSpan}. + */ + public static void fastStartSpan(String operation, SpanType type) { + getOrCreateCurrentTrace().startSpan(operation, type); + } + + /** + * Like {@link #startSpan(String)}, but does not return an {@link OpenSpan}. + */ + public static void fastStartSpan(String operation) { + fastStartSpan(operation, SpanType.LOCAL); + } + private static OpenSpan startSpanInternal(String operation, SpanType type) { Trace trace = getOrCreateCurrentTrace(); Optional prevState = trace.top(); @@ -152,7 +166,8 @@ private static OpenSpan startSpanInternal(String operation, SpanType type) { static void fastDiscardSpan() { Trace trace = currentTrace.get(); checkNotNull(trace, "Expected current trace to exist"); - checkState(popCurrentSpan().isPresent(), "Expected span to exist before discarding"); + checkState(!trace.isEmpty(), "Expected span to exist before discarding"); + popCurrentSpan(); } /** diff --git a/tracing/src/test/java/com/palantir/tracing/AsyncSlf4jSpanObserverTest.java b/tracing/src/test/java/com/palantir/tracing/AsyncSlf4jSpanObserverTest.java index 5659653db..3223e2cd3 100644 --- a/tracing/src/test/java/com/palantir/tracing/AsyncSlf4jSpanObserverTest.java +++ b/tracing/src/test/java/com/palantir/tracing/AsyncSlf4jSpanObserverTest.java @@ -78,6 +78,8 @@ public final class AsyncSlf4jSpanObserverTest { public void before() { MockitoAnnotations.initMocks(this); + Tracer.setSampler(AlwaysSampler.INSTANCE); + when(appender.getName()).thenReturn("MOCK"); logger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(AsyncSlf4jSpanObserver.class); logger.addAppender(appender); diff --git a/tracing/src/test/java/com/palantir/tracing/AsyncTracerTest.java b/tracing/src/test/java/com/palantir/tracing/AsyncTracerTest.java index 3eb6be1b9..756d83917 100644 --- a/tracing/src/test/java/com/palantir/tracing/AsyncTracerTest.java +++ b/tracing/src/test/java/com/palantir/tracing/AsyncTracerTest.java @@ -20,9 +20,16 @@ import com.google.common.collect.Lists; import java.util.List; +import org.junit.Before; import org.junit.Test; public class AsyncTracerTest { + + @Before + public void before() { + Tracer.setSampler(AlwaysSampler.INSTANCE); + } + @Test public void doesNotLeakEnqueueSpan() { Tracer.initTrace(Observability.UNDECIDED, "defaultTraceId"); diff --git a/tracing/src/test/java/com/palantir/tracing/CloseableTracerTest.java b/tracing/src/test/java/com/palantir/tracing/CloseableTracerTest.java index 6a31cf72c..d8c71d499 100644 --- a/tracing/src/test/java/com/palantir/tracing/CloseableTracerTest.java +++ b/tracing/src/test/java/com/palantir/tracing/CloseableTracerTest.java @@ -29,6 +29,7 @@ public final class CloseableTracerTest { @Before public void before() { + Tracer.setSampler(AlwaysSampler.INSTANCE); Tracer.getAndClearTrace(); } diff --git a/tracing/src/test/java/com/palantir/tracing/TraceTest.java b/tracing/src/test/java/com/palantir/tracing/TraceTest.java index e2fa8c2f5..23a3dce13 100644 --- a/tracing/src/test/java/com/palantir/tracing/TraceTest.java +++ b/tracing/src/test/java/com/palantir/tracing/TraceTest.java @@ -27,13 +27,13 @@ public final class TraceTest { @Test public void constructTrace_emptyTraceId() { - assertThatThrownBy(() -> new Trace(false, "")) + assertThatThrownBy(() -> Trace.of(false, "")) .isInstanceOf(IllegalArgumentException.class); } @Test public void testToString() { - Trace trace = new Trace(true, "traceId"); + Trace trace = Trace.of(true, "traceId"); trace.push(OpenSpan.builder() .type(SpanType.LOCAL) .spanId("spanId") diff --git a/tracing/src/test/java/com/palantir/tracing/TracerTest.java b/tracing/src/test/java/com/palantir/tracing/TracerTest.java index d9d63e473..7e1e2e9a9 100644 --- a/tracing/src/test/java/com/palantir/tracing/TracerTest.java +++ b/tracing/src/test/java/com/palantir/tracing/TracerTest.java @@ -138,17 +138,33 @@ public void testObserversAreInvokedOnObservableTracesOnly() throws Exception { verifyNoMoreInteractions(observer1); Tracer.initTrace(Observability.DO_NOT_SAMPLE, Tracers.randomId()); - startAndCompleteSpan(); // not sampled, see above + startAndFastCompleteSpan(); // not sampled, see above verifyNoMoreInteractions(observer1); } @Test - public void testDerivesNewSpansWhenTraceIsNotObservable() throws Exception { - Tracer.initTrace(Observability.DO_NOT_SAMPLE, Tracers.randomId()); + public void testCountsSpansWhenTraceIsNotObservable() throws Exception { + String traceId = Tracers.randomId(); + assertThat(MDC.get(Tracers.TRACE_ID_KEY)).isNull(); + assertThat(Tracer.hasTraceId()).isFalse(); + Tracer.initTrace(Observability.DO_NOT_SAMPLE, traceId); + // Unsampled trace should still apply thread state + assertThat(MDC.get(Tracers.TRACE_ID_KEY)).isEqualTo(traceId); + assertThat(Tracer.hasTraceId()).isTrue(); + assertThat(Tracer.getTraceId()).isEqualTo(traceId); Tracer.startSpan("foo"); Tracer.startSpan("bar"); - assertThat(Tracer.completeSpan().get().getOperation()).isEqualTo("bar"); - assertThat(Tracer.completeSpan().get().getOperation()).isEqualTo("foo"); + + Tracer.fastCompleteSpan(); + // Unsampled trace should still apply thread state + assertThat(MDC.get(Tracers.TRACE_ID_KEY)).isEqualTo(traceId); + assertThat(Tracer.hasTraceId()).isTrue(); + assertThat(Tracer.getTraceId()).isEqualTo(traceId); + + // Complete the root span, which should clear thread state + Tracer.fastCompleteSpan(); + assertThat(MDC.get(Tracers.TRACE_ID_KEY)).isNull(); + assertThat(Tracer.hasTraceId()).isFalse(); } @Test @@ -163,7 +179,7 @@ public void testInitTraceCallsSampler() throws Exception { verifyNoMoreInteractions(observer1, sampler); Mockito.reset(observer1, sampler); - startAndCompleteSpan(); // not sampled, see above + startAndFastCompleteSpan(); // not sampled, see above verify(sampler).sample(); verifyNoMoreInteractions(observer1, sampler); } @@ -183,7 +199,7 @@ public void testTraceCopyIsIndependent() throws Exception { @Test public void testSetTraceSetsCurrentTraceAndMdcTraceIdKey() throws Exception { Tracer.startSpan("operation"); - Tracer.setTrace(new Trace(true, "newTraceId")); + Tracer.setTrace(Trace.of(true, "newTraceId")); assertThat(Tracer.getTraceId()).isEqualTo("newTraceId"); assertThat(MDC.get(Tracers.TRACE_ID_KEY)).isEqualTo("newTraceId"); assertThat(Tracer.completeSpan()).isEmpty(); @@ -192,7 +208,7 @@ public void testSetTraceSetsCurrentTraceAndMdcTraceIdKey() throws Exception { @Test public void testSetTraceSetsMdcTraceSampledKeyWhenObserved() { - Tracer.setTrace(new Trace(true, "observedTraceId")); + Tracer.setTrace(Trace.of(true, "observedTraceId")); assertThat(MDC.get(Tracers.TRACE_SAMPLED_KEY)).isEqualTo("1"); assertThat(Tracer.completeSpan()).isEmpty(); assertThat(MDC.get(Tracers.TRACE_SAMPLED_KEY)).isNull(); @@ -200,7 +216,7 @@ public void testSetTraceSetsMdcTraceSampledKeyWhenObserved() { @Test public void testSetTraceMissingMdcTraceSampledKeyWhenNotObserved() { - Tracer.setTrace(new Trace(false, "notObservedTraceId")); + Tracer.setTrace(Trace.of(false, "notObservedTraceId")); assertThat(MDC.get(Tracers.TRACE_SAMPLED_KEY)).isNull(); assertThat(Tracer.completeSpan()).isEmpty(); assertThat(MDC.get(Tracers.TRACE_SAMPLED_KEY)).isNull(); @@ -275,7 +291,7 @@ public void testObserversThrow() { @Test public void testGetAndClearTraceIfPresent() { - Trace trace = new Trace(true, "newTraceId"); + Trace trace = Trace.of(true, "newTraceId"); Tracer.setTrace(trace); Optional nonEmptyTrace = Tracer.getAndClearTraceIfPresent(); @@ -329,6 +345,11 @@ public void testHasTraceId() { assertThat(Tracer.hasTraceId()).isEqualTo(false); } + private static void startAndFastCompleteSpan() { + Tracer.startSpan("operation"); + Tracer.fastCompleteSpan(); + } + private static Span startAndCompleteSpan() { Tracer.startSpan("operation"); return Tracer.completeSpan().get(); diff --git a/tracing/src/test/java/com/palantir/tracing/TracersTest.java b/tracing/src/test/java/com/palantir/tracing/TracersTest.java index b46a5aed3..540fff476 100644 --- a/tracing/src/test/java/com/palantir/tracing/TracersTest.java +++ b/tracing/src/test/java/com/palantir/tracing/TracersTest.java @@ -45,6 +45,7 @@ public void before() { MockitoAnnotations.initMocks(this); MDC.clear(); + Tracer.setSampler(AlwaysSampler.INSTANCE); // Initialize a new trace for each test Tracer.initTrace(Observability.UNDECIDED, "defaultTraceId"); } From f08617bb47b47cf8fb668e6be85f8e94d186d206 Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Thu, 20 Jun 2019 12:17:21 -0400 Subject: [PATCH 02/12] error prone validation to prefer the fast path --- .../tracing/jaxrs/JaxRsTracersTest.java | 16 +++--- .../tracing/jersey/TraceEnrichingFilter.java | 4 +- .../servlet/LeakedTraceFilterTest.java | 4 +- .../undertow/TracedOperationHandler.java | 4 +- .../com/palantir/tracing/AsyncTracer.java | 4 +- .../com/palantir/tracing/CloseableTracer.java | 2 +- .../com/palantir/tracing/DeferredTracer.java | 2 +- .../java/com/palantir/tracing/Tracer.java | 4 ++ .../java/com/palantir/tracing/Tracers.java | 6 +- .../tracing/AsyncSlf4jSpanObserverTest.java | 6 +- .../com/palantir/tracing/AsyncTracerTest.java | 8 +-- .../java/com/palantir/tracing/TracerTest.java | 28 +++++----- .../com/palantir/tracing/TracersTest.java | 56 +++++++++---------- 13 files changed, 74 insertions(+), 70 deletions(-) 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 index 62b36f83d..a08200a9b 100644 --- a/tracing-jaxrs/src/test/java/com/palantir/tracing/jaxrs/JaxRsTracersTest.java +++ b/tracing-jaxrs/src/test/java/com/palantir/tracing/jaxrs/JaxRsTracersTest.java @@ -31,9 +31,9 @@ public void testWrappingStreamingOutput_streamingOutputTraceIsIsolated_sampled() Tracer.setSampler(AlwaysSampler.INSTANCE); Tracer.getAndClearTrace(); - Tracer.startSpan("outside"); + 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"); @@ -44,9 +44,9 @@ public void testWrappingStreamingOutput_streamingOutputTraceIsIsolated_unsampled Tracer.setSampler(() -> false); Tracer.getAndClearTrace(); - Tracer.startSpan("outside"); + Tracer.fastStartSpan("outside"); StreamingOutput streamingOutput = JaxRsTracers.wrap(os -> { - Tracer.startSpan("inside"); // never completed + Tracer.fastStartSpan("inside"); // never completed }); streamingOutput.write(new ByteArrayOutputStream()); assertThat(Tracer.hasTraceId()).isTrue(); @@ -59,11 +59,11 @@ public void testWrappingStreamingOutput_traceStateIsCapturedAtConstructionTime_s Tracer.setSampler(AlwaysSampler.INSTANCE); Tracer.getAndClearTrace(); - Tracer.startSpan("before-construction"); + 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()); } @@ -72,13 +72,13 @@ public void testWrappingStreamingOutput_traceStateIsCapturedAtConstructionTime_u Tracer.setSampler(() -> false); Tracer.getAndClearTrace(); - Tracer.startSpan("before-construction"); + Tracer.fastStartSpan("before-construction"); StreamingOutput streamingOutput = JaxRsTracers.wrap(os -> { assertThat(Tracer.hasTraceId()).isTrue(); Tracer.fastCompleteSpan(); assertThat(Tracer.hasTraceId()).isFalse(); }); - Tracer.startSpan("after-construction"); + 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 index fb0a6029f..423c948cf 100644 --- 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,11 +68,11 @@ 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); 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 index b71617c5a..183a8a558 100644 --- 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 index da0e558b0..32b065ccc 100644 --- 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,7 +103,7 @@ 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); @@ -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 index 266328851..e18ca3f88 100644 --- 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 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 withTrace(Tracers.ThrowingCallable 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 index edd490829..c32cd3710 100644 --- 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 index 73474b859..f7c2a0515 100644 --- a/tracing/src/main/java/com/palantir/tracing/DeferredTracer.java +++ b/tracing/src/main/java/com/palantir/tracing/DeferredTracer.java @@ -108,7 +108,7 @@ public T withTrace(Tracers.ThrowingCallable inner if (parentSpanId != null) { Tracer.startSpan(operation, parentSpanId, SpanType.LOCAL); } else { - Tracer.startSpan(operation); + Tracer.fastStartSpan(operation); } try { diff --git a/tracing/src/main/java/com/palantir/tracing/Tracer.java b/tracing/src/main/java/com/palantir/tracing/Tracer.java index 83943f507..418f6acec 100644 --- a/tracing/src/main/java/com/palantir/tracing/Tracer.java +++ b/tracing/src/main/java/com/palantir/tracing/Tracer.java @@ -121,14 +121,18 @@ public static OpenSpan startSpan(String operation, String parentSpanId, SpanType /** * Like {@link #startSpan(String)}, but opens a span of the explicitly given {@link SpanType span type}. + * If the return value is not used, prefer {@link Tracer#fastStartSpan(String, SpanType)}}. */ + @CheckReturnValue public static OpenSpan startSpan(String operation, SpanType type) { return startSpanInternal(operation, type); } /** * Opens a new {@link SpanType#LOCAL LOCAL} span for this thread's call trace, labeled with the provided operation. + * If the return value is not used, prefer {@link Tracer#fastStartSpan(String)}}. */ + @CheckReturnValue public static OpenSpan startSpan(String operation) { return startSpanInternal(operation, SpanType.LOCAL); } diff --git a/tracing/src/main/java/com/palantir/tracing/Tracers.java b/tracing/src/main/java/com/palantir/tracing/Tracers.java index 47dee7d7e..377da2ba0 100644 --- a/tracing/src/main/java/com/palantir/tracing/Tracers.java +++ b/tracing/src/main/java/com/palantir/tracing/Tracers.java @@ -235,7 +235,7 @@ public static Callable wrapWithNewTrace(String operation, Observability o try { Tracer.initTrace(observability, Tracers.randomId()); - Tracer.startSpan(operation); + Tracer.fastStartSpan(operation); return delegate.call(); } finally { Tracer.fastCompleteSpan(); @@ -271,7 +271,7 @@ public static Runnable wrapWithNewTrace(String operation, Observability observab try { Tracer.initTrace(observability, Tracers.randomId()); - Tracer.startSpan(operation); + Tracer.fastStartSpan(operation); delegate.run(); } finally { Tracer.fastCompleteSpan(); @@ -309,7 +309,7 @@ public static Runnable wrapWithAlternateTraceId(String traceId, String operation try { Tracer.initTrace(observability, traceId); - Tracer.startSpan(operation); + Tracer.fastStartSpan(operation); delegate.run(); } finally { Tracer.fastCompleteSpan(); diff --git a/tracing/src/test/java/com/palantir/tracing/AsyncSlf4jSpanObserverTest.java b/tracing/src/test/java/com/palantir/tracing/AsyncSlf4jSpanObserverTest.java index 3223e2cd3..52195328f 100644 --- a/tracing/src/test/java/com/palantir/tracing/AsyncSlf4jSpanObserverTest.java +++ b/tracing/src/test/java/com/palantir/tracing/AsyncSlf4jSpanObserverTest.java @@ -101,7 +101,7 @@ public void testJsonFormatToLog() throws Exception { Tracer.subscribe(TEST_OBSERVER, AsyncSlf4jSpanObserver.of( "serviceName", Inet4Address.getLoopbackAddress(), logger, executor)); Tracer.initTrace(Observability.SAMPLE, Tracers.randomId()); - Tracer.startSpan("operation"); + Tracer.fastStartSpan("operation"); Span span = Tracer.completeSpan().get(); verify(appender, never()).doAppend(any(ILoggingEvent.class)); // async logger only fires when executor runs @@ -122,7 +122,7 @@ public void testDefaultConstructorDeterminesIpAddress() throws Exception { DeterministicScheduler executor = new DeterministicScheduler(); Tracer.subscribe(TEST_OBSERVER, AsyncSlf4jSpanObserver.of("serviceName", executor)); Tracer.initTrace(Observability.SAMPLE, Tracers.randomId()); - Tracer.startSpan("operation"); + Tracer.fastStartSpan("operation"); Span span = Tracer.completeSpan().get(); executor.runNextPendingCommand(); @@ -254,7 +254,7 @@ public void testFastCompleteSpanAfterExecutorShutdown() { .extracting("spanId", "operation") .contains(span1.getSpanId(), span1.getOperation()); - Tracer.startSpan("operation"); + Tracer.fastStartSpan("operation"); executor.shutdown(); Tracer.fastCompleteSpan(); } diff --git a/tracing/src/test/java/com/palantir/tracing/AsyncTracerTest.java b/tracing/src/test/java/com/palantir/tracing/AsyncTracerTest.java index 756d83917..092ae92af 100644 --- a/tracing/src/test/java/com/palantir/tracing/AsyncTracerTest.java +++ b/tracing/src/test/java/com/palantir/tracing/AsyncTracerTest.java @@ -49,7 +49,7 @@ public void doesNotLeakEnqueueSpan() { @Test public void completesBothDeferredSpans() { Tracer.initTrace(Observability.SAMPLE, "defaultTraceId"); - Tracer.startSpan("defaultSpan"); + Tracer.fastStartSpan("defaultSpan"); AsyncTracer asyncTracer = new AsyncTracer(); List observedSpans = Lists.newArrayList(); Tracer.subscribe( @@ -64,9 +64,9 @@ public void completesBothDeferredSpans() { @Test public void preservesState() { Tracer.initTrace(Observability.UNDECIDED, "defaultTraceId"); - Tracer.startSpan("foo"); - Tracer.startSpan("bar"); - Tracer.startSpan("baz"); + Tracer.fastStartSpan("foo"); + Tracer.fastStartSpan("bar"); + Tracer.fastStartSpan("baz"); Trace originalTrace = getTrace(); AsyncTracer asyncTracer = new AsyncTracer(); diff --git a/tracing/src/test/java/com/palantir/tracing/TracerTest.java b/tracing/src/test/java/com/palantir/tracing/TracerTest.java index 7e1e2e9a9..3bc60b569 100644 --- a/tracing/src/test/java/com/palantir/tracing/TracerTest.java +++ b/tracing/src/test/java/com/palantir/tracing/TracerTest.java @@ -152,8 +152,8 @@ public void testCountsSpansWhenTraceIsNotObservable() throws Exception { assertThat(MDC.get(Tracers.TRACE_ID_KEY)).isEqualTo(traceId); assertThat(Tracer.hasTraceId()).isTrue(); assertThat(Tracer.getTraceId()).isEqualTo(traceId); - Tracer.startSpan("foo"); - Tracer.startSpan("bar"); + Tracer.fastStartSpan("foo"); + Tracer.fastStartSpan("bar"); Tracer.fastCompleteSpan(); // Unsampled trace should still apply thread state @@ -186,7 +186,7 @@ public void testInitTraceCallsSampler() throws Exception { @Test public void testTraceCopyIsIndependent() throws Exception { - Tracer.startSpan("span"); + Tracer.fastStartSpan("span"); try { Trace trace = Tracer.copyTrace().get(); trace.push(mock(OpenSpan.class)); @@ -198,7 +198,7 @@ public void testTraceCopyIsIndependent() throws Exception { @Test public void testSetTraceSetsCurrentTraceAndMdcTraceIdKey() throws Exception { - Tracer.startSpan("operation"); + Tracer.fastStartSpan("operation"); Tracer.setTrace(Trace.of(true, "newTraceId")); assertThat(Tracer.getTraceId()).isEqualTo("newTraceId"); assertThat(MDC.get(Tracers.TRACE_ID_KEY)).isEqualTo("newTraceId"); @@ -225,12 +225,12 @@ public void testSetTraceMissingMdcTraceSampledKeyWhenNotObserved() { @Test public void testCompletedSpanHasCorrectSpanType() throws Exception { for (SpanType type : SpanType.values()) { - Tracer.startSpan("1", type); + Tracer.fastStartSpan("1", type); assertThat(Tracer.completeSpan().get().type()).isEqualTo(type); } // Default is LOCAL - Tracer.startSpan("1"); + Tracer.fastStartSpan("1"); assertThat(Tracer.completeSpan().get().type()).isEqualTo(SpanType.LOCAL); } @@ -239,7 +239,7 @@ public void testCompleteSpanWithMetadataIncludesMetadata() { Map metadata = ImmutableMap.of( "key1", "value1", "key2", "value2"); - Tracer.startSpan("operation"); + Tracer.fastStartSpan("operation"); Optional maybeSpan = Tracer.completeSpan(metadata); assertTrue(maybeSpan.isPresent()); assertThat(maybeSpan.get().getMetadata()).isEqualTo(metadata); @@ -254,7 +254,7 @@ public void testCompleteSpanWithoutMetadataHasNoMetadata() { public void testFastCompleteSpan() { Tracer.subscribe("1", observer1); String operation = "operation"; - Tracer.startSpan(operation); + Tracer.fastStartSpan(operation); Tracer.fastCompleteSpan(); verify(observer1).consume(spanCaptor.capture()); assertThat(spanCaptor.getValue().getOperation()).isEqualTo(operation); @@ -265,7 +265,7 @@ public void testFastCompleteSpanWithMetadata() { Tracer.subscribe("1", observer1); Map metadata = ImmutableMap.of("key", "value"); String operation = "operation"; - Tracer.startSpan("operation"); + Tracer.fastStartSpan("operation"); Tracer.fastCompleteSpan(metadata); verify(observer1).consume(spanCaptor.capture()); assertThat(spanCaptor.getValue().getOperation()).isEqualTo(operation); @@ -282,7 +282,7 @@ public void testObserversThrow() { throw new IllegalStateException("2"); }); String operation = "operation"; - Tracer.startSpan(operation); + Tracer.fastStartSpan(operation); Tracer.fastCompleteSpan(); verify(observer1).consume(spanCaptor.capture()); assertThat(spanCaptor.getValue().getOperation()).isEqualTo(operation); @@ -304,7 +304,7 @@ public void testGetAndClearTraceIfPresent() { @Test public void testClearAndGetTraceClearsMdc() { - Tracer.startSpan("test"); + Tracer.fastStartSpan("test"); try { String startTrace = Tracer.getTraceId(); assertThat(MDC.get(Tracers.TRACE_ID_KEY)).isEqualTo(startTrace); @@ -336,7 +336,7 @@ public void testCompleteRootSpanCompletesTrace() { @Test public void testHasTraceId() { assertThat(Tracer.hasTraceId()).isEqualTo(false); - Tracer.startSpan("testSpan"); + Tracer.fastStartSpan("testSpan"); try { assertThat(Tracer.hasTraceId()).isEqualTo(true); } finally { @@ -346,12 +346,12 @@ public void testHasTraceId() { } private static void startAndFastCompleteSpan() { - Tracer.startSpan("operation"); + Tracer.fastStartSpan("operation"); Tracer.fastCompleteSpan(); } private static Span startAndCompleteSpan() { - Tracer.startSpan("operation"); + Tracer.fastStartSpan("operation"); return Tracer.completeSpan().get(); } } diff --git a/tracing/src/test/java/com/palantir/tracing/TracersTest.java b/tracing/src/test/java/com/palantir/tracing/TracersTest.java index 540fff476..94c33991c 100644 --- a/tracing/src/test/java/com/palantir/tracing/TracersTest.java +++ b/tracing/src/test/java/com/palantir/tracing/TracersTest.java @@ -66,9 +66,9 @@ public void testWrapExecutorService() throws Exception { wrappedService.submit(traceExpectingCallableWithSingleSpan("DeferredTracer(unnamed operation)")).get(); // Non-empty trace - Tracer.startSpan("foo"); - Tracer.startSpan("bar"); - Tracer.startSpan("baz"); + Tracer.fastStartSpan("foo"); + Tracer.fastStartSpan("bar"); + Tracer.fastStartSpan("baz"); wrappedService.submit(traceExpectingCallableWithSingleSpan("DeferredTracer(unnamed operation)")).get(); wrappedService.submit(traceExpectingCallableWithSingleSpan("DeferredTracer(unnamed operation)")).get(); Tracer.fastCompleteSpan(); @@ -86,9 +86,9 @@ public void testWrapExecutorService_withSpan() throws Exception { wrappedService.submit(traceExpectingRunnableWithSingleSpan("operation")).get(); // Non-empty trace - Tracer.startSpan("foo"); - Tracer.startSpan("bar"); - Tracer.startSpan("baz"); + Tracer.fastStartSpan("foo"); + Tracer.fastStartSpan("bar"); + Tracer.fastStartSpan("baz"); wrappedService.submit(traceExpectingCallableWithSingleSpan("operation")).get(); wrappedService.submit(traceExpectingRunnableWithSingleSpan("operation")).get(); Tracer.fastCompleteSpan(); @@ -108,9 +108,9 @@ public void testWrapScheduledExecutorService() throws Exception { traceExpectingRunnableWithSingleSpan("DeferredTracer(unnamed operation)"), 0, TimeUnit.SECONDS).get(); // Non-empty trace - Tracer.startSpan("foo"); - Tracer.startSpan("bar"); - Tracer.startSpan("baz"); + Tracer.fastStartSpan("foo"); + Tracer.fastStartSpan("bar"); + Tracer.fastStartSpan("baz"); wrappedService.schedule( traceExpectingCallableWithSingleSpan("DeferredTracer(unnamed operation)"), 0, TimeUnit.SECONDS).get(); wrappedService.schedule( @@ -130,9 +130,9 @@ public void testWrapScheduledExecutorService_withSpan() throws Exception { wrappedService.schedule(traceExpectingRunnableWithSingleSpan("operation"), 0, TimeUnit.SECONDS).get(); // Non-empty trace - Tracer.startSpan("foo"); - Tracer.startSpan("bar"); - Tracer.startSpan("baz"); + Tracer.fastStartSpan("foo"); + Tracer.fastStartSpan("bar"); + Tracer.fastStartSpan("baz"); wrappedService.schedule(traceExpectingCallableWithSingleSpan("operation"), 0, TimeUnit.SECONDS).get(); wrappedService.schedule(traceExpectingRunnableWithSingleSpan("operation"), 0, TimeUnit.SECONDS).get(); Tracer.fastCompleteSpan(); @@ -156,9 +156,9 @@ public void testWrapExecutorServiceWithNewTrace() throws Exception { wrappedService.submit(runnable).get(); // Non-empty trace - Tracer.startSpan("foo"); - Tracer.startSpan("bar"); - Tracer.startSpan("baz"); + Tracer.fastStartSpan("foo"); + Tracer.fastStartSpan("bar"); + Tracer.fastStartSpan("baz"); wrappedService.submit(callable).get(); wrappedService.submit(runnable).get(); Tracer.fastCompleteSpan(); @@ -182,9 +182,9 @@ public void testWrapScheduledExecutorServiceWithNewTrace() throws Exception { wrappedService.schedule(runnable, 0, TimeUnit.SECONDS).get(); // Non-empty trace - Tracer.startSpan("foo"); - Tracer.startSpan("bar"); - Tracer.startSpan("baz"); + Tracer.fastStartSpan("foo"); + Tracer.fastStartSpan("bar"); + Tracer.fastStartSpan("baz"); wrappedService.schedule(callable, 0, TimeUnit.SECONDS).get(); wrappedService.schedule(runnable, 0, TimeUnit.SECONDS).get(); Tracer.fastCompleteSpan(); @@ -194,9 +194,9 @@ public void testWrapScheduledExecutorServiceWithNewTrace() throws Exception { @Test public void testWrapCallable_callableTraceIsIsolated() throws Exception { - Tracer.startSpan("outside"); + Tracer.fastStartSpan("outside"); Callable callable = Tracers.wrap(() -> { - Tracer.startSpan("inside"); // never completed + Tracer.fastStartSpan("inside"); // never completed return null; }); callable.call(); @@ -205,18 +205,18 @@ public void testWrapCallable_callableTraceIsIsolated() throws Exception { @Test public void testWrapCallable_traceStateIsCapturedAtConstructionTime() throws Exception { - Tracer.startSpan("before-construction"); + Tracer.fastStartSpan("before-construction"); Callable callable = Tracers.wrap(() -> { assertThat(Tracer.completeSpan().get().getOperation()).isEqualTo("DeferredTracer(unnamed operation)"); return null; }); - Tracer.startSpan("after-construction"); + Tracer.fastStartSpan("after-construction"); callable.call(); } @Test public void testWrapCallable_withSpan() throws Exception { - Tracer.startSpan("outside"); + Tracer.fastStartSpan("outside"); Runnable runnable = Tracers.wrap("operation", () -> { assertThat(Tracer.completeSpan().get().getOperation()).isEqualTo("operation"); }); @@ -226,9 +226,9 @@ public void testWrapCallable_withSpan() throws Exception { @Test public void testWrapRunnable_runnableTraceIsIsolated() throws Exception { - Tracer.startSpan("outside"); + Tracer.fastStartSpan("outside"); Runnable runnable = Tracers.wrap(() -> { - Tracer.startSpan("inside"); // never completed + Tracer.fastStartSpan("inside"); // never completed }); runnable.run(); assertThat(Tracer.completeSpan().get().getOperation()).isEqualTo("outside"); @@ -236,17 +236,17 @@ public void testWrapRunnable_runnableTraceIsIsolated() throws Exception { @Test public void testWrapRunnable_traceStateIsCapturedAtConstructionTime() throws Exception { - Tracer.startSpan("before-construction"); + Tracer.fastStartSpan("before-construction"); Runnable runnable = Tracers.wrap(() -> { assertThat(Tracer.completeSpan().get().getOperation()).isEqualTo("DeferredTracer(unnamed operation)"); }); - Tracer.startSpan("after-construction"); + Tracer.fastStartSpan("after-construction"); runnable.run(); } @Test public void testWrapRunnable_startsNewSpan() throws Exception { - Tracer.startSpan("outside"); + Tracer.fastStartSpan("outside"); Runnable runnable = Tracers.wrap("operation", () -> { assertThat(Tracer.completeSpan().get().getOperation()).isEqualTo("operation"); }); From 6063502f6b1f2681a059e1d1a4a095bca76a3f71 Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Thu, 20 Jun 2019 13:49:42 -0400 Subject: [PATCH 03/12] Refactor startSpan logic into Tracer to reduce duplication Added final fastStartSpan overload --- .gitignore | 1 + .../tracing/jersey/TraceEnrichingFilter.java | 2 +- .../undertow/TracedOperationHandler.java | 2 +- .../com/palantir/tracing/DeferredTracer.java | 2 +- .../main/java/com/palantir/tracing/Trace.java | 65 +++++++++++++++---- .../java/com/palantir/tracing/Tracer.java | 38 ++++------- .../java/com/palantir/tracing/TracerTest.java | 9 +++ 7 files changed, 79 insertions(+), 40 deletions(-) diff --git a/.gitignore b/.gitignore index 9be4cac7d..0ce6227af 100644 --- a/.gitignore +++ b/.gitignore @@ -19,6 +19,7 @@ bin/ .idea/ out/ generated_src/ +generated_testSrc/ # Codegen .generated 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 index 423c948cf..8a6db3599 100644 --- a/tracing-jersey/src/main/java/com/palantir/tracing/jersey/TraceEnrichingFilter.java +++ b/tracing-jersey/src/main/java/com/palantir/tracing/jersey/TraceEnrichingFilter.java @@ -75,7 +75,7 @@ public void filter(ContainerRequestContext requestContext) throws IOException { 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-undertow/src/main/java/com/palantir/tracing/undertow/TracedOperationHandler.java b/tracing-undertow/src/main/java/com/palantir/tracing/undertow/TracedOperationHandler.java index 32b065ccc..d255369f4 100644 --- a/tracing-undertow/src/main/java/com/palantir/tracing/undertow/TracedOperationHandler.java +++ b/tracing-undertow/src/main/java/com/palantir/tracing/undertow/TracedOperationHandler.java @@ -106,7 +106,7 @@ private void initializeTraceFromExisting(HeaderMap headers, String traceId) { 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/src/main/java/com/palantir/tracing/DeferredTracer.java b/tracing/src/main/java/com/palantir/tracing/DeferredTracer.java index f7c2a0515..607c81e9d 100644 --- a/tracing/src/main/java/com/palantir/tracing/DeferredTracer.java +++ b/tracing/src/main/java/com/palantir/tracing/DeferredTracer.java @@ -106,7 +106,7 @@ public T withTrace(Tracers.ThrowingCallable inner Tracer.setTrace(Trace.of(isObservable, traceId)); if (parentSpanId != null) { - Tracer.startSpan(operation, parentSpanId, SpanType.LOCAL); + Tracer.fastStartSpan(operation, parentSpanId, SpanType.LOCAL); } else { Tracer.fastStartSpan(operation); } diff --git a/tracing/src/main/java/com/palantir/tracing/Trace.java b/tracing/src/main/java/com/palantir/tracing/Trace.java index cd5f40a99..a7dd6ddfd 100644 --- a/tracing/src/main/java/com/palantir/tracing/Trace.java +++ b/tracing/src/main/java/com/palantir/tracing/Trace.java @@ -17,6 +17,7 @@ package com.palantir.tracing; import static com.palantir.logsafe.Preconditions.checkArgument; +import static com.palantir.logsafe.Preconditions.checkState; import com.google.common.base.Strings; import com.palantir.logsafe.SafeArg; @@ -41,7 +42,45 @@ private Trace(String traceId) { this.traceId = traceId; } - abstract void startSpan(String operation, SpanType type); + /** + * Opens a new span for this thread's call trace, labeled with the provided operation and parent span. Only allowed + * when the current trace is empty. + */ + final OpenSpan startSpan(String operation, String parentSpanId, SpanType type) { + checkState(isEmpty(), "Cannot start a span with explicit parent if the current thread's trace is non-empty"); + checkArgument(!Strings.isNullOrEmpty(parentSpanId), "parentSpanId must be non-empty"); + OpenSpan span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.of(parentSpanId)); + push(span); + return span; + } + + /** + * Opens a new span for this thread's call trace, labeled with the provided operation. + * If the return value is not used, prefer {@link #fastStartSpan(String, SpanType)}}. + */ + final OpenSpan startSpan(String operation, SpanType type) { + Optional prevState = top(); + final OpenSpan span; + // Avoid lambda allocation in hot paths + if (prevState.isPresent()) { + span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.of(prevState.get().getSpanId())); + } else { + span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.empty()); + } + + push(span); + return span; + } + + /** + * Like {@link #startSpan(String, String, SpanType)}, but does not return an {@link OpenSpan}. + */ + abstract void fastStartSpan(String operation, String parentSpanId, SpanType type); + + /** + * Like {@link #startSpan(String, SpanType)}, but does not return an {@link OpenSpan}. + */ + abstract void fastStartSpan(String operation, SpanType type); abstract void push(OpenSpan span); @@ -85,16 +124,13 @@ private Sampled(String traceId) { } @Override - void startSpan(String operation, SpanType type) { - Optional prevState = top(); - final OpenSpan span; - // Avoid lambda allocation in hot paths - if (prevState.isPresent()) { - span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.of(prevState.get().getSpanId())); - } else { - span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.empty()); - } - push(span); + void fastStartSpan(String operation, String parentSpanId, SpanType type) { + startSpan(operation, parentSpanId, type); + } + + @Override + void fastStartSpan(String operation, SpanType type) { + startSpan(operation, type); } @Override @@ -147,7 +183,12 @@ private Unsampled(String traceId) { } @Override - void startSpan(String operation, SpanType type) { + void fastStartSpan(String operation, String parentSpanId, SpanType type) { + fastStartSpan(operation, type); + } + + @Override + void fastStartSpan(String operation, SpanType type) { depth++; } diff --git a/tracing/src/main/java/com/palantir/tracing/Tracer.java b/tracing/src/main/java/com/palantir/tracing/Tracer.java index 418f6acec..e70bf92fb 100644 --- a/tracing/src/main/java/com/palantir/tracing/Tracer.java +++ b/tracing/src/main/java/com/palantir/tracing/Tracer.java @@ -108,15 +108,11 @@ public static void initTrace(Observability observability, String traceId) { /** * Opens a new span for this thread's call trace, labeled with the provided operation and parent span. Only allowed * when the current trace is empty. + * If the return value is not used, prefer {@link Tracer#fastStartSpan(String, String, SpanType)}}. */ + @CheckReturnValue public static OpenSpan startSpan(String operation, String parentSpanId, SpanType type) { - Trace current = getOrCreateCurrentTrace(); - checkState(current.isEmpty(), - "Cannot start a span with explicit parent if the current thread's trace is non-empty"); - checkArgument(!Strings.isNullOrEmpty(parentSpanId), "parentSpanId must be non-empty"); - OpenSpan span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.of(parentSpanId)); - current.push(span); - return span; + return getOrCreateCurrentTrace().startSpan(operation, parentSpanId, type); } /** @@ -125,7 +121,7 @@ public static OpenSpan startSpan(String operation, String parentSpanId, SpanType */ @CheckReturnValue public static OpenSpan startSpan(String operation, SpanType type) { - return startSpanInternal(operation, type); + return getOrCreateCurrentTrace().startSpan(operation, type); } /** @@ -134,14 +130,21 @@ public static OpenSpan startSpan(String operation, SpanType type) { */ @CheckReturnValue public static OpenSpan startSpan(String operation) { - return startSpanInternal(operation, SpanType.LOCAL); + return startSpan(operation, SpanType.LOCAL); + } + + /** + * Like {@link #startSpan(String, String, SpanType)}, but does not return an {@link OpenSpan}. + */ + public static void fastStartSpan(String operation, String parentSpanId, SpanType type) { + getOrCreateCurrentTrace().fastStartSpan(operation, parentSpanId, type); } /** * Like {@link #startSpan(String, SpanType)}, but does not return an {@link OpenSpan}. */ public static void fastStartSpan(String operation, SpanType type) { - getOrCreateCurrentTrace().startSpan(operation, type); + getOrCreateCurrentTrace().fastStartSpan(operation, type); } /** @@ -151,21 +154,6 @@ public static void fastStartSpan(String operation) { fastStartSpan(operation, SpanType.LOCAL); } - private static OpenSpan startSpanInternal(String operation, SpanType type) { - Trace trace = getOrCreateCurrentTrace(); - Optional prevState = trace.top(); - final OpenSpan span; - // Avoid lambda allocation in hot paths - if (prevState.isPresent()) { - span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.of(prevState.get().getSpanId())); - } else { - span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.empty()); - } - - trace.push(span); - return span; - } - /** Discards the current span without emitting it. */ static void fastDiscardSpan() { Trace trace = currentTrace.get(); diff --git a/tracing/src/test/java/com/palantir/tracing/TracerTest.java b/tracing/src/test/java/com/palantir/tracing/TracerTest.java index 3bc60b569..ea8a40aa5 100644 --- a/tracing/src/test/java/com/palantir/tracing/TracerTest.java +++ b/tracing/src/test/java/com/palantir/tracing/TracerTest.java @@ -70,6 +70,7 @@ public void after() { } @Test + @SuppressWarnings("ResultOfMethodCallIgnored") // testing that exceptions are thrown public void testIdsMustBeNonNullAndNotEmpty() throws Exception { assertThatLoggableExceptionThrownBy(() -> Tracer.initTrace(Observability.UNDECIDED, null)) .hasLogMessage("traceId must be non-empty") @@ -86,6 +87,14 @@ public void testIdsMustBeNonNullAndNotEmpty() throws Exception { assertThatLoggableExceptionThrownBy(() -> Tracer.startSpan("op", "", null)) .hasLogMessage("parentSpanId must be non-empty") .hasArgs(); + + assertThatLoggableExceptionThrownBy(() -> Tracer.fastStartSpan("op", null, null)) + .hasLogMessage("parentSpanId must be non-empty") + .hasArgs(); + + assertThatLoggableExceptionThrownBy(() -> Tracer.fastStartSpan("op", "", null)) + .hasLogMessage("parentSpanId must be non-empty") + .hasArgs(); } @Test From e1adc3c4d1868b49dea9eaa314f733b130a320ee Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Thu, 20 Jun 2019 13:58:34 -0400 Subject: [PATCH 04/12] Clean up TracingBenchmark a bit Doesn't change performance. --- .../com/palantir/tracing/TracingBenchmark.java | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java b/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java index f57eda981..973e80886 100644 --- 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,7 +48,7 @@ @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 { @@ -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.fastStartSpan("span"); - toBenNested.run(); + next.run(); } finally { Tracer.fastCompleteSpan(); } From 41896d4341d44d4f3549507d927f3ebcfe6533be Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Thu, 20 Jun 2019 21:59:03 -0400 Subject: [PATCH 05/12] Match default sample rate --- .../src/jmh/java/com/palantir/tracing/TracingBenchmark.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java b/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java index 973e80886..ec3576339 100644 --- a/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java +++ b/tracing-benchmarks/src/jmh/java/com/palantir/tracing/TracingBenchmark.java @@ -54,7 +54,7 @@ public class TracingBenchmark { public enum BenchmarkObservability { SAMPLE(AlwaysSampler.INSTANCE), DO_NOT_SAMPLE(() -> false), - UNDECIDED(new RandomSampler(0.1f)); + UNDECIDED(new RandomSampler(0.01f)); private final TraceSampler traceSampler; From 90e45fbb9095ec34e901cdb676d10781268dc15c Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Fri, 21 Jun 2019 08:14:23 -0400 Subject: [PATCH 06/12] Annotate Trace internal methods with CheckReturnValue --- tracing/src/main/java/com/palantir/tracing/Trace.java | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/tracing/src/main/java/com/palantir/tracing/Trace.java b/tracing/src/main/java/com/palantir/tracing/Trace.java index a7dd6ddfd..3a6dc8373 100644 --- a/tracing/src/main/java/com/palantir/tracing/Trace.java +++ b/tracing/src/main/java/com/palantir/tracing/Trace.java @@ -20,6 +20,7 @@ import static com.palantir.logsafe.Preconditions.checkState; import com.google.common.base.Strings; +import com.google.errorprone.annotations.CheckReturnValue; import com.palantir.logsafe.SafeArg; import com.palantir.logsafe.exceptions.SafeIllegalStateException; import com.palantir.tracing.api.OpenSpan; @@ -45,7 +46,9 @@ private Trace(String traceId) { /** * Opens a new span for this thread's call trace, labeled with the provided operation and parent span. Only allowed * when the current trace is empty. + * If the return value is not used, prefer {@link #fastStartSpan(String, String, SpanType)}}. */ + @CheckReturnValue final OpenSpan startSpan(String operation, String parentSpanId, SpanType type) { checkState(isEmpty(), "Cannot start a span with explicit parent if the current thread's trace is non-empty"); checkArgument(!Strings.isNullOrEmpty(parentSpanId), "parentSpanId must be non-empty"); @@ -58,6 +61,7 @@ final OpenSpan startSpan(String operation, String parentSpanId, SpanType type) { * Opens a new span for this thread's call trace, labeled with the provided operation. * If the return value is not used, prefer {@link #fastStartSpan(String, SpanType)}}. */ + @CheckReturnValue final OpenSpan startSpan(String operation, SpanType type) { Optional prevState = top(); final OpenSpan span; @@ -124,11 +128,13 @@ private Sampled(String traceId) { } @Override + @SuppressWarnings("ResultOfMethodCallIgnored") // Sampled traces cannot optimize this path void fastStartSpan(String operation, String parentSpanId, SpanType type) { startSpan(operation, parentSpanId, type); } @Override + @SuppressWarnings("ResultOfMethodCallIgnored") // Sampled traces cannot optimize this path void fastStartSpan(String operation, SpanType type) { startSpan(operation, type); } From 64e92149c596a383a4f5dfa41a3bf01fa337e0a2 Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Fri, 21 Jun 2019 08:50:26 -0400 Subject: [PATCH 07/12] s/depth/numberOfSpans --- .../main/java/com/palantir/tracing/Trace.java | 29 +++++++++++-------- 1 file changed, 17 insertions(+), 12 deletions(-) diff --git a/tracing/src/main/java/com/palantir/tracing/Trace.java b/tracing/src/main/java/com/palantir/tracing/Trace.java index 3a6dc8373..b244c9995 100644 --- a/tracing/src/main/java/com/palantir/tracing/Trace.java +++ b/tracing/src/main/java/com/palantir/tracing/Trace.java @@ -176,11 +176,15 @@ public String toString() { } private static final class Unsampled extends Trace { - private int depth; + /** + * Tracks the size that a {@link Sampled} trace {@link Sampled#stack} would have if this was sampled. + * This allows thread trace state to be cleared when all "started" spans have been "removed". + */ + private int numberOfSpans; - private Unsampled(int depth, String traceId) { + private Unsampled(int numberOfSpans, String traceId) { super(traceId); - this.depth = depth; + this.numberOfSpans = numberOfSpans; validateDepth(); } @@ -195,12 +199,12 @@ void fastStartSpan(String operation, String parentSpanId, SpanType type) { @Override void fastStartSpan(String operation, SpanType type) { - depth++; + numberOfSpans++; } @Override void push(OpenSpan span) { - depth++; + numberOfSpans++; } @Override @@ -211,8 +215,8 @@ Optional top() { @Override Optional pop() { validateDepth(); - if (depth > 0) { - depth--; + if (numberOfSpans > 0) { + numberOfSpans--; } return Optional.empty(); } @@ -220,7 +224,7 @@ Optional pop() { @Override boolean isEmpty() { validateDepth(); - return depth <= 0; + return numberOfSpans <= 0; } @Override @@ -230,18 +234,19 @@ boolean isObservable() { @Override Trace deepCopy() { - return new Unsampled(depth, getTraceId()); + return new Unsampled(numberOfSpans, getTraceId()); } + /** Internal validation, this should never fail because {@link #pop()} only decrements positive values. */ private void validateDepth() { - if (depth < 0) { - throw new SafeIllegalStateException("Unexpected negative depth", SafeArg.of("depth", depth)); + if (numberOfSpans < 0) { + throw new SafeIllegalStateException("Unexpected negative numberOfSpans", SafeArg.of("numberOfSpans", numberOfSpans)); } } @Override public String toString() { - return "Trace{depth=" + depth + ", isObservable=false, traceId='" + getTraceId() + "'}"; + return "Trace{numberOfSpans=" + numberOfSpans + ", isObservable=false, traceId='" + getTraceId() + "'}"; } } } From 752fb36dc77ce3bda6b7affc44e3832b5d46d21b Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Fri, 21 Jun 2019 08:54:27 -0400 Subject: [PATCH 08/12] style --- tracing/src/main/java/com/palantir/tracing/Trace.java | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/tracing/src/main/java/com/palantir/tracing/Trace.java b/tracing/src/main/java/com/palantir/tracing/Trace.java index b244c9995..55f4e77ed 100644 --- a/tracing/src/main/java/com/palantir/tracing/Trace.java +++ b/tracing/src/main/java/com/palantir/tracing/Trace.java @@ -240,7 +240,8 @@ Trace deepCopy() { /** Internal validation, this should never fail because {@link #pop()} only decrements positive values. */ private void validateDepth() { if (numberOfSpans < 0) { - throw new SafeIllegalStateException("Unexpected negative numberOfSpans", SafeArg.of("numberOfSpans", numberOfSpans)); + throw new SafeIllegalStateException("Unexpected negative numberOfSpans", + SafeArg.of("numberOfSpans", numberOfSpans)); } } From 1b57d51a2ac25b7223125f635da7c5d24935d30e Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Fri, 21 Jun 2019 08:58:40 -0400 Subject: [PATCH 09/12] class level design documentation --- tracing/src/main/java/com/palantir/tracing/Trace.java | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/tracing/src/main/java/com/palantir/tracing/Trace.java b/tracing/src/main/java/com/palantir/tracing/Trace.java index 55f4e77ed..895decabf 100644 --- a/tracing/src/main/java/com/palantir/tracing/Trace.java +++ b/tracing/src/main/java/com/palantir/tracing/Trace.java @@ -33,6 +33,13 @@ /** * Represents a trace as an ordered list of non-completed spans. Supports adding and removing of spans. This class is * not thread-safe and is intended to be used in a thread-local context. + * + * There are two implementations of {@link Trace}: {@link Sampled} and {@link Unsampled}. + * A {@link Sampled sampled trace} records each span in order to record tracing data, however in most scenarios + * most traces will be {@link Unsampled}, which avoids creation of span objects, random span ID generation, + * clock reads, etc. Instead, the {@link Unsampled unsampled} implementation tracks the number of 'active' spans + * on the current thread so it can provide correct {@link Trace#isEmpty()} values allowing the {@link Tracer} + * utility to reset thread state after the emulated root span has been completed. */ public abstract class Trace { From 80340a3f91df18eb19bb03532d259704dc96ea04 Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Sun, 23 Jun 2019 13:54:18 -0400 Subject: [PATCH 10/12] Trace.push is an internal concern --- .../src/main/java/com/palantir/tracing/Trace.java | 6 +++--- .../test/java/com/palantir/tracing/TraceTest.java | 14 +++++--------- .../test/java/com/palantir/tracing/TracerTest.java | 4 +--- 3 files changed, 9 insertions(+), 15 deletions(-) diff --git a/tracing/src/main/java/com/palantir/tracing/Trace.java b/tracing/src/main/java/com/palantir/tracing/Trace.java index 895decabf..86c1221c1 100644 --- a/tracing/src/main/java/com/palantir/tracing/Trace.java +++ b/tracing/src/main/java/com/palantir/tracing/Trace.java @@ -93,7 +93,7 @@ final OpenSpan startSpan(String operation, SpanType type) { */ abstract void fastStartSpan(String operation, SpanType type); - abstract void push(OpenSpan span); + protected abstract void push(OpenSpan span); abstract Optional top(); @@ -147,7 +147,7 @@ void fastStartSpan(String operation, SpanType type) { } @Override - void push(OpenSpan span) { + protected void push(OpenSpan span) { stack.push(span); } @@ -210,7 +210,7 @@ void fastStartSpan(String operation, SpanType type) { } @Override - void push(OpenSpan span) { + protected void push(OpenSpan span) { numberOfSpans++; } diff --git a/tracing/src/test/java/com/palantir/tracing/TraceTest.java b/tracing/src/test/java/com/palantir/tracing/TraceTest.java index 23a3dce13..0c1158ddc 100644 --- a/tracing/src/test/java/com/palantir/tracing/TraceTest.java +++ b/tracing/src/test/java/com/palantir/tracing/TraceTest.java @@ -34,14 +34,10 @@ public void constructTrace_emptyTraceId() { @Test public void testToString() { Trace trace = Trace.of(true, "traceId"); - trace.push(OpenSpan.builder() - .type(SpanType.LOCAL) - .spanId("spanId") - .operation("operation") - .startClockNanoSeconds(0L) - .startTimeMicroSeconds(0L) - .build()); - assertThat(trace.toString()).isEqualTo("Trace{stack=[OpenSpan{operation=operation, startTimeMicroSeconds=0, " - + "startClockNanoSeconds=0, spanId=spanId, type=LOCAL}], isObservable=true, traceId='traceId'}"); + OpenSpan span = trace.startSpan("operation", SpanType.LOCAL); + assertThat(trace.toString()) + .isEqualTo("Trace{stack=[" + span + "], isObservable=true, traceId='traceId'}") + .contains(span.getOperation()) + .contains(span.getSpanId()); } } diff --git a/tracing/src/test/java/com/palantir/tracing/TracerTest.java b/tracing/src/test/java/com/palantir/tracing/TracerTest.java index ea8a40aa5..330e73c41 100644 --- a/tracing/src/test/java/com/palantir/tracing/TracerTest.java +++ b/tracing/src/test/java/com/palantir/tracing/TracerTest.java @@ -19,13 +19,11 @@ import static com.palantir.logsafe.testing.Assertions.assertThatLoggableExceptionThrownBy; import static org.assertj.core.api.Assertions.assertThat; import static org.junit.Assert.assertTrue; -import static org.mockito.Mockito.mock; import static org.mockito.Mockito.verify; import static org.mockito.Mockito.verifyNoMoreInteractions; import static org.mockito.Mockito.when; import com.google.common.collect.ImmutableMap; -import com.palantir.tracing.api.OpenSpan; import com.palantir.tracing.api.Span; import com.palantir.tracing.api.SpanObserver; import com.palantir.tracing.api.SpanType; @@ -198,7 +196,7 @@ public void testTraceCopyIsIndependent() throws Exception { Tracer.fastStartSpan("span"); try { Trace trace = Tracer.copyTrace().get(); - trace.push(mock(OpenSpan.class)); + trace.fastStartSpan("fop", SpanType.LOCAL); } finally { Tracer.fastCompleteSpan(); } From 9d06c36bfb01d7b234f61e75ba8a58cb23105d1a Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Sun, 23 Jun 2019 18:33:32 -0400 Subject: [PATCH 11/12] rename validateDepth -> validateNumberOfSpans --- tracing/src/main/java/com/palantir/tracing/Trace.java | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/tracing/src/main/java/com/palantir/tracing/Trace.java b/tracing/src/main/java/com/palantir/tracing/Trace.java index 86c1221c1..c22d9d48a 100644 --- a/tracing/src/main/java/com/palantir/tracing/Trace.java +++ b/tracing/src/main/java/com/palantir/tracing/Trace.java @@ -192,7 +192,7 @@ private static final class Unsampled extends Trace { private Unsampled(int numberOfSpans, String traceId) { super(traceId); this.numberOfSpans = numberOfSpans; - validateDepth(); + validateNumberOfSpans(); } private Unsampled(String traceId) { @@ -221,7 +221,7 @@ Optional top() { @Override Optional pop() { - validateDepth(); + validateNumberOfSpans(); if (numberOfSpans > 0) { numberOfSpans--; } @@ -230,7 +230,7 @@ Optional pop() { @Override boolean isEmpty() { - validateDepth(); + validateNumberOfSpans(); return numberOfSpans <= 0; } @@ -245,7 +245,7 @@ Trace deepCopy() { } /** Internal validation, this should never fail because {@link #pop()} only decrements positive values. */ - private void validateDepth() { + private void validateNumberOfSpans() { if (numberOfSpans < 0) { throw new SafeIllegalStateException("Unexpected negative numberOfSpans", SafeArg.of("numberOfSpans", numberOfSpans)); From da00afb76ac5141dc7950b2c0ddd46ca0a66f0bf Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Sun, 23 Jun 2019 21:34:49 -0400 Subject: [PATCH 12/12] popCurrentSpan takes a trace We already have it in most cases, no reason to look up from the threadlocal. --- .../java/com/palantir/tracing/Tracer.java | 30 ++++++++++--------- 1 file changed, 16 insertions(+), 14 deletions(-) diff --git a/tracing/src/main/java/com/palantir/tracing/Tracer.java b/tracing/src/main/java/com/palantir/tracing/Tracer.java index e70bf92fb..08830338f 100644 --- a/tracing/src/main/java/com/palantir/tracing/Tracer.java +++ b/tracing/src/main/java/com/palantir/tracing/Tracer.java @@ -159,7 +159,7 @@ static void fastDiscardSpan() { Trace trace = currentTrace.get(); checkNotNull(trace, "Expected current trace to exist"); checkState(!trace.isEmpty(), "Expected span to exist before discarding"); - popCurrentSpan(); + popCurrentSpan(trace); } /** @@ -178,14 +178,20 @@ public static void fastCompleteSpan() { public static void fastCompleteSpan(Map metadata) { Trace trace = currentTrace.get(); if (trace != null) { - Optional span = popCurrentSpan(); + Optional span = popCurrentSpan(trace); if (trace.isObservable()) { - span.map(openSpan -> toSpan(openSpan, metadata, trace.getTraceId())) - .ifPresent(Tracer::notifyObservers); + completeSpanAndNotifyObservers(span, metadata, trace.getTraceId()); } } } + private static void completeSpanAndNotifyObservers( + Optional openSpan, Map metadata, String traceId) { + if (openSpan.isPresent()) { + Tracer.notifyObservers(toSpan(openSpan.get(), metadata, traceId)); + } + } + /** * Completes and returns the current span (if it exists) and notifies all {@link #observers subscribers} about the * completed span. @@ -206,7 +212,7 @@ public static Optional completeSpan(Map metadata) { if (trace == null) { return Optional.empty(); } - Optional maybeSpan = popCurrentSpan() + Optional maybeSpan = popCurrentSpan(trace) .map(openSpan -> toSpan(openSpan, metadata, trace.getTraceId())); // Notify subscribers iff trace is observable @@ -222,16 +228,12 @@ private static void notifyObservers(Span span) { compositeObserver.accept(span); } - private static Optional popCurrentSpan() { - Trace trace = currentTrace.get(); - if (trace != null) { - Optional span = trace.pop(); - if (trace.isEmpty()) { - clearCurrentTrace(); - } - return span; + private static Optional popCurrentSpan(Trace trace) { + Optional span = trace.pop(); + if (trace.isEmpty()) { + clearCurrentTrace(); } - return Optional.empty(); + return span; } private static Span toSpan(OpenSpan openSpan, Map metadata, String traceId) {