Skip to content

Commit f1608f5

Browse files
bm1549devflow.devflow-routing-intake
andauthored
Optimize PendingTrace span registration and time tracking (#11078)
Optimize PendingTrace hot paths with lazySet and CAS guard tag: no release note tag: ai generated Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com> Add startAndFinishSpan and contended benchmarks to TimeSourceBenchmark Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com> Co-authored-by: devflow.devflow-routing-intake <devflow.devflow-routing-intake@kubernetes.us1.ddbuild.io>
1 parent 7426235 commit f1608f5

File tree

2 files changed

+110
-5
lines changed

2 files changed

+110
-5
lines changed
Lines changed: 99 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,99 @@
1+
package datadog.trace.core;
2+
3+
import static java.util.concurrent.TimeUnit.NANOSECONDS;
4+
5+
import datadog.trace.api.DDTraceId;
6+
import org.openjdk.jmh.annotations.Benchmark;
7+
import org.openjdk.jmh.annotations.BenchmarkMode;
8+
import org.openjdk.jmh.annotations.Fork;
9+
import org.openjdk.jmh.annotations.Level;
10+
import org.openjdk.jmh.annotations.Measurement;
11+
import org.openjdk.jmh.annotations.Mode;
12+
import org.openjdk.jmh.annotations.OutputTimeUnit;
13+
import org.openjdk.jmh.annotations.Scope;
14+
import org.openjdk.jmh.annotations.Setup;
15+
import org.openjdk.jmh.annotations.State;
16+
import org.openjdk.jmh.annotations.TearDown;
17+
import org.openjdk.jmh.annotations.Threads;
18+
import org.openjdk.jmh.annotations.Warmup;
19+
20+
@State(Scope.Thread)
21+
@Warmup(iterations = 3)
22+
@Measurement(iterations = 5)
23+
@BenchmarkMode(Mode.Throughput)
24+
@Threads(8)
25+
@OutputTimeUnit(NANOSECONDS)
26+
@Fork(value = 1)
27+
public class TimeSourceBenchmark {
28+
29+
static final CoreTracer TRACER = CoreTracer.builder().build();
30+
31+
private PendingTrace pendingTrace;
32+
33+
@Setup(Level.Trial)
34+
public void setup() {
35+
TraceCollector collector = TRACER.createTraceCollector(DDTraceId.ONE);
36+
pendingTrace = (PendingTrace) collector;
37+
}
38+
39+
@TearDown(Level.Trial)
40+
public void teardown() {
41+
pendingTrace = null;
42+
}
43+
44+
@Benchmark
45+
public long getCurrentTimeNano() {
46+
return pendingTrace.getCurrentTimeNano();
47+
}
48+
49+
@Benchmark
50+
public long systemNanoTime() {
51+
return System.nanoTime();
52+
}
53+
54+
@Benchmark
55+
public long systemCurrentTimeMillis() {
56+
return System.currentTimeMillis();
57+
}
58+
59+
@Benchmark
60+
public long traceGetTimeWithNanoTicks() {
61+
return TRACER.getTimeWithNanoTicks(System.nanoTime());
62+
}
63+
64+
/**
65+
* Measures a full span start + finish cycle, exercising both the {@code rootSpan} CAS guard in
66+
* {@link PendingTrace#registerSpan} and the {@code lazySet} of {@code lastReferenced} in {@link
67+
* PendingTrace#getCurrentTimeNano}.
68+
*/
69+
@Benchmark
70+
public void startAndFinishSpan() {
71+
TRACER.startSpan("benchmark", "op").finish();
72+
}
73+
74+
@State(Scope.Benchmark)
75+
public static class SharedState {
76+
PendingTrace sharedTrace;
77+
78+
@Setup(Level.Trial)
79+
public void setup() {
80+
TraceCollector collector = TRACER.createTraceCollector(DDTraceId.ONE);
81+
sharedTrace = (PendingTrace) collector;
82+
}
83+
84+
@TearDown(Level.Trial)
85+
public void teardown() {
86+
sharedTrace = null;
87+
}
88+
}
89+
90+
/**
91+
* Measures {@link PendingTrace#getCurrentTimeNano()} under cross-thread contention on a single
92+
* shared {@code PendingTrace}. All threads write to the same {@code lastReferenced} field,
93+
* demonstrating the benefit of {@code lazySet} over a volatile store under contention.
94+
*/
95+
@Benchmark
96+
public long getCurrentTimeNano_contended(SharedState shared) {
97+
return shared.sharedTrace.getCurrentTimeNano();
98+
}
99+
}

dd-trace-core/src/main/java/datadog/trace/core/PendingTrace.java

Lines changed: 11 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -131,10 +131,14 @@ public PendingTrace create(@Nonnull DDTraceId traceId, ConfigSnapshot traceConfi
131131

132132
/**
133133
* Updated with the latest nanoTicks each time getCurrentTimeNano is called (at the start and
134-
* finish of each span).
134+
* finish of each span). Uses lazySet for writes (release-store semantics) since the value is only
135+
* read for approximate timeout detection by the PendingTraceBuffer background thread.
135136
*/
136137
private volatile long lastReferenced = 0;
137138

139+
private static final AtomicLongFieldUpdater<PendingTrace> LAST_REFERENCED =
140+
AtomicLongFieldUpdater.newUpdater(PendingTrace.class, "lastReferenced");
141+
138142
private PendingTrace(
139143
@Nonnull CoreTracer tracer,
140144
@Nonnull DDTraceId traceId,
@@ -163,25 +167,27 @@ private PendingTrace(
163167
@Override
164168
public long getCurrentTimeNano() {
165169
long nanoTicks = timeSource.getNanoTicks();
166-
lastReferenced = nanoTicks;
170+
LAST_REFERENCED.lazySet(this, nanoTicks);
167171
return tracer.getTimeWithNanoTicks(nanoTicks);
168172
}
169173

170174
@Override
171175
void touch() {
172-
lastReferenced = timeSource.getNanoTicks();
176+
LAST_REFERENCED.lazySet(this, timeSource.getNanoTicks());
173177
}
174178

175179
@Override
176180
public boolean lastReferencedNanosAgo(long nanos) {
177181
long currentNanoTicks = timeSource.getNanoTicks();
178-
long age = currentNanoTicks - lastReferenced;
182+
long age = currentNanoTicks - LAST_REFERENCED.get(this);
179183
return nanos < age;
180184
}
181185

182186
@Override
183187
void registerSpan(final DDSpan span) {
184-
ROOT_SPAN.compareAndSet(this, null, span);
188+
if (rootSpan == null) {
189+
ROOT_SPAN.compareAndSet(this, null, span);
190+
}
185191
PENDING_REFERENCE_COUNT.incrementAndGet(this);
186192
healthMetrics.onCreateSpan();
187193
if (pendingTraceBuffer.longRunningSpansEnabled()) {

0 commit comments

Comments
 (0)