Fix: adapt host build graph swimlane clock alignment

docs/dfx/host-trace.md

@@ -28,10 +28,24 @@ initialization-time policy described in [logging.md](../logging.md).
 
 The host logger writes to stderr until it is given a directory, and then it
 writes to `<directory>/host.<pid>.log` instead. The directory is
-`CallConfig.output_prefix` — the one every other diagnostic artifact already goes
-under — so a run that has one gets its host log beside its other artifacts, and a
-run that does not keeps its records on the console. There is no separate switch to
-configure, and the runtime never derives the path itself.
+`<CallConfig.output_prefix>` when configured through Worker. The first
+non-empty prefix wins for the process; later runs keep writing to that directory.
+Until a prefix is bound, records stay on the console. There is no separate
+switch to configure.
+
+After successful execution and validation of an HBG level-3/4 capture with Host
+recording armed and finished and an output prefix, native finalize
+flushes the executing process's log and exports a capture-local
+`host_clock_alignment.<pid>.log` beside the raw swimlane file, before completion
+is published. Level 4 enables Host records automatically; level 3 requires the
+independent `SIMPLER_HBG_HOST_PHASE_RECORDS_ENABLE=1` switch and an output prefix.
+This works for direct L2 and forked ChipWorker runs without SceneTest. The file
+contains only the current invocation's original alignment spans and is not the
+persistent logger destination. It requires TIMING-or-finer logging. Use the
+persistent `host.<pid>.log` files for ordinary messages or the complete Host call
+tree. The AICPU-launch marker is a TIMING Host-clock point sampled immediately
+before the launch API call (`dur=0`, `depth=2`), not a Device-start or
+launch-completion timestamp.
 
 **The destination belongs to the logger, not to a record.** Everything that logger
 writes follows it: `LOG_*` records, `[STRACE]` spans, `[CLOCK_ANCHOR]`, the
@@ -230,7 +244,7 @@ including time the caller spends polling or doing other host work; blocking
 | ----- | ---------- |
 | 0 | `chip.run` |
 | 1 | `chip.run.bind`, `chip.run.runner_run`, `chip.run.claim_release`, `chip.run.validate` |
-| 2 | `chip.run.bind.args`, `chip.run.bind.prebuilt`, the other HBG `chip.run.bind.*` segments, `chip.run.runner_run.device_wall` |
+| 2 | `chip.run.bind.args`, `chip.run.bind.prebuilt`, the other HBG `chip.run.bind.*` segments, `chip.run.runner_run.aicpu_launch` (onboard point), `chip.run.runner_run.device_wall` |
 | 3 | TMR phase spans `chip.run.runner_run.device_wall.{preamble,so_load,graph_build,config_validate,arena_wire,sm_reset,post_orch,orch,sched}` and optional `task_slot_*` spans |
 
 ## Host scheduler spans

docs/logging.md

@@ -224,7 +224,10 @@ exposes the drop counter to diagnostics and tests, while
 `_host_log_pending_records()` distinguishes accepted work still waiting for the
 writer. Python and C++ flush defaults are both 1000 ms. Teardown and `os._exit()`
 paths report a timeout with both counters instead of silently abandoning the
-accepted backlog.
+accepted backlog. Bound runtime DSOs can also flush the current process writer
+using the shared counters. A successful flush means the accepted queue was drained;
+write failures are counted separately as drops, and flush does not call `fsync`.
+It does not drain another process's writer.
 
 ### Attributing a drop, and saying so in the log
 

python/simpler/worker.py

