[Feature] Host swimlane (L3/L4) — the missing third DFX timeline

[ChaoWao]

Summary

Add a host swimlane: a Perfetto/Chrome-trace timeline of one run's host-side
execution (graph build → orchestrator submit → scheduler dispatch → waiting on chip
children → completion), emitted from the [STRACE] markers we already produce.

simpler has two of the three levels covered (see #995):

	Level	Answers	Status
core swimlane	L0	which pipe (MTE2/CUBE/FIXP/…) a task stalls on inside the core	✅ ships
chip swimlane	L2	when each task ran on device, and where the AICPU scheduler loop spent its time	✅ ships
host swimlane	L3/L4	why a task started when it did	❌ missing

The three are successive zoom levels, not alternatives. L2 says "this task ran from t1 to
t2"; L0 says "here is why it was slow inside the core"; nothing today says why it only
started at t1.

Motivation / Use Case

When a run is slower than expected and the device timeline looks fine, there is currently
no timeline to look at. Concretely unanswerable today:

• Did the time go to graph build, to scheduler dispatch, or to waiting on a child?
• Is the host scheduler the bottleneck, and if so is it starved for work or slow to dispatch?
• Did run N+1's host-side preparation actually overlap run N's device execution?
• Why is decode invocation Simplify AicpuExecutor API and unify naming conventions #7 slower than support extern func define in aicore #6?

Two extra reasons this is worth doing as its own feature:

1. The data already exists. [STRACE] markers already carry real pid, real tid,
   invocation id, name, ts, dur, clock, and open-ended k=v attributes; host
   timestamps are CLOCK_MONOTONIC and comparable across the parent and its forked
   children. Unknown k=v fields are ignored by the parser, so adding attributes needs
   no marker-version bump.
2. The current viewer discards it. strace_timing.py --trace-out reads the real tid
   and then throws it away, synthesizing a dense lane id from (pid, invocation).
   Consequences: one lane per invocation rather than per thread, so a single L4 run
   fans out to (1 + N_L3 + N_L2) × N_inv flat lanes, and spans from one thread get
   split across lanes by invocation — which is exactly what makes "is Simplify AicpuExecutor API and unify naming conventions #7 slower than support extern func define in aicore #6"
   impossible to see.

Proposed API / Behavior

New output mode; --trace-out stays byte-identical (it is a per-invocation call-tree view,
a legitimate and different question):

python -m simpler_setup.tools.strace_timing <log> --swimlane host_swimlane.json
# Chrome Trace JSON -> Perfetto, same viewer as chip swimlane

Lanes are the real OS pid / tid — no synthetic numbering. The roles already map
1:1 onto real threads, so real ids are sufficient and strictly more useful:

• Scheduler owns a dedicated sched_thread_
• WorkerThread is documented as "one worker, one std::thread"
• Orchestrator has no thread of its own — it runs on the caller (Python facade) thread
• each chip child is a real fork(), so it already has its own pid

Real ids additionally let a busy lane be taken straight to perf top -t <tid>,
gdb -p <pid>, or /proc, and need no mapping table that can drift. The only thing to add
is process_name / thread_name metadata so Perfetto shows names instead of bare numbers —
a labelling concern, not an identity one.

Spans — one per real decision point (deliberately not the internal lane CAS or every
poll_progress iteration; those are too hot to instrument):

span	site
l3.graph_build	Python Worker._submit_l3_locked, around the serialized graph callback
l3.submit	Orchestrator::submit_next_level, after task-slot allocation
l3.dispatch	WorkerThread::enqueue_dispatch, after successful publication
l3.frame_submit	LocalMailboxEndpoint::submit_progress
l3.activate	activate_progress
l3.complete	finish_progress_dispatch

Scheduler phases (optional second tier — the loop is hot enough that instrumenting
every iteration would perturb what it measures). Scheduler::run() has the same shape as
the AICPU loop that chip swimlane already profiles:

loop {
    completion_cv_.wait(...)     // sched.wait
    Phase 1: drain completions   // sched.drain
    Phase 2: dispatch_ready()    // sched.dispatch
}

That split is the direct answer to "is the host starved, or slow to dispatch?".

Three cases the design has to serve:

• L3/L2 run interleaving — falls out of real ids for free: parent and child are
  different pids on a shared CLOCK_MONOTONIC, so overlapping runs are visibly
  overlapping. Requires only that the child actually emits spans.
• Detail inside one worker.run — spans on the same (pid, tid) nest by ts/dur
  containment automatically. But l3.graph_build (facade thread) and l3.dispatch
  (WorkerThread) are on different tids and will not nest — that pair needs an explicit
  Chrome flow event (ph:"s"/ph:"f"). This is the real reason flow arrows are needed,
  not aesthetics.
• Device timing info printed by the host — already emitted: the host prints device-domain
  phases after readback as clk=dev spans under simpler_run.runner_run.device_wall
  (strace_timing.py derives its Device/Orch/Sched/Effective columns from exactly these).
  Draw them on a separate device sub-track, keeping the clk=dev tag and doing no
  alignment. Rendering them alongside is not the same as placing them on the host axis —
  the latter needs a measured clock anchor and is explicitly out of scope. Merging them into
  the host axis would look aligned while being wrong, which is worse than keeping them apart.

Gating: reuse the existing SIMPLER_HOST_STRACE compile-time gate. No new environment
variable or macro. When off, C++ markers and the logger lookup compile out, Python takes
its direct-call path, and throughput must not regress.

Alternatives Considered

• Extend --trace-out instead of adding a mode — rejected: its per-invocation grouping
  is the right shape for a call-tree view and may have consumers; the two answer different
  questions and should coexist.
• Synthesize role-based lane ids (tid 0=facade, 1=orch, 2=sched, 10+=chip) — rejected
  after checking the code: the roles already correspond 1:1 to real threads, so synthetic ids
  would re-number real ones with zero added information while losing perf/gdb//proc
  correlation and adding a mapping table that can drift.
• Go straight to a unified L4→L3→L2→L0 trace (shared pid numbering, host/device clock
  alignment, cross-level flow arrows) — deferred. The dominant use case is looking at one
  level at a time, and bundling the independent, immediately useful piece (host has no
  timeline at all) with the two hard ones (clock calibration, hierarchy folding) would block
  the former on the latter.

Additional Context

Sub-issue of #995 (DFX capability tracking), alongside the two shipping swimlanes:

• docs/dfx/chip-swimlane-profiling.md — L2
• docs/dfx/core-swimlane-profiling.md — L0

Two forward-compatibility constraints, so a future unified view does not require redoing
this work — neither adds effort now:

1. Carry the run/task/endpoint keys as span attributes (they are needed for joins anyway).
2. Keep device timestamps tagged clk=dev with no fake alignment — applying a guessed
   offset now would make every historical trace untrustworthy later.

Landing constraints worth stating up front:

• One sink. All spans cross the _task_interface extension boundary; add a non-variadic
  host-span emit C entry point to the existing process-global libsimpler_log.so. Do not
  compile a private logger into _task_interface and do not introduce a second Python
  grammar.
• Preload before fork(). The child must inherit an already-loaded logger. Getting the
  order wrong shows up as "the child's spans are all missing" rather than as an error.
• Unsupported topologies disable quietly. A SUB-only L3, an L4+ add_worker, or a
  remote-only parent has no _l3_bins logger path; the bridge stays off and initialization
  must still succeed.

[ChaoWao]

Status update — scope narrowed, and corrections to this issue's own text

#1730 implements the swimlane. Reviewing it surfaced both work that belongs
elsewhere and several places where this issue's original text no longer matches
what is correct, so both are recorded here.

This issue now covers

The host swimlane itself, plus the one part of it that is still missing:

• Shipped by Add: expose L3/L4 host scheduling swimlane #1730 — six spans, real pid/tid lanes with process_name /
  thread_name metadata, submit-to-dispatch flow arrows, --swimlane alongside an
  unchanged --trace-out, and device clk=dev records kept out of the visible axis.
• Still open — the L3↔L2 seam. The child already emits a whole simpler_run*
  tree and the swimlane already renders it as its own pid lane, so L2 is not
  missing. What is missing is the join between the two families: three
  uninstrumented edges.

parent  ──[frame_submit ends: TASK_READY just written]
             ⋮  (a) how long until the child's poll loop reads the state word?
             ⋮      + OS scheduling delay on a shared box
child   ──[worker.py:1823   state == _TASK_READY → handle_task()]
             ⋮  (b) Python prologue: unpack the args blob, rebuild ChipTensors
child   ──[simpler_run begins]  ← existing markers only start here
             ⋮
child   ──[writes TASK_DONE]
             ⋮  (c) how long until the parent's spin-poll notices?
parent  ──[complete]

(a) matters on a shared box, where other users' NPU work competes for the core; (b)
is a pure black box; (c) sits inside the parent's spin-poll. The parent has only
indirect visibility into (a) — the sticky ACK is observed via on_accept, but no
span records when the child accepted.

Closing it is cheap: one span in the child at the transition where _TASK_READY is
first observed. That is one span per task, the same cost class as the existing six,
and it does not violate this issue's own rule against instrumenting every
poll_progress iteration — the ban is on the loop, not on the transition. No
cross-process arithmetic is needed either: parent and child share
CLOCK_MONOTONIC on one axis, so (a) is readable as the visible gap before the new
span.

Also still open here: whether SUB-only topologies should emit host-scheduling spans
at all. dispatch currently fires for SUB workers while submit is NEXT_LEVEL-only,
so those dispatches have no paired flow arrow — either make it symmetric or document
the asymmetry.

Split out

Three tracks came out of the review that do not share a close condition with the
swimlane, so they are tracked separately rather than blocking this issue:

• [Code Health] Log subsystem — one clock, one grammar, one gate #1792 — log subsystem: one clock, one grammar, one gate. This is the substrate
  and would be needed even without a swimlane; keeping it here would make this issue
  un-closable even though the swimlane ships.
• [Code Health] Rename span families to pod/host/chip/core — coordinated across simpler, pypto-lib, pypto-serving #1793 — rename span families to pod. / host. / chip. / core.,
  coordinated across simpler, pypto-lib and pypto-serving. The span names turn out to
  be a de-facto contract with two external repos, so this needs its own coordination
  and its own audience.
• [Feature] Public Python tracing API — let callers put their own spans on the host swimlane #1794 — a public Python tracing API, so a caller can put its own spans on this
  timeline instead of only reading ours.

Corrections to the text above

Five places where the original write-up is now wrong or too weak. Recorded so the
next reader does not implement to the stale version.

1. Flow arrows connect submit → dispatch, not graph_build → dispatch.
The text above names the graph_build/dispatch pair as "the real reason flow
arrows are needed". #1730 pairs submit → dispatch instead, which is per-task
rather than per-run and loses nothing (submit nests inside graph_build on the
same tid). Better, but not what was specified.

2. The scheduler phases were deferred. sched.wait / sched.drain /
sched.dispatch — the "optional second tier", and the direct answer to is the host
starved, or slow to dispatch? — are not implemented. Deferral is fine; it was not
recorded anywhere until now.

3. Device spans are not on a sub-track; they are not rendered. The text asks for
them "on a separate device sub-track". #1730 keeps them out of traceEvents
entirely, in a top-level unalignedDeviceSpans array. The reasoning is sound —
Chrome Trace JSON has one visible timestamp axis, so placing an unrelated clock on it
either needs an invented offset or produces a multi-day empty viewport — but the
result is that this use case is served by a JSON array a human reads by hand.

Worth recording why that is structural rather than cautious: onboard device records
go to a different sink entirely (CANN dlog → device log files), never to host
stderr. Host-and-device on one axis is therefore only reachable by read-back plus
host-side synthesis, which is exactly what the clk=dev spans are — and a real
alignment needs a measured clock anchor, which #1792's clock_anchor record is the
vehicle for.

4. Two of the three landing constraints are stale.

• "Preload before fork()" — too weak as written, and now moot. The requirement
  was never really about fork(); getting it wrong loses the parent's spans too,
  not just the children's. And the design landed on passing the entry-point address
  from Python explicitly, so there is no load-order constraint at all.
• "Unsupported topologies disable quietly — no _l3_bins logger path, the bridge
  stays off" — describes a mechanism that no longer exists. The logger is loaded
  unconditionally, so a SUB-only L3 does have a live sink and does emit
  dispatch spans. The intent (initialization must still succeed) is met, and
  better than before — a missing logger is now a quiet no-op rather than an error.
• "non-variadic C entry point" still holds, but its rationale changed: the original
  reason was the ABI hazard of calling a variadic function through a dlsym'd
  pointer, which disappeared once the address is passed explicitly. What supports it
  now is simply "one grammar, one owner".

5. Six spans, six emit sites. The table above lists six spans; there were briefly
eight call sites, and upstream's submit_dispatch restructure collapsed the two
frame_submit paths and the two complete paths into one each. Six and six as of
009b7c86.