diff --git a/docs/dfx/chip-timing.md b/docs/dfx/chip-timing.md new file mode 100644 index 000000000..158591c18 --- /dev/null +++ b/docs/dfx/chip-timing.md @@ -0,0 +1,120 @@ +# Chip Timing — per-stage `run_prepared()` wall-clock breakdown + +`CHIP_TIMING` is an opt-in DFX facility that breaks a single `run_prepared()` +into per-stage durations on both the host and the device, reconciled against the +two wall numbers the runtime already reports (`host_wall_ns` / `device_wall_ns`, +see [profiling-framework.md](../profiling-framework.md)). It answers "where did +the time go" — host binding vs device execution — without intrusive +instrumentation: the runtime emits a handful of `[CHIP_TIMING]` log lines, and +the offline parser [`simpler_setup/tools/chip_timing.py`](../../simpler_setup/tools/chip_timing.py) +assembles them into an indented tree. + +It is deliberately **minimal and extensible**: the runtime seeds only the +outermost boundaries (enough to reproduce `host_wall` / `device_wall`). To drill +into any stage, add one more `ev=B` / `ev=E` pair in the same grammar — the tool +needs no change. + +## Enabling + +The lines are emitted on the **V4** log tier, which is hidden at the default V5 +threshold (V4 < V5). Lower the log level to V4 to collect them: + +```bash +python /test_*.py -p a5 --log-level v4 2>&1 | tee run.log +``` + +V4 (rather than V0/V1) keeps the collateral chatter low — only V4..V9 lines are +unmuted, not the V0 flood. When disabled, the emit path short-circuits before +formatting, so there is no measurable overhead. + +## Grammar + +One event per line. The surrounding log prefix (host timestamp or CANN dlog +header) is ignored — the timestamp rides in the message body as nanoseconds in +the **emitting clock's** domain, mirroring the embedded-cycle convention in +[`tools/benchmark_rounds.sh`](../../tools/benchmark_rounds.sh): + +```text +[CHIP_TIMING] run= clk=host name= ev= t= +[CHIP_TIMING] clk=dev name= ev= t= tid= +[CHIP_TIMING] run= clk=host name=host_wall ev=WALL us= +[CHIP_TIMING] run= clk=dev name=device_wall ev=WALL us= +``` + +- `clk=host` — `t` is host `steady_clock` ns (the clock backing `host_wall_ns`). +- `clk=dev` — `t` is ns derived from `get_sys_cnt_aicpu()` (the counter backing + `device_wall_ns`); `tid` distinguishes the AICPU threads. +- `ev=WALL` — the authoritative baseline, emitted host-side after the run with + the value in the body. Both `host_wall` and `device_wall` carry the host + `run` index. + +Host and device are **separate clock domains**: durations are only meaningful +*within* a domain. Host stages reconcile against `host_wall`; device stages +against `device_wall`. There is no cross-domain absolute alignment. + +## Seeded stages + +| clk | name | bounds | +| --- | ---- | ------ | +| host | `run_prepared` | the whole envelope (== `host_wall`) | +| host | `attach` / `bind_callable` / `bind_impl` / `runner_run` / `validate` | the five `run_prepared` stages (onboard; sim has no `attach`) | +| dev | `aicpu_wall` | `simpler_aicpu_init` start .. last `simpler_aicpu_exec` exit (== `device_wall`) | +| dev | `aicpu_exec` | the `aicpu_execute()` window inside each AICPU thread | + +Source: host in [`c_api_shared.cpp`](../../src/common/platform/onboard/host/c_api_shared.cpp) +(onboard) and its sim counterpart; device in +[`kernel.cpp`](../../src/a5/platform/onboard/aicpu/kernel.cpp) (onboard a5/a2a3) +and the sim `device_runner.cpp` execution loop. + +## Tool usage + +```bash +# sim — host + device logs both land on stderr +python -m simpler_setup.tools.chip_timing --log run.log + +# onboard — host stderr + CANN device log dir +python -m simpler_setup.tools.chip_timing --host-log host.log \ + --device-log-dir ~/ascend/log/debug/device-5 +# ... or let it resolve the dir like benchmark_rounds.sh: +python -m simpler_setup.tools.chip_timing --host-log host.log --device-id 5 +``` + +How it assembles events: + +- **host** (single-threaded) — B/E paired as a nested stack → `run_prepared` + with its children; `(unattributed)` is the remainder vs the child sum. +- **device** (multi-threaded) — reduced per name to `min(B) .. max(E)`; rounds + are segmented by tid reappearance (the host `run` index is not available + on-device), so point `--device-log-dir` at a fresh log. Stale rounds with no + matching host run print under `run=?`. + +Example output: + +```text +[CHIP_TIMING] run=0 + host (steady_clock): + run_prepared 121.300 ms (host_wall 121.300 ms, Δ +0.000 ms) + attach 0.100 ms + bind_callable 1.000 ms + bind_impl 100.000 ms + runner_run 20.000 ms + validate 0.050 ms + (unattributed) 0.150 ms + device (sys_cnt): + aicpu_wall 19.850 ms (device_wall 19.850 ms, Δ +0.000 ms) + aicpu_exec 19.600 ms +``` + +The `Δ` against `host_wall` / `device_wall` is the built-in sanity check: a +large delta means a boundary is missing or mis-paired. + +## Extending + +To attribute time inside a stage (e.g. split `bind_impl` into +`args_malloc_copy` / `prebuilt_arena`, or `aicpu_exec` into `so_load` / +`graph_build`), emit a nested `ev=B` / `ev=E` pair with the same grammar at the +new boundary. Host uses `steady_clock` ns; device uses +`cycles_to_us(get_sys_cnt_aicpu()) * 1000`. No parser change is required — +nesting is inferred from the timestamps. + +Tests: [`tests/ut/py/test_chip_timing.py`](../../tests/ut/py/test_chip_timing.py). diff --git a/simpler_setup/tools/chip_timing.py b/simpler_setup/tools/chip_timing.py new file mode 100644 index 000000000..207cfd742 --- /dev/null +++ b/simpler_setup/tools/chip_timing.py @@ -0,0 +1,376 @@ +#!/usr/bin/env python3 +# Copyright (c) PyPTO Contributors. +# This program is free software, you can redistribute it and/or modify it under the terms and conditions of +# CANN Open Software License Agreement Version 2.0 (the "License"). +# Please refer to the License for details. You may not use this file except in compliance with the License. +# THIS SOFTWARE IS PROVIDED ON AN "AS IS" BASIS, WITHOUT WARRANTIES OF ANY KIND, EITHER EXPRESS OR IMPLIED, +# INCLUDING BUT NOT LIMITED TO NON-INFRINGEMENT, MERCHANTABILITY, OR FITNESS FOR A PARTICULAR PURPOSE. +# See LICENSE in the root of the software repository for the full text of the License. +# ----------------------------------------------------------------------------------------------------------- +""" +CHIP_TIMING log parser — per-stage run_prepared() wall-clock breakdown (issue #1012). + +Reads the opt-in ``[CHIP_TIMING]`` log lines emitted by the runtime when the log +level is lowered to V4 and prints one indented per-run tree, reconciled against +the authoritative ``host_wall`` / ``device_wall`` numbers the runtime already +reports. + +The grammar (one line per event, fields are space-separated ``key=value``; the +surrounding log prefix is ignored): + + [CHIP_TIMING] run= clk=host name= ev= t= + [CHIP_TIMING] clk=dev name= ev= t= tid= + [CHIP_TIMING] run= clk=host name=host_wall ev=WALL us= + [CHIP_TIMING] run= clk=dev name=device_wall ev=WALL us= + +``t`` is nanoseconds in the emitting clock domain (host steady_clock, device +get_sys_cnt). Durations are only meaningful *within* a domain, so host stages +reconcile against host_wall and device stages against device_wall. The value +rides in the message body (never the log prefix), matching the device-log +convention in tools/benchmark_rounds.sh. + +host events (single-threaded run_prepared) are paired as a nested B/E stack. +device events (multi-threaded) are reduced per name to min(B)..max(E), and +device rounds are segmented by tid reappearance like benchmark_rounds.sh — the +host run index is not available on-device. + +To extend the breakdown, add another ``[CHIP_TIMING] ... ev=B`` / ``ev=E`` pair +anywhere in the runtime using the same grammar; no change to this tool is needed. + +Usage: + # sim (host + device logs both land on stderr) + python -m simpler_setup.tools.chip_timing --log run.log + + # onboard (host stderr + CANN device log dir) + python -m simpler_setup.tools.chip_timing --host-log host.log \ + --device-log-dir ~/ascend/log/debug/device-5 + + # default device-log dir resolution mirrors benchmark_rounds.sh + python -m simpler_setup.tools.chip_timing --host-log host.log --device-id 5 +""" + +import argparse +import glob +import os +import re +import sys +from dataclasses import dataclass, field +from typing import Optional + +# The device backend (CANN dlog) wraps the message in quotes, so a value must +# stop at the closing quote as well as whitespace. +_LINE_RE = re.compile(r"\[CHIP_TIMING\]\s+(.*)$") +_KV_RE = re.compile(r'(\w+)=([^\s"]+)') + + +@dataclass +class Event: + clk: str # "host" | "dev" + name: str + ev: str # "B" | "E" | "WALL" + run: Optional[int] = None + t_ns: Optional[int] = None + tid: Optional[int] = None + us: Optional[float] = None + + +@dataclass +class Span: + name: str + depth: int + dur_ns: int + start_ns: int = 0 + + +@dataclass +class RunReport: + run: Optional[int] + host_spans: list = field(default_factory=list) # list[Span] + dev_spans: list = field(default_factory=list) # list[Span] + host_wall_ns: Optional[int] = None + device_wall_ns: Optional[int] = None + notes: list = field(default_factory=list) # list[str] + + +def parse_lines(lines): + """Extract Event objects from an iterable of log lines (order preserved).""" + events = [] + for line in lines: + m = _LINE_RE.search(line) + if not m: + continue + fields = dict(_KV_RE.findall(m.group(1))) + if "clk" not in fields or "name" not in fields or "ev" not in fields: + continue + ev = Event(clk=fields["clk"], name=fields["name"], ev=fields["ev"]) + if "run" in fields: + try: + ev.run = int(fields["run"]) + except ValueError: + pass + if "t" in fields: + try: + ev.t_ns = int(fields["t"]) + except ValueError: + pass + if "tid" in fields: + try: + ev.tid = int(fields["tid"]) + except ValueError: + pass + if "us" in fields: + try: + ev.us = float(fields["us"]) + except ValueError: + pass + events.append(ev) + return events + + +def _pair_host_stack(events): + """Pair host B/E events into nested spans. Returns (spans, notes). + + Sorted by timestamp (B before E on ties) so interleaved stderr still nests + correctly; LIFO pop matches the scoped-span emission order. + """ + # On equal timestamps, close (E) before open (B) so a stage that ends exactly + # when the next sibling begins still nests correctly under a coarse clock. + ordered = sorted( + [e for e in events if e.ev in ("B", "E") and e.t_ns is not None], + key=lambda e: (e.t_ns, 0 if e.ev == "E" else 1), + ) + spans = [] + notes = [] + stack = [] # list[Event] of open B's + for e in ordered: + if e.ev == "B": + stack.append(e) + else: # E + if not stack: + notes.append(f"host: unmatched end for '{e.name}'") + continue + opener = stack.pop() + if opener.name != e.name: + notes.append(f"host: nesting mismatch ('{opener.name}' B / '{e.name}' E)") + spans.append(Span(name=e.name, depth=len(stack), dur_ns=max(0, e.t_ns - opener.t_ns), start_ns=opener.t_ns)) + for leftover in stack: + notes.append(f"host: missing end for '{leftover.name}'") + # Pre-order for display: parent (earliest B) before its children. + spans.sort(key=lambda s: s.start_ns) + return spans, notes + + +def _reduce_dev(events): + """Reduce device B/E events per name to min(B)..max(E). Returns (spans, notes). + + Nesting is inferred by interval containment so an outer ``aicpu_wall`` shows + its inner phases indented. + """ + by_name = {} # name -> {"minB": int|None, "maxE": int|None} + for e in events: + if e.ev not in ("B", "E") or e.t_ns is None: + continue + slot = by_name.setdefault(e.name, {"minB": None, "maxE": None}) + if e.ev == "B": + slot["minB"] = e.t_ns if slot["minB"] is None else min(slot["minB"], e.t_ns) + else: + slot["maxE"] = e.t_ns if slot["maxE"] is None else max(slot["maxE"], e.t_ns) + + intervals = [] # (name, start, end) + notes = [] + for name, slot in by_name.items(): + if slot["minB"] is None or slot["maxE"] is None: + notes.append(f"device: incomplete span for '{name}' (missing {'B' if slot['minB'] is None else 'E'})") + continue + intervals.append((name, slot["minB"], max(slot["minB"], slot["maxE"]))) + + intervals.sort(key=lambda iv: (iv[1], -(iv[2] - iv[1]))) # by start, widest first + spans = [] + for name, start, end in intervals: + depth = sum(1 for _, s2, e2 in intervals if s2 <= start and e2 >= end and (s2, e2) != (start, end)) + spans.append(Span(name=name, depth=depth, dur_ns=end - start, start_ns=start)) + return spans, notes + + +def _segment_dev_rounds(dev_events): + """Split device events into rounds by tid reappearance (benchmark_rounds.sh). + + A 'B' event whose tid already produced a 'B' in the current round opens a new + round. Events keep file order. Single run with no repeats → one round. + """ + rounds = [] + cur = [] + seen_b_tids = set() + for e in dev_events: + if e.ev == "B" and e.tid is not None and e.tid in seen_b_tids: + rounds.append(cur) + cur = [] + seen_b_tids = set() + cur.append(e) + if e.ev == "B" and e.tid is not None: + seen_b_tids.add(e.tid) + if cur: + rounds.append(cur) + return rounds + + +def assemble(events): + """Build per-run reports from a flat event list.""" + # WALL baselines are emitted host-side with a run index for both host_wall + # (clk=host) and device_wall (clk=dev), so route them by run, not by clk. + wall_by_run = {} + for e in events: + if e.ev == "WALL": + wall_by_run.setdefault(e.run, []).append(e) + + dev_events = [e for e in events if e.clk == "dev" and e.ev in ("B", "E")] + + # host runs keyed by run index (None bucketed together as a single run). + host_by_run = {} + for e in events: + if e.clk == "host" and e.ev in ("B", "E"): + host_by_run.setdefault(e.run, []).append(e) + run_ids = sorted(host_by_run.keys(), key=lambda r: (r is None, r)) + + # device rounds aligned to host runs by position (host run index absent on + # device). WALL device_wall comes from the host side, keyed by run. + dev_rounds = _segment_dev_rounds(dev_events) + + reports = [] + for idx, run_id in enumerate(run_ids): + evs = host_by_run[run_id] + rep = RunReport(run=run_id) + spans, notes = _pair_host_stack(evs) + rep.host_spans = spans + rep.notes.extend(notes) + for e in wall_by_run.get(run_id, []): + if e.us is None: + continue + if e.name == "host_wall": + rep.host_wall_ns = int(e.us * 1000) + elif e.name == "device_wall": + rep.device_wall_ns = int(e.us * 1000) + if idx < len(dev_rounds): + dspans, dnotes = _reduce_dev(dev_rounds[idx]) + rep.dev_spans = dspans + rep.notes.extend(dnotes) + reports.append(rep) + + # Device rounds with no matching host run (e.g. device-only log). + for idx in range(len(run_ids), len(dev_rounds)): + rep = RunReport(run=None) + dspans, dnotes = _reduce_dev(dev_rounds[idx]) + rep.dev_spans = dspans + rep.notes.extend(dnotes) + rep.notes.append("device round without matching host run") + reports.append(rep) + + return reports + + +def _ms(ns): + return ns / 1e6 + + +def _fmt_delta(measured_ns, baseline_ns, label): + if baseline_ns is None: + return "" + delta = _ms(measured_ns - baseline_ns) + return f" ({label} {_ms(baseline_ns):.3f} ms, Δ {delta:+.3f} ms)" + + +def render(reports): + """Render reports to a human-readable indented tree string.""" + out = [] + for rep in reports: + label = f"run={rep.run}" if rep.run is not None else "run=?" + out.append(f"[CHIP_TIMING] {label}") + + if rep.host_spans: + out.append(" host (steady_clock):") + for s in rep.host_spans: + indent = " " + " " * s.depth + suffix = "" + if s.name == "run_prepared": + suffix = _fmt_delta(s.dur_ns, rep.host_wall_ns, "host_wall") + out.append(f"{indent}{s.name:<20}{_ms(s.dur_ns):>10.3f} ms{suffix}") + # Unattributed = run_prepared - sum(direct children). + root = next((s for s in rep.host_spans if s.name == "run_prepared"), None) + if root is not None: + child_sum = sum(s.dur_ns for s in rep.host_spans if s.depth == 1) + rem = root.dur_ns - child_sum + if rem > 0: + out.append(f" {'(unattributed)':<20}{_ms(rem):>10.3f} ms") + + if rep.dev_spans: + out.append(" device (sys_cnt):") + for s in rep.dev_spans: + indent = " " + " " * s.depth + suffix = "" + if s.name == "aicpu_wall": + suffix = _fmt_delta(s.dur_ns, rep.device_wall_ns, "device_wall") + out.append(f"{indent}{s.name:<20}{_ms(s.dur_ns):>10.3f} ms{suffix}") + + if not rep.host_spans and not rep.dev_spans: + out.append(" (no spans parsed)") + for note in rep.notes: + out.append(f" ! {note}") + out.append("") + return "\n".join(out) + + +def _read_files(paths): + lines = [] + for p in paths: + try: + with open(p, errors="replace") as f: + lines.extend(f.readlines()) + except OSError as exc: + print(f"warning: cannot read {p}: {exc}", file=sys.stderr) + return lines + + +def _resolve_device_log_dir(device_id): + work = os.environ.get("ASCEND_WORK_PATH") + candidates = [] + if work: + candidates.append(os.path.join(work, "log", "debug")) + candidates.append(os.path.join(os.path.expanduser("~"), "ascend", "log", "debug")) + for root in candidates: + d = os.path.join(root, f"device-{device_id}") + if os.path.isdir(d): + return d + return None + + +def main(argv=None): + parser = argparse.ArgumentParser(description="Parse [CHIP_TIMING] logs into a per-run wall-clock breakdown.") + parser.add_argument("--log", action="append", default=[], help="combined log file (sim: host+device on stderr)") + parser.add_argument("--host-log", action="append", default=[], help="host stderr log file") + parser.add_argument("--device-log-dir", help="CANN device log dir (parses device-*.log inside)") + parser.add_argument("--device-id", type=int, help="resolve device log dir like benchmark_rounds.sh") + args = parser.parse_args(argv) + + paths = list(args.log) + list(args.host_log) + dev_dir = args.device_log_dir + if dev_dir is None and args.device_id is not None: + dev_dir = _resolve_device_log_dir(args.device_id) + if dev_dir is None: + print(f"warning: no device log dir found for device-{args.device_id}", file=sys.stderr) + if dev_dir: + paths.extend(sorted(glob.glob(os.path.join(dev_dir, "device-*.log")))) + + if not paths: + parser.error("no input: pass --log / --host-log / --device-log-dir / --device-id") + + events = parse_lines(_read_files(paths)) + if not events: + print("no [CHIP_TIMING] lines found — was the log level lowered to V4?", file=sys.stderr) + return 1 + reports = assemble(events) + print(render(reports)) + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/src/a2a3/platform/onboard/aicpu/kernel.cpp b/src/a2a3/platform/onboard/aicpu/kernel.cpp index 21b0368d3..81d8d0228 100644 --- a/src/a2a3/platform/onboard/aicpu/kernel.cpp +++ b/src/a2a3/platform/onboard/aicpu/kernel.cpp @@ -11,6 +11,7 @@ #include #include "common/unified_log.h" +#include "common/chip_timing.h" #include "common/kernel_args.h" #include "common/platform_config.h" #include "aicpu/dep_gen_collector_aicpu.h" @@ -114,12 +115,16 @@ extern "C" __attribute__((visibility("default"))) int simpler_aicpu_exec(void *a const int32_t wall_slot = platform_aicpu_affinity_thread_idx(); uint64_t *const wall = reinterpret_cast(k_args->device_wall_data_base); const bool wall_ok = wall != nullptr && wall_slot >= 0 && wall_slot < PLATFORM_MAX_AICPU_THREADS_JUST_FOR_LAUNCH; + const uint64_t wall_start = get_sys_cnt_aicpu(); if (wall_ok) { - wall[wall_slot * 2] = get_sys_cnt_aicpu(); + wall[wall_slot * 2] = wall_start; } + CHIP_TIMING_DEV_CYCLES("aicpu_wall", 'B', wall_start); LOG_INFO_V0("%s", "simpler_aicpu_exec: Calling aicpu_execute with Runtime"); + CHIP_TIMING_DEV_CYCLES("aicpu_exec", 'B', get_sys_cnt_aicpu()); int rc = aicpu_execute(runtime); + CHIP_TIMING_DEV_CYCLES("aicpu_exec", 'E', get_sys_cnt_aicpu()); if (rc != 0) { LOG_ERROR("simpler_aicpu_exec: aicpu_execute failed with rc=%d", rc); return rc; @@ -128,9 +133,11 @@ extern "C" __attribute__((visibility("default"))) int simpler_aicpu_exec(void *a // Run-wall: record this thread's end into its own slot (plain store). // Host reduces max(end) - min(start) → ns (see wall-capture note above). + const uint64_t wall_end = get_sys_cnt_aicpu(); if (wall_ok) { - wall[wall_slot * 2 + 1] = get_sys_cnt_aicpu(); + wall[wall_slot * 2 + 1] = wall_end; } + CHIP_TIMING_DEV_CYCLES("aicpu_wall", 'E', wall_end); return rc; } diff --git a/src/a2a3/platform/sim/host/device_runner.cpp b/src/a2a3/platform/sim/host/device_runner.cpp index b6e60d079..440b35999 100644 --- a/src/a2a3/platform/sim/host/device_runner.cpp +++ b/src/a2a3/platform/sim/host/device_runner.cpp @@ -31,6 +31,7 @@ #include "aicpu/platform_aicpu_affinity.h" #include "callable_protocol.h" +#include "common/chip_timing.h" #include "common/memory_barrier.h" #include "common/platform_config.h" #include "common/unified_log.h" @@ -460,19 +461,21 @@ int DeviceRunner::run(Runtime &runtime, int block_dim, int launch_aicpu_num) { *reinterpret_cast(kernel_args_.device_wall_data_base) = 0; } const auto sim_t0 = std::chrono::steady_clock::now(); + CHIP_TIMING_DEV_TP("aicpu_wall", 'B', sim_t0, -1); for (int i = 0; i < over_launch; i++) { - aicpu_threads.push_back(create_thread([this, &runtime, launch_aicpu_num, over_launch, &aicpu_rc, sim_t0]() { + aicpu_threads.push_back(create_thread([this, &runtime, launch_aicpu_num, over_launch, &aicpu_rc, sim_t0, i]() { if (!platform_aicpu_affinity_gate(launch_aicpu_num, over_launch)) { return; } int rc = aicpu_execute_func_(&runtime); + const auto t1 = std::chrono::steady_clock::now(); + CHIP_TIMING_DEV_TP("aicpu_wall", 'E', t1, i); if (rc != 0) { int expected = 0; aicpu_rc.compare_exchange_strong(expected, rc, std::memory_order_acq_rel); } if (kernel_args_.device_wall_data_base != 0) { - const auto t1 = std::chrono::steady_clock::now(); *reinterpret_cast(kernel_args_.device_wall_data_base) = static_cast(std::chrono::duration_cast(t1 - sim_t0).count()); } diff --git a/src/a2a3/runtime/tensormap_and_ringbuffer/docs/device_log_profiling.md b/src/a2a3/runtime/tensormap_and_ringbuffer/docs/device_log_profiling.md index af661d440..bb7c4144e 100644 --- a/src/a2a3/runtime/tensormap_and_ringbuffer/docs/device_log_profiling.md +++ b/src/a2a3/runtime/tensormap_and_ringbuffer/docs/device_log_profiling.md @@ -150,6 +150,8 @@ When `--enable-l2-swimlane` is used, the host terminal prints a **Task Statistic A high sched/exec ratio (e.g., >3x) indicates that scheduling overhead dominates, and optimizations should target the scheduler's dispatch hot path (cache flush, payload construction) or upstream task flow. +For a host+device per-stage breakdown of a single `run_prepared()` (reconciled against `host_wall` / `device_wall`), see [Chip Timing](../../../../../docs/dfx/chip-timing.md) — opt-in `[CHIP_TIMING]` log lines at the V4 tier, parsed by `simpler_setup/tools/chip_timing.py`. + --- ## Quick Reference: Extracting Profiling Data diff --git a/src/a5/platform/onboard/aicpu/kernel.cpp b/src/a5/platform/onboard/aicpu/kernel.cpp index 1c360c324..b5951fc03 100644 --- a/src/a5/platform/onboard/aicpu/kernel.cpp +++ b/src/a5/platform/onboard/aicpu/kernel.cpp @@ -11,6 +11,7 @@ #include #include "common/unified_log.h" +#include "common/chip_timing.h" #include "common/kernel_args.h" #include "common/platform_config.h" #include "aicpu/dep_gen_collector_aicpu.h" @@ -124,12 +125,16 @@ extern "C" __attribute__((visibility("default"))) int simpler_aicpu_exec(void *a const int32_t wall_slot = platform_aicpu_affinity_thread_idx(); uint64_t *const wall = reinterpret_cast(k_args->device_wall_data_base); const bool wall_ok = wall != nullptr && wall_slot >= 0 && wall_slot < PLATFORM_MAX_AICPU_THREADS_JUST_FOR_LAUNCH; + const uint64_t wall_start = get_sys_cnt_aicpu(); if (wall_ok) { - wall[wall_slot * 2] = get_sys_cnt_aicpu(); + wall[wall_slot * 2] = wall_start; } + CHIP_TIMING_DEV_CYCLES("aicpu_wall", 'B', wall_start); LOG_INFO_V0("%s", "simpler_aicpu_exec: Calling aicpu_execute with Runtime"); + CHIP_TIMING_DEV_CYCLES("aicpu_exec", 'B', get_sys_cnt_aicpu()); int rc = aicpu_execute(runtime); + CHIP_TIMING_DEV_CYCLES("aicpu_exec", 'E', get_sys_cnt_aicpu()); if (rc != 0) { LOG_ERROR("simpler_aicpu_exec: aicpu_execute failed with rc=%d", rc); return rc; @@ -138,9 +143,11 @@ extern "C" __attribute__((visibility("default"))) int simpler_aicpu_exec(void *a // Run-wall: record this thread's end into its own slot (plain store). // Host reduces max(end) - min(start) → ns (see wall-capture note above). + const uint64_t wall_end = get_sys_cnt_aicpu(); if (wall_ok) { - wall[wall_slot * 2 + 1] = get_sys_cnt_aicpu(); + wall[wall_slot * 2 + 1] = wall_end; } + CHIP_TIMING_DEV_CYCLES("aicpu_wall", 'E', wall_end); return rc; } diff --git a/src/a5/platform/sim/host/device_runner.cpp b/src/a5/platform/sim/host/device_runner.cpp index d43925d09..436235283 100644 --- a/src/a5/platform/sim/host/device_runner.cpp +++ b/src/a5/platform/sim/host/device_runner.cpp @@ -32,6 +32,7 @@ #include "aicpu/platform_aicpu_affinity.h" #include "callable_protocol.h" +#include "common/chip_timing.h" #include "common/memory_barrier.h" #include "common/platform_config.h" #include "common/unified_log.h" @@ -421,19 +422,21 @@ int DeviceRunner::run(Runtime &runtime, int block_dim, int launch_aicpu_num) { *reinterpret_cast(kernel_args_.device_wall_data_base) = 0; } const auto sim_t0 = std::chrono::steady_clock::now(); + CHIP_TIMING_DEV_TP("aicpu_wall", 'B', sim_t0, -1); for (int i = 0; i < over_launch; i++) { - aicpu_threads.push_back(create_thread([this, &runtime, launch_aicpu_num, over_launch, &aicpu_rc, sim_t0]() { + aicpu_threads.push_back(create_thread([this, &runtime, launch_aicpu_num, over_launch, &aicpu_rc, sim_t0, i]() { if (!platform_aicpu_affinity_gate(launch_aicpu_num, over_launch)) { return; } int rc = aicpu_execute_func_(&runtime); + const auto t1 = std::chrono::steady_clock::now(); + CHIP_TIMING_DEV_TP("aicpu_wall", 'E', t1, i); if (rc != 0) { int expected = 0; aicpu_rc.compare_exchange_strong(expected, rc, std::memory_order_acq_rel); } if (kernel_args_.device_wall_data_base != 0) { - const auto t1 = std::chrono::steady_clock::now(); *reinterpret_cast(kernel_args_.device_wall_data_base) = static_cast(std::chrono::duration_cast(t1 - sim_t0).count()); } diff --git a/src/a5/runtime/tensormap_and_ringbuffer/docs/device_log_profiling.md b/src/a5/runtime/tensormap_and_ringbuffer/docs/device_log_profiling.md index af661d440..bb7c4144e 100644 --- a/src/a5/runtime/tensormap_and_ringbuffer/docs/device_log_profiling.md +++ b/src/a5/runtime/tensormap_and_ringbuffer/docs/device_log_profiling.md @@ -150,6 +150,8 @@ When `--enable-l2-swimlane` is used, the host terminal prints a **Task Statistic A high sched/exec ratio (e.g., >3x) indicates that scheduling overhead dominates, and optimizations should target the scheduler's dispatch hot path (cache flush, payload construction) or upstream task flow. +For a host+device per-stage breakdown of a single `run_prepared()` (reconciled against `host_wall` / `device_wall`), see [Chip Timing](../../../../../docs/dfx/chip-timing.md) — opt-in `[CHIP_TIMING]` log lines at the V4 tier, parsed by `simpler_setup/tools/chip_timing.py`. + --- ## Quick Reference: Extracting Profiling Data diff --git a/src/common/log/include/common/chip_timing.h b/src/common/log/include/common/chip_timing.h new file mode 100644 index 000000000..bfc883788 --- /dev/null +++ b/src/common/log/include/common/chip_timing.h @@ -0,0 +1,133 @@ +/* + * Copyright (c) PyPTO Contributors. + * This program is free software, you can redistribute it and/or modify it under the terms and conditions of + * CANN Open Software License Agreement Version 2.0 (the "License"). + * Please refer to the License for details. You may not use this file except in compliance with the License. + * THIS SOFTWARE IS PROVIDED ON AN "AS IS" BASIS, WITHOUT WARRANTIES OF ANY KIND, EITHER EXPRESS OR IMPLIED, + * INCLUDING BUT NOT LIMITED TO NON-INFRINGEMENT, MERCHANTABILITY, OR FITNESS FOR A PARTICULAR PURPOSE. + * See LICENSE in the root of the software repository for the full text of the License. + * ----------------------------------------------------------------------------------------------------------- + */ +#ifndef COMMON_CHIP_TIMING_H_ +#define COMMON_CHIP_TIMING_H_ + +/** + * CHIP_TIMING (issue #1012): the single source of truth for the opt-in + * per-stage run_prepared() timing log grammar. Every emit across the host + * c_api and the per-arch device kernels goes through these macros so the + * grammar can never drift away from the parser + * (simpler_setup/tools/chip_timing.py). + * + * Lines are emitted on the V4 log tier — hidden at the default V5 threshold + * (4 < 5), enabled by lowering the log level to V4. The gate short-circuits + * before formatting, so disabled is near-zero cost. The timestamp rides in the + * message body (ns in the emitting clock's domain), never the dlog prefix, so + * the parser is prefix-independent. Durations are only meaningful within a + * clock domain: host events (steady_clock) reconcile against host_wall, device + * events (sys_cnt) against device_wall. + * + * Grammar: + * [CHIP_TIMING] run= clk=host name= ev= t= + * [CHIP_TIMING] clk=dev name= ev= t= tid= + * [CHIP_TIMING] run= clk=host name=host_wall ev=WALL us= + * [CHIP_TIMING] run= clk=dev name=device_wall ev=WALL us= + */ + +#include "common/unified_log.h" + +/* --------------------------------------------------------------------------- + * Format macros — no std dependencies, safe to expand in any TU (host, onboard + * AICPU, sim). The caller supplies the timestamp already converted to ns in its + * own clock domain. + * ------------------------------------------------------------------------- */ + +#define CHIP_TIMING_HOST_EVENT(run, name, ev, t_ns) \ + LOG_INFO_V4( \ + "[CHIP_TIMING] run=%llu clk=host name=%s ev=%c t=%llu", static_cast(run), (name), \ + static_cast(ev), static_cast(t_ns) \ + ) + +#define CHIP_TIMING_HOST_WALL(run, name, us) \ + LOG_INFO_V4( \ + "[CHIP_TIMING] run=%llu clk=host name=%s ev=WALL us=%.3f", static_cast(run), (name), \ + static_cast(us) \ + ) + +#define CHIP_TIMING_DEV_WALL(run, name, us) \ + LOG_INFO_V4( \ + "[CHIP_TIMING] run=%llu clk=dev name=%s ev=WALL us=%.3f", static_cast(run), (name), \ + static_cast(us) \ + ) + +#define CHIP_TIMING_DEV_EVENT(name, ev, t_ns, tid) \ + LOG_INFO_V4( \ + "[CHIP_TIMING] clk=dev name=%s ev=%c tid=%ld t=%llu", (name), static_cast(ev), static_cast(tid), \ + static_cast(t_ns) \ + ) + +/* --------------------------------------------------------------------------- + * Per-clock convenience wrappers. Each references symbols that exist only in + * one TU flavor; because macros expand lazily, an unused wrapper costs nothing + * in the other TUs. + * ------------------------------------------------------------------------- */ + +// Onboard AICPU: raw sys-counter cycles → ns via cycles_to_us(), tagged GET_TID(). +// Requires common/platform_config.h (cycles_to_us) and the device-log GET_TID(). +#define CHIP_TIMING_DEV_CYCLES(name, ev, cycles) \ + CHIP_TIMING_DEV_EVENT((name), (ev), static_cast(cycles_to_us(cycles) * 1000.0), GET_TID()) + +// Sim device: a steady_clock::time_point → ns in the steady_clock epoch. +// Requires . +#define CHIP_TIMING_DEV_TP(name, ev, tp, tid) \ + CHIP_TIMING_DEV_EVENT( \ + (name), (ev), \ + static_cast(std::chrono::duration_cast((tp).time_since_epoch()).count()), \ + (tid) \ + ) + +/* --------------------------------------------------------------------------- + * Host RAII span + run counter — opt-in because it pulls /. + * A host TU defines CHIP_TIMING_HOST_SPANS before including this header; the + * device kernels (which avoid the std deps) leave it undefined. + * ------------------------------------------------------------------------- */ + +#ifdef CHIP_TIMING_HOST_SPANS +#include +#include + +namespace simpler::chip_timing { + +// One monotonic per-run index per process. Inline so both arches' host c_api +// TUs share one definition without an ODR clash. +inline std::atomic g_run_counter{0}; + +inline uint64_t next_run() { return g_run_counter.fetch_add(1, std::memory_order_relaxed); } + +inline uint64_t now_ns() { + return static_cast( + std::chrono::duration_cast(std::chrono::steady_clock::now().time_since_epoch()) + .count() + ); +} + +// B on construction, E on destruction — exception-safe pairing that also fires +// on the early-return error paths inside run_prepared(). +struct Span { + uint64_t run; + const char *name; + Span(uint64_t run_, const char *name_) : + run(run_), + name(name_) { + CHIP_TIMING_HOST_EVENT(run, name, 'B', now_ns()); + } + ~Span() { CHIP_TIMING_HOST_EVENT(run, name, 'E', now_ns()); } + Span(const Span &) = delete; + Span &operator=(const Span &) = delete; +}; + +} // namespace simpler::chip_timing + +#define CHIP_TIMING_SCOPE(run, name) ::simpler::chip_timing::Span _chip_timing_span_(run, name) +#endif // CHIP_TIMING_HOST_SPANS + +#endif // COMMON_CHIP_TIMING_H_ diff --git a/src/common/platform/onboard/host/c_api_shared.cpp b/src/common/platform/onboard/host/c_api_shared.cpp index 5ffc934e9..54d368234 100644 --- a/src/common/platform/onboard/host/c_api_shared.cpp +++ b/src/common/platform/onboard/host/c_api_shared.cpp @@ -43,6 +43,9 @@ #include "host/raii_scope_guard.h" #include "runtime.h" +#define CHIP_TIMING_HOST_SPANS +#include "common/chip_timing.h" + // Forward-declared (rather than `#include "dlog_pub.h"`) so this TU does not // require CANN's toolchain include path on the host build. Resolved at link // time against `libunified_dlog.so` / `libascendalog.so`. @@ -399,9 +402,18 @@ int run_prepared( }); const auto host_t0 = std::chrono::steady_clock::now(); + const uint64_t run_idx = simpler::chip_timing::next_run(); + CHIP_TIMING_HOST_EVENT( + run_idx, "run_prepared", 'B', + static_cast(std::chrono::duration_cast(host_t0.time_since_epoch()).count()) + ); try { - int rc = runner->attach_current_thread(runner->device_id()); + int rc = 0; + { + CHIP_TIMING_SCOPE(run_idx, "attach"); + rc = runner->attach_current_thread(runner->device_id()); + } if (rc != 0) return rc; Runtime *r = new (runtime) Runtime(); @@ -430,16 +442,23 @@ int run_prepared( // per-tensor direction decisions in runtime_maker. trb consumes it to // skip the D2H copy-back of read-only INPUT tensors; hbg still // ignores it — see bind_callable_to_runtime_impl. - auto bind_result = runner->bind_callable_to_runtime(*r, callable_id); + BindCallableResult bind_result; + { + CHIP_TIMING_SCOPE(run_idx, "bind_callable"); + bind_result = runner->bind_callable_to_runtime(*r, callable_id); + } if (bind_result.rc != 0) { return bind_result.rc; } // Per-run binding (tensor args, GM heap, SM alloc) - rc = bind_callable_to_runtime_impl( - r, reinterpret_cast(args), bind_result.host_orch_func_ptr, - bind_result.signature, bind_result.sig_count, ring_task_window, ring_heap, ring_dep_pool - ); + { + CHIP_TIMING_SCOPE(run_idx, "bind_impl"); + rc = bind_callable_to_runtime_impl( + r, reinterpret_cast(args), bind_result.host_orch_func_ptr, + bind_result.signature, bind_result.sig_count, ring_task_window, ring_heap, ring_dep_pool + ); + } if (rc != 0) { r->set_gm_sm_ptr(nullptr); validate_runtime_impl(r); @@ -455,7 +474,10 @@ int run_prepared( runner->set_scope_stats_enabled(enable_scope_stats != 0); runner->set_output_prefix(output_prefix); - rc = runner->run(*r, block_dim, aicpu_thread_num); + { + CHIP_TIMING_SCOPE(run_idx, "runner_run"); + rc = runner->run(*r, block_dim, aicpu_thread_num); + } if (rc != 0) { validate_runtime_impl(r); return rc; @@ -468,12 +490,23 @@ int run_prepared( } } - rc = validate_runtime_impl(r); + { + CHIP_TIMING_SCOPE(run_idx, "validate"); + rc = validate_runtime_impl(r); + } if (out_timing != NULL) { const auto host_t1 = std::chrono::steady_clock::now(); out_timing->host_wall_ns = static_cast(std::chrono::duration_cast(host_t1 - host_t0).count()); out_timing->device_wall_ns = runner->last_device_wall_ns(); + CHIP_TIMING_HOST_EVENT( + run_idx, "run_prepared", 'E', + static_cast( + std::chrono::duration_cast(host_t1.time_since_epoch()).count() + ) + ); + CHIP_TIMING_HOST_WALL(run_idx, "host_wall", out_timing->host_wall_ns / 1000.0); + CHIP_TIMING_DEV_WALL(run_idx, "device_wall", out_timing->device_wall_ns / 1000.0); } return rc; } catch (...) { diff --git a/src/common/platform/sim/host/c_api_shared.cpp b/src/common/platform/sim/host/c_api_shared.cpp index 27fd72771..c0bc6eb76 100644 --- a/src/common/platform/sim/host/c_api_shared.cpp +++ b/src/common/platform/sim/host/c_api_shared.cpp @@ -41,6 +41,9 @@ #include "host/raii_scope_guard.h" #include "runtime.h" +#define CHIP_TIMING_HOST_SPANS +#include "common/chip_timing.h" + extern "C" { /* =========================================================================== @@ -355,6 +358,11 @@ int run_prepared( pthread_setspecific(g_runner_key, ctx); const auto host_t0 = std::chrono::steady_clock::now(); + const uint64_t run_idx = simpler::chip_timing::next_run(); + CHIP_TIMING_HOST_EVENT( + run_idx, "run_prepared", 'B', + static_cast(std::chrono::duration_cast(host_t0.time_since_epoch()).count()) + ); try { Runtime *r = new (runtime) Runtime(); @@ -376,17 +384,24 @@ int run_prepared( r->host_api.acquire_pooled_runtime_arena = acquire_pooled_runtime_arena_wrapper; r->host_api.upload_chip_callable_buffer = upload_chip_callable_buffer_wrapper; - auto bind_result = runner->bind_callable_to_runtime(*r, callable_id); + BindCallableResult bind_result; + { + CHIP_TIMING_SCOPE(run_idx, "bind_callable"); + bind_result = runner->bind_callable_to_runtime(*r, callable_id); + } int rc = bind_result.rc; if (rc != 0) { pthread_setspecific(g_runner_key, nullptr); return rc; } - rc = bind_callable_to_runtime_impl( - r, reinterpret_cast(args), bind_result.host_orch_func_ptr, - bind_result.signature, bind_result.sig_count, ring_task_window, ring_heap, ring_dep_pool - ); + { + CHIP_TIMING_SCOPE(run_idx, "bind_impl"); + rc = bind_callable_to_runtime_impl( + r, reinterpret_cast(args), bind_result.host_orch_func_ptr, + bind_result.signature, bind_result.sig_count, ring_task_window, ring_heap, ring_dep_pool + ); + } if (rc != 0) { r->set_gm_sm_ptr(nullptr); validate_runtime_impl(r); @@ -401,7 +416,10 @@ int run_prepared( runner->set_scope_stats_enabled(enable_scope_stats != 0); runner->set_output_prefix(output_prefix); - rc = runner->run(*r, block_dim, aicpu_thread_num); + { + CHIP_TIMING_SCOPE(run_idx, "runner_run"); + rc = runner->run(*r, block_dim, aicpu_thread_num); + } if (rc != 0) { validate_runtime_impl(r); pthread_setspecific(g_runner_key, nullptr); @@ -416,13 +434,24 @@ int run_prepared( } } - rc = validate_runtime_impl(r); + { + CHIP_TIMING_SCOPE(run_idx, "validate"); + rc = validate_runtime_impl(r); + } pthread_setspecific(g_runner_key, nullptr); if (out_timing != NULL) { const auto host_t1 = std::chrono::steady_clock::now(); out_timing->host_wall_ns = static_cast(std::chrono::duration_cast(host_t1 - host_t0).count()); out_timing->device_wall_ns = runner->last_device_wall_ns(); + CHIP_TIMING_HOST_EVENT( + run_idx, "run_prepared", 'E', + static_cast( + std::chrono::duration_cast(host_t1.time_since_epoch()).count() + ) + ); + CHIP_TIMING_HOST_WALL(run_idx, "host_wall", out_timing->host_wall_ns / 1000.0); + CHIP_TIMING_DEV_WALL(run_idx, "device_wall", out_timing->device_wall_ns / 1000.0); } return rc; } catch (...) { diff --git a/tests/ut/py/test_chip_timing.py b/tests/ut/py/test_chip_timing.py new file mode 100644 index 000000000..735a16bdd --- /dev/null +++ b/tests/ut/py/test_chip_timing.py @@ -0,0 +1,139 @@ +# Copyright (c) PyPTO Contributors. +# This program is free software, you can redistribute it and/or modify it under the terms and conditions of +# CANN Open Software License Agreement Version 2.0 (the "License"). +# Please refer to the License for details. You may not use this file except in compliance with the License. +# THIS SOFTWARE IS PROVIDED ON AN "AS IS" BASIS, WITHOUT WARRANTIES OF ANY KIND, EITHER EXPRESS OR IMPLIED, +# INCLUDING BUT NOT LIMITED TO NON-INFRINGEMENT, MERCHANTABILITY, OR FITNESS FOR A PARTICULAR PURPOSE. +# See LICENSE in the root of the software repository for the full text of the License. +# ----------------------------------------------------------------------------------------------------------- +"""Tests for simpler_setup.tools.chip_timing — the [CHIP_TIMING] log parser (issue #1012).""" + +from simpler_setup.tools.chip_timing import assemble, parse_lines, render + +# A host log: one run_prepared envelope wrapping 5 sequential stages, plus the +# two authoritative WALL baselines. The log prefix is decorative — only the +# [CHIP_TIMING] substring matters. Timestamps in ns (steady_clock). +HOST_LINES = [ + "[V4] f: [CHIP_TIMING] run=0 clk=host name=run_prepared ev=B t=1000000000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=attach ev=B t=1000100000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=attach ev=E t=1000200000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=bind_callable ev=B t=1000200000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=bind_callable ev=E t=1001200000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=bind_impl ev=B t=1001200000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=bind_impl ev=E t=1101200000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=runner_run ev=B t=1101200000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=runner_run ev=E t=1121200000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=validate ev=B t=1121200000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=validate ev=E t=1121250000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=run_prepared ev=E t=1121300000", + "[V4] f: [CHIP_TIMING] run=0 clk=host name=host_wall ev=WALL us=121300.000", + "[V4] f: [CHIP_TIMING] run=0 clk=dev name=device_wall ev=WALL us=19850.000", +] + +# A device log line as the CANN dlog backend renders it: the message is wrapped +# in quotes (note the trailing "), exercising the value-parsing regression. +# aicpu_wall spans init-start..last-thread-exit; aicpu_exec is the inner window. +# Two exec threads (tids) exercise the min-B/max-E reduction. +DEV_LINES = [ + '[INFO] AICPU: 31125 init [V4] "[CHIP_TIMING] clk=dev name=aicpu_wall ev=B tid=31125 t=500000000"', + '[INFO] AICPU: 31126 exec [V4] "[CHIP_TIMING] clk=dev name=aicpu_exec ev=B tid=31126 t=500100000"', + '[INFO] AICPU: 31127 exec [V4] "[CHIP_TIMING] clk=dev name=aicpu_exec ev=B tid=31127 t=500150000"', + '[INFO] AICPU: 31126 exec [V4] "[CHIP_TIMING] clk=dev name=aicpu_exec ev=E tid=31126 t=519600000"', + '[INFO] AICPU: 31127 exec [V4] "[CHIP_TIMING] clk=dev name=aicpu_exec ev=E tid=31127 t=519700000"', + '[INFO] AICPU: 31126 exec [V4] "[CHIP_TIMING] clk=dev name=aicpu_wall ev=E tid=31126 t=519800000"', + '[INFO] AICPU: 31127 exec [V4] "[CHIP_TIMING] clk=dev name=aicpu_wall ev=E tid=31127 t=519850000"', +] + + +def _host_spans(): + reports = assemble(parse_lines(HOST_LINES)) + assert len(reports) == 1 + return {s.name: s for s in reports[0].host_spans}, reports[0] + + +def test_host_stage_durations_and_nesting(): + spans, _ = _host_spans() + # ns deltas -> ms. + assert spans["attach"].dur_ns == 100_000 + assert spans["bind_callable"].dur_ns == 1_000_000 + assert spans["bind_impl"].dur_ns == 100_000_000 + assert spans["runner_run"].dur_ns == 20_000_000 + assert spans["validate"].dur_ns == 50_000 + # run_prepared is the root (depth 0); the 5 stages are depth 1. + assert spans["run_prepared"].depth == 0 + for name in ("attach", "bind_callable", "bind_impl", "runner_run", "validate"): + assert spans[name].depth == 1 + + +def test_host_wall_reconciliation(): + _, rep = _host_spans() + root = next(s for s in rep.host_spans if s.name == "run_prepared") + # run_prepared envelope == host_wall baseline exactly (same clock). + assert root.dur_ns == 121_300_000 + assert rep.host_wall_ns == 121_300_000 + assert rep.device_wall_ns == 19_850_000 + + +def test_device_reduction_min_b_max_e(): + reports = assemble(parse_lines(DEV_LINES)) + assert len(reports) == 1 + spans = {s.name: s for s in reports[0].dev_spans} + # aicpu_wall: min B (500000000) .. max E (519850000). + assert spans["aicpu_wall"].dur_ns == 19_850_000 + # aicpu_exec: min B over tids (500100000) .. max E over tids (519700000). + assert spans["aicpu_exec"].dur_ns == 19_600_000 + # aicpu_exec nested under aicpu_wall. + assert spans["aicpu_wall"].depth == 0 + assert spans["aicpu_exec"].depth == 1 + + +def test_device_rounds_segmented_by_tid_reappearance(): + # Two back-to-back runs: tid 31125's second 'B' opens a new round. + two_runs = DEV_LINES + DEV_LINES + reports = assemble(parse_lines(two_runs)) + assert len(reports) == 2 + for rep in reports: + names = {s.name for s in rep.dev_spans} + assert names == {"aicpu_wall", "aicpu_exec"} + + +def test_combined_host_and_device_single_run(): + reports = assemble(parse_lines(HOST_LINES + DEV_LINES)) + assert len(reports) == 1 + rep = reports[0] + assert rep.run == 0 + assert any(s.name == "run_prepared" for s in rep.host_spans) + assert any(s.name == "aicpu_wall" for s in rep.dev_spans) + + +def test_missing_end_degrades_with_note(): + lines = [ + "[..][V4] f: [CHIP_TIMING] run=0 clk=host name=run_prepared ev=B t=1000000000", + "[..][V4] f: [CHIP_TIMING] run=0 clk=host name=attach ev=B t=1000100000", + # no attach E, no run_prepared E + ] + reports = assemble(parse_lines(lines)) + assert reports[0].notes # at least one "missing end" note + assert any("missing end" in n for n in reports[0].notes) + + +def test_quoted_device_value_parses_trailing_quote(): + # Regression: CANN dlog wraps the message in quotes; the last field must not + # swallow the closing quote. + events = parse_lines(DEV_LINES[:1]) + assert len(events) == 1 + assert events[0].t_ns == 500_000_000 + assert events[0].tid == 31125 + + +def test_render_contains_tree_and_reconciliation(): + text = render(assemble(parse_lines(HOST_LINES + DEV_LINES))) + assert "run_prepared" in text + assert "host_wall" in text # reconciliation suffix + assert "device_wall" in text + assert "aicpu_wall" in text + assert "(unattributed)" in text + + +def test_no_chip_timing_lines_yields_no_events(): + assert parse_lines(["just some unrelated log line", "[INFO] hello world"]) == []