Add: expose L3/L4 host scheduling swimlane

.claude/rules/project-layout.md

@@ -11,8 +11,13 @@ How this repo organizes Python packages, the build system, and example / test di
 | `_task_interface` | `python/bindings/` | nanobind `.so` at wheel root | Internal nanobind module |
 
 `simpler` exposes `Worker` and the `task_interface` submodule lazily (PEP 562
-`__getattr__`), so `from simpler import Worker` works while `import simpler`
-still costs nothing and does not require the `_task_interface` extension.
+`__getattr__`), so `from simpler import Worker` works while `import simpler` does
+not require the `_task_interface` extension. Import time is not quite free: it
+dlopens `build/lib/libsimpler_log.so` into the global symbol scope (~3 ms when
+that library is built, ~25 µs when it is not), which must precede the first
+worker fork. When `_task_interface` is available, `_log` passes the logger's
+host-span entry point into the extension's nullable, extension-local sink slot. The dlopen and
+binding are best-effort and raise nothing — see `python/simpler/_log_preload.py`.
 `simpler.task_interface.ChipTensor` is the GM-address-bearing device descriptor
 a `ChipWorker` consumes; `simpler_setup.TensorArg` is the address-free
 scene-test arg spec `NamedTuple`. They are separate types in separate

docs/dfx/host-trace.md

@@ -40,6 +40,12 @@ One line per span, emitted on scope exit
 | `ts` `dur` | start + duration in ns. Maps 1:1 onto a Chrome-trace `"X"` event. For host spans `ts` is `CLOCK_MONOTONIC` (`steady_clock`), same-host cross-process comparable. For `clk=dev` device spans (see below) `ts` is instead a **device-clock** start offset on a per-invocation origin — comparable to the other device spans (so the orch∪sched window is recoverable), not the host clock. |
 | `k=v ...` | optional per-span attributes (e.g. `ntensor=4`); a parser that doesn't recognize one ignores it. |
 
+Span names and attributes percent-encode control bytes and record delimiters.
+They are length-capped (with `~` marking truncation) so each marker remains a
+single atomic pipe write even when forked workers share captured stderr.
+`strace_timing.py` decodes both on the way back in, so a consumer reading its
+output sees the original text; a consumer reading the raw log does not.
+
 ## Span tree
 
 ```text
@@ -82,22 +88,76 @@ including time the caller spends polling or doing other host work; blocking
 | 2 | `simpler_run.bind.args`, `simpler_run.bind.prebuilt`, `simpler_run.runner_run.device_wall` |
 | 3 | `simpler_run.runner_run.device_wall.{preamble,so_load,graph_build,config_validate,arena_wire,sm_reset,post_orch,orch,sched,task_slot_*}` |
 
+## L3/L4 host scheduler spans
+
+Every hierarchical worker that drives next-level children emits these spans
+through the same process-global `libsimpler_log.so` sink — an L3 with chips and
+an L4 pod alike, since the orchestrator and scheduler code they run is the same:
+
+| Span | Host decision point |
+| ---- | ------------------- |
+| `l3.graph_build` | serialized Python graph callback |
+| `l3.submit` | next-level task publication after slot allocation |
+| `l3.dispatch` | scheduler handoff to a worker thread |
+| `l3.frame_submit` | local child mailbox-frame publication |
+| `l3.activate` | prepared-frame activation |
+| `l3.complete` | terminal child progress handling |
+
+Their attributes carry the available `run_id`, `task_slot`, `group_index`,
+`worker_id`, `dispatch_id`, and endpoint kind.
+
+Because the names do not encode which level emitted them, a pod run puts the L4
+process and each of its L3 processes on lanes that differ only by pid. The
+per-level vocabulary that resolves this is tracked in
+[#1793](https://github.com/hw-native-sys/simpler/issues/1793).
+
+One process contributes at most two host lanes, because the scheduler runs on
+one thread: the facade thread emits `l3.graph_build` and `l3.submit`, and the
+scheduler thread emits the other four. `role=worker` on `l3.frame_submit`,
+`l3.activate` and `l3.complete` names the worker a dispatch targets, not the
+thread that ran it.
+
+The spans reach the logger over a fixed POD C ABI, `SimplerHostSpan` in
+`common/host_span.h`. `_task_interface` cannot link `libsimpler_log.so` — that
+library is reached by `RTLD_GLOBAL` dlopen at runtime — so each extension/DSO
+owns its own nullable sink function pointer instead of an undefined link symbol.
+`simpler._log_preload` loads the library, and `simpler._log` passes the exported
+entry-point address into `_task_interface` before Worker initialization. Every later
+`fork()` therefore inherits the bound pointer and logger mapping, so parent and
+child markers reach one sink. A process that never loads the logger leaves the
+extension-local pointer null, which disables host spans without failing anything. A later
+`ChipWorker.init` refreshes the binding after loading the required runtime
+logger. `host_runtime.so` links the library directly and needs none of this.
+
 ## Reading the markers — `strace_timing.py`
 
 ```bash
 # TPOT table (per-callable, decode = most-invoked hid bucket)
 python -m simpler_setup.tools.strace_timing path/to/host_or_device.log
 