@@ -2950,6 +2950,13 @@ def read_task_config(
         diagnostic_capture_index += 1
         return cfg
 
+    def finish_task_logging(cfg: CallConfig | None, code: int, msg: str) -> tuple[int, str]:
+        # TASK_DONE permits the parent to read this child's completed invocation.
+        if cfg is not None and cfg.enable_chip_swimlane and cfg.output_prefix:
+            if not _flush_host_log_or_warn(f"chip_process dev={device_id}: task completion"):
+                return 1, msg or f"chip_process dev={device_id}: diagnostic Host log flush failed"
+        return code, msg
+
     def handle_task(task_buf) -> tuple[int, str]:
         task_addr = ctypes.addressof(ctypes.c_char.from_buffer(task_buf))
         digest = _read_task_digest(task_buf)
@@ -2958,6 +2965,7 @@ def handle_task(task_buf) -> tuple[int, str]:
 
         code = 0
         msg = ""
+        cfg = None
         try:
             # Inside the try because it writes the diagnostic sidecar: a full or
             # read-only output_prefix must surface as this task's error, not as
@@ -3010,7 +3018,7 @@ def handle_task(task_buf) -> tuple[int, str]:
         # staging garbage would mask the real error in post-mortems.
         if code == 0 and on_task_done_success is not None:
             code, msg = on_task_done_success()
-        return code, msg
+        return finish_task_logging(cfg, code, msg)
 
     def handle_control(  # noqa: PLR0912, PLR0915 -- one branch per control sub-command
         sub_cmd: int,
@@ -3351,6 +3359,7 @@ def submit_frame(frame: _StagedFrame) -> None:
                                 except Exception as e:  # noqa: BLE001
                                     code = 1
                                     msg = _format_exc(f"chip_process dev={device_id}: task completion hook", e)
+                            code, msg = finish_task_logging(staged.config, code, msg)
                             _write_error(staged.frame_buf, code, msg)
                             _mailbox_store_i32(
                                 staged.frame_addr + _OFF_STATE,
@@ -11254,6 +11263,12 @@ def run(self, callable, args=None, config=None) -> None:
     def _submit_locked(self, callable, args, config) -> RunHandle:
         cfg = config if config is not None else CallConfig()
 
+        # The first non-empty output prefix binds the persistent process log.
+        # Capture-local timing exports use separate files in each run's prefix.
+        log_directory = getattr(cfg, "output_prefix", "")
+        if log_directory:
+            _native_set_host_log_directory(log_directory)
+
         if self.level == 2:
             assert self._chip_worker is not None
             state = self._resolve_handle(callable, expected_namespace="LOCAL_CHIP")
@@ -11515,13 +11530,6 @@ def _chip_run_for(self, run_id: int) -> Any | None:
     def _submit_l3_locked(self, callable, args, cfg: CallConfig) -> RunHandle:
         assert self._orch is not None
         assert self._worker is not None
-        # This process's log belongs beside the run's other diagnostic artifacts,
-        # so the directory comes from the config that already names it. First one
-        # in a process wins; with no prefix the logger stays on stderr. Read
-        # defensively: wiring an output must never be what fails a submit.
-        log_directory = getattr(cfg, "output_prefix", "")
-        if log_directory:
-            _native_set_host_log_directory(log_directory)
         run_id = self._orch._begin_run()
         resources = _RunResources()
         handle = RunHandle(self, run_id, (callable, args, cfg), resources)

simpler_setup/scene_test.py

@@ -1200,6 +1200,7 @@ def _run_swimlane_converter(
     input_path: Path | None = None,
     func_names_path: Path | None = None,
     enable_overhead: bool = False,
+    host_logs: list[Path] | None = None,
     *,
     dispatch: str | None = None,
     dispatch_id: str | None = None,
@@ -1234,12 +1235,16 @@ def _run_swimlane_converter(
         cmd += ["--dispatch-id", dispatch_id]
     if output_path is not None:
         cmd += ["--output", str(output_path)]
+    for host_log in host_logs or []:
+        cmd += ["--host-log", str(host_log)]
     if enable_overhead:
         cmd.append("--overhead")
     try:
         result = subprocess.run(cmd, check=True, capture_output=True, text=True)
         if result.stdout:
             logger.info(result.stdout)
+        if result.stderr:
+            logger.warning(result.stderr.strip())
         logger.info("Swimlane JSON generation completed")
         return True
     except subprocess.CalledProcessError as e:
@@ -1251,6 +1256,22 @@ def _run_swimlane_converter(
         return False
 
 
+def _bound_host_logs() -> list[Path]:
+    """Flush this process and locate the persistent process logs without copying."""
+    try:
+        from _task_interface import _host_log_directory  # noqa: PLC0415  # pyright: ignore[reportMissingImports]
+    except ImportError:
+        return []
+    bound = _host_log_directory()
+    if not bound:
+        return []
+    from simpler.task_interface import _flush_host_log_or_warn  # noqa: PLC0415
+
+    if not _flush_host_log_or_warn("SceneTest Host log conversion"):
+        return []
+    return sorted(Path(bound).glob("host.*.log"))
+
+
 def _sanitize_for_filename(s: str) -> str:
     return "".join(c if c.isalnum() or c in "._-" else "_" for c in s)
 
@@ -1283,6 +1304,7 @@ def _convert_rank_swimlanes(
     callable_spec: dict | None,
     enable_overhead: bool,
     logger: logging.Logger,
+    host_logs: list[Path] | None = None,
 ) -> None:
     """Convert the ``rankN/dN`` captures below one L3 case prefix.
 
@@ -1325,6 +1347,7 @@ def dump_name_map(capture_dir: Path) -> Path | None:
             dump_name_map(capture_dir)
         merged = _run_swimlane_converter(
             input_path=output_prefix,
+            host_logs=host_logs,
             enable_overhead=enable_overhead,
             dispatch=target["dispatch"],
             dispatch_id=target["dispatch_id"],
@@ -1334,6 +1357,7 @@ def dump_name_map(capture_dir: Path) -> Path | None:
             for capture_dir in target["capture_dirs"]:
                 _run_swimlane_converter(
                     input_path=capture_dir / "chip_swimlane_records.json",
+                    host_logs=host_logs,
                     func_names_path=dump_name_map(capture_dir),
                     enable_overhead=enable_overhead,
                 )
@@ -1356,12 +1380,25 @@ def _convert_case_swimlane(
 
     logger = logging.getLogger(__name__)
     if _rank_dirs(output_prefix):
+        captures = [
+            directory
+            for directory in _rank_capture_dirs(output_prefix)
+            if (directory / "chip_swimlane_records.json").is_file()
+        ]
+        # Runtime-exported timing logs allow capture-local lookup when all are present.
+        # Other Rank merges use the bound persistent logs.
+        host_logs = (
+            None
+            if captures and all(list(path.glob("host_clock_alignment.*.log")) for path in captures)
+            else _bound_host_logs()
+        )
         _convert_rank_swimlanes(
             case_label,
             output_prefix,
             callable_spec=callable_spec,
             enable_overhead=enable_overhead,
             logger=logger,
+            host_logs=host_logs,
         )
         return
 

simpler_setup/tools/README.md

@@ -167,14 +167,56 @@ python -m simpler_setup.tools.swimlane_converter build_output/<case>/dfx_outputs
     --dispatch-id 17:5 -o build_output/<case>/dfx_outputs/l3_swimlane.json
 ```
 
+For level-3/4 `host_build_graph` captures containing Host records or Host capture
+metadata, single-file conversion attempts containment when matching Host logs are
+available beside the capture (or supplied with `--host-log`). Level 4 enables
+Host records automatically; level 3 can include them through
+`SIMPLER_HBG_HOST_PHASE_RECORDS_ENABLE=1` with an output prefix. Levels 1-2 and
+Device-only single-file captures, including TMR captures, skip this step.
+This runs inside `swimlane_converter.py`; no additional command is needed. It saves
+`metadata.clock_alignment` in the source JSON, so subsequent conversion and IDE
+readers that consume this field can use that one file without logs. Device-only
+single-file conversion does not compute containment or rewrite its source.
+Missing or unusable logs skip
+alignment; a valid saved mapping is reused. Raw timestamps are preserved.
+The saved object contains only `status`, `device_anchor_cycles`, `host_anchor_ns`,
+`host_anchor_min_ns`, and `host_anchor_max_ns`. Frequency comes from the capture
+metadata and uncertainty is the upper bound minus the lower bound. Unavailable
+alignment contains `status` and `reason`. Saved mappings assume unchanged raw
+capture data; full placement diagnostics stay in traces calculated from logs.
+Worker binds cumulative process logs to the first output prefix as `host.<pid>.log`.
+After successful execution and validation of a mixed HBG capture with Host
+recording armed and finished and an output prefix, native finalize flushes the
+executing process's
+accepted Host-log records and atomically exports that invocation's original timing
+spans as `host_clock_alignment.<pid>.log` beside the capture before publishing
+completion. Direct L2 and forked ChipWorker executions share this path, so ST,
+PyPTO, pypto-lib, and models using these execution paths need no SceneTest log
+preparation. The exporter starts at the file position recorded before the invocation,
+filters by its PID/invocation, and keeps the complete process log unchanged.
+Other diagnostic flags and Device-only captures do not trigger this export.
+TIMING-or-finer logging is required; coarser logging warns and skips export.
+Flush or artifact-export failures are reported as diagnostic errors.
+A TIMING `chip.run.runner_run.aicpu_launch` marker raises the Device placement
+lower bound to the later of the runner start and launch. Required Host spans
+need a TIMING-or-finer log threshold. The remaining interval bounds placement
+freedom; saved anchor bounds also include phase-join freedom. Old logs without
+the marker retain the original containment bounds.
+Directory conversion also saves alignment metadata in mixed HBG source captures.
+The converter reads runtime-exported timing logs and does not create them.
+See [the single-capture schema](../../docs/dfx/chip-swimlane-profiling.md#optional-alignment-embedded-in-a-single-capture).
+
 Directory mode puts the Ranks on one axis by containment, not by calibration:
 each Rank's device work is placed inside the `chip.run.runner_run` window that
-held it, read from the run's `host.<pid>.log`. It therefore needs those logs
-(`--host-log` overrides the default of every `host.*.log` beside the captures)
-and works at any capture level. Every drawn slice carries the `slack_ns` its Rank was placed under, each
-Rank's metadata carries the full `placement` record, and the top level carries
-`cross_rank_uncertainty_ns` — the sum of the two widest, which bounds any
-interval read between two Ranks. See
+held it, read from persistent or capture-local timing logs. Default lookup reads
+`host.*.log` and `host_clock_alignment.*.log` directly under the input directory,
+plus `rank*/d*/host_clock_alignment.*.log` (`--host-log` overrides this lookup)
+and works at any capture level. Device slices carry their Rank's `slack_ns`.
+Each Rank's metadata carries the full `placement` record, and the top level carries
+`cross_rank_uncertainty_ns` — the sum of the two widest slacks, bounding
+placement freedom between two Ranks for their selected joins. Phase-join freedom
+is reported separately as `join.residual_ns` and must also be considered when
+interpreting cross-Rank gaps. See
 [`containment.py`](containment.py) for the mechanism.
 
 The merged trace also carries the processes that dispatched to the Ranks —
@@ -259,7 +301,7 @@ SPMD tasks are present.
 | `--output` | `-o` | Output JSON file (default: `merged_swimlane.json` beside a file input, `l3_swimlane.json` inside a directory input) |
 | `--dispatch` | | Directory mode only: local capture directory to merge across Ranks, e.g. `d0`. Mutually exclusive with `--dispatch-id` |
 | `--dispatch-id` | | Directory mode only: parent dispatch identity to merge, formatted `RUN_ID:TASK_SLOT`. Resolves each Rank's own `dN` through `dispatch_identity.json`. Mutually exclusive with `--dispatch` |
-| `--host-log` | | Directory mode: Host `[STRACE]` log holding the `chip.run.runner_run` windows the captures are placed in (repeatable). Defaults to every `host.*.log` in the input directory |
+| `--host-log` | | Host `[STRACE]` log holding the `chip.run.runner_run` windows (repeatable). Single-file mode prefers sibling `host_clock_alignment.*.log`, falling back to `host.*.log`; directory mode reads both at the root plus `rank*/d*/host_clock_alignment.*.log`. An explicit argument recalculates single-file alignment |
 | `--rank-pid` | | Directory mode: pin one Rank's capture to the Host invocation that ran it, `RANK=PID` or `RANK=PID:INV` (repeatable). Only needed when the captures carry no `dispatch_identity.json` and Ranks running the same shape cannot be told apart by their device windows |
 | `--kernel-config` | `-k` | Path to kernel_config.py, used for function name mapping. Rejected in directory mode |
 | `--func-names` | | Path to name_map*.json (SceneTest format) for function name mapping. Rejected in directory mode |