Skip to content

Implement async trace mechanism - #7670

Open
jasnell wants to merge 43 commits into
mainfrom
jasnell/async-trace
Open

jasnell wants to merge 43 commits into
mainfrom
jasnell/async-trace

Conversation

@jasnell

@jasnell jasnell commented Oct 9, 2026 •

Copy link
Copy Markdown
Collaborator

Revisting the old #5842 prototype. This PR adds the async trace internal mechanisms. See the doc for details.

Planning to use this to help evaluate TS streams and other API optimizations.

@jasnell
jasnell requested review from a team as code owners October 9, 2026 03:02
@ask-bonk

This comment was marked as resolved.

Comment thread src/rust/async-trace/listener.h Outdated
Comment thread src/rust/async-trace/listener.h Outdated
Comment thread src/rust/async-trace/isolate.rs
Comment thread src/workerd/io/async-trace-inspector.c++ Outdated
Comment thread src/workerd/api/queue.c++
@jasnell jasnell changed the title Add async-trace Rust crate for async activity tracking Implement async trace mechanism Oct 9, 2026
Comment thread src/workerd/io/async-trace-inspector.c++
Comment thread src/workerd/io/async-trace-inspector.c++
Comment thread src/workerd/io/async-trace-test.c++ Outdated
Comment thread src/workerd/io/async-trace-inspector.c++
@jasnell
jasnell marked this pull request as draft October 9, 2026 12:05
@jasnell
jasnell marked this pull request as ready for review October 9, 2026 16:54
Comment thread src/workerd/server/cli-main.c++
Comment thread src/workerd/server/tests/async-trace/async-trace-shutdown-test.sh
Comment thread docs/async-trace.md
jasnell added 19 commits October 9, 2026 22:03
First step of the async trace core: a standalone crate with no callers
yet. It holds the stateful half of the design, which is unit-testable
without V8:

- IsolateState: per-isolate resource ID allocation and stack
  deduplication.
- Tracker: one per IoContext. Tracks the execution scope stack, turns
  and their causes (the default trigger for resources created during a
  turn, which attributes work after `await` without promise hooks),
  live resources, and the adoption of a binding operation by the
  awaitIo bridge that resumes it. Caller mistakes are counted in
  ContextStats rather than panicking.
- Sink trait with an NDJSON sink (format v1, one shared writer per
  process, per-tracker buffering so lines never interleave) and a
  recording sink for tests.
- A cxx bridge exposing opaque Isolate, Tracker and Writer types.
  Kinds and outcomes cross as u8.

No JavaScript-visible API change.
Prepares the crate for the C++ facade:

- CppSink forwards events to a C++ AsyncTraceListener (listener.h, in
  this package so the bridge has no library cycle). The inline shims
  catch listener exceptions, which would otherwise become Rust panics.
- turn_begin() takes a default cause (typically the current request).
  set_turn_cause() replaces it, closing its scope; a second explicit
  cause is still rejected.
- ContextStats gains foreign_thread, for events the C++ wrapper drops
  because they came from another thread; reported as foreignThread in
  ctx_end.
- Strings from C++ cross as bytes and are decoded lossily, because
  cxx's rust::Str constructor throws on invalid UTF-8. The writer path
  must still be UTF-8.
//src/workerd/io:async-trace wraps the async-trace Rust crate:

- AsyncTraceIsolate: per-isolate ID allocation and stack dedup.
- AsyncTraceWriter: a process-wide NDJSON output file.
- AsyncTraceSinks: listeners and writers collected for one context.
- AsyncTracker: per-context tracker, held by kj::Arc. Methods are
  const and may be called from any thread; calls off the creating
  thread are dropped and counted.
- AsyncResource: move-only handle that keeps its tracker alive and
  reports destroy on release if the resource never settled. Inert
  (null Arc, zero ID) when tracing is off.
- TurnScope / CallbackScope: RAII turn and callback brackets, no-ops
  without a tracker.
- OwnedAsyncTracker: closes the tracker when its owner goes away.

Nothing uses it yet.
IsolateObserver gains two hooks, both no-ops by default:

- getAsyncTraceConfig(), called once when the Worker::Isolate is
  created. A config makes the isolate own an AsyncTraceIsolate.
- addAsyncTraceSinks(sinks, worker, actorId), called once per
  IoContext. The context is traced only if a sink is added. It takes
  names rather than Worker& and Worker::Actor& because observer.h
  cannot include worker.h.

