profiling.step_profiler ======================= .. py:module:: profiling.step_profiler .. autoapi-nested-parse:: Deep per-step runtime profiler for raccoon missions. The mission step machinery wraps every user step in :meth:`Step.run_step`, which does more than just run the step: it reads/writes the SQLite timing database, acquires hardware-resource locks, generates signatures and logs. When a robot "stands still" between two steps, the standstill is this *overhead* — not the step body — and until now there was no way to see where it actually goes. ``StepProfiler`` answers that by instrumenting the machinery at runtime (no edits to the core). For every step it records a phase breakdown:: total = execute + db_read + db_write + acquire + (unattributed overhead) and it runs an event-loop-lag monitor in parallel, which reveals whether *something blocks the asyncio loop* (a synchronous C++/HAL call, an fsync that doesn't really yield, GC pauses, ...). That distinguishes "Python overhead between steps" from "a blocking call stalls everything". Usage (wrap the mission run):: from raccoon.profiling import StepProfiler async def main(): async with StepProfiler(trace_path="profile.json") as prof: await mission.run(robot) # report prints automatically on exit; prof holds the raw samples Then open ``profile.json`` at ``chrome://tracing`` (or ``edge://tracing`` / https://ui.perfetto.dev) to *see* the gaps between steps on a timeline. It also works as a plain ``with`` block if you are not inside async code yet; the loop-lag monitor then starts lazily on the first step. Classes ------- .. autoapisummary:: profiling.step_profiler.Phase profiling.step_profiler.StepSample profiling.step_profiler.LagSpike profiling.step_profiler.StepProfiler Module Contents --------------- .. py:class:: Phase A timed sub-region of a step (execute / db_read / db_write / acquire). .. py:attribute:: label :type: str .. py:attribute:: ts :type: float .. py:attribute:: dur :type: float .. py:class:: StepSample One execution of one step, with its phase breakdown. .. py:attribute:: signature :type: str .. py:attribute:: path :type: str .. py:attribute:: depth :type: int .. py:attribute:: composite :type: bool .. py:attribute:: tid :type: int .. py:attribute:: ts :type: float :value: 0.0 .. py:attribute:: total :type: float :value: 0.0 .. py:attribute:: execute :type: float :value: 0.0 .. py:attribute:: db_read :type: float :value: 0.0 .. py:attribute:: db_write :type: float :value: 0.0 .. py:attribute:: acquire :type: float :value: 0.0 .. py:attribute:: motion_compute :type: float :value: 0.0 .. py:attribute:: motion_updates :type: int :value: 0 .. py:attribute:: hal :type: float :value: 0.0 .. py:attribute:: hal_calls :type: int :value: 0 .. py:attribute:: sleep :type: float :value: 0.0 .. py:attribute:: phases :type: list[Phase] :value: [] .. py:property:: overhead :type: float Wall time inside run_step not spent in the step body. .. py:property:: unattributed :type: float Overhead not explained by db/acquire (logging, signatures, asyncio). .. py:property:: body_compute :type: float Step-body time that is neither a deliberate sleep nor a HAL call. This is the "stands still but profiling shows no wait" budget: pure Python compute *plus* any blocking that escaped attribution. ``hal`` is a subset of ``execute`` (for motion steps it happens inside ``on_update``), so it is subtracted here only to isolate the remainder. .. py:class:: LagSpike .. py:attribute:: ts :type: float .. py:attribute:: lag_ms :type: float .. py:class:: StepProfiler(trace_path: str | None = None, *, loop_lag: bool = True, loop_lag_interval: float = 0.005, lag_spike_ms: float = 5.0, print_report: bool = True, top: int = 25, hal: bool = True, sleep_track: bool = True, hal_span_ms: float = 1.0, defer_trace: bool = True) Runtime profiler that decomposes per-step wall time and event-loop lag. :param trace_path: If set, write a Chrome-tracing (``chrome://tracing``) JSON file here on exit. Open it there or at https://ui.perfetto.dev. :param loop_lag: Run the event-loop-lag monitor (default True). :param loop_lag_interval: Sampling period of the lag monitor, seconds. Smaller = finer resolution but more samples. Default 0.005 (5 ms). :param lag_spike_ms: Lag above this (ms) is recorded as a spike and shown in the report / trace. Default 5 ms. :param print_report: Print the text report on exit (default True). :param top: How many step signatures to show in the per-signature table. :param defer_trace: Buffer the Chrome-trace write in RAM instead of writing it to disk when the profiled block exits, and flush all buffered traces in one go via :meth:`flush_traces` after the run. Default True — a per-mission profiler otherwise json.dumps a multi-MB trace to the Pi's SD card *between missions*, standing the robot still (~1.8 s for the setup trace) and perturbing the very run it measures. .. py:attribute:: trace_path :value: None .. py:attribute:: loop_lag :value: True .. py:attribute:: loop_lag_interval :value: 0.005 .. py:attribute:: lag_spike_ms :value: 5.0 .. py:attribute:: print_report :value: True .. py:attribute:: top :value: 25 .. py:attribute:: hal :value: True .. py:attribute:: sleep_track :value: True .. py:attribute:: hal_span_ms :value: 1.0 .. py:attribute:: defer_trace :value: True .. py:attribute:: samples :type: list[StepSample] :value: [] .. py:attribute:: lag_spikes :type: list[LagSpike] :value: [] .. py:attribute:: lag_samples :type: list[tuple[float, float]] :value: [] .. py:attribute:: max_lag_ms :type: float :value: 0.0 .. py:attribute:: hal_stats :type: dict[str, list[float]] .. py:method:: from_env(env: dict[str, str] | None = None) -> StepProfiler | None :classmethod: Build a profiler from environment variables, or ``None`` if disabled. Profiling is **off** unless ``RACCOON_PROFILE`` is set to a truthy value. Every knob of :class:`StepProfiler` is exposed so a run can be tuned without touching any code: ==================================== ==================================== Environment variable Effect ==================================== ==================================== ``RACCOON_PROFILE`` Master switch. A path (contains ``/`` or ends ``.json``) is used as the Chrome-trace path. ``1``/``true``/ ``on``/``yes`` enables with the default trace path (``raccoon-profile.json``). ``0``/ ``false``/``off``/``""`` disables. ``RACCOON_PROFILE_TRACE`` Explicit trace path (overrides the path inferred from ``RACCOON_PROFILE``; set to empty to skip the trace file). ``RACCOON_PROFILE_REPORT`` ``0``/``off`` to suppress the text report (default on). ``RACCOON_PROFILE_LOOP_LAG`` ``0``/``off`` to disable the event-loop-lag monitor (default on). ``RACCOON_PROFILE_LAG_INTERVAL_MS`` Lag sampling period in ms (default 5). ``RACCOON_PROFILE_LAG_SPIKE_MS`` Spike threshold in ms (default 5). ``RACCOON_PROFILE_TOP`` Rows in the per-signature table (default 25). ``RACCOON_PROFILE_HAL`` ``0``/``off`` to disable timing of synchronous HAL/transport calls (``set_position``, ``set_velocity``, ...) made *inside* a step body (default on). ``RACCOON_PROFILE_SLEEP`` ``0``/``off`` to disable splitting deliberate ``asyncio.sleep`` waits out of the step body (default on). ``RACCOON_PROFILE_HAL_SPAN_MS`` Only HAL calls at least this long (ms) get an individual trace span (the per-method totals always accumulate). Default 1 ms. ``RACCOON_PROFILE_DEFER`` ``0``/``off`` to write each trace inline when its block exits instead of buffering it for a single post-run flush (default on — keeps the multi-MB json.dump off the between-missions hot path). ==================================== ==================================== Example:: RACCOON_PROFILE=1 RACCOON_PROFILE_LAG_SPIKE_MS=2 uv run raccoon run .. py:method:: flush_traces() -> list[str] :classmethod: Write every buffered Chrome trace to disk; return the paths written. Call once after the run (robot idle) to drain the traces buffered by deferred per-mission profilers. Failures on one trace never block the others. Idempotent: a second call finds an empty queue. .. py:method:: format_report() -> str