added timing

python_app/orchestration/pipeline_metrics.py

@@ -0,0 +1,104 @@
+"""Rolling pipeline timing metrics emitted to the runtime log.
+
+Three independent samples are accumulated:
+  * acquisition  — `capture_end_ns - capture_start_ns` from each raw sweep
+  * processing   — `processing_duration_ns` from each result collection
+  * rendering    — wall time of the Python render call
+
+Each metric flushes an averaged report to a caller-supplied logger as soon as
+its rolling buffer reaches `report_every` samples (default 50). Metrics are
+strictly read-only: malformed or missing input is silently ignored so a busy
+pipeline never blocks on a stray sample.
+"""
+
+from __future__ import annotations
+
+from collections import deque
+from dataclasses import dataclass
+from typing import Callable, Iterable
+
+
+@dataclass(frozen=True, slots=True)
+class MetricReport:
+    """Summary of one rolling-window flush.
+
+    All durations are in nanoseconds. `n` is the number of samples that fed the
+    summary — never less than 1. `min_ns` / `max_ns` mark the extremes of the
+    window so spikes are visible even when the average stays calm.
+    """
+
+    name: str
+    n: int
+    avg_ns: int
+    min_ns: int
+    max_ns: int
+
+    def format_ms(self) -> str:
+        """Format the summary as a one-line `ms`-scaled log message."""
+        return (
+            f"metrics: {self.name} n={self.n} "
+            f"avg={self.avg_ns / 1_000_000:.2f}ms "
+            f"min={self.min_ns / 1_000_000:.2f}ms "
+            f"max={self.max_ns / 1_000_000:.2f}ms"
+        )
+
+
+class PipelineMetrics:
+    """Accumulate per-stage durations and flush averaged reports.
+
+    The caller supplies a `log_sink` (a function taking a single string) that
+    receives one report line per flushed metric. Wiring `log_sink` to the GUI
+    log writer keeps metric output co-located with the rest of the runtime
+    log; routing it to `print` keeps the class trivially unit-testable.
+    """
+
+    def __init__(
+        self,
+        *,
+        report_every: int = 50,
+        log_sink: Callable[[str], None] | None = None,
+    ) -> None:
+        """Create a collector with a flush threshold and optional log sink."""
+        if report_every < 1:
+            raise ValueError("report_every must be >= 1")
+        self._report_every = int(report_every)
+        self._log_sink = log_sink
+        self._buffers: dict[str, deque[int]] = {}
+
+    def set_log_sink(self, log_sink: Callable[[str], None] | None) -> None:
+        """Reassign the log sink (used when the GUI log appears after init)."""
+        self._log_sink = log_sink
+
+    def record(self, name: str, duration_ns: int) -> MetricReport | None:
+        """Append one sample. Return a flushed report if the buffer is full."""
+        if duration_ns <= 0:
+            return None
+        buffer = self._buffers.setdefault(name, deque())
+        buffer.append(int(duration_ns))
+        if len(buffer) < self._report_every:
+            return None
+
+        samples = list(buffer)
+        buffer.clear()
+        report = self._summarize(name, samples)
+        if self._log_sink is not None:
+            self._log_sink(report.format_ms())
+        return report
+
+    def reset(self) -> None:
+        """Discard all buffered samples without emitting a report."""
+        self._buffers.clear()
+
+    @staticmethod
+    def _summarize(name: str, samples: Iterable[int]) -> MetricReport:
+        """Reduce a sample sequence to one report."""
+        sample_list = list(samples)
+        total = sum(sample_list)
+        count = len(sample_list)
+        return MetricReport(
+            name=name,
+            n=count,
+            avg_ns=total // count,
+            min_ns=min(sample_list),
+            max_ns=max(sample_list),
+        )