With tracing on, the IoContext owns a tracker (declared before its task
sets, so their resources are released before it closes), each
IncomingRequest records a REQUEST resource on delivery (named by the
delivering function) and settles it on destruction, and runImpl()
brackets each entry into JavaScript in a TurnScope from before the lock
until after the microtask drain, with the current request as the
default cause.

When tracing is off, which is always the case unless an embedder
overrides the hooks, each site costs one null check and no Rust call.

TestFixture accepts an isolateObserver.
- adopt_operation() makes the bridge a second holder of the operation.
  destroy() forgets a resource (reporting destroy if unsettled) only
  when its last holder releases it. A binding's span is attached to
  the KJ promise and ends before the bridge's continuation runs; until
  now that left the bridge reporting under an ID the tracker had
  forgotten.
- A turn's default cause is entered lazily: only when the turn creates
  a resource, enters a scope, or starts a nested turn before an
  explicit cause is set. A turn resumed by a bridge no longer reports a
  zero-length before/after for the request. The C++ tests' expected
  sequences change accordingly.
- AsyncTracker::adoptOrCreate() replaces adoptOperation(): it returns an
  owning handle on the adopted operation (a second holder), or a new
  resource. A bare ID from adoption could outlive the operation.
- AsyncResource's methods are inline, so an inert handle costs one null
  check and no call. settle(), annotate() and enterAsTurnCause() are
  const: they change the tracker's record, not the handle, and handles
  captured in JS closures can call them.
With async tracing on:

- awaitIo() adopts the turn's pending operation or creates a KJ_TO_JS
  resource, settles it when the KJ promise completes (error if it
  rejected), and makes it the cause of the turn that resumes
  JavaScript. Code after an `await` on I/O is thereby triggered by
  that I/O, without promise hooks.
- awaitJs() creates a JS_TO_KJ resource, settled when the JavaScript
  promise settles.
- Timers are traced centrally in TimeoutManagerImpl, so every caller is
  covered: setTimeout, setInterval, setImmediate, scheduler.wait and
  AbortSignal.timeout, each named accordingly. A one-shot timer settles
  when the KJ timer fires, before its turn, so settle-to-before is the
  scheduling delay. Each firing causes a turn. Clearing a timer reports
  destroy; an interval never settles.
- queueMicrotask() creates a MICROTASK resource that nests in the turn
  running it, and releases it after the callback rather than at GC.

When tracing is off, each site costs one inline null check: awaitIo
captures an inert handle, timers and microtasks skip creation.

No compatibility flag: nothing observable to Workers changes.
When a TraceContext is created during a traced turn,
TraceContextParent::newChild() creates an OPERATION resource named
after the span, whether or not the spans are observed. That covers KV,
R2, DO storage, SQL, cache, JSRPC and fetch with no per-site changes.
The next awaitIo() in the turn adopts it, so the bridge reports under
the binding's operation.

- newChild() finds the tracker through AsyncTracker::inTurn(), a
  thread-local that every TurnScope sets (null for untraced turns, so a
  nested untraced context hides an enclosing traced one). :trace sits
  below :io and cannot reach the IoContext.
- Destroying a TraceContext settles its operation; overwriting one by
  move-assignment settles the old operation first. setTag() annotates
  it.
- TraceContext::detachAsync() takes the operation out of consideration
  for adoption, for spans that outlive the call without being attached
  to the next awaitIo()'s promise.

When tracing is off, newChild() costs a thread-local read and a null
check, and TurnScope two thread-local writes per turn.
From an audit of the 61 TraceContext creation sites: 39 bind to the
next awaitIo(), 7 end synchronously, and these could otherwise be
adopted by an unrelated awaitIo() later in the turn:

- IoContext::getSubrequestNoChecks() parks the span on the returned
  client (DO and facet subrequests, Hyperdrive, writeLogfwdr,
  fetch_default, and the outer span of the DO fetch paths). Detached.
  Queue and WebSocket sends, which were bound only by recency, get
  their own bridge resource instead.
- IoContext::attachSpans() attaches spans to a promise that is already
  awaited or already resolved (DO storage cache hits, transaction()).
  It detaches attached TraceContexts.
- Fetcher::getClientForOneCall(): the session span was alive next to
  the jsRpcCall span (ambiguous). Detached.
- Server-side jsRpcCall: owned by the dispatch promise, so the method's
  own awaits could adopt it. Detached.
