Add: expose L3/L4 host scheduling swimlane

docs/dfx/host-trace.md

@@ -82,22 +82,55 @@ 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
+
+A hierarchical worker with direct local chip children also emits these spans
+through the same process-global `libsimpler_log.so` sink:
+
+| 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. The logger is loaded
+and the fixed host-span ABI is resolved before local children are forked, so
+parent and child markers reach one sink. Topologies without a local chip binary
+path do not initialize this bridge and continue without scheduler markers.
+
 ## 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

@@ -18,6 +18,7 @@ list(TRANSFORM BINDING_SOURCES PREPEND "${CMAKE_CURRENT_SOURCE_DIR}/")
 set(HIERARCHICAL_SRC ${CMAKE_SOURCE_DIR}/src/common/hierarchical)
 
 set(HIERARCHICAL_SOURCES
+    ${HIERARCHICAL_SRC}/host_trace.cpp
     ${HIERARCHICAL_SRC}/types.cpp
     ${HIERARCHICAL_SRC}/tensormap.cpp
     ${HIERARCHICAL_SRC}/ring.cpp
@@ -63,6 +64,7 @@ target_include_directories(_task_interface PRIVATE
     ${CMAKE_SOURCE_DIR}/src/common/hierarchical
     ${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

@@ -57,6 +57,7 @@
 #include "chip_worker.h"
 #include "data_type.h"
 #include "dma_workspace.h"
+#include "host_trace.h"
 #include "worker_chip_orch_comm.h"
 #include "worker_chip_orch_region_access.h"
 #include "worker_bind.h"
@@ -958,6 +959,27 @@ 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", &simpler::host_trace::bind_process_sink,
+        "Resolve the process-global host-span sink after libsimpler_log.so is loaded."
+    );
+    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 the process-global logger."
+    );
     // Byte size of a ChipTensor and the offset of its child_memory flag 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/task_interface.py

@@ -1086,6 +1086,24 @@ def _preload_global(path: str) -> ctypes.CDLL:
     return handle
 
 
+def _initialize_simpler_log(bins: Any, log_level: int | None = None) -> ctypes.CDLL:
+    """Load and seed the process-global logger before runtime use or fork."""
+    if log_level is None:
+        from . import _log  # noqa: PLC0415
+
+        log_level = _log.get_current_config()
+    if not bins.simpler_log_path:
+        raise ValueError("ChipWorker.init: bins.simpler_log_path is required")
+
+    log_handle = _preload_global(str(bins.simpler_log_path))
+    log_handle.simpler_log_init.argtypes = [ctypes.c_int]
+    log_handle.simpler_log_init.restype = ctypes.c_int
+    rc = log_handle.simpler_log_init(int(log_level))
+    if rc != 0:
+        raise RuntimeError(f"simpler_log_init failed with code {rc}")
+    return log_handle
+
+
 class ChipWorker:
     """Unified execution interface wrapping the host runtime C API.
 
@@ -1166,20 +1184,8 @@ def init(
             self._init_in_progress = True
 
         try:
-            if log_level is None:
-                from . import _log  # noqa: PLC0415
-
-                log_level = _log.get_current_config()
-
             # 1. libsimpler_log.so — RTLD_GLOBAL singleton, before host_runtime.so.
-            if not bins.simpler_log_path:
-                raise ValueError("ChipWorker.init: bins.simpler_log_path is required")
-            log_handle = _preload_global(str(bins.simpler_log_path))
-            log_handle.simpler_log_init.argtypes = [ctypes.c_int]
-            log_handle.simpler_log_init.restype = ctypes.c_int
-            rc = log_handle.simpler_log_init(int(log_level))
-            if rc != 0:
-                raise RuntimeError(f"simpler_log_init failed with code {rc}")
+            _initialize_simpler_log(bins, log_level)
 
             # 2. libcpu_sim_context.so — sim platforms only.
             if bins.sim_context_path:

python/simpler/worker.py

@@ -84,10 +84,13 @@ def my_l4_orch(orch, args, config):
 import cloudpickle
 from _task_interface import (  # pyright: ignore[reportMissingImports]
     CHIP_TENSOR_CHILD_MEMORY_OFFSET,
+    HOST_STRACE_ENABLED,
     MAX_REGISTERED_CALLABLE_IDS,
     PTO_PIPELINE_MAX_DEPTH,
     RUNTIME_ENV_RING_COUNT,
     WorkerType,
+    _bind_host_span_sink,
+    _emit_host_span,
     _l3_child_onboard_region_close,
     _l3_child_onboard_region_create,
     _mailbox_load_i32,
@@ -136,6 +139,7 @@ def my_l4_orch(orch, args, config):
     RemoteBufferExport,
     RemoteBufferHandle,
     TaskArgs,
+    _initialize_simpler_log,
     _Worker,
 )
 from .worker_chip_orch_comm import (
@@ -3979,6 +3983,7 @@ def __init__(
         # Level-3+ internals
         self._worker: _Worker | None = None
         self._orch: Orchestrator | None = None
+        self._host_trace_enabled: bool = False
         self._chip_shms: list[SharedMemory] = []
         self._chip_pids: list[int] = []
         self._sub_shms: list[SharedMemory] = []
@@ -6467,6 +6472,14 @@ def _init_hierarchical(self) -> None:
             # invocation is `os.fork()` + direct function call, so no pickle
             # barrier — the bins object is just a Python value passed through.
             self._l3_bins = binaries
+            if HOST_STRACE_ENABLED:
+                # The parent and every later fork inherit one RTLD_GLOBAL logger
+                # and the binding's resolved sink pointer. Loading it after the
+                # first fork would silently lose child-process host spans.
+                _initialize_simpler_log(binaries)
+                if not _bind_host_span_sink():
+                    raise RuntimeError("libsimpler_log.so does not export simpler_log_emit_host_span")
+                self._host_trace_enabled = True
 
             # Allocate chip mailboxes (unified layout, MAILBOX_SIZE each).
             for i, _dev_id in enumerate(device_ids):
@@ -8746,7 +8759,23 @@ def _submit_l3_locked(self, callable, args, cfg: CallConfig) -> RunHandle:
             self._orch._scope_begin()
             scope_open = True
             with _callback_run(run_id, self):
-                callable(self._orch, args, cfg)
+                if HOST_STRACE_ENABLED and self._host_trace_enabled:
+                    graph_start_ns = time.monotonic_ns()
+                    try:
+                        callable(self._orch, args, cfg)
+                    finally:
+                        graph_end_ns = time.monotonic_ns()
+                        _emit_host_span(
+                            "l3.graph_build",
+                            run_id,
+                            0,
+                            0,
+                            graph_start_ns,
+                            graph_end_ns - graph_start_ns,
+                            f"run_id={run_id} role=facade",
+                        )
+                else:
+                    callable(self._orch, args, cfg)
             scope_open = False
             self._orch._scope_end()
             self._orch._close_run_submission(run_id)

simpler_setup/tools/README.md

@@ -328,6 +328,9 @@ python -m simpler_setup.tools.strace_timing path/to/log --tree
 # Also emit a Chrome-trace / Perfetto JSON (one named lane per invocation, with
 # separate host and device(clk=dev) tracks; nested by span containment)
 python -m simpler_setup.tools.strace_timing path/to/log --trace-out strace.json
+
+# L3/L4 host scheduler timeline (real OS pid/tid lanes + cross-thread flows)
+python -m simpler_setup.tools.strace_timing path/to/log --swimlane host_swimlane.json
 ```
 
 Groups spans by `(pid, inv)`, rebuilds each invocation's tree from `depth`,
@@ -352,6 +355,15 @@ to a file (`python test_*.py … --rounds N > run.log 2>&1`) and pass `run.log`
 here. Because grouping is per `(pid, inv)`, this captures **L3 multi-round**
 (every chip-child invocation), not just round 0.
 
+`--swimlane` consumes both the `l3.*` scheduler markers and child
+`simpler_run` markers. Host lanes retain their OS pid/tid. Because Chrome Trace
+JSON has one visible timestamp axis, raw device-domain `clk=dev` slices are
+stored in the top-level `unalignedDeviceSpans` array rather than placed beside
+the unrelated host clock and stretching Perfetto into an empty-looking
+multi-day viewport. Their ns timestamps remain unchanged; no clock offset is
+invented. This does not alter the established per-invocation `--trace-out`
+view.
+
 ---
 
 ## deps_viewer