diff --git a/dd-trace-core/src/jmh/java/datadog/trace/core/TimeSourceBenchmark.java b/dd-trace-core/src/jmh/java/datadog/trace/core/TimeSourceBenchmark.java new file mode 100644 index 00000000000..0f7dd2769f8 --- /dev/null +++ b/dd-trace-core/src/jmh/java/datadog/trace/core/TimeSourceBenchmark.java @@ -0,0 +1,99 @@ +package datadog.trace.core; + +import static java.util.concurrent.TimeUnit.NANOSECONDS; + +import datadog.trace.api.DDTraceId; +import org.openjdk.jmh.annotations.Benchmark; +import org.openjdk.jmh.annotations.BenchmarkMode; +import org.openjdk.jmh.annotations.Fork; +import org.openjdk.jmh.annotations.Level; +import org.openjdk.jmh.annotations.Measurement; +import org.openjdk.jmh.annotations.Mode; +import org.openjdk.jmh.annotations.OutputTimeUnit; +import org.openjdk.jmh.annotations.Scope; +import org.openjdk.jmh.annotations.Setup; +import org.openjdk.jmh.annotations.State; +import org.openjdk.jmh.annotations.TearDown; +import org.openjdk.jmh.annotations.Threads; +import org.openjdk.jmh.annotations.Warmup; + +@State(Scope.Thread) +@Warmup(iterations = 3) +@Measurement(iterations = 5) +@BenchmarkMode(Mode.Throughput) +@Threads(8) +@OutputTimeUnit(NANOSECONDS) +@Fork(value = 1) +public class TimeSourceBenchmark { + + static final CoreTracer TRACER = CoreTracer.builder().build(); + + private PendingTrace pendingTrace; + + @Setup(Level.Trial) + public void setup() { + TraceCollector collector = TRACER.createTraceCollector(DDTraceId.ONE); + pendingTrace = (PendingTrace) collector; + } + + @TearDown(Level.Trial) + public void teardown() { + pendingTrace = null; + } + + @Benchmark + public long getCurrentTimeNano() { + return pendingTrace.getCurrentTimeNano(); + } + + @Benchmark + public long systemNanoTime() { + return System.nanoTime(); + } + + @Benchmark + public long systemCurrentTimeMillis() { + return System.currentTimeMillis(); + } + + @Benchmark + public long traceGetTimeWithNanoTicks() { + return TRACER.getTimeWithNanoTicks(System.nanoTime()); + } + + /** + * Measures a full span start + finish cycle, exercising both the {@code rootSpan} CAS guard in + * {@link PendingTrace#registerSpan} and the {@code lazySet} of {@code lastReferenced} in {@link + * PendingTrace#getCurrentTimeNano}. + */ + @Benchmark + public void startAndFinishSpan() { + TRACER.startSpan("benchmark", "op").finish(); + } + + @State(Scope.Benchmark) + public static class SharedState { + PendingTrace sharedTrace; + + @Setup(Level.Trial) + public void setup() { + TraceCollector collector = TRACER.createTraceCollector(DDTraceId.ONE); + sharedTrace = (PendingTrace) collector; + } + + @TearDown(Level.Trial) + public void teardown() { + sharedTrace = null; + } + } + + /** + * Measures {@link PendingTrace#getCurrentTimeNano()} under cross-thread contention on a single + * shared {@code PendingTrace}. All threads write to the same {@code lastReferenced} field, + * demonstrating the benefit of {@code lazySet} over a volatile store under contention. + */ + @Benchmark + public long getCurrentTimeNano_contended(SharedState shared) { + return shared.sharedTrace.getCurrentTimeNano(); + } +} diff --git a/dd-trace-core/src/main/java/datadog/trace/core/PendingTrace.java b/dd-trace-core/src/main/java/datadog/trace/core/PendingTrace.java index 19525d6109b..ad872164718 100644 --- a/dd-trace-core/src/main/java/datadog/trace/core/PendingTrace.java +++ b/dd-trace-core/src/main/java/datadog/trace/core/PendingTrace.java @@ -131,10 +131,14 @@ public PendingTrace create(@Nonnull DDTraceId traceId, ConfigSnapshot traceConfi /** * Updated with the latest nanoTicks each time getCurrentTimeNano is called (at the start and - * finish of each span). + * finish of each span). Uses lazySet for writes (release-store semantics) since the value is only + * read for approximate timeout detection by the PendingTraceBuffer background thread. */ private volatile long lastReferenced = 0; + private static final AtomicLongFieldUpdater LAST_REFERENCED = + AtomicLongFieldUpdater.newUpdater(PendingTrace.class, "lastReferenced"); + private PendingTrace( @Nonnull CoreTracer tracer, @Nonnull DDTraceId traceId, @@ -163,25 +167,27 @@ private PendingTrace( @Override public long getCurrentTimeNano() { long nanoTicks = timeSource.getNanoTicks(); - lastReferenced = nanoTicks; + LAST_REFERENCED.lazySet(this, nanoTicks); return tracer.getTimeWithNanoTicks(nanoTicks); } @Override void touch() { - lastReferenced = timeSource.getNanoTicks(); + LAST_REFERENCED.lazySet(this, timeSource.getNanoTicks()); } @Override public boolean lastReferencedNanosAgo(long nanos) { long currentNanoTicks = timeSource.getNanoTicks(); - long age = currentNanoTicks - lastReferenced; + long age = currentNanoTicks - LAST_REFERENCED.get(this); return nanos < age; } @Override void registerSpan(final DDSpan span) { - ROOT_SPAN.compareAndSet(this, null, span); + if (rootSpan == null) { + ROOT_SPAN.compareAndSet(this, null, span); + } PENDING_REFERENCE_COUNT.incrementAndGet(this); healthMetrics.onCreateSpan(); if (pendingTraceBuffer.longRunningSpansEnabled()) {