- Cache::put(): the output-lock awaitIo() would adopt it. Detached.
- r2GetClient() (unused): lives as long as the client. Detached.

Only affects async tracing; spans are unchanged.
flush() writes buffered events to the file, for embedders that exit
without running destructors. Sinks already flush at the end of each
outermost turn, so this only matters for the last turn's events.

Failing to create the file now reports the path.
Writes an async activity trace of every worker to <path> as NDJSON (one
event per line, format v1): requests, turns, timers, microtasks, I/O
bridges and binding operations, and what triggered what. For local
debugging of async behaviour: what a request is waiting on, which I/O
resumed which code, and where turns spend time.

- The option is parsed in args.rs and passed through ServeOrTestOptions.
  CliMain opens the file (declared before the Server, which refers to
  it) and flushes it before exiting, since context.exit() doesn't run
  destructors.
- When the option is set, Server::makeWorkerIsolate() uses an
  AsyncTraceIsolateObserver, which enables tracing for the isolate and
  adds the shared NDJSON sink to each IoContext. Without it, isolates
  get the plain IsolateObserver and nothing changes.
- server/tests/async-trace runs a worker under --async-trace, then
  checks the file from a second worker via a disk service: the causal
  chain (request -> timer -> fetch -> body read), the subrequest's
  context, balanced scopes, per-context time order and zero error
  stats.

Not observable to Workers; operator configuration, so no compatibility
flag or autogate.
A new Perfetto category, workerd.async, records async activity next to
the existing workerd slices:

  workerd test config.wd-test \
      --perfetto-trace=out.pftrace=workerd,workerd.async

Layout: a track per IoContext with a slice per turn (and a nested lock
slice for the time spent waiting for locks), and under it a track per
resource. A resource's slice spans from creation until it settles;
"run" slices span its callbacks; annotations are instants. Flows link
the creating callback to each new resource, and a resource's
settlement to its next callback, so the scheduling delay is visible.

- The sink keeps no per-resource state: track and flow IDs are hashed
  from (isolate, id), and track descriptors are erased when a resource
  settles or is destroyed, so the SDK's track registry doesn't grow.
- Turns are reported when they end, with times on the tracker's clock;
  they are mapped onto the trace clock through the turn's end.
- The category is recorded only when listed; "workerd" alone doesn't
  enable it. When it is being recorded as an isolate is created, the
  isolate gets async trace state even without --async-trace, and each
  IoContext gets the Perfetto sink. A session started later doesn't
  see existing isolates.

Builds without Perfetto report the category as disabled.

Tested by running a worker under --perfetto-trace with and without the
category and checking for the interned names. The structure (tracks,
nesting, flows, no unfinished slices) was checked with trace_processor,
which the test can't depend on.
TurnScope::end() ends the turn early, as the destructor would.
IoContext::runImpl() calls it after the microtask drain, inside the
lock scope, rather than when the TurnScope is destroyed after the lock
is released.

Ending a turn closes its cause's callback scope (reporting `after`),
and a sink that calls into V8, such as the inspector's, must see that
while the isolate is locked. Turn end times now exclude releasing the
lock.
DevTools async stack traces now continue across timers, microtasks,
I/O bridges and binding operations, not only promises. With workerd
--inspector-addr (and so wrangler dev), a callback scheduled with
setTimeout or queueMicrotask pauses with an async stack showing where
it was scheduled.

Local development only: an inspector exists only outside multi-tenant
processes, and production doesn't attach the inspector.

- Every IoContext of an isolate with an inspector gets the sink, and
  the isolate gets async trace state.
- Creating a resource schedules a V8 async task, capturing the current
  stack; each callback runs as that task; destroying an unsettled
  resource cancels it. Keys are even, because V8 keys its own promise
  tasks with odd values. Only setInterval is recurring. awaitJs
  resources are skipped: they never run a callback.
- V8 is called only while the isolate is current and locked. Started
  tasks are mirrored on a stack so starts and finishes always pair,
  including when the tracker discards unbalanced scopes.
- V8 ignores all of it unless a session set an async call stack depth,
  and bounds the stacks it keeps.