-# also emit a Chrome-trace / Perfetto JSON (lane = pid → host call tree)
+# also emit the established per-invocation call-tree JSON
 python -m simpler_setup.tools.strace_timing path/to/log --trace-out strace.json
+
+# emit the L3/L4 host scheduler timeline on real OS pid/tid lanes
+python -m simpler_setup.tools.strace_timing path/to/log --swimlane host_swimlane.json
 ```
 
 The tool groups by `(pid, inv)`, rebuilds each invocation's tree from `depth`,
 buckets by `hid`, and prints each callable's mean `simpler_run` plus per-stage
-means. With `--trace-out` it writes one `ph:"X"` event per span keyed by pid, so
-the L3 parent and each L2 child render as separate lanes in
+means. With `--trace-out` it writes one `ph:"X"` event per span on a synthetic
+per-invocation lane, so each call renders as an isolated nested tree in
 [Perfetto](https://ui.perfetto.dev) / `chrome://tracing`.
 
+`--swimlane` is a separate view. Host slices keep their real OS pid/tid, and
+task submission-to-dispatch handoffs render as flow arrows. Chrome Trace JSON
+has only one visible timestamp axis, so putting the raw per-invocation device
+clock beside `CLOCK_MONOTONIC` would create a multi-day empty interval. The
+converter therefore keeps `clk=dev` records, with their original ns timestamps,
+in the top-level `unalignedDeviceSpans` array instead of `traceEvents`; it does
+not guess a clock offset. Perfetto opens directly on the host activity, while
+the existing tables, tree, and `--trace-out` still provide the device-phase
+timing views.
+
 ## Why markers, not a return value
 
 Android's atrace writes to the ftrace `trace_marker` sink and systrace renders

python/bindings/CMakeLists.txt

@@ -65,6 +65,7 @@ target_include_directories(_task_interface PRIVATE
     ${CMAKE_SOURCE_DIR}/src/common/platform/include
     ${CMAKE_SOURCE_DIR}/src/common/platform/include/common
     ${CMAKE_SOURCE_DIR}/src/common/platform/include/host
+    ${CMAKE_SOURCE_DIR}/src/common/log/include
     ${CMAKE_CURRENT_SOURCE_DIR}
 )
 

python/bindings/task_interface.cpp

@@ -56,6 +56,7 @@
 #include "callable_protocol.h"
 #include "chip_run_lane.h"
 #include "chip_worker.h"
+#include "common/host_span_scope.h"
 #include "data_type.h"
 #include "dma_workspace.h"
 #include "worker_chip_orch_comm.h"
