From d25bf20e9888f2415b32cd0434ec898efe7ebfc3 Mon Sep 17 00:00:00 2001 From: sheldon-nadarajah-sft Date: Wed, 8 Jul 2026 10:38:17 +0200 Subject: [PATCH 1/2] Fix span timestamps staying stale after an AWS Lambda SnapStart restore CoreTracer caches a startTimeNano/startNanoTicks reference pair once at construction and derives every span timestamp from a monotonic-tick delta off it, self-correcting drift once clockSyncPeriod (default 30s) of *monotonic* time has elapsed since the last check. AWS Lambda SnapStart checkpoints the JVM at snapshot-creation time and restores a new execution environment from that snapshot later - potentially hours or days later, on different hardware. System.nanoTime() does not account for that gap, so a short-lived restore-then-invoke sequence never accumulates enough monotonic ticks to trigger the periodic correction, and every span stays anchored near the original snapshot-creation instant instead of the real invocation time. Confirmed in production: DynamoDB child spans timestamped ~2 hours before their own parent Lambda span, landing squarely inside the snapshot's original platform.initStart window. Resyncs the cached clock reference from CoreTracer.notifyLambdaStart(), already invoked once per Lambda invocation before any span for that invocation is created. Any real restore is always followed by an invocation, so this catches it without reacting to the restore event itself or needing a new runtime dependency. Gated behind a new, opt-in, disabled-by-default config: DD_TRACE_LAMBDA_SNAPSTART_CLOCK_RESYNC_ENABLED. Co-Authored-By: Claude Sonnet 5 --- .../datadog/trace/api/ConfigDefaults.java | 2 + .../trace/api/config/TracerConfig.java | 11 +++ .../java/datadog/trace/core/CoreTracer.java | 57 +++++++++++- .../datadog/trace/core/CoreTracerTest.java | 88 +++++++++++++++++++ .../main/java/datadog/trace/api/Config.java | 12 +++ metadata/supported-configurations.json | 8 ++ 6 files changed, 174 insertions(+), 4 deletions(-) diff --git a/dd-trace-api/src/main/java/datadog/trace/api/ConfigDefaults.java b/dd-trace-api/src/main/java/datadog/trace/api/ConfigDefaults.java index 1aba2cb276b..28e14df224c 100644 --- a/dd-trace-api/src/main/java/datadog/trace/api/ConfigDefaults.java +++ b/dd-trace-api/src/main/java/datadog/trace/api/ConfigDefaults.java @@ -95,6 +95,8 @@ public final class ConfigDefaults { static final int DEFAULT_CLOCK_SYNC_PERIOD = 30; // seconds + static final boolean DEFAULT_TRACE_LAMBDA_SNAPSTART_CLOCK_RESYNC_ENABLED = false; + static final TracePropagationBehaviorExtract DEFAULT_TRACE_PROPAGATION_BEHAVIOR_EXTRACT = TracePropagationBehaviorExtract.CONTINUE; static final boolean DEFAULT_TRACE_PROPAGATION_EXTRACT_FIRST = false; diff --git a/dd-trace-api/src/main/java/datadog/trace/api/config/TracerConfig.java b/dd-trace-api/src/main/java/datadog/trace/api/config/TracerConfig.java index 9faf4f4ea8e..3c4a66d271b 100644 --- a/dd-trace-api/src/main/java/datadog/trace/api/config/TracerConfig.java +++ b/dd-trace-api/src/main/java/datadog/trace/api/config/TracerConfig.java @@ -133,6 +133,17 @@ public final class TracerConfig { public static final String CLOCK_SYNC_PERIOD = "trace.clock.sync.period"; + /** + * Opt-in (defaults to disabled). When enabled, resyncs the tracer's cached clock reference on + * every AWS Lambda invocation, before any span for that invocation is created, instead of + * relying on the periodic {@link #CLOCK_SYNC_PERIOD} check - which is gated on monotonic ticks + * elapsed and may never trigger following an AWS Lambda SnapStart restore, since a short-lived + * restore-then-invoke sequence can leave that reference stale for hours or days. Only takes + * effect inside an instrumented AWS Lambda handler invocation; a no-op everywhere else. + */ + public static final String TRACE_LAMBDA_SNAPSTART_CLOCK_RESYNC_ENABLED = + "trace.lambda.snapstart.clock.resync.enabled"; + public static final String TRACE_SPAN_ATTRIBUTE_SCHEMA = "trace.span.attribute.schema"; public static final String TRACE_LONG_RUNNING_ENABLED = "trace.experimental.long-running.enabled"; diff --git a/dd-trace-core/src/main/java/datadog/trace/core/CoreTracer.java b/dd-trace-core/src/main/java/datadog/trace/core/CoreTracer.java index 75513b1b01e..528662e432d 100644 --- a/dd-trace-core/src/main/java/datadog/trace/core/CoreTracer.java +++ b/dd-trace-core/src/main/java/datadog/trace/core/CoreTracer.java @@ -144,11 +144,22 @@ public static CoreTracerBuilder builder() { return new CoreTracerBuilder(); } - /** Tracer start time in nanoseconds measured up to a millisecond accuracy */ - private final long startTimeNano; + /** + * Tracer start time in nanoseconds measured up to a millisecond accuracy. + * + *

Not final: reset by {@link #maybeResyncClockForLambdaInvocation()} on every Lambda invocation, + * since the value captured at construction time can predate an AWS Lambda SnapStart restore by + * hours or days - see that method's javadoc for why. + */ + private volatile long startTimeNano; - /** Nanosecond ticks value at tracer start */ - private final long startNanoTicks; + /** + * Nanosecond ticks value at tracer start. + * + *

Not final: reset by {@link #maybeResyncClockForLambdaInvocation()} on every Lambda invocation - + * see {@link #startTimeNano}. + */ + private volatile long startNanoTicks; /** How often should traced threads check clock ticks against the wall clock */ private final long clockSyncPeriod; @@ -1032,6 +1043,42 @@ long getTimeWithNanoTicks(long nanoTicks) { return computedNanoTime + counterDrift; } + /** + * AWS Lambda SnapStart checkpoints the JVM at snapshot-creation time and later restores it, + * potentially much later (a restored snapshot can go {@code Inactive} and be restored again after + * 14 days of no invocations). {@link System#nanoTime()} does not account for the frozen duration + * across that restore, so {@link #startTimeNano}/{@link #startNanoTicks} - captured once at + * construction time, i.e. at snapshot-creation time - go stale, and the periodic self-correction + * in {@link #getTimeWithNanoTicks} may never trigger to fix it: that correction is gated on + * {@code nanoTicks - lastSyncTicks >= clockSyncPeriod} (monotonic ticks elapsed), which a + * short-lived restore-then-invoke sequence can easily never reach even though wall-clock time has + * moved on by hours or days. Left uncorrected, every span timestamp computed via {@link + * #getTimeWithNanoTicks} stays anchored near the original snapshot-creation instant instead of + * the real restore/invocation time. + * + *

Rather than reacting to the restore event itself (which would need a JVM-level + * checkpoint/restore hook), this is called from {@link #notifyLambdaStart} - already invoked once + * per Lambda invocation, before any span for that invocation is created. Any real restore is + * always followed by an invocation, so resyncing there catches it with no extra dependency. Doing + * this on every invocation (not just ones following a restore) is deliberate: outside SnapStart, + * {@link System#nanoTime()} correctly tracks elapsed time across a warm container's normal + * freeze/thaw between invocations (same continuously-executing process, unlike SnapStart's + * restore-into-a-new-context), so this is a correct no-op there - just a few field writes, + * negligible next to the HTTP round-trip {@link #notifyLambdaStart} already makes. + * + *

Gated on {@link Config#isLambdaSnapStartClockResyncEnabled()} as an escape hatch. + */ + @VisibleForTesting + void maybeResyncClockForLambdaInvocation() { + if (!initialConfig.isLambdaSnapStartClockResyncEnabled()) { + return; + } + startTimeNano = timeSource.getCurrentTimeNanos(); + startNanoTicks = timeSource.getNanoTicks(); + lastSyncTicks = startNanoTicks; + counterDrift = 0; + } + @Override public CoreSpanBuilder buildSpan( final String instrumentationName, final CharSequence operationName) { @@ -1238,6 +1285,8 @@ public void closeActive() { @Override public AgentSpanContext notifyLambdaStart(Object event, String lambdaRequestId) { + maybeResyncClockForLambdaInvocation(); + // Get context from AppSec AgentSpanContext appSecContext = LambdaAppSecHandler.processRequestStart(event); diff --git a/dd-trace-core/src/test/java/datadog/trace/core/CoreTracerTest.java b/dd-trace-core/src/test/java/datadog/trace/core/CoreTracerTest.java index 794af6d4650..8c5921ee69c 100644 --- a/dd-trace-core/src/test/java/datadog/trace/core/CoreTracerTest.java +++ b/dd-trace-core/src/test/java/datadog/trace/core/CoreTracerTest.java @@ -28,6 +28,7 @@ import datadog.trace.api.config.TracerConfig; import datadog.trace.api.remoteconfig.ServiceNameCollector; import datadog.trace.api.sampling.PrioritySampling; +import datadog.trace.api.time.ControllableTimeSource; import datadog.trace.bootstrap.instrumentation.api.AgentSpan; import datadog.trace.bootstrap.instrumentation.api.ServiceNameSources; import datadog.trace.common.sampling.AllSampler; @@ -79,6 +80,93 @@ void verifyDefaultsOnTracer() { } } + @Test + void + getTimeWithNanoTicks_whenNanoTicksStaleAfterSimulatedRestore_thenTimestampStaysAnchoredToConstructionTime() { + // Characterizes the AWS Lambda SnapStart bug this fix addresses: System.nanoTime() does not + // account for the frozen duration across a checkpoint/restore, so a nanoTicks reading taken + // right after restore can be indistinguishable from one taken at construction (snapshot + // creation) time, even though wall-clock time has moved on by hours. Without a resync, span + // timestamps computed from that stale nanoTicks stay anchored to construction time. + ControllableTimeSource timeSource = new ControllableTimeSource(); + timeSource.set(TimeUnit.SECONDS.toNanos(1000)); + CoreTracer tracer = tracerBuilder().writer(new ListWriter()).timeSource(timeSource).build(); + try { + long constructionTimeNanoTicks = timeSource.getNanoTicks(); + + // Wall-clock time moves on by 2 hours (the restore happens much later), but the nanoTicks + // value a span would be timestamped with right after restore hasn't advanced. + timeSource.set(TimeUnit.SECONDS.toNanos(1000) + TimeUnit.HOURS.toNanos(2)); + + assertEquals( + TimeUnit.SECONDS.toNanos(1000), tracer.getTimeWithNanoTicks(constructionTimeNanoTicks)); + } finally { + tracer.close(); + } + } + + @Test + @WithConfig(key = TracerConfig.TRACE_LAMBDA_SNAPSTART_CLOCK_RESYNC_ENABLED, value = "true") + void + maybeResyncClockForLambdaInvocation_whenEnabledAndCalledAfterSimulatedRestore_thenTimestampReflectsPostRestoreTime() { + ControllableTimeSource timeSource = new ControllableTimeSource(); + timeSource.set(TimeUnit.SECONDS.toNanos(1000)); + CoreTracer tracer = tracerBuilder().writer(new ListWriter()).timeSource(timeSource).build(); + try { + // The restore happens: wall-clock/tick source jumps forward by 2 hours. + long postRestoreNanos = TimeUnit.SECONDS.toNanos(1000) + TimeUnit.HOURS.toNanos(2); + timeSource.set(postRestoreNanos); + + tracer.maybeResyncClockForLambdaInvocation(); + + // A span timestamped right after resync now reflects the real post-restore time, not the + // stale construction-time (pre-restore) anchor. + assertEquals(postRestoreNanos, tracer.getTimeWithNanoTicks(timeSource.getNanoTicks())); + } finally { + tracer.close(); + } + } + + @Test + @WithConfig(key = TracerConfig.TRACE_LAMBDA_SNAPSTART_CLOCK_RESYNC_ENABLED, value = "true") + void notifyLambdaStart_whenExplicitlyEnabled_thenResyncsClockToCurrentTime() { + // notifyLambdaStart runs once per Lambda invocation, before any span for that invocation is + // created - the actual trigger point for the resync in production, not just the extracted + // maybeResyncClockForLambdaInvocation() logic exercised directly above. + ControllableTimeSource timeSource = new ControllableTimeSource(); + timeSource.set(TimeUnit.SECONDS.toNanos(1000)); + CoreTracer tracer = tracerBuilder().writer(new ListWriter()).timeSource(timeSource).build(); + try { + long postRestoreNanos = TimeUnit.SECONDS.toNanos(1000) + TimeUnit.HOURS.toNanos(2); + timeSource.set(postRestoreNanos); + + tracer.notifyLambdaStart(new Object(), "lambda-request-123"); + + assertEquals(postRestoreNanos, tracer.getTimeWithNanoTicks(timeSource.getNanoTicks())); + } finally { + tracer.close(); + } + } + + @Test + void notifyLambdaStart_whenResyncDefaultsToDisabled_thenTimestampStaysAnchoredToConstructionTime() { + ControllableTimeSource timeSource = new ControllableTimeSource(); + timeSource.set(TimeUnit.SECONDS.toNanos(1000)); + CoreTracer tracer = tracerBuilder().writer(new ListWriter()).timeSource(timeSource).build(); + try { + long constructionTimeNanoTicks = timeSource.getNanoTicks(); + timeSource.set(TimeUnit.SECONDS.toNanos(1000) + TimeUnit.HOURS.toNanos(2)); + + // No @WithConfig override here - this is an opt-in feature, off by default. + tracer.notifyLambdaStart(new Object(), "lambda-request-123"); + + assertEquals( + TimeUnit.SECONDS.toNanos(1000), tracer.getTimeWithNanoTicks(constructionTimeNanoTicks)); + } finally { + tracer.close(); + } + } + @Test @WithConfig(key = TracerConfig.PRIORITY_SAMPLING, value = "false") void verifyOverridingSampler() { diff --git a/internal-api/src/main/java/datadog/trace/api/Config.java b/internal-api/src/main/java/datadog/trace/api/Config.java index 5ced61622ca..011ec5ac471 100644 --- a/internal-api/src/main/java/datadog/trace/api/Config.java +++ b/internal-api/src/main/java/datadog/trace/api/Config.java @@ -178,6 +178,7 @@ import static datadog.trace.api.ConfigDefaults.DEFAULT_TRACE_EXPERIMENTAL_FEATURES_ENABLED; import static datadog.trace.api.ConfigDefaults.DEFAULT_TRACE_HTTP_RESOURCE_REMOVE_TRAILING_SLASH; import static datadog.trace.api.ConfigDefaults.DEFAULT_TRACE_KEEP_LATENCY_THRESHOLD_MS; +import static datadog.trace.api.ConfigDefaults.DEFAULT_TRACE_LAMBDA_SNAPSTART_CLOCK_RESYNC_ENABLED; import static datadog.trace.api.ConfigDefaults.DEFAULT_TRACE_LONG_RUNNING_ENABLED; import static datadog.trace.api.ConfigDefaults.DEFAULT_TRACE_LONG_RUNNING_FLUSH_INTERVAL; import static datadog.trace.api.ConfigDefaults.DEFAULT_TRACE_LONG_RUNNING_INITIAL_FLUSH_INTERVAL; @@ -691,6 +692,7 @@ import static datadog.trace.api.config.TracerConfig.TRACE_HTTP_SERVER_PATH_RESOURCE_NAME_MAPPING; import static datadog.trace.api.config.TracerConfig.TRACE_INFERRED_PROXY_SERVICES_ENABLED; import static datadog.trace.api.config.TracerConfig.TRACE_KEEP_LATENCY_THRESHOLD_MS; +import static datadog.trace.api.config.TracerConfig.TRACE_LAMBDA_SNAPSTART_CLOCK_RESYNC_ENABLED; import static datadog.trace.api.config.TracerConfig.TRACE_LONG_RUNNING_ENABLED; import static datadog.trace.api.config.TracerConfig.TRACE_LONG_RUNNING_FLUSH_INTERVAL; import static datadog.trace.api.config.TracerConfig.TRACE_LONG_RUNNING_INITIAL_FLUSH_INTERVAL; @@ -1317,6 +1319,8 @@ public static String getHostName() { private final boolean secureRandom; + private final boolean lambdaSnapStartClockResyncEnabled; + private final boolean trace128bitTraceIdGenerationEnabled; private final boolean logs128bitTraceIdEnabled; @@ -1521,6 +1525,10 @@ private Config(final ConfigProvider configProvider, final InstrumenterConfig ins } else { secureRandom = configProvider.getBoolean(SECURE_RANDOM, DEFAULT_SECURE_RANDOM); } + lambdaSnapStartClockResyncEnabled = + configProvider.getBoolean( + TRACE_LAMBDA_SNAPSTART_CLOCK_RESYNC_ENABLED, + DEFAULT_TRACE_LAMBDA_SNAPSTART_CLOCK_RESYNC_ENABLED); cassandraKeyspaceStatementExtractionEnabled = configProvider.getBoolean( CASSANDRA_KEYSPACE_STATEMENT_EXTRACTION_ENABLED, @@ -4977,6 +4985,10 @@ public boolean isAwsServerless() { return awsServerless; } + public boolean isLambdaSnapStartClockResyncEnabled() { + return lambdaSnapStartClockResyncEnabled; + } + public boolean isDataStreamsEnabled() { return dataStreamsEnabled; } diff --git a/metadata/supported-configurations.json b/metadata/supported-configurations.json index 733f3736cbb..5ab61c4dcfd 100644 --- a/metadata/supported-configurations.json +++ b/metadata/supported-configurations.json @@ -5097,6 +5097,14 @@ "aliases": [] } ], + "DD_TRACE_LAMBDA_SNAPSTART_CLOCK_RESYNC_ENABLED": [ + { + "version": "A", + "type": "boolean", + "default": "false", + "aliases": [] + } + ], "DD_TRACE_CLOUD_PAYLOAD_TAGGING_MAX_DEPTH": [ { "version": "A", From 50f48bdf04ba41f0ecd4c5bba4415d7a353b68f1 Mon Sep 17 00:00:00 2001 From: sheldon-nadarajah-sft Date: Wed, 8 Jul 2026 20:00:43 +0200 Subject: [PATCH 2/2] Address review: resync clock drift without making start fields volatile mcculls pointed out on #11882 that resetting startTimeNano/startNanoTicks from maybeResyncClockForLambdaInvocation() only works if those fields are volatile, since they're read on every getTimeWithNanoTicks() call from arbitrary tracing threads. Instead, fold the observed drift directly into counterDrift (already volatile, already used by the periodic self-correction in getTimeWithNanoTicks) and update lastSyncTicks, leaving startTimeNano/ startNanoTicks final as before. Co-Authored-By: Claude Sonnet 5 --- .../java/datadog/trace/core/CoreTracer.java | 39 +++++++++---------- .../datadog/trace/core/CoreTracerTest.java | 3 +- 2 files changed, 20 insertions(+), 22 deletions(-) diff --git a/dd-trace-core/src/main/java/datadog/trace/core/CoreTracer.java b/dd-trace-core/src/main/java/datadog/trace/core/CoreTracer.java index 528662e432d..320f694cf64 100644 --- a/dd-trace-core/src/main/java/datadog/trace/core/CoreTracer.java +++ b/dd-trace-core/src/main/java/datadog/trace/core/CoreTracer.java @@ -144,22 +144,11 @@ public static CoreTracerBuilder builder() { return new CoreTracerBuilder(); } - /** - * Tracer start time in nanoseconds measured up to a millisecond accuracy. - * - *

Not final: reset by {@link #maybeResyncClockForLambdaInvocation()} on every Lambda invocation, - * since the value captured at construction time can predate an AWS Lambda SnapStart restore by - * hours or days - see that method's javadoc for why. - */ - private volatile long startTimeNano; + /** Tracer start time in nanoseconds measured up to a millisecond accuracy */ + private final long startTimeNano; - /** - * Nanosecond ticks value at tracer start. - * - *

Not final: reset by {@link #maybeResyncClockForLambdaInvocation()} on every Lambda invocation - - * see {@link #startTimeNano}. - */ - private volatile long startNanoTicks; + /** Nanosecond ticks value at tracer start */ + private final long startNanoTicks; /** How often should traced threads check clock ticks against the wall clock */ private final long clockSyncPeriod; @@ -1056,6 +1045,13 @@ long getTimeWithNanoTicks(long nanoTicks) { * #getTimeWithNanoTicks} stays anchored near the original snapshot-creation instant instead of * the real restore/invocation time. * + *

Rather than reset {@link #startTimeNano}/{@link #startNanoTicks} themselves - which would + * require making those fields {@code volatile}, since they're read on every {@link + * #getTimeWithNanoTicks} call from arbitrary tracing threads - this folds the entire observed + * drift into {@link #counterDrift} directly, the same field (already {@code volatile}) that the + * periodic self-correction in {@link #getTimeWithNanoTicks} uses, just without that correction's + * 1ms drift threshold, since here the drift can be hours or days. + * *

Rather than reacting to the restore event itself (which would need a JVM-level * checkpoint/restore hook), this is called from {@link #notifyLambdaStart} - already invoked once * per Lambda invocation, before any span for that invocation is created. Any real restore is @@ -1063,8 +1059,9 @@ long getTimeWithNanoTicks(long nanoTicks) { * this on every invocation (not just ones following a restore) is deliberate: outside SnapStart, * {@link System#nanoTime()} correctly tracks elapsed time across a warm container's normal * freeze/thaw between invocations (same continuously-executing process, unlike SnapStart's - * restore-into-a-new-context), so this is a correct no-op there - just a few field writes, - * negligible next to the HTTP round-trip {@link #notifyLambdaStart} already makes. + * restore-into-a-new-context), so this is a correct no-op there - just a couple of field reads + * and a subtraction, negligible next to the HTTP round-trip {@link #notifyLambdaStart} already + * makes. * *

Gated on {@link Config#isLambdaSnapStartClockResyncEnabled()} as an escape hatch. */ @@ -1073,10 +1070,10 @@ void maybeResyncClockForLambdaInvocation() { if (!initialConfig.isLambdaSnapStartClockResyncEnabled()) { return; } - startTimeNano = timeSource.getCurrentTimeNanos(); - startNanoTicks = timeSource.getNanoTicks(); - lastSyncTicks = startNanoTicks; - counterDrift = 0; + long nanoTicks = timeSource.getNanoTicks(); + long computedNanoTime = startTimeNano + Math.max(0, nanoTicks - startNanoTicks); + counterDrift = timeSource.getCurrentTimeNanos() - computedNanoTime; + lastSyncTicks = nanoTicks; } @Override diff --git a/dd-trace-core/src/test/java/datadog/trace/core/CoreTracerTest.java b/dd-trace-core/src/test/java/datadog/trace/core/CoreTracerTest.java index 8c5921ee69c..911af591da5 100644 --- a/dd-trace-core/src/test/java/datadog/trace/core/CoreTracerTest.java +++ b/dd-trace-core/src/test/java/datadog/trace/core/CoreTracerTest.java @@ -149,7 +149,8 @@ void notifyLambdaStart_whenExplicitlyEnabled_thenResyncsClockToCurrentTime() { } @Test - void notifyLambdaStart_whenResyncDefaultsToDisabled_thenTimestampStaysAnchoredToConstructionTime() { + void + notifyLambdaStart_whenResyncDefaultsToDisabled_thenTimestampStaysAnchoredToConstructionTime() { ControllableTimeSource timeSource = new ControllableTimeSource(); timeSource.set(TimeUnit.SECONDS.toNanos(1000)); CoreTracer tracer = tracerBuilder().writer(new ListWriter()).timeSource(timeSource).build();