Tested in server/tests/inspector: pausing in setTimeout and
queueMicrotask callbacks yields async stacks naming them and the
function that scheduled them. Both cases fail without the sink.
An AsyncTraceIsolate can be given an AsyncStackCapturer, implemented by
whoever can reach V8 (this layer can't). AsyncTracker::create() then
has it walk the current stack into an AsyncStackBuilder, which feeds
the existing Rust interning: stacks are deduplicated per isolate on
(scriptId, line, column) and the init event carries the stack's ID.

- Tracker::accepts_resources() lets create() skip the capture, the
  expensive part, when the tracker is closed or at its live cap.
- C++ listeners get stack events: AsyncTraceListener::onStack(isolate,
  id, frames), before the first onInit() that refers to the stack.
  Frames cross the bridge one call at a time and are buffered
  thread-locally by the shim, since a shared struct of frames would
  have to be defined before cxx generates it.
Records up to <frames> (1-64) frames of the JavaScript stack that
created each async resource: timers, microtasks, I/O bridges, binding
operations. For example, a fetch operation's stack points at the
fetch() call, so a trace shows where each operation came from, not just
what triggered it.

- AsyncTraceConfig::stackDepth enables capture for an isolate. The V8
  capturer (io/async-trace-stacks.c++) walks the stack with
  StackTrace::CurrentStackTrace only while its isolate is current and
  locked; a resource created with no JavaScript on the stack gets no
  stack.
- The option applies to every output: `stack` lines in the
  --async-trace file, and a `stack` arg ("fn (script:line:col)" per
  line) on each resource's slice in the workerd.async Perfetto
  category. It can be used without --async-trace.
- It is a separate option, rather than a suffix on --async-trace's
  path, because a path can contain commas.

Each capture costs a stack walk per resource created, so it is off by
default.
Tracker::create_unowned() records a resource that nothing will release,
such as a JavaScript promise: it is forgotten when it settles (with no
destroy), or when the tracker closes. A callback running when it
settles still reports `after`, since scopes are tracked separately.
Tracker::knows() tells whether an ID is one of the tracker's live
resources.

AsyncTracker gets the promise hook's entry points: createPromise()
(an unowned JS_PROMISE, triggered by its parent promise or the turn's
cause, never with a creation stack), knows(), and enterPromise(),
exitPromise() and settlePromise() by ID.
With --async-trace-promises, each promise created during a traced turn
becomes a JS_PROMISE resource, through V8's promise hook, so a trace
follows async functions and promise chains, not only timers and I/O:

- init: triggered by the promise it derives from, if traced by the
  same context, else by the turn's cause.
- before/after: its reaction runs as a callback, so resources created
  after an `await` show that reaction as their execution context.
- resolve: settled, ERROR if rejected.

Installing a promise hook permanently sends the isolate's promise
operations through V8's slow path, so the hook is installed only on
isolates configured for it (AsyncTraceConfig::promises), at creation,
and never in a multi-tenant process (logged and skipped).

- Promise IDs live on the promise under a per-isolate private symbol.
  The hook finds that state through SET_DATA_ISOLATE, and does nothing
  outside traced turns. It catches everything, since V8 calls it.
- A reaction's promise usually settles during the reaction, so `after`
  is matched to the current scope rather than to a live resource.
- The Inspector sink ignores promises: V8 tracks their async stacks.

Tested by recording the scenario with and without the option: with
it, the code after `await new Promise((r) => setTimeout(r, 1))` runs as
a reaction derived from the awaited promise, which the timer's callback
settles, and every context's stats are clean; without it, no promises
are traced.
IoContext::AwaitIoOperation, wrapped around one awaitIo() call, makes
that bridge an OPERATION with the given name instead of a generic
`awaitIo` bridge, bound so that no other bridge adopts it. It is used
for I/O that has no trace span:

- Internal (KJ-backed) streams: stream_read, stream_write (the sink
  write, not the output-lock wait), stream_pipe, stream_close.
- Sockets: socket_connect, socket_start_tls, socket_disconnect (the
  wait for the peer), datagram_receive, datagram_send.

A trace now shows, for example, that the handler was resumed by a
stream read rather than by "awaitIo".

Standard (JavaScript-backed) streams do no I/O and get no operation;
with --async-trace-promises their promises are traced. Settling an
operation from the promise returned to JavaScript was rejected:
attaching a reaction marks the promise handled, which would suppress
unhandledrejection only while tracing.

Tested at the IoContext level (the first bridge in the scope is named;
a named bridge neither adopts a span's operation nor makes its adoption
ambiguous) and end to end with an IdentityTransformStream read and
write in the scenario. connect-handler-test, run by hand under
--async-trace, produces the socket and stream operations with clean
stats.
jasnell added 24 commits October 9, 2026 22:03
IncomingRequest::delivered() gains an overload taking the event type,
which names the request's async trace resource: fetch, connect,
scheduled, alarm, test, queue, jsrpc, trace, tail_stream,
hibernatable_websocket, restore, restore_rpc_stub, udp_connect.
Previously the resource was named after the delivering function
(requestImpl, run, ...), which said little and was the same for every
custom event.

The old overload remains, for callers outside this repository, and
still falls back to the function name.
A request delivered synchronously from another context's turn, such as
a service binding or SELF fetch, now records what caused it there: a
`link` event naming that turn's latest operation (typically the fetch
span's operation, adopted or detached), or else its running resource.
Resource IDs are per isolate, so the link names the source's isolate
and context rather than being a trigger:

  {"e":"link","ctx":8,"id":12,"fromIso":1,"fromCtx":7,"fromId":11}

- IncomingRequest::delivered() calls AsyncTracker::linkFromCallerTurn(),
  which links only when AsyncTracker::inTurn() is another tracker, so
  asynchronous delivery (or delivery from the network) gets no link.
- C++ listeners get AsyncTraceListener::onLink(). Perfetto draws a flow
  from the caller's resource track to the request, naming the caller's
  tracks from the IDs alone.

Tested in Rust (link source selection, link reporting), in the facade
(only during another tracker's turn, naming its latest operation), and
end to end: the scenario's subrequest links to the caller's fetch.
…details

Span tags (URLs, storage keys, ...) are written verbatim, and creation
stacks name source locations.
An operation created within another's span, through
TraceContext::getSpanParents() (a fetch attempt within the fetch, a
jsRpcCall within its session, actor calls), now names the enclosing
operation as its parent. TraceContextParent carries the async trace
operation of the TraceContext it came from, and newChild() passes it
to AsyncTracker::createChild().

The parent is structural, unlike the trigger, which stays the turn's
cause, so it is a separate field: `parent` on `init` lines (omitted
when 0), AsyncInitEvent::parent for C++ listeners, and a Perfetto arg.
It may name an operation that has already settled.

Parents taken from getSpanParentsIfObserved() exist only when spans
are observed, so those sites lose the edge when they aren't.
The scenario's fetch now POSTs a JavaScript ReadableStream body (read
by the handler after its wait). This checks that the body pump does not
take over the fetch operation: the response still resumes under it,
and no adoption is ambiguous. It didn't, as suspected it might.
getSubrequestNoChecks() detaches the span it parks on the client,
because the client may outlive the call and the caller's next awaitIo()
may await something else. For queue sends, queue metrics and WebSocket
opens, though, the next awaitIo() awaits exactly that subrequest, so
their I/O showed up as a generic awaitIo bridge instead.

These callers now pass SpanAwaitedNext::YES to getHttpClient()
(SubrequestOptions::spanAwaitedNext). The span is then not detached,
and when the context is traced it is kept with the client even if
unobserved, since dropping it would settle the operation before it can
be adopted. The span's own lifetime does not change.

Tested at the IoContext level with a stub client (adopted with YES,
detached by default). By hand under --async-trace, queue-test now shows
queue_send and queue_metrics resuming the handler, and the WebSocket
tests that connect show websocket_open doing so.
workerd exits through context.exit(), which skips destructors, so
contexts still open at that point never got a ctx_end, and a consumer
could not tell them from a truncated file.

The NDJSON writer now tracks the contexts whose ctx line has been
produced but not their ctx_end. AsyncTraceWriter::finish(), which
cli-main calls instead of flush() before context.exit(), writes a last
line listing them, and flushes; later lines are dropped:

  {"e":"exit","at":2480000,"open":[9]}

With KJ_CLEAN_SHUTDOWN, destructors run and contexts end normally, so
cli-main only flushes. Killing workerd by signal still bypasses this.

The scenario checker requires the exit line, last, with no open
contexts; a Rust test covers a context left open.
docs/async-trace.md explains what async tracing is for, how to enable
it (--async-trace, --async-trace-stacks, --async-trace-promises, the
workerd.async Perfetto category, the inspector), the concepts (contexts,
resources, turns and causes, triggers, operation adoption, parents,
cross-context links), the NDJSON format with a worked example, the
Perfetto and inspector outputs, completeness statistics, limitations,
the architecture, and how to instrument new runtime code.
Replace the rhetorical question list, bold-lead bullets and pseudo-
headings, colon-led setups and filler phrasing with plain statements,
paragraphs and real subheadings. No content changes.
A new section explains how the two differ in purpose and audience,
model (a tree of intervals versus a causal graph of resources and
turns), coverage, causality, timing and cost, how async tracing builds
on spans without changing them, and when to use each.
listener_stack_frame() allocated outside any exception handling, but
its extern "C++" bridge signature is infallible, so an allocation
failure would have become an unhandleable Rust panic. It now catches
the exception, logs it, and marks the pending stack broken;
listener_stack_end() then drops that stack rather than deliver it
truncated. Building the frame views in listener_stack_end() moved
inside callListener() for the same reason.

listener_stack_end() also handed the listener views into the
thread-local pending buffer. A listener that caused another tracker on
the same thread to report a stack would clear that buffer while the
views were in use. The frames are now moved out of the buffer before
the listener is called. A new test covers this; ASAN reports a
heap-use-after-free without the fix.

AsyncTraceListener now states that a listener must not call back into
the tracker calling it, and that onStack() may be skipped.
The inspector sink skips promises, js_to_kj resources and resources
created while the isolate is not locked (such as requests) in onInit(),
but onBefore() still called asyncTaskStarted() for them. V8 handles a
task it was never told about by pushing an empty async parent, which
hides the async stack of the V8 task (such as a promise reaction) it
runs inside.

The sink now remembers which resources it scheduled, and only starts,
finishes and cancels those. Like V8, it forgets a non-recurring task
once it finishes, so the set holds only tasks still pending.
Every distinct creation stack was kept for the isolate's lifetime, and
dynamically compiled code gets new script IDs, so a worker could grow
the table without bound while stack capture was on.

IsolateState now keeps at most 10,000 stacks or about 16 MiB (frames,
keys and strings, approximately). Past either limit intern_stack()
returns None for a new stack, so resources created at new sites have no
stack; stacks already kept still resolve.
The scenario sends a queue message, routed back to the same worker
(another worker would add an isolate, and the checker assumes one).
check.js asserts that queue_send causes the turn that resumes the
handler, which holds only because queue.c++ passes
SpanAwaitedNext::YES, and that the delivered message links back to the
send. With that call site set to NO, the check fails.
The test checks that a moved-from AsyncResource is inert, which the
workerd-use-after-move clang-tidy check reports as an error.
The inspector sink keeps each task it schedules until the task runs or
is canceled. A resource can settle and lose its last handle without
running a callback (the operation of a detached span, for example), and
a settled resource gets no destroy event, so its task stayed in the
sink until the context ended. A Durable Object's context lives as long
as the actor, so these accumulated.

Sinks now get release(id) (AsyncTraceListener::onRelease()) when the
tracker forgets a resource: after its settle or destroy, whichever is
last. The inspector sink cancels and forgets any task it still has
scheduled for it, forgetting it even when the isolate is not current
and V8 cannot be told. The NDJSON and Perfetto sinks ignore release,
so the trace format is unchanged.
The test checks that a listener's stack stays valid while the listener
causes another tracker to report a stack. Both captures produced the
same frames, so with the old shared buffer the refilled frames matched
and the test passed except under ASAN. The captures now differ, and
without the fix the outer listener reads the nested stack's text.
With KJ_CLEAN_SHUTDOWN set (as in the ASAN and coverage builds), workerd
only flushed the trace, so it had no exit line and the end-to-end check
failed. The writer now finishes after the server is destroyed, when its
contexts have ended, so both shutdown paths end the trace the same way.
The test uses nothing from it, and it brought kj-async-os's
kj::UnixEventPort into a binary that also links setup-async-io's, an
ODR violation that fails the test under ASAN.
Bare uint is a glibc typedef, so async-trace-test.c++ did not compile
on Windows.
The writer test built its file path by dropping TEST_TMPDIR's first
character and prepending '/', which assumes a POSIX path: on Windows,
C:/tmp/... became /:/tmp/.... It now passes the native path to the
writer and reads the file back through evalNative().

The bad-path test matched the POSIX error text; it now matches the
path, which the error names on every platform.
The exit line must follow every ctx_end. In workerd test runs every
context ends before shutdown, so moving the clean-shutdown finish()
back before the server is destroyed went unnoticed by the existing
tests. A new test keeps a Durable Object's context open past the test
and checks both shutdown paths: without KJ_CLEAN_SHUTDOWN, the exit
line lists the context as open; with it, the context ends first and
the exit line lists none.
The clean-shutdown check compared only the total numbers of contexts and
ctx_end lines, so a trace that dropped the Durable Object's end but
ended the request context twice would pass. It now checks that every
context, the actor's included, ends exactly once.
The example elided awaitIo()'s continuation with '...'. It now uses the
two-argument overload.
@jasnell
jasnell force-pushed the jasnell/async-trace branch from 00ad8ea to 09f1fc1 Compare October 9, 2026 22:06

@guybedford guybedford left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Checked this out and ran the full set locally (async-trace_test, async-trace-test@, async-trace-io-test@, the three server e2e tests and both inspector tests), plus the scenario by hand: all contexts end with all-zero stats and a clean exit line.

This is well put together. The tracker never panics on caller mistakes and self-reports them, the off-path really is a null check per site, the lifetime ordering (asyncTracker vs. task sets in IoContext, TimeoutState, the KJ_DEFER(turnScope.end()) placement before the microtask drain) is careful, and the owner-thread/foreignThread story is coherent. The doc matches the code.

A few points inline, none blocking. One process note: a number of the 43 commits are fixups by title ("mark a test's moved-from checks as intentional", "use kj::uint in the async-trace tests", "make the NDJSON writer tests portable to Windows", "give the nested-stack test distinct frames"); these should be squashed into their logical commits before merge.

Minor, no action needed: TraceContext grows by 16 bytes and gains a non-trivial dtor/move-assign, and each awaitIoImpl lambda grows by 16 bytes; and ~TraceContext always settles OK, so an operation that fails without an adopted bridge reports ok.

Comment thread src/workerd/io/worker.c++
// A Perfetto session recording "workerd.async" also needs the isolate's state (only sessions
// already running when the isolate is created see its contexts), and so does an inspector.
auto asyncTraceConfig = metrics->getAsyncTraceConfig();
if (asyncTraceConfig != kj::none || isAsyncTracePerfettoEnabled() ||

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This makes --inspector-addr alone turn tracking on for every IoContext in the isolate (the inspector sink is added unconditionally in makeAsyncTracker()), so every request under wrangler dev now pays the per-resource bookkeeping on each awaitIo(), timer and span: HashMap insert, pending_ops, sink virtual calls, scheduled.upsert. V8 itself does nothing in asyncTaskScheduled() unless a session has called setAsyncCallStackDepth, so most of that work is wasted when DevTools isn't attached.

The doc does say this, but is default-on under the inspector the intent? It would be good to either have a number for the per-request cost, or gate the inspector sink on an active session.

Comment thread src/workerd/io/trace.h

inline TraceContext TraceContextParent::newChild(kj::ConstString operationName) {
AsyncResource asyncTraceResource;
KJ_IF_SOME(tracker, AsyncTracker::inTurn()) {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This attributes the operation to whichever tracker's turn is ambient on the thread rather than to the owning context. IoContext::makeUserTraceSpan() has tryGetAsyncTracker() available and could pass it into TraceContextParent explicitly, leaving the thread-local only for the getSpanParents() paths that genuinely can't reach the context.

As written, a span created for context B synchronously inside context A's turn but outside B's own TurnScope lands in A's tracker with A's isolate's IDs. I don't see a workerd delivery path that does this today, but embedder delivery paths may.

previous(context.awaitIoOperationName) {
context.awaitIoOperationName = name;
}
~AwaitIoOperation() noexcept(false) {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

First-bridge-wins with no feedback: if anything inside the wrapped expression creates a bridge first, the name silently lands on the wrong one, and if nothing consumes it the scope just drops it. Since the tracker already self-reports ambiguousBindings, it would be cheap to count an unconsumed name here too (awaitIoOperationName != kj::none at scope exit) so instrumentation drift shows up in ctx_end.

isolate(isolate) {}

~InspectorSink() noexcept(false) {
finishAll();

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This runs from ~IoContext via close(), where the isolate lock is not necessarily held and another thread may hold it for a different context of the same isolate, so asyncTaskFinished() can race with V8. It's only reachable when started is already unbalanced, but a data race seems worse than an unbalanced inspector task stack; suggest checking isCurrent() here (and in onAfter's finish loop) and otherwise just clearing.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants