profiling.step_profiler

Deep per-step runtime profiler for raccoon missions.

The mission step machinery wraps every user step in 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

Phase	A timed sub-region of a step (execute / db_read / db_write / acquire).
StepSample	One execution of one step, with its phase breakdown.
LagSpike
StepProfiler	Runtime profiler that decomposes per-step wall time and event-loop lag.

Module Contents

class profiling.step_profiler.Phase

A timed sub-region of a step (execute / db_read / db_write / acquire).

label: str

ts: float

dur: float

class profiling.step_profiler.StepSample

One execution of one step, with its phase breakdown.

signature: str

path: str

depth: int

composite: bool

tid: int

ts: float = 0.0

total: float = 0.0

execute: float = 0.0

db_read: float = 0.0

db_write: float = 0.0

acquire: float = 0.0

motion_compute: float = 0.0

motion_updates: int = 0

hal: float = 0.0

hal_calls: int = 0

sleep: float = 0.0

phases: list[Phase] = []

property overhead: float

Wall time inside run_step not spent in the step body.

property unattributed: float

Overhead not explained by db/acquire (logging, signatures, asyncio).

property body_compute: 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.

class profiling.step_profiler.LagSpike

ts: float

lag_ms: float

class profiling.step_profiler.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.

Parameters:

• trace_path – If set, write a Chrome-tracing (chrome://tracing) JSON file here on exit. Open it there or at https://ui.perfetto.dev.

• loop_lag – Run the event-loop-lag monitor (default True).

• loop_lag_interval – Sampling period of the lag monitor, seconds. Smaller = finer resolution but more samples. Default 0.005 (5 ms).

• lag_spike_ms – Lag above this (ms) is recorded as a spike and shown in the report / trace. Default 5 ms.

• print_report – Print the text report on exit (default True).

• top – How many step signatures to show in the per-signature table.

• 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 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.

trace_path = None

loop_lag = True

loop_lag_interval = 0.005

lag_spike_ms = 5.0

print_report = True

top = 25

hal = True

sleep_track = True

hal_span_ms = 1.0

defer_trace = True

samples: list[StepSample] = []

lag_spikes: list[LagSpike] = []

lag_samples: list[tuple[float, float]] = []

max_lag_ms: float = 0.0

hal_stats: dict[str, list[float]]

classmethod from_env(env: dict[str, str] | None = None) → StepProfiler | None

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 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

classmethod flush_traces() → list[str]

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.

format_report() → str