@@ -993,6 +994,35 @@ NB_MODULE(_task_interface, m) {
     m.attr("MAX_TENSOR_DIMS") = MAX_TENSOR_DIMS;
     m.attr("MAX_REGISTERED_CALLABLE_IDS") = MAX_REGISTERED_CALLABLE_IDS;
     m.attr("RUNTIME_ENV_RING_COUNT") = RUNTIME_ENV_RING_COUNT;
+#if SIMPLER_HOST_STRACE
+    m.attr("HOST_STRACE_ENABLED") = true;
+#else
+    m.attr("HOST_STRACE_ENABLED") = false;
+#endif
+    m.def(
+        "_bind_host_span_sink",
+        [](uintptr_t address) {
+            simpler::host_trace::bind_sink(reinterpret_cast<SimplerLogEmitHostSpanFn>(address));
+            return simpler::host_trace::sink_available();
+        },
+        nb::arg("address"), "Bind this extension's host-span sink to the process-global logger, or zero to disable it."
+    );
+    m.def(
+        "_host_span_sink_available", &simpler::host_trace::sink_available,
+        "Whether this extension's host-span sink is bound to the process-global logger."
+    );
+    m.def(
+        "_emit_host_span",
+        [](const std::string &name, uint64_t invocation_id, uint64_t callable_hash, int32_t depth, int64_t timestamp_ns,
+           int64_t duration_ns, const std::string &attributes) {
+            simpler::host_trace::emit(
+                name.c_str(), invocation_id, callable_hash, depth, timestamp_ns, duration_ns, attributes.c_str()
+            );
+        },
+        nb::arg("name"), nb::arg("invocation_id"), nb::arg("callable_hash"), nb::arg("depth"), nb::arg("timestamp_ns"),
+        nb::arg("duration_ns"), nb::arg("attributes") = "",
+        "Emit one explicitly timed host span through this extension's bound logger sink."
+    );
     // Byte size of a ChipTensor and the offset of its address_space field within it.
     // A task-args blob stores ChipTensors as a raw memcpy array, so a Python-side
     // blob walker locates tensor i's fields at i * CHIP_TENSOR_STRIDE_BYTES without

python/simpler/__init__.py

@@ -8,13 +8,17 @@
 # -----------------------------------------------------------------------------------------------------------
 """Simpler runtime — public Python surface.
 
-Host-side log filter setup happens in `ChipWorker.init` (see
-`simpler.task_interface`): it `ctypes.CDLL`s libsimpler_log.so RTLD_GLOBAL,
-calls its `simpler_log_init` C entry to seed the process-wide HostLogger, then
-hands off to the C++ `_ChipWorker.init` which dlopens host_runtime.so (whose
-`simpler_init` reads CANN dlog config off that same HostLogger, onboard only).
-The level forwarded is a one-shot snapshot of the `simpler` Python logger.
-Nothing log-related needs to happen at import time here.
+Host-side log filter setup happens during worker initialization. A hierarchical
+`Worker` seeds the parent before its first fork; `ChipWorker.init` (see
+`simpler.task_interface`) repeats that initialization in each child before the
+C++ `_ChipWorker.init` dlopens host_runtime.so. The level forwarded is a
+one-shot snapshot of the `simpler` Python logger, and onboard `simpler_init`
+maps it onto CANN's coarser dlog ladder.
+Import time here only dlopens libsimpler_log.so into the global symbol scope
+(`simpler._log_preload`, reached through `._log` below); no level is seeded and
+no failure is raised if the library is absent. When `_task_interface` is
+available, `_log` passes the logger entry point into the extension's nullable,
+extension-local host-span sink slot before Worker initialization.
 
 `Worker` and the `task_interface` submodule resolve on first attribute access
 rather than at import time: both pull in the `_task_interface` extension, so

python/simpler/_log.py

@@ -12,23 +12,40 @@
 INFO and WARN and is the default so stable performance markers remain visible
 without enabling ordinary INFO traffic. NUL is a suppression sentinel.
 
-`Worker.init()` snapshots the effective ``simpler`` logger threshold and
-forwards it to `ChipWorker.init()` once. The Python wrapper seeds the
-process-wide HostLogger before the C++ side loads host_runtime.so; onboard
+`Worker.init()` snapshots the effective ``simpler`` logger threshold. A
+hierarchical worker seeds the parent process before its first fork, and every
+`ChipWorker.init()` seeds its child before loading host_runtime.so; onboard
 setup maps the same threshold onto CANN's coarser severity ladder.
 """
 
 import logging
 
+from ._log_preload import host_span_sink_address as _host_span_sink_address
+from ._log_preload import preload as _preload_simpler_log
+
+# Load the logger mapping before probing the extension below. ``simpler``
+# imports this module eagerly; once the extension is available, its local sink
+# slot is therefore bound before Worker initialization can fork.
+_host_log_handle = _preload_simpler_log()
+
 # DEFAULT_LOG_THRESHOLD is exposed by the _task_interface nanobind module so
 # Python and C++ share one constant. During a fresh `pip install -e .` the
 # pre-existing .so may be stale or absent, so fall back to the hardcoded
 # value (kept in sync manually with src/common/log/include/common/log_level.h).
 try:
-    from _task_interface import DEFAULT_LOG_THRESHOLD as _NATIVE_DEFAULT  # pyright: ignore[reportMissingImports]
+    from _task_interface import (  # pyright: ignore[reportMissingImports]
+        DEFAULT_LOG_THRESHOLD as _NATIVE_DEFAULT,
+    )
 except (ImportError, AttributeError):
     _NATIVE_DEFAULT = 25
 
+try:
+    from _task_interface import _bind_host_span_sink  # pyright: ignore[reportMissingImports]
+except (ImportError, AttributeError):
+    pass
+else:
+    _bind_host_span_sink(_host_span_sink_address(_host_log_handle))
+
 # Public verbosity constants (Python integer levels).
 TIMING = 25
 NUL = 60

python/simpler/_log_preload.py

@@ -0,0 +1,99 @@
+# 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.
+# -----------------------------------------------------------------------------------------------------------
+
+"""Put ``libsimpler_log.so`` in the process-global symbol scope.
+
+The logger has to be loaded before host runtimes and before workers fork. The
+package's earliest ``_task_interface`` import also passes its host-span entry
+point into the extension, where a nullable function pointer provides the
+cross-platform optional-sink contract.
+
+A missing library leaves that pointer null, which disables host spans and fails
+nothing. The path is resolved with ``find_spec`` rather than by importing
+``simpler_setup.environment``: locating the package does not execute it, so
+``import simpler`` does not pull in the compiler-side surface for a diagnostic.
+"""
+
+from __future__ import annotations
+
+import ctypes
+import functools
+import importlib.util
+import os
+from pathlib import Path
+
+_LIBRARY_NAME = "libsimpler_log.so"
+
+# RTLD_GLOBAL dlopen registry, keyed by path. host_runtime.so and the sim context
+# resolve against these globals, so each must be loaded exactly once before any
+# host_runtime.so dlopen; a second dlopen of a path already here is skipped
+# rather than repeated. Never closed. Lives here rather than in task_interface so
+# the import-time preload below and ChipWorker.init share one registry.
+_preloaded_globals: dict[str, ctypes.CDLL] = {}
+
+
+def preload_global(path: str) -> ctypes.CDLL:
+    """dlopen `path` with RTLD_NOW | RTLD_GLOBAL, idempotently (one CDLL per path).
+
+    Eager resolution (RTLD_NOW) surfaces a missing-symbol problem at load time
+    rather than at first use.
+    """
+    handle = _preloaded_globals.get(path)
+    if handle is None:
+        handle = ctypes.CDLL(path, mode=os.RTLD_NOW | os.RTLD_GLOBAL)
+        _preloaded_globals[path] = handle
+    return handle
+
+
+def _resolve_library() -> Path | None:
+    """Locate libsimpler_log.so under either install layout, or None.
+
+    Mirrors ``simpler_setup.environment._resolve_project_root``: a wheel keeps
+    the built libraries under ``simpler_setup/_assets``, a source tree or
+    editable install keeps them at the repo root.
+    """
+    try:
+        spec = importlib.util.find_spec("simpler_setup")
+    except (ImportError, ValueError):
+        return None
+    if spec is None or spec.origin is None:
+        return None
+
+    package = Path(spec.origin).resolve().parent
+    assets = package / "_assets"
+    project_root = assets if (assets / "src").is_dir() else package.parent
+    library = project_root / "build" / "lib" / _LIBRARY_NAME
+    return library if library.is_file() else None
+
+
+@functools.cache
+def preload() -> ctypes.CDLL | None:
+    """dlopen the process-global logger RTLD_GLOBAL, or return None quietly.
+
+    Cached, so the repeated call from ``ChipWorker.init``'s own preload of this
+    library does not bump the loader refcount again.
+    """
+    library = _resolve_library()
+    if library is None:
+        return None
+    try:
+        return preload_global(str(library))
+    except OSError:
+        return None
+
+
+def host_span_sink_address(handle: ctypes.CDLL | None) -> int:
+    """Return the logger's host-span entry-point address, or zero if absent."""
+    if handle is None:
+        return 0
+    try:
+        symbol = handle.simpler_log_emit_host_span
+    except AttributeError:
+        return 0
+    return int(ctypes.cast(symbol, ctypes.c_void_p).value or 0)