From c28aead4a4249ee76b7dcdedd5dd0a16ca1c80b6 Mon Sep 17 00:00:00 2001 From: Chao Wang <26245345+ChaoWao@users.noreply.github.com> Date: Sun, 7 Jun 2026 17:38:52 +0800 Subject: [PATCH] Add: queue-depth viz + Complete arrows + lifecycle context on swimlane MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Brings two missing causal threads into the level-4 swimlane: 1. **Local / shared queue depth at scheduler phase boundaries.** Each `aicpu_scheduler_phases` record now carries a `(local, shared) × (start, end)` snapshot indexed by [AIC, AIV, MIX]. The converter renders them as Perfetto counter tracks (`local_ready_buf_T{0,1,2}` per scheduler thread plus a global `shared_ready_queue` track), and folds the numbers into the phase block's hover args. This surfaces the dep-release → local-push → flush-to-shared → peer-pop transition that aggregate timing alone can't distinguish from MMIO latency. Hot-path cost discipline: local is a single int read on this thread's stack (free). Shared is two atomic relaxed loads against cache lines that peer schedulers also write — measurably slow when sampled twice per active iter. Mitigations: - Complete carries `phase_start_shared` forward as end (its fast-path release_fanin pushes to local, not shared); - Dispatch samples shared lazily, at most once per iter, reusing the cached value across the iter's emits. Measured impact on qwen3 decode_layer (a2a3 onboard, level 4): wall mean 919 → 898 us, variance 7% → <1% — back to within the pre-instrumentation noise floor. 2. **Complete phase ↔ task wiring on the trace.** - Inbound `complete` flow: one per logical task, anchored at the LAST subtask's AICore `end_us` (so it binds to the AICore slice the user clicks). Destination is the complete phase that contains the last subtask's `finish_us` — matches the AICPU's polling attribution semantics. - Outbound `complete→ready` flow: a consumer becomes ready only on the LAST fanin-bump, so the converter walks completes in temporal order and tracks each consumer's satisfied fanin count via `deps.json`. Arrows go only from the complete that triggered the final bump → that consumer's earliest dispatch. Drops the previous DAG-over-paint version. Phase block label kept terse — `complete(N)` where N matches the inbound arrow count exactly (verified 207/207 across the qwen3 workload). `finishes_processed` (per-subtask FIN count) stays in hover args for SPMD forensics. Converter only renders queue depth & complete arrows when the data is present; older swimlane JSON / runs without `deps.json` degrade gracefully (no edges, no counter tracks). Bracketed key names in hover args (`...[AIC,AIV,MIX]`) are encoded as `(aic,aiv,mix)` to dodge Perfetto's args-SQL array-index parsing. Counter samples emit once per phase (at phase end only) to avoid the duplicate-ts rate-calc divide- by-zero crash on synthetic zero-duration drains. Co-Authored-By: Claude Opus 4.7 (1M context) --- simpler_setup/tools/swimlane_converter.py | 384 +++++++++++++++++- .../aicpu/l2_swimlane_collector_aicpu.h | 15 +- .../include/common/l2_swimlane_profiling.h | 37 +- .../aicpu/l2_swimlane_collector_aicpu.cpp | 16 +- .../shared/host/l2_swimlane_collector.cpp | 8 + .../runtime/scheduler/scheduler_dispatch.cpp | 95 ++++- .../aicpu/l2_swimlane_collector_aicpu.h | 15 +- .../include/common/l2_swimlane_profiling.h | 37 +- .../aicpu/l2_swimlane_collector_aicpu.cpp | 16 +- .../shared/host/l2_swimlane_collector.cpp | 8 + .../runtime/scheduler/scheduler_dispatch.cpp | 95 ++++- 11 files changed, 690 insertions(+), 36 deletions(-) diff --git a/simpler_setup/tools/swimlane_converter.py b/simpler_setup/tools/swimlane_converter.py index 10137d654c..8436cc855a 100644 --- a/simpler_setup/tools/swimlane_converter.py +++ b/simpler_setup/tools/swimlane_converter.py @@ -22,6 +22,7 @@ """ import argparse +import bisect import importlib.util import json import sys @@ -993,6 +994,57 @@ def generate_chrome_trace_json( # noqa: PLR0912, PLR0915 "dispatch": "terrible", # red } + # Per-complete subtask-finish counts surface "how many AICore FINs + # did the AICPU poll in this phase" — useful context that + # tasks_processed (logical task count) doesn't convey. Computed + # with "phase contains finish_us" semantics so it matches how the + # AICPU actually attributes finishes to its polling windows. + complete_phases_by_thread_pre = [] + complete_starts_by_thread_pre = [] + for thread_records in scheduler_phases: + sorted_completes = sorted( + (r for r in thread_records if r.get("phase") == "complete"), + key=lambda r: r["start_time_us"], + ) + complete_phases_by_thread_pre.append(sorted_completes) + complete_starts_by_thread_pre.append([c["start_time_us"] for c in sorted_completes]) + + def _find_containing_complete(thread_idx: int, finish_us: float): + # Bisect into the per-thread sorted start_time_us list. Complete + # phases on a thread don't overlap, so the only complete that can + # CONTAIN finish_us is the last one whose start is <= finish_us + # (= entry at idx-1 after bisect_right). Fall back to the next + # starting complete (entry at idx) if it doesn't contain. + phases = complete_phases_by_thread_pre[thread_idx] + starts = complete_starts_by_thread_pre[thread_idx] + if not phases: + return None + idx = bisect.bisect_right(starts, finish_us) + if idx > 0: + prev_c = phases[idx - 1] + if prev_c["start_time_us"] <= finish_us <= prev_c["end_time_us"]: + return prev_c + if idx < len(phases): + return phases[idx] + return None + + finishes_per_complete: dict[int, int] = defaultdict(int) + if core_to_thread: + for t in tasks: + f_us = t.get("finish_time_us") + if f_us is None or f_us < 0: + continue + t_cid = t["core_id"] + if t_cid >= len(core_to_thread): + continue + t_thr = core_to_thread[t_cid] + if t_thr < 0 or t_thr >= len(complete_phases_by_thread_pre): + continue + t_comp = _find_containing_complete(t_thr, f_us) + if t_comp is None: + continue + finishes_per_complete[id(t_comp)] += 1 + for thread_idx, thread_records in enumerate(scheduler_phases): tid = 3000 + thread_idx @@ -1020,16 +1072,57 @@ def generate_chrome_trace_json( # noqa: PLR0912, PLR0915 dur = end_us - start_us tasks_processed = record.get("tasks_processed", 0) + # Queue-depth snapshot fields. Layout per + # L2SwimlaneAicpuSchedPhaseRecord docstring: [AIC, AIV, MIX]. + local_at_start = record.get("local_at_start") + local_at_end = record.get("local_at_end") + shared_at_start = record.get("shared_at_start") + shared_at_end = record.get("shared_at_end") + depths_valid = ( + isinstance(local_at_start, list) + and isinstance(local_at_end, list) + and isinstance(shared_at_start, list) + and isinstance(shared_at_end, list) + and len(local_at_start) == 3 + and len(local_at_end) == 3 + and len(shared_at_start) == 3 + and len(shared_at_end) == 3 + ) + + # Phase block. When queue depths are present, fold them into + # args so hover on a complete/dispatch bar surfaces the + # before/after queue state alongside the phase metadata. + phase_args = { + "phase": phase, + "loop_iter": record.get("loop_iter", 0), + "tasks_processed": tasks_processed, + } + if depths_valid: + # Perfetto's args SQL parses key names; `[...]` looks like + # an array-index op and crashes the details-panel query. + # Encode the AIC/AIV/MIX layout inline so the key stays + # parser-safe while still self-documenting. + phase_args.update( + { + f"T{thread_idx}_local_at_start (aic,aiv,mix)": list(local_at_start), + f"T{thread_idx}_local_at_end (aic,aiv,mix)": list(local_at_end), + "shared_at_start (aic,aiv,mix)": list(shared_at_start), + "shared_at_end (aic,aiv,mix)": list(shared_at_end), + } + ) + if phase == "complete": + # finishes_processed kept in args (hover) for forensics — + # SPMD cases where one logical task has N subtask FINs + # observed in the phase. Label stays minimal. + finishes_count = finishes_per_complete.get(id(record), 0) + phase_args["finishes_processed"] = finishes_count + display_name = f"{phase}({tasks_processed})" events.append( { - "args": { - "phase": phase, - "loop_iter": record.get("loop_iter", 0), - "tasks_processed": tasks_processed, - }, + "args": phase_args, "cat": "scheduler", "cname": phase_colors.get(phase, "generic_work"), - "name": f"{phase}({tasks_processed})", + "name": display_name, "ph": "X", "pid": 3, "tid": tid, @@ -1038,6 +1131,69 @@ def generate_chrome_trace_json( # noqa: PLR0912, PLR0915 } ) + # Queue-depth counter tracks (Perfetto "ph": "C"). Emit ONE + # sample per phase at its end_us — phase N's end is phase N+1's + # start, so emitting both is redundant. Two samples at the + # SAME ts (e.g. final-drain emit where start_time==end_time) + # also breaks Perfetto's rate calc (divide-by-zero → NULL). + # Track name carries thread index so it reads standalone + # even with the thread tree collapsed. + if not depths_valid: + continue + local_track_name = f"local_ready_buf_T{thread_idx}" + events.append( + { + "args": {"AIC": local_at_end[0], "AIV": local_at_end[1], "MIX": local_at_end[2]}, + "cat": "queue", + "name": local_track_name, + "ph": "C", + "pid": 3, + "tid": tid, + "ts": end_us, + } + ) + # Shared queue: dedicated tid 3999 so all 3 schedulers' + # snapshots compose onto one timeline (it's the same global + # queue regardless of who sampled it). Samples from different + # threads at slightly different ts are fine — Perfetto plots + # them in time order to render the step function. + events.append( + { + "args": {"AIC": shared_at_end[0], "AIV": shared_at_end[1], "MIX": shared_at_end[2]}, + "cat": "queue", + "name": "shared_ready_queue", + "ph": "C", + "pid": 3, + "tid": 3999, + "ts": end_us, + } + ) + + # Name the shared-queue pseudo-thread + give it a sort index that + # places it after the 3 scheduler threads but still inside the + # AICPU Scheduler process row, so the user reads top-to-bottom: + # Sched_0 / Sched_1 / Sched_2 / Shared queue (global). + events.append( + { + "args": {"name": "shared_ready_queue (global)"}, + "cat": "__metadata", + "name": "thread_name", + "ph": "M", + "pid": 3, + "tid": 3999, + } + ) + events.append( + { + "args": {"sort_index": 100}, + "cat": "__metadata", + "name": "thread_sort_index", + "ph": "M", + "pid": 3, + "tid": 3999, + } + ) + # AICPU Orchestrator lane (l2_swimlane_level >= 4) # # Per-event AicpuPhaseRecord[] is the single source of truth for @@ -1168,6 +1324,222 @@ def generate_chrome_trace_json( # noqa: PLR0912, PLR0915 flow_id += 1 + # Complete-phase flow arrows. The complete phase wraps the AICPU's + # completion-polling loop: it observes AICore subtask FINs, increments + # the slot's per-task subtask counter, and on the LAST subtask of a + # logical task it walks the fanout list and releases each consumer's + # fanin refcount. The arrows are built in two stages. + # + # Inbound: per-task, NOT per-subtask. A task is logically "completed" + # only when its LAST subtask is observed (the one that triggers + # phase_complete_count++ in firmware). For SPMD with N subtasks across + # N cores, the earlier N-1 subtasks just bump the slot's + # completed_subtasks counter inside whatever complete phase happened to + # poll them; only the LAST subtask's finish actually completes the + # task. So per task: take max(finish_time_us) across its subtasks, find + # the complete phase that CONTAINS that time, draw one arrow from that + # subtask's core lane to the complete phase start. + # + # Outbound: per-consumer, gated on full fanin. Each consumer in + # deps.json has multiple producer fanin edges; refcount += 1 fires + # whenever ANY producer's complete walks its fanout, but the consumer + # only becomes ready when ALL producers have completed. The complete + # that triggers the LAST refcount bump is the one that "released" the + # consumer — that's the causal edge. Compute by walking complete + # phases in temporal order and tracking each consumer's satisfied + # fanin count. + if scheduler_phases and core_to_thread: + complete_phases_by_thread = [] + complete_starts_by_thread = [] + for thread_records in scheduler_phases: + sorted_completes = sorted( + (r for r in thread_records if r.get("phase") == "complete"), + key=lambda r: r["start_time_us"], + ) + complete_phases_by_thread.append(sorted_completes) + complete_starts_by_thread.append([c["start_time_us"] for c in sorted_completes]) + + # Group subtask records by task_id; SPMD tasks have multiple rows. + tasks_by_id: dict[int, list[dict]] = defaultdict(list) + for t in tasks: + tasks_by_id[t["task_id"]].append(t) + + # For each task: completion = LAST subtask's finish observation. + # The owning thread is determined by core_to_thread of that last + # subtask's core — typical case is the same thread observed + # earlier subtasks too, but we don't assume. The source anchor for + # the flow arrow is the last subtask's AICore slice (its end_us) + # so the user can click the AICore task block in Perfetto and see + # the outbound complete arrow. + task_to_complete: dict[int, dict] = {} + task_last_subtask: dict[int, tuple[float, float, int]] = {} # tid -> (last_end_us, last_finish_us, core_id) + for tid, recs in tasks_by_id.items(): + valid_finishes = [ + (r.get("finish_time_us"), r.get("end_time_us"), r["core_id"]) + for r in recs + if r.get("finish_time_us") is not None and r["finish_time_us"] >= 0 and r.get("end_time_us") is not None + ] + if not valid_finishes: + continue + last_finish_us, last_end_us, last_cid = max(valid_finishes, key=lambda x: x[0]) + if last_cid >= len(core_to_thread): + continue + owning_thread = core_to_thread[last_cid] + if owning_thread < 0 or owning_thread >= len(complete_phases_by_thread): + continue + task_last_subtask[tid] = (last_end_us, last_finish_us, last_cid) + # Find the complete phase that CONTAINS this last_finish_us. + # Fall back to the next-starting complete if none contains + # (rare: AICore reported the finish but the scheduler hadn't + # entered its next complete phase by run end). Bisect for O(log N). + chosen = None + phases = complete_phases_by_thread[owning_thread] + starts = complete_starts_by_thread[owning_thread] + if phases: + idx = bisect.bisect_right(starts, last_finish_us) + if idx > 0: + prev_c = phases[idx - 1] + if prev_c["start_time_us"] <= last_finish_us <= prev_c["end_time_us"]: + chosen = prev_c + if chosen is None and idx < len(phases): + chosen = phases[idx] + if chosen is not None: + task_to_complete[tid] = chosen + + # ---- Inbound: one arrow per task, anchored on the AICore slice ---- + # Source ts = end_us - epsilon so it lands INSIDE the AICore task + # X event (last subtask of this task on its core). Without this + # anchoring Perfetto can't bind the flow to a slice and the arrow + # is invisible when you click the task. Same convention as the + # existing `dependency` arrows. + FLOW_EPSILON_US = 0.01 + for tid, comp in task_to_complete.items(): + last_end_us, _last_finish_us, last_cid = task_last_subtask[tid] + src_tid = core_to_tid[last_cid] + owning_thread = core_to_thread[last_cid] + dst_tid = 3000 + owning_thread + events.append( + { + "cat": "flow", + "id": flow_id, + "name": "complete", + "ph": "s", + "pid": 1, + "tid": src_tid, + "ts": last_end_us - FLOW_EPSILON_US, + } + ) + events.append( + { + "cat": "flow", + "id": flow_id, + "name": "complete", + "ph": "f", + "pid": 3, + "tid": dst_tid, + "ts": comp["start_time_us"], + "bp": "e", + } + ) + flow_id += 1 + + # ---- Outbound: per-consumer, gated on full fanin ---- + if deps_edges is not None: + # Invert deps_edges to consumer → predecessors for fanin counting. + preds_for_consumer: dict[int, list[int]] = defaultdict(list) + for pred, succs in deps_edges.items(): + for succ in succs: + preds_for_consumer[succ].append(pred) + fanin_total = {c: len(preds) for c, preds in preds_for_consumer.items()} + fanin_satisfied: dict[int, int] = defaultdict(int) + + # Reverse map: complete_phase id → list of task_ids it completed. + complete_to_tasks: dict[int, list[int]] = defaultdict(list) + for tid, comp in task_to_complete.items(): + complete_to_tasks[id(comp)].append(tid) + + # Walk completes in temporal order (by end_time). Within each, + # walk the tasks it completed; for each completed task, bump + # its consumers' satisfied fanin. The complete that pushes a + # consumer's satisfied count to its total is the one that + # released that consumer. + all_completes = [] + for thr_idx, phases in enumerate(complete_phases_by_thread): + for p in phases: + all_completes.append((p["end_time_us"], thr_idx, p)) + # Explicit key restricts the comparison to (end_time_us, thr_idx). + # Without it, ties in both fields fall through to comparing the + # third element (a dict), which raises TypeError in Python 3. + all_completes.sort(key=lambda x: (x[0], x[1])) + + # Earliest dispatch per task_id (for arrow target). + earliest_dispatch_us: dict[int, tuple[float, int]] = {} + for tid, recs in tasks_by_id.items(): + valid = [ + (r.get("dispatch_time_us"), r["core_id"]) + for r in recs + if r.get("dispatch_time_us") is not None and r["dispatch_time_us"] >= 0 + ] + if not valid: + continue + d_us, d_cid = min(valid, key=lambda x: x[0]) + if d_cid >= len(core_to_thread): + continue + d_thr = core_to_thread[d_cid] + if d_thr < 0: + continue + earliest_dispatch_us[tid] = (d_us, d_thr) + + for end_us, comp_thr, comp in all_completes: + completed_tids = complete_to_tasks.get(id(comp), ()) + if not completed_tids: + continue + triggered: list[int] = [] + for completed_tid in completed_tids: + for consumer in deps_edges.get(completed_tid, ()): + fanin_satisfied[consumer] += 1 + if fanin_satisfied[consumer] == fanin_total.get(consumer, 0): + triggered.append(consumer) + if not triggered: + continue + src_tid = 3000 + comp_thr + for consumer in triggered: + if consumer not in earliest_dispatch_us: + continue + d_us, d_thr = earliest_dispatch_us[consumer] + # Skip degenerate "dispatched before complete ended" — + # the consumer was popped/dispatched off a still-in-flight + # release path while the complete was still running; + # the arrow would point backwards. + if d_us < end_us: + continue + events.append( + { + "cat": "flow", + "id": flow_id, + "name": "complete→ready", + "ph": "s", + "pid": 3, + "tid": src_tid, + # Anchor inside the complete phase X event so + # clicking the complete block surfaces this arrow. + "ts": end_us - FLOW_EPSILON_US, + } + ) + events.append( + { + "cat": "flow", + "id": flow_id, + "name": "complete→ready", + "ph": "f", + "pid": 3, + "tid": 3000 + d_thr, + "ts": d_us, + "bp": "e", + } + ) + flow_id += 1 + # Scheduler DISPATCH → task execution arrows if scheduler_phases and has_aicpu_data: # Build core_id → scheduler thread mapping. diff --git a/src/a2a3/platform/include/aicpu/l2_swimlane_collector_aicpu.h b/src/a2a3/platform/include/aicpu/l2_swimlane_collector_aicpu.h index 543d20e471..80da54476f 100644 --- a/src/a2a3/platform/include/aicpu/l2_swimlane_collector_aicpu.h +++ b/src/a2a3/platform/include/aicpu/l2_swimlane_collector_aicpu.h @@ -167,6 +167,12 @@ void l2_swimlane_aicpu_init_phase(int worker_count, int num_sched_phase_threads, * pool. Silently drops records when the buffer is full or the pool was not * primed (init failed for this thread). * + * Queue-depth snapshots distinguish "task hidden in T0's local_buf" from + * "shared queue has it but peers spin on the wrong shape" — the former shows + * `local_depth > 0, shared_depth == 0` for the owning thread while peers see + * `shared_depth == 0` until overflow. Pass nullptr for any of the four arrays + * when not capturing (the record's corresponding slot is zero-filled). + * * @param thread_idx Scheduler thread index * @param kind Complete or Dispatch * @param start_time Phase start timestamp @@ -175,10 +181,17 @@ void l2_swimlane_aicpu_init_phase(int worker_count, int num_sched_phase_threads, * @param tasks_processed Tasks processed in this phase batch * @param pop_hit Dispatch delta since last emit (0 for Complete) * @param pop_miss Dispatch delta since last emit (0 for Complete) + * @param local_at_start Per-shape PTO2LocalReadyBuffer.count at phase start (size L2SWIMLANE_NUM_QUEUE_SHAPES; may be + * nullptr) + * @param shared_at_start Per-shape sched.ready_queues[shape].size() at phase start (may be nullptr) + * @param local_at_end Per-shape PTO2LocalReadyBuffer.count at phase end (may be nullptr) + * @param shared_at_end Per-shape sched.ready_queues[shape].size() at phase end (may be nullptr) */ void l2_swimlane_aicpu_record_sched_phase( int thread_idx, L2SwimlaneSchedPhaseKind kind, uint64_t start_time, uint64_t end_time, uint32_t loop_iter, - uint32_t tasks_processed, uint32_t pop_hit = 0, uint32_t pop_miss = 0 + uint32_t tasks_processed, uint32_t pop_hit = 0, uint32_t pop_miss = 0, const int16_t *local_at_start = nullptr, + const int16_t *shared_at_start = nullptr, const int16_t *local_at_end = nullptr, + const int16_t *shared_at_end = nullptr ); /** diff --git a/src/a2a3/platform/include/common/l2_swimlane_profiling.h b/src/a2a3/platform/include/common/l2_swimlane_profiling.h index 667f29ccc4..079626a1a1 100644 --- a/src/a2a3/platform/include/common/l2_swimlane_profiling.h +++ b/src/a2a3/platform/include/common/l2_swimlane_profiling.h @@ -473,26 +473,43 @@ enum class L2SwimlaneSchedPhaseKind : uint32_t { Dispatch = 1, // Dispatch ready tasks to idle cores }; +/** Index layout of the queue-depth snapshot arrays below: AIC=0, AIV=1, MIX=2. + * Must match PTO2ResourceShape's first three values (see pto_submit_types.h). + * Hardcoded here rather than included to keep this header runtime-independent. */ +constexpr int L2SWIMLANE_NUM_QUEUE_SHAPES = 3; + /** - * AICPU scheduler phase record (40 bytes). + * AICPU scheduler phase record (64 bytes). * * Position in the per-thread buffer is the identity — no thread_id field. * * pop_hit / pop_miss carry SCHED_DISPATCH delta counters since the last emit * (zero for Complete). Kept named, not "extra1"/"extra2", so the device-side * commit and the host-side JSON emit don't drift on which extra means which. + * + * Queue-depth snapshots (local_depth_*, shared_depth_*) record the per-shape + * scheduler queue occupancy at phase boundaries. They surface the + * dep-release-then-discovery latency that head OH alone can't distinguish from + * register-write latency: a phase whose start sees `local_depth=N, shared=0` + * and end sees `local_depth=N-K` shows that K tasks were popped from this + * thread's private buffer (invisible to peer threads) — peers must spin until + * those tasks overflow into shared. Filled with 0 below SCHED_PHASES. */ struct L2SwimlaneAicpuSchedPhaseRecord { - uint64_t start_time; // Phase start timestamp - uint64_t end_time; // Phase end timestamp - uint32_t loop_iter; // Scheduler-loop iteration number on this thread - L2SwimlaneSchedPhaseKind kind; // Complete or Dispatch - uint32_t tasks_processed; // Tasks processed in this phase batch - uint32_t pop_hit; // SCHED_DISPATCH delta since last emit (0 for Complete) - uint32_t pop_miss; // SCHED_DISPATCH delta since last emit (0 for Complete) - uint32_t _pad; // 40B alignment padding + uint64_t start_time; // Phase start timestamp + uint64_t end_time; // Phase end timestamp + uint32_t loop_iter; // Scheduler-loop iteration number on this thread + L2SwimlaneSchedPhaseKind kind; // Complete or Dispatch + uint32_t tasks_processed; // Tasks processed in this phase batch + uint32_t pop_hit; // SCHED_DISPATCH delta since last emit (0 for Complete) + uint32_t pop_miss; // SCHED_DISPATCH delta since last emit (0 for Complete) + int16_t local_depth_at_start[L2SWIMLANE_NUM_QUEUE_SHAPES]; // this thread's PTO2LocalReadyBuffer.count + int16_t local_depth_at_end[L2SWIMLANE_NUM_QUEUE_SHAPES]; + int16_t shared_depth_at_start[L2SWIMLANE_NUM_QUEUE_SHAPES]; // sched->ready_queues[shape].size() + int16_t shared_depth_at_end[L2SWIMLANE_NUM_QUEUE_SHAPES]; + uint32_t _pad; // 64B alignment padding }; -static_assert(sizeof(L2SwimlaneAicpuSchedPhaseRecord) == 40, "L2SwimlaneAicpuSchedPhaseRecord layout drift"); +static_assert(sizeof(L2SwimlaneAicpuSchedPhaseRecord) == 64, "L2SwimlaneAicpuSchedPhaseRecord layout drift"); /** * AICPU orchestrator phase record (32 bytes). diff --git a/src/a2a3/platform/shared/aicpu/l2_swimlane_collector_aicpu.cpp b/src/a2a3/platform/shared/aicpu/l2_swimlane_collector_aicpu.cpp index 14dd98c029..5ed92cd613 100644 --- a/src/a2a3/platform/shared/aicpu/l2_swimlane_collector_aicpu.cpp +++ b/src/a2a3/platform/shared/aicpu/l2_swimlane_collector_aicpu.cpp @@ -797,7 +797,8 @@ static Record *acquire_phase_slot( void l2_swimlane_aicpu_record_sched_phase( int thread_idx, L2SwimlaneSchedPhaseKind kind, uint64_t start_time, uint64_t end_time, uint32_t loop_iter, - uint32_t tasks_processed, uint32_t pop_hit, uint32_t pop_miss + uint32_t tasks_processed, uint32_t pop_hit, uint32_t pop_miss, const int16_t *local_at_start, + const int16_t *shared_at_start, const int16_t *local_at_end, const int16_t *shared_at_end ) { if (!s_phase_initialized) return; auto *state = s_sched_phase_pools[thread_idx]; @@ -820,6 +821,19 @@ void l2_swimlane_aicpu_record_sched_phase( record->tasks_processed = tasks_processed; record->pop_hit = pop_hit; record->pop_miss = pop_miss; + auto copy_snapshot = [](int16_t dst[L2SWIMLANE_NUM_QUEUE_SHAPES], const int16_t *src) { + if (src == nullptr) { + for (int i = 0; i < L2SWIMLANE_NUM_QUEUE_SHAPES; i++) + dst[i] = 0; + } else { + for (int i = 0; i < L2SWIMLANE_NUM_QUEUE_SHAPES; i++) + dst[i] = src[i]; + } + }; + copy_snapshot(record->local_depth_at_start, local_at_start); + copy_snapshot(record->shared_depth_at_start, shared_at_start); + copy_snapshot(record->local_depth_at_end, local_at_end); + copy_snapshot(record->shared_depth_at_end, shared_at_end); } void l2_swimlane_aicpu_set_orch_thread_idx(int thread_idx) { s_orch_thread_idx = thread_idx; } diff --git a/src/a2a3/platform/shared/host/l2_swimlane_collector.cpp b/src/a2a3/platform/shared/host/l2_swimlane_collector.cpp index 9040467053..e07ad9ba06 100644 --- a/src/a2a3/platform/shared/host/l2_swimlane_collector.cpp +++ b/src/a2a3/platform/shared/host/l2_swimlane_collector.cpp @@ -817,6 +817,9 @@ int L2SwimlaneCollector::export_swimlane_json() { return "unknown"; }; + auto emit_depth_array = [&outfile](const char *key, const int16_t arr[L2SWIMLANE_NUM_QUEUE_SHAPES]) { + outfile << ", \"" << key << "\": [" << arr[0] << "," << arr[1] << "," << arr[2] << "]"; + }; outfile << ",\n \"aicpu_scheduler_phases\": [\n"; for (size_t t = 0; t < collected_sched_phase_records_.size(); t++) { outfile << " ["; @@ -829,6 +832,11 @@ int L2SwimlaneCollector::export_swimlane_json() { if (pr.kind == L2SwimlaneSchedPhaseKind::Dispatch) { outfile << ", \"pop_hit\": " << pr.pop_hit << ", \"pop_miss\": " << pr.pop_miss; } + // Queue-depth snapshots — [AIC, AIV, MIX] per L2SwimlaneAicpuSchedPhaseRecord docstring. + emit_depth_array("local_at_start", pr.local_depth_at_start); + emit_depth_array("shared_at_start", pr.shared_depth_at_start); + emit_depth_array("local_at_end", pr.local_depth_at_end); + emit_depth_array("shared_at_end", pr.shared_depth_at_end); outfile << "}"; first = false; } diff --git a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp index bbba5cacc9..0457d07c48 100644 --- a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp +++ b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp @@ -12,6 +12,7 @@ #include #include +#include #include "common.h" // debug_assert @@ -540,6 +541,63 @@ int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_ l2_swimlane.sched_start_ts = get_sys_cnt_aicpu(); #endif +#if PTO2_PROFILING + // Queue-depth snapshot carried across the iteration boundary: each phase + // emit consumes (phase_start_*) and refreshes them with its own end snapshot + // so the next phase's "at_start" equals the previous phase's "at_end". + // + // L2SWIMLANE_NUM_QUEUE_SHAPES (3) matches PTO2_NUM_RESOURCE_SHAPES: AIC/AIV/MIX. + // + // **Hot-path cost discipline.** Local depth (this thread's PTO2LocalReadyBuffer) + // is a single int read on a register-cached stack — free. Shared depth + // (PTO2ReadyQueue::size) is two atomic relaxed loads against cache lines + // that all peer sched threads also write to (enqueue_pos and dequeue_pos + // bounce on every flush_local_bufs + every pop). With both phases emitting + // per iter that's 12 cross-core loads × thousands of iters per run, a + // measurable AICPU slowdown. Mitigation: lazy + per-iter cached shared + // snapshot, refreshed at most once per iteration. The complete-emit and + // dispatch-emit in the same iter both reuse the same shared sample; the + // big transitions (local→shared flush) still show up across iter boundaries. + static_assert( + L2SWIMLANE_NUM_QUEUE_SHAPES == PTO2_NUM_RESOURCE_SHAPES, + "queue snapshot width must match runtime resource shape count" + ); + int16_t phase_start_local[L2SWIMLANE_NUM_QUEUE_SHAPES] = {0}; + int16_t phase_start_shared[L2SWIMLANE_NUM_QUEUE_SHAPES] = {0}; + int16_t iter_shared_snapshot[L2SWIMLANE_NUM_QUEUE_SHAPES] = {0}; + bool iter_shared_sampled = false; + auto capture_local_snapshot = [&](int16_t local_out[L2SWIMLANE_NUM_QUEUE_SHAPES]) { + for (int s = 0; s < L2SWIMLANE_NUM_QUEUE_SHAPES; s++) { + local_out[s] = static_cast(local_bufs[s].count); + } + }; + auto get_or_sample_shared = [&]() -> const int16_t * { + if (!iter_shared_sampled) { + // Clamp to int16_t max before narrowing. PTO2_PROF_READYQUEUE_SIZE + // is in the low thousands today but could grow with platform + // scaling — without clamp, sizes above 32767 wrap to negatives + // and silently corrupt the snapshot. + constexpr size_t kMax = static_cast(std::numeric_limits::max()); + for (int s = 0; s < L2SWIMLANE_NUM_QUEUE_SHAPES; s++) { + const size_t qsize = sched_->ready_queues[s].size(); + iter_shared_snapshot[s] = static_cast(std::min(qsize, kMax)); + } + iter_shared_sampled = true; + } + return iter_shared_snapshot; + }; + auto capture_phase_end = [&](int16_t local_out[L2SWIMLANE_NUM_QUEUE_SHAPES], + int16_t shared_out[L2SWIMLANE_NUM_QUEUE_SHAPES]) { + capture_local_snapshot(local_out); + const int16_t *shared_cached = get_or_sample_shared(); + for (int s = 0; s < L2SWIMLANE_NUM_QUEUE_SHAPES; s++) + shared_out[s] = shared_cached[s]; + }; + if (l2_swimlane_level_ >= L2SwimlaneLevel::SCHED_PHASES) { + capture_phase_end(phase_start_local, phase_start_shared); + } +#endif + // Wall-clock timestamp of the last completed task on this thread. // Updated on made_progress; consulted to decide whether the wall-clock // budget for declaring a scheduler hang has elapsed. Initialized to @@ -556,6 +614,11 @@ int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_ CYCLE_COUNT_START(); l2_swimlane.sched_loop_count++; uint64_t _t0_phase = _t0; + // Per-iter lazy shared-queue snapshot: first phase emit in this iter + // pays the atomic-load cost, subsequent emits in the same iter reuse + // the cached value. Reset here so we re-sample exactly once per iter + // (or skip entirely on iters with no phase emit). + iter_shared_sampled = false; #endif int32_t task_count = 0; if (!tracker.has_any_running_cores()) { @@ -635,10 +698,24 @@ int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_ } else { CYCLE_COUNT_LAP(l2_swimlane.sched_complete_cycle); if (l2_swimlane_level_ >= L2SwimlaneLevel::SCHED_PHASES && l2_swimlane.phase_complete_count > 0) { + // Local depth is cheap (this thread's own buffer counter). + // Shared depth is NOT sampled here: complete's release_fanin + // pushes to local_bufs in the fast path (try_push succeeds + // until cap=64). Shared only changes on dispatch's flush + // path. Carrying phase_start_shared forward as end_shared + // is the right answer 99% of the time AND skips three + // contended atomic loads per emit. + int16_t phase_end_local[L2SWIMLANE_NUM_QUEUE_SHAPES]; + capture_local_snapshot(phase_end_local); l2_swimlane_aicpu_record_sched_phase( thread_idx, L2SwimlaneSchedPhaseKind::Complete, _t0_phase, _t1, l2_swimlane.sched_loop_count, - l2_swimlane.phase_complete_count + l2_swimlane.phase_complete_count, /*pop_hit=*/0, /*pop_miss=*/0, phase_start_local, + phase_start_shared, phase_end_local, phase_start_shared ); + for (int s = 0; s < L2SWIMLANE_NUM_QUEUE_SHAPES; s++) { + phase_start_local[s] = phase_end_local[s]; + // phase_start_shared unchanged — carried forward + } _t0_phase = _t1; l2_swimlane.phase_complete_count = 0; } @@ -727,11 +804,19 @@ int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_ // realistic dispatch cadence and silently truncates without this guard. debug_assert(pop_hit_delta < (1ULL << 32)); debug_assert(pop_miss_delta < (1ULL << 32)); + int16_t phase_end_local[L2SWIMLANE_NUM_QUEUE_SHAPES]; + int16_t phase_end_shared[L2SWIMLANE_NUM_QUEUE_SHAPES]; + capture_phase_end(phase_end_local, phase_end_shared); l2_swimlane_aicpu_record_sched_phase( thread_idx, L2SwimlaneSchedPhaseKind::Dispatch, _t0_phase, _t1, l2_swimlane.sched_loop_count, l2_swimlane.phase_dispatch_count, static_cast(pop_hit_delta), - static_cast(pop_miss_delta) + static_cast(pop_miss_delta), phase_start_local, phase_start_shared, phase_end_local, + phase_end_shared ); + for (int s = 0; s < L2SWIMLANE_NUM_QUEUE_SHAPES; s++) { + phase_start_local[s] = phase_end_local[s]; + phase_start_shared[s] = phase_end_shared[s]; + } _t0_phase = _t1; l2_swimlane.phase_dispatch_count = 0; l2_swimlane.pop_hit_at_last_emit = l2_swimlane.pop_hit; @@ -841,9 +926,13 @@ int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_ debug_assert(final_pop_miss_delta < (1ULL << 32)); if (final_pop_hit_delta != 0 || final_pop_miss_delta != 0) { uint64_t t_now = get_sys_cnt_aicpu(); + int16_t phase_end_local[L2SWIMLANE_NUM_QUEUE_SHAPES]; + int16_t phase_end_shared[L2SWIMLANE_NUM_QUEUE_SHAPES]; + capture_phase_end(phase_end_local, phase_end_shared); l2_swimlane_aicpu_record_sched_phase( thread_idx, L2SwimlaneSchedPhaseKind::Dispatch, t_now, t_now, l2_swimlane.sched_loop_count, 0, - static_cast(final_pop_hit_delta), static_cast(final_pop_miss_delta) + static_cast(final_pop_hit_delta), static_cast(final_pop_miss_delta), + phase_end_local, phase_end_shared, phase_end_local, phase_end_shared ); l2_swimlane.pop_hit_at_last_emit = l2_swimlane.pop_hit; l2_swimlane.pop_miss_at_last_emit = l2_swimlane.pop_miss; diff --git a/src/a5/platform/include/aicpu/l2_swimlane_collector_aicpu.h b/src/a5/platform/include/aicpu/l2_swimlane_collector_aicpu.h index 543d20e471..80da54476f 100644 --- a/src/a5/platform/include/aicpu/l2_swimlane_collector_aicpu.h +++ b/src/a5/platform/include/aicpu/l2_swimlane_collector_aicpu.h @@ -167,6 +167,12 @@ void l2_swimlane_aicpu_init_phase(int worker_count, int num_sched_phase_threads, * pool. Silently drops records when the buffer is full or the pool was not * primed (init failed for this thread). * + * Queue-depth snapshots distinguish "task hidden in T0's local_buf" from + * "shared queue has it but peers spin on the wrong shape" — the former shows + * `local_depth > 0, shared_depth == 0` for the owning thread while peers see + * `shared_depth == 0` until overflow. Pass nullptr for any of the four arrays + * when not capturing (the record's corresponding slot is zero-filled). + * * @param thread_idx Scheduler thread index * @param kind Complete or Dispatch * @param start_time Phase start timestamp @@ -175,10 +181,17 @@ void l2_swimlane_aicpu_init_phase(int worker_count, int num_sched_phase_threads, * @param tasks_processed Tasks processed in this phase batch * @param pop_hit Dispatch delta since last emit (0 for Complete) * @param pop_miss Dispatch delta since last emit (0 for Complete) + * @param local_at_start Per-shape PTO2LocalReadyBuffer.count at phase start (size L2SWIMLANE_NUM_QUEUE_SHAPES; may be + * nullptr) + * @param shared_at_start Per-shape sched.ready_queues[shape].size() at phase start (may be nullptr) + * @param local_at_end Per-shape PTO2LocalReadyBuffer.count at phase end (may be nullptr) + * @param shared_at_end Per-shape sched.ready_queues[shape].size() at phase end (may be nullptr) */ void l2_swimlane_aicpu_record_sched_phase( int thread_idx, L2SwimlaneSchedPhaseKind kind, uint64_t start_time, uint64_t end_time, uint32_t loop_iter, - uint32_t tasks_processed, uint32_t pop_hit = 0, uint32_t pop_miss = 0 + uint32_t tasks_processed, uint32_t pop_hit = 0, uint32_t pop_miss = 0, const int16_t *local_at_start = nullptr, + const int16_t *shared_at_start = nullptr, const int16_t *local_at_end = nullptr, + const int16_t *shared_at_end = nullptr ); /** diff --git a/src/a5/platform/include/common/l2_swimlane_profiling.h b/src/a5/platform/include/common/l2_swimlane_profiling.h index 326c59ccc2..9b33101c4d 100644 --- a/src/a5/platform/include/common/l2_swimlane_profiling.h +++ b/src/a5/platform/include/common/l2_swimlane_profiling.h @@ -473,26 +473,43 @@ enum class L2SwimlaneSchedPhaseKind : uint32_t { Dispatch = 1, // Dispatch ready tasks to idle cores }; +/** Index layout of the queue-depth snapshot arrays below: AIC=0, AIV=1, MIX=2. + * Must match PTO2ResourceShape's first three values (see pto_submit_types.h). + * Hardcoded here rather than included to keep this header runtime-independent. */ +constexpr int L2SWIMLANE_NUM_QUEUE_SHAPES = 3; + /** - * AICPU scheduler phase record (40 bytes). + * AICPU scheduler phase record (64 bytes). * * Position in the per-thread buffer is the identity — no thread_id field. * * pop_hit / pop_miss carry SCHED_DISPATCH delta counters since the last emit * (zero for Complete). Kept named, not "extra1"/"extra2", so the device-side * commit and the host-side JSON emit don't drift on which extra means which. + * + * Queue-depth snapshots (local_depth_*, shared_depth_*) record the per-shape + * scheduler queue occupancy at phase boundaries. They surface the + * dep-release-then-discovery latency that head OH alone can't distinguish from + * register-write latency: a phase whose start sees `local_depth=N, shared=0` + * and end sees `local_depth=N-K` shows that K tasks were popped from this + * thread's private buffer (invisible to peer threads) — peers must spin until + * those tasks overflow into shared. Filled with 0 below SCHED_PHASES. */ struct L2SwimlaneAicpuSchedPhaseRecord { - uint64_t start_time; // Phase start timestamp - uint64_t end_time; // Phase end timestamp - uint32_t loop_iter; // Scheduler-loop iteration number on this thread - L2SwimlaneSchedPhaseKind kind; // Complete or Dispatch - uint32_t tasks_processed; // Tasks processed in this phase batch - uint32_t pop_hit; // SCHED_DISPATCH delta since last emit (0 for Complete) - uint32_t pop_miss; // SCHED_DISPATCH delta since last emit (0 for Complete) - uint32_t _pad; // 40B alignment padding + uint64_t start_time; // Phase start timestamp + uint64_t end_time; // Phase end timestamp + uint32_t loop_iter; // Scheduler-loop iteration number on this thread + L2SwimlaneSchedPhaseKind kind; // Complete or Dispatch + uint32_t tasks_processed; // Tasks processed in this phase batch + uint32_t pop_hit; // SCHED_DISPATCH delta since last emit (0 for Complete) + uint32_t pop_miss; // SCHED_DISPATCH delta since last emit (0 for Complete) + int16_t local_depth_at_start[L2SWIMLANE_NUM_QUEUE_SHAPES]; // this thread's PTO2LocalReadyBuffer.count + int16_t local_depth_at_end[L2SWIMLANE_NUM_QUEUE_SHAPES]; + int16_t shared_depth_at_start[L2SWIMLANE_NUM_QUEUE_SHAPES]; // sched->ready_queues[shape].size() + int16_t shared_depth_at_end[L2SWIMLANE_NUM_QUEUE_SHAPES]; + uint32_t _pad; // 64B alignment padding }; -static_assert(sizeof(L2SwimlaneAicpuSchedPhaseRecord) == 40, "L2SwimlaneAicpuSchedPhaseRecord layout drift"); +static_assert(sizeof(L2SwimlaneAicpuSchedPhaseRecord) == 64, "L2SwimlaneAicpuSchedPhaseRecord layout drift"); /** * AICPU orchestrator phase record (32 bytes). diff --git a/src/a5/platform/shared/aicpu/l2_swimlane_collector_aicpu.cpp b/src/a5/platform/shared/aicpu/l2_swimlane_collector_aicpu.cpp index 14dd98c029..5ed92cd613 100644 --- a/src/a5/platform/shared/aicpu/l2_swimlane_collector_aicpu.cpp +++ b/src/a5/platform/shared/aicpu/l2_swimlane_collector_aicpu.cpp @@ -797,7 +797,8 @@ static Record *acquire_phase_slot( void l2_swimlane_aicpu_record_sched_phase( int thread_idx, L2SwimlaneSchedPhaseKind kind, uint64_t start_time, uint64_t end_time, uint32_t loop_iter, - uint32_t tasks_processed, uint32_t pop_hit, uint32_t pop_miss + uint32_t tasks_processed, uint32_t pop_hit, uint32_t pop_miss, const int16_t *local_at_start, + const int16_t *shared_at_start, const int16_t *local_at_end, const int16_t *shared_at_end ) { if (!s_phase_initialized) return; auto *state = s_sched_phase_pools[thread_idx]; @@ -820,6 +821,19 @@ void l2_swimlane_aicpu_record_sched_phase( record->tasks_processed = tasks_processed; record->pop_hit = pop_hit; record->pop_miss = pop_miss; + auto copy_snapshot = [](int16_t dst[L2SWIMLANE_NUM_QUEUE_SHAPES], const int16_t *src) { + if (src == nullptr) { + for (int i = 0; i < L2SWIMLANE_NUM_QUEUE_SHAPES; i++) + dst[i] = 0; + } else { + for (int i = 0; i < L2SWIMLANE_NUM_QUEUE_SHAPES; i++) + dst[i] = src[i]; + } + }; + copy_snapshot(record->local_depth_at_start, local_at_start); + copy_snapshot(record->shared_depth_at_start, shared_at_start); + copy_snapshot(record->local_depth_at_end, local_at_end); + copy_snapshot(record->shared_depth_at_end, shared_at_end); } void l2_swimlane_aicpu_set_orch_thread_idx(int thread_idx) { s_orch_thread_idx = thread_idx; } diff --git a/src/a5/platform/shared/host/l2_swimlane_collector.cpp b/src/a5/platform/shared/host/l2_swimlane_collector.cpp index 9040467053..e07ad9ba06 100644 --- a/src/a5/platform/shared/host/l2_swimlane_collector.cpp +++ b/src/a5/platform/shared/host/l2_swimlane_collector.cpp @@ -817,6 +817,9 @@ int L2SwimlaneCollector::export_swimlane_json() { return "unknown"; }; + auto emit_depth_array = [&outfile](const char *key, const int16_t arr[L2SWIMLANE_NUM_QUEUE_SHAPES]) { + outfile << ", \"" << key << "\": [" << arr[0] << "," << arr[1] << "," << arr[2] << "]"; + }; outfile << ",\n \"aicpu_scheduler_phases\": [\n"; for (size_t t = 0; t < collected_sched_phase_records_.size(); t++) { outfile << " ["; @@ -829,6 +832,11 @@ int L2SwimlaneCollector::export_swimlane_json() { if (pr.kind == L2SwimlaneSchedPhaseKind::Dispatch) { outfile << ", \"pop_hit\": " << pr.pop_hit << ", \"pop_miss\": " << pr.pop_miss; } + // Queue-depth snapshots — [AIC, AIV, MIX] per L2SwimlaneAicpuSchedPhaseRecord docstring. + emit_depth_array("local_at_start", pr.local_depth_at_start); + emit_depth_array("shared_at_start", pr.shared_depth_at_start); + emit_depth_array("local_at_end", pr.local_depth_at_end); + emit_depth_array("shared_at_end", pr.shared_depth_at_end); outfile << "}"; first = false; } diff --git a/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp b/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp index 37ecaeb914..d6de0a4324 100644 --- a/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp +++ b/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp @@ -12,6 +12,7 @@ #include #include +#include #include "common.h" // debug_assert #include "common/unified_log.h" @@ -529,6 +530,63 @@ int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_ l2_swimlane.sched_start_ts = get_sys_cnt_aicpu(); #endif +#if PTO2_PROFILING + // Queue-depth snapshot carried across the iteration boundary: each phase + // emit consumes (phase_start_*) and refreshes them with its own end snapshot + // so the next phase's "at_start" equals the previous phase's "at_end". + // + // L2SWIMLANE_NUM_QUEUE_SHAPES (3) matches PTO2_NUM_RESOURCE_SHAPES: AIC/AIV/MIX. + // + // **Hot-path cost discipline.** Local depth (this thread's PTO2LocalReadyBuffer) + // is a single int read on a register-cached stack — free. Shared depth + // (PTO2ReadyQueue::size) is two atomic relaxed loads against cache lines + // that all peer sched threads also write to (enqueue_pos and dequeue_pos + // bounce on every flush_local_bufs + every pop). With both phases emitting + // per iter that's 12 cross-core loads × thousands of iters per run, a + // measurable AICPU slowdown. Mitigation: lazy + per-iter cached shared + // snapshot, refreshed at most once per iteration. The complete-emit and + // dispatch-emit in the same iter both reuse the same shared sample; the + // big transitions (local→shared flush) still show up across iter boundaries. + static_assert( + L2SWIMLANE_NUM_QUEUE_SHAPES == PTO2_NUM_RESOURCE_SHAPES, + "queue snapshot width must match runtime resource shape count" + ); + int16_t phase_start_local[L2SWIMLANE_NUM_QUEUE_SHAPES] = {0}; + int16_t phase_start_shared[L2SWIMLANE_NUM_QUEUE_SHAPES] = {0}; + int16_t iter_shared_snapshot[L2SWIMLANE_NUM_QUEUE_SHAPES] = {0}; + bool iter_shared_sampled = false; + auto capture_local_snapshot = [&](int16_t local_out[L2SWIMLANE_NUM_QUEUE_SHAPES]) { + for (int s = 0; s < L2SWIMLANE_NUM_QUEUE_SHAPES; s++) { + local_out[s] = static_cast(local_bufs[s].count); + } + }; + auto get_or_sample_shared = [&]() -> const int16_t * { + if (!iter_shared_sampled) { + // Clamp to int16_t max before narrowing. PTO2_PROF_READYQUEUE_SIZE + // is in the low thousands today but could grow with platform + // scaling — without clamp, sizes above 32767 wrap to negatives + // and silently corrupt the snapshot. + constexpr size_t kMax = static_cast(std::numeric_limits::max()); + for (int s = 0; s < L2SWIMLANE_NUM_QUEUE_SHAPES; s++) { + const size_t qsize = sched_->ready_queues[s].size(); + iter_shared_snapshot[s] = static_cast(std::min(qsize, kMax)); + } + iter_shared_sampled = true; + } + return iter_shared_snapshot; + }; + auto capture_phase_end = [&](int16_t local_out[L2SWIMLANE_NUM_QUEUE_SHAPES], + int16_t shared_out[L2SWIMLANE_NUM_QUEUE_SHAPES]) { + capture_local_snapshot(local_out); + const int16_t *shared_cached = get_or_sample_shared(); + for (int s = 0; s < L2SWIMLANE_NUM_QUEUE_SHAPES; s++) + shared_out[s] = shared_cached[s]; + }; + if (l2_swimlane_level_ >= L2SwimlaneLevel::SCHED_PHASES) { + capture_phase_end(phase_start_local, phase_start_shared); + } +#endif + // Wall-clock timestamp of the last completed task on this thread. // Updated on made_progress; consulted to decide whether the wall-clock // budget for declaring a scheduler hang has elapsed. Initialized to @@ -545,6 +603,11 @@ int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_ CYCLE_COUNT_START(); l2_swimlane.sched_loop_count++; uint64_t _t0_phase = _t0; + // Per-iter lazy shared-queue snapshot: first phase emit in this iter + // pays the atomic-load cost, subsequent emits in the same iter reuse + // the cached value. Reset here so we re-sample exactly once per iter + // (or skip entirely on iters with no phase emit). + iter_shared_sampled = false; #endif int32_t task_count = 0; if (!tracker.has_any_running_cores()) { @@ -624,10 +687,24 @@ int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_ } else { CYCLE_COUNT_LAP(l2_swimlane.sched_complete_cycle); if (l2_swimlane_level_ >= L2SwimlaneLevel::SCHED_PHASES && l2_swimlane.phase_complete_count > 0) { + // Local depth is cheap (this thread's own buffer counter). + // Shared depth is NOT sampled here: complete's release_fanin + // pushes to local_bufs in the fast path (try_push succeeds + // until cap=64). Shared only changes on dispatch's flush + // path. Carrying phase_start_shared forward as end_shared + // is the right answer 99% of the time AND skips three + // contended atomic loads per emit. + int16_t phase_end_local[L2SWIMLANE_NUM_QUEUE_SHAPES]; + capture_local_snapshot(phase_end_local); l2_swimlane_aicpu_record_sched_phase( thread_idx, L2SwimlaneSchedPhaseKind::Complete, _t0_phase, _t1, l2_swimlane.sched_loop_count, - l2_swimlane.phase_complete_count + l2_swimlane.phase_complete_count, /*pop_hit=*/0, /*pop_miss=*/0, phase_start_local, + phase_start_shared, phase_end_local, phase_start_shared ); + for (int s = 0; s < L2SWIMLANE_NUM_QUEUE_SHAPES; s++) { + phase_start_local[s] = phase_end_local[s]; + // phase_start_shared unchanged — carried forward + } _t0_phase = _t1; l2_swimlane.phase_complete_count = 0; } @@ -717,11 +794,19 @@ int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_ // realistic dispatch cadence and silently truncates without this guard. debug_assert(pop_hit_delta < (1ULL << 32)); debug_assert(pop_miss_delta < (1ULL << 32)); + int16_t phase_end_local[L2SWIMLANE_NUM_QUEUE_SHAPES]; + int16_t phase_end_shared[L2SWIMLANE_NUM_QUEUE_SHAPES]; + capture_phase_end(phase_end_local, phase_end_shared); l2_swimlane_aicpu_record_sched_phase( thread_idx, L2SwimlaneSchedPhaseKind::Dispatch, _t0_phase, _t1, l2_swimlane.sched_loop_count, l2_swimlane.phase_dispatch_count, static_cast(pop_hit_delta), - static_cast(pop_miss_delta) + static_cast(pop_miss_delta), phase_start_local, phase_start_shared, phase_end_local, + phase_end_shared ); + for (int s = 0; s < L2SWIMLANE_NUM_QUEUE_SHAPES; s++) { + phase_start_local[s] = phase_end_local[s]; + phase_start_shared[s] = phase_end_shared[s]; + } _t0_phase = _t1; l2_swimlane.phase_dispatch_count = 0; l2_swimlane.pop_hit_at_last_emit = l2_swimlane.pop_hit; @@ -825,9 +910,13 @@ int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_ debug_assert(final_pop_miss_delta < (1ULL << 32)); if (final_pop_hit_delta != 0 || final_pop_miss_delta != 0) { uint64_t t_now = get_sys_cnt_aicpu(); + int16_t phase_end_local[L2SWIMLANE_NUM_QUEUE_SHAPES]; + int16_t phase_end_shared[L2SWIMLANE_NUM_QUEUE_SHAPES]; + capture_phase_end(phase_end_local, phase_end_shared); l2_swimlane_aicpu_record_sched_phase( thread_idx, L2SwimlaneSchedPhaseKind::Dispatch, t_now, t_now, l2_swimlane.sched_loop_count, 0, - static_cast(final_pop_hit_delta), static_cast(final_pop_miss_delta) + static_cast(final_pop_hit_delta), static_cast(final_pop_miss_delta), + phase_end_local, phase_end_shared, phase_end_local, phase_end_shared ); l2_swimlane.pop_hit_at_last_emit = l2_swimlane.pop_hit; l2_swimlane.pop_miss_at_last_emit = l2_swimlane.pop_miss;