Fix span timestamps staying stale after an AWS Lambda SnapStart restore

[sheldon-nadarajah-sft]

Problem

Datadog flamegraphs for AWS Lambda functions with SnapStart enabled can render as a multi-hour (or multi-day) empty timeline with the actual work squeezed into a tiny sliver at each end — even though the real invocation took under a second.

We tracked this down from a production trace on a Java Lambda function with SnapStart enabled: the parent aws.lambda span was timestamped correctly (13:42:21Z), but its 18 DynamoDB child spans — created by this tracer's AWS SDK instrumentation during the same invocation — were all timestamped 11:45:25Z, ~1h57m earlier. Correlating against CloudWatch logs for that invocation confirmed the DynamoDB spans' timestamp landed squarely inside the original snapshot-creation platform.initStart window (when the SnapStart snapshot was published), not anywhere near the actual platform.restoreStart/invocation time that ran ~2 hours later.

Root cause

CoreTracer computes every span's timestamp from a cached reference pair — startTimeNano/startNanoTicks — captured once at construction, plus a monotonic-tick delta (getTimeWithNanoTicks()). It self-corrects drift periodically, but that correction is gated on monotonic ticks elapsed (nanoTicks - lastSyncTicks >= clockSyncPeriod, default 30s), not wall-clock time elapsed.

AWS Lambda SnapStart checkpoints the JVM at snapshot-creation time and later restores a new execution environment from that snapshot — potentially hours or days later, on different hardware. System.nanoTime() does not account for that gap: the restored instance's monotonic clock has no relationship to real elapsed time since the snapshot. A short-lived restore-then-invoke sequence (our production case: restore → invocation within ~14s) never accumulates 30 seconds of monotonic ticks, so the periodic correction never fires, and every span stays anchored near the original snapshot-creation instant.

This is a real, reproducible bug — not a config mistake on the user's side — and it's specific to SnapStart's restore-into-a-new-context semantics: a regular (non-SnapStart) Lambda container merely pauses/resumes the same continuously-existing process between invocations, which does not exhibit this clock discontinuity.

Fix

Resync the cached clock reference from CoreTracer.notifyLambdaStart() — already invoked once per Lambda invocation, before any span for that invocation is created (see LambdaHandlerInstrumentation's @OnMethodEnter advice, which calls it immediately before the first startSpan(...) call). Any real SnapStart restore is always followed by an invocation, so resyncing there catches it without needing to react to the restore event itself.

This is gated behind a new, opt-in, disabled-by-default config, DD_TRACE_LAMBDA_SNAPSTART_CLOCK_RESYNC_ENABLED. Doing this on every invocation (not just ones following a restore) is deliberate: outside SnapStart there's no clock bug to fix (see above), so it's a correct, cheap no-op there — a few volatile field writes, negligible next to the HTTP round-trip notifyLambdaStart already makes to the Lambda extension.

Alternatives considered

• Lower DD_TRACE_CLOCK_SYNC_PERIOD globally. The periodic correction is clamped to a 1ms floor regardless of configured value, so setting it to 0 does mitigate most of this today, with zero code changes, and users hitting this can do so immediately. We didn't pursue this as the fix because it's a blanket per-tracer-instance setting affecting every span for every user, not just Lambda SnapStart ones, and it only shrinks the bad window rather than eliminating it.
• A CRaC (org.crac) afterRestore hook, reacting to the actual restore event via the JVM checkpoint/restore SPI. We built and tested this first, but self-review turned up real problems specific to that approach: it requires a new runtime dependency that, in our build, ended up shipping a second unrelocated copy of org.crac in the shaded agent jar (a class that, it turns out, is already present unrelocated via an existing transitive dependency — likely Spring, given Spring Framework 6.1+ ships its own CRaC integration and is a common SnapStart audience); it published this from mid-constructor into a JVM-wide static registry; and the registered callback fired on an arbitrary async thread with no test coverage of the actual registration path. The notifyLambdaStart hook needs no new dependency, fires deterministically on a known thread at a well-defined point in the invocation lifecycle, and is already exercised by existing Lambda instrumentation tests.

Known limitation

The resync writes startTimeNano/startNanoTicks/lastSyncTicks/counterDrift as four independent volatile fields with no encompassing lock, so a concurrent reader (e.g. the background trace-buffer flush thread) could in principle observe a partially-updated combination. This isn't a new class of risk introduced here: getTimeWithNanoTicks()'s existing periodic self-correction already updates counterDrift and lastSyncTicks independently today, with the same eventual-consistency trade-off (a worst-case redundant correction on the next call). We didn't expand scope to refactor that pre-existing pattern into an atomic holder for this fix, but flagging it here for visibility.

Testing

• CoreTracerTest: a test characterizing the underlying bug in isolation (getTimeWithNanoTicks with a stale nanoTicks reading stays anchored to construction time), plus tests exercising the real fix end-to-end through notifyLambdaStart() — resync happens when explicitly enabled, and (the default) does not happen when left disabled.
• Verified against the original production trace/CloudWatch log timeline that motivated this fix.

[mcculls]

Couldn't you forcibly trigger an update of counterDrift from maybeResyncClockForLambdaInvocation?

Or alternatively update counterDrift (and lastSyncTicks) directly from that method.

That would let you account for the drift without making these final fields volatile.

[sheldon-nadarajah-sft]

Good call — done in 50f48bd. startTimeNano/startNanoTicks stay final; maybeResyncClockForLambdaInvocation() now computes the drift against those fixed values and folds it into counterDrift, updating lastSyncTicks too, so no new volatile fields.