From 90f5f496f8ee02ad07a802e42f9f81d247e89f98 Mon Sep 17 00:00:00 2001 From: Ziming Wang Date: Thu, 3 Sep 2026 09:43:51 -0700 Subject: [PATCH 1/6] Add correlated V2 runtime latency profiles Signed-off-by: Ziming Wang --- AGENTS.md | 1 + .../developer_guides/latency_tuning.rst | 39 ++ .../flashdreams/api_v2/client_window.py | 10 + flashdreams/flashdreams/api_v2/loop.py | 23 + flashdreams/flashdreams/runtime_v2/README.md | 9 + .../flashdreams/runtime_v2/__init__.py | 3 +- .../runtime_v2/application_runner.py | 17 + flashdreams/flashdreams/runtime_v2/cli.py | 85 +++- .../runtime_v2/native_window_client_window.py | 10 + .../runtime_v2/presentation_manager.py | 169 ++++--- .../runtime_v2/runtime_profiler.py | 471 ++++++++++++++++++ .../runtime_v2/serving/webrtc_server.py | 16 +- .../flashdreams/runtime_v2/session_runner.py | 85 +++- .../runtime_v2/webrtc_client_window.py | 20 +- .../test_v2/test_client_window_factory.py | 47 +- .../test_native_window_client_window.py | 2 +- flashdreams/test_v2/test_runtime_profiler.py | 189 +++++++ flashdreams/test_v2/test_session_runner.py | 68 ++- .../test_v2/test_webrtc_client_window.py | 4 +- 19 files changed, 1168 insertions(+), 100 deletions(-) create mode 100644 flashdreams/flashdreams/runtime_v2/runtime_profiler.py create mode 100644 flashdreams/test_v2/test_runtime_profiler.py diff --git a/AGENTS.md b/AGENTS.md index ad8ce090d..c38f58b7f 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -85,6 +85,7 @@ Use `--no-instantiate` before GPU work to inspect the resolved runner config wit - Inspect available runners with `uv run flashdreams-run --help`, then inspect a specific runner with `uv run flashdreams-run --no-instantiate `. - Prefer CPU checks first: config imports, checkpoint key-remap shape/bijection tests on CPU or meta tensors, docs builds, `pytest -m ci_cpu`, and static assertions about runner names and pipeline wiring. +- For interactive V2 latency work, capture `--profile-path artifacts/.jsonl` and use `docs/source/developer_guides/latency_tuning.rst` to interpret each host-side endpoint. - Avoid `ci_gpu`, generation, `torchrun`, Docker GPU tests, large Hugging Face downloads, rollout parity, CUDA graph, WebRTC runtime, and quality-regression tests on CPU-only hosts unless the user requests them or the test explicitly skips cleanly. ## Testing Guidance diff --git a/docs/source/developer_guides/latency_tuning.rst b/docs/source/developer_guides/latency_tuning.rst index 2b32f91b0..50b5ff9df 100644 --- a/docs/source/developer_guides/latency_tuning.rst +++ b/docs/source/developer_guides/latency_tuning.rst @@ -157,6 +157,45 @@ resolution, and native-acceleration knobs first. Profiling and validated reference --------------------------------- +V2 runtime input latency profile +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + +Use ``--profile-path`` with any V2 application to write a correlated JSONL +profile under ``artifacts/``: + +.. code-block:: bash + + uv run flashdreams-run-v2 interactive-drive-omnidreams-perf \ + --mode native-window \ + --profile-path artifacts/interactive-drive-runtime.jsonl + +Every record uses the host monotonic clock. Input latency starts at the existing +session-relative ``UserInputEvent.timestamp`` and follows the UI step that first +claims the event. The final ``profile_summary`` records report count, mean, +median, p90, and maximum values for these measurements: + +- ``input_to_ui_step_s`` measures event receipt through UI-step entry. +- ``input_to_window_write_s`` measures event receipt through the first + observable client-window write after its UI claim. +- ``model_step_s`` measures the model loop's ``step`` call. +- ``ui_step_s`` measures the UI loop's ``step`` call. +- ``publish_wait_s`` measures admission to the bounded presentation queue. +- ``frame_to_window_write_s`` measures UI composition and the observable + client-window write. + +The ``endpoint`` field defines the final boundary. Native-window records use +``native_presenter_return`` after the presenter returns. WebRTC records use +``webrtc_sender_admission`` after frame materialization and sender admission. +Writes completed without a connected WebRTC sender carry a null endpoint. Input +and selected-frame correlations remain pending until a sender admits a later +write. Browser decode, network transit, compositor scheduling, and physical +scanout form a client-side continuation and can be joined with browser +telemetry. + +Profiles add host timestamping and JSONL writes to the measured run. Keep the +same profile setting across candidate and reference measurements. Use Nsight +Systems for CUDA kernel, stream, and CPU/GPU overlap analysis. + Set ``output.profile_world_model: true`` to enable FlashDreams CUDA-event profiling for the world-model runtime. Set ``output.sync_gpu_timing: true`` only when you need raster compute diff --git a/flashdreams/flashdreams/api_v2/client_window.py b/flashdreams/flashdreams/api_v2/client_window.py index 8befe1c02..9463dcd63 100644 --- a/flashdreams/flashdreams/api_v2/client_window.py +++ b/flashdreams/flashdreams/api_v2/client_window.py @@ -24,3 +24,13 @@ class IClientWindow(InputSource, OutputSink, ABC): Created by the runtime, never by an application. """ + + @property + def profile_endpoint(self) -> str | None: + """Name the observable boundary reached when ``write`` returns.""" + return "window_write_return" + + @property + def input_timestamp_origin_ns(self) -> int | None: + """Return the host monotonic origin for input-event timestamps.""" + return None diff --git a/flashdreams/flashdreams/api_v2/loop.py b/flashdreams/flashdreams/api_v2/loop.py index 491703b0b..841285b38 100644 --- a/flashdreams/flashdreams/api_v2/loop.py +++ b/flashdreams/flashdreams/api_v2/loop.py @@ -23,6 +23,7 @@ if TYPE_CHECKING: from flashdreams.runtime_v2.presentation_manager import PresentationManager + from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler StateT = TypeVar("StateT") @@ -219,6 +220,7 @@ def _run_model_loop( event_buffer: EventBuffer, reader_id: int, publish: Callable[[int, list[StepResult], float], None], + profiler: RuntimeProfiler | None = None, max_steps: int | None = None, ) -> None: """Run model steps until shutdown or completion. @@ -228,6 +230,7 @@ def _run_model_loop( reader_id: This loop's event reader ID. publish: Function called with each model result and the elapsed seconds spent in :meth:`step`. + profiler: Optional correlated runtime profiler. max_steps: Maximum steps; ``None`` runs until stopped. """ steps_run = 0 @@ -243,9 +246,29 @@ def _run_model_loop( last_run_started = self._pace(last_run_started) if self._shutdown_event.is_set(): break + profile_started_at_ns = ( + None if profiler is None else profiler.timestamp_ns() + ) step_started_at = time.monotonic() raw_result = self.step(step_index, events) step_elapsed_s = time.monotonic() - step_started_at + profile_completed_at_ns = ( + None if profiler is None else profiler.timestamp_ns() + ) + if profiler is not None: + assert profile_started_at_ns is not None + assert profile_completed_at_ns is not None + profiler.model_step_started( + generation=generation, + step=step_index, + time_ns=profile_started_at_ns, + ) + profiler.model_step_completed( + generation=generation, + step=step_index, + duration_s=step_elapsed_s, + time_ns=profile_completed_at_ns, + ) result = _model_results(raw_result) self._finish_run(result) publish(generation, result, step_elapsed_s) diff --git a/flashdreams/flashdreams/runtime_v2/README.md b/flashdreams/flashdreams/runtime_v2/README.md index edb00c79e..ba8ea8bc6 100644 --- a/flashdreams/flashdreams/runtime_v2/README.md +++ b/flashdreams/flashdreams/runtime_v2/README.md @@ -111,6 +111,15 @@ presentation-queue depth/publish-wait measurements under the reserved `runtime_` metric prefix. UI and window timings are not folded into a later model record because they describe a different frame. +`--profile-path artifacts/.jsonl` adds a correlated host-side runtime +profile. It follows each input event through the UI step that claims it and the +next observable client-window write. Native-window records end at presenter +return. WebRTC records end at sender admission. The final records summarize +model-step, UI-step, publish, presentation, client-window, and input-latency +distributions. The +[latency tuning guide](../../../docs/source/developer_guides/latency_tuning.rst) +defines every field and measurement boundary. + ## Starting and stopping a run `ApplicationRunner.run` calls `init`, `create_session` and `run_session` in diff --git a/flashdreams/flashdreams/runtime_v2/__init__.py b/flashdreams/flashdreams/runtime_v2/__init__.py index 8bcb7a5ce..69001db64 100644 --- a/flashdreams/flashdreams/runtime_v2/__init__.py +++ b/flashdreams/flashdreams/runtime_v2/__init__.py @@ -3,10 +3,11 @@ """Runtime that runs a FlashDreams v2 application against a client window.""" +from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler from flashdreams.runtime_v2.session_desc import ( BackpressureMode, PresentationMode, SessionDesc, ) -__all__ = ["BackpressureMode", "PresentationMode", "SessionDesc"] +__all__ = ["BackpressureMode", "PresentationMode", "RuntimeProfiler", "SessionDesc"] diff --git a/flashdreams/flashdreams/runtime_v2/application_runner.py b/flashdreams/flashdreams/runtime_v2/application_runner.py index 381a1b7f9..4e2804d5f 100644 --- a/flashdreams/flashdreams/runtime_v2/application_runner.py +++ b/flashdreams/flashdreams/runtime_v2/application_runner.py @@ -10,6 +10,7 @@ from flashdreams.api_v2.application import IApplication from flashdreams.api_v2.client_window import IClientWindow from flashdreams.api_v2.output_sink import OutputSink +from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler from flashdreams.runtime_v2.session_desc import SessionDesc from flashdreams.runtime_v2.session_runner import run_session @@ -26,16 +27,19 @@ def __init__( client_window: IClientWindow, *, metrics_output_sink: OutputSink | None = None, + profiler: RuntimeProfiler | None = None, ) -> None: """ Args: application: Long-lived application that creates the session. client_window: Window that supplies input and presents generated output. metrics_output_sink: Optional sink for model-step metrics. + profiler: Optional correlated host-side runtime profiler. """ self._application = application self._client_window = client_window self._metrics_output_sink = metrics_output_sink + self._profiler = profiler def run( self, session_desc: SessionDesc, commandline_args: Sequence[str] = () @@ -64,12 +68,15 @@ def run( session, self._client_window, metrics_output_sink=self._metrics_output_sink, + profiler=self._profiler, ) finally: if not run_started: _close_client_window(self._client_window) if self._metrics_output_sink is not None: _close_output_sink(self._metrics_output_sink) + if self._profiler is not None: + _close_profiler(self._profiler) _close_application( self._application, run_failed=sys.exc_info()[0] is not None ) @@ -99,6 +106,16 @@ def _close_output_sink(output_sink: OutputSink) -> None: ) +def _close_profiler(profiler: RuntimeProfiler) -> None: + """Close a runtime profile after a run that never reached the session.""" + try: + profiler.close() + except Exception: + _LOGGER.exception( + "The runtime profiler failed to close after a run that never started." + ) + + def _close_application(application: IApplication, *, run_failed: bool) -> None: """Close an application, keeping its close from hiding an earlier failure. diff --git a/flashdreams/flashdreams/runtime_v2/cli.py b/flashdreams/flashdreams/runtime_v2/cli.py index 9d1af1755..9aeec5a66 100644 --- a/flashdreams/flashdreams/runtime_v2/cli.py +++ b/flashdreams/flashdreams/runtime_v2/cli.py @@ -14,9 +14,11 @@ """ import argparse +import logging import sys from collections.abc import Sequence from dataclasses import replace +from pathlib import Path from typing import Any from flashdreams.api_v2.application import IApplication @@ -30,6 +32,7 @@ client_window_mode, ) from flashdreams.runtime_v2.metrics_output_sink import MetricsOutputSink +from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler from flashdreams.runtime_v2.session_desc import ( BackpressureMode, PresentationMode, @@ -37,6 +40,8 @@ ) from flashdreams.runtime_v2.video_tensor import VideoTensorLayout +_LOGGER = logging.getLogger(__name__) + _ARGUMENT_SEPARATOR = "--" """What separates this command's arguments from the application's. @@ -63,6 +68,7 @@ def entrypoint(argv: Sequence[str] | None = None) -> None: if not wants_application_help: try: mode.check_arguments(parsed) + _validate_artifact_paths(parsed) except ValueError as error: parser.error(str(error)) @@ -73,19 +79,33 @@ def entrypoint(argv: Sequence[str] | None = None) -> None: application.init(application_args) return session_desc = _session_desc(application, parsed) - window = mode.create(parsed) - _report(mode.starting(window)) - # Nothing here says how long the run is: a session reports itself finished, - # and a window ends the run when its client goes away. - metrics_output_sink = ( - None if parsed.stats_path is None else MetricsOutputSink(parsed.stats_path) + profiler = ( + None if parsed.profile_path is None else RuntimeProfiler(parsed.profile_path) ) - ApplicationRunner( - application, - window, - metrics_output_sink=metrics_output_sink, - ).run(session_desc, application_args) - _report(mode.finished(window)) + runner_owns_profiler = False + try: + window = mode.create(parsed) + _report(mode.starting(window)) + # Nothing here says how long the run is: a session reports itself finished, + # and a window ends the run when its client goes away. + metrics_output_sink = ( + None if parsed.stats_path is None else MetricsOutputSink(parsed.stats_path) + ) + runner = ApplicationRunner( + application, + window, + metrics_output_sink=metrics_output_sink, + profiler=profiler, + ) + runner_owns_profiler = True + runner.run(session_desc, application_args) + _report(mode.finished(window)) + finally: + if profiler is not None and not runner_owns_profiler: + _close_unowned_profiler( + profiler, + setup_failed=sys.exc_info()[0] is not None, + ) def split_arguments(arguments: Sequence[str]) -> tuple[list[str], list[str]]: @@ -136,6 +156,12 @@ def _add_session_arguments(parser: argparse.ArgumentParser) -> None: Each defaults to asking for nothing, so a run that names none of them gets what the application generates. """ + parser.add_argument( + "--profile-path", + type=Path, + default=None, + help="Write correlated host-side runtime latency records as JSONL.", + ) parser.add_argument( "--pixel-width", type=int, default=None, help="Frame width to generate." ) @@ -176,6 +202,41 @@ def _add_session_arguments(parser: argparse.ArgumentParser) -> None: ) +def _validate_artifact_paths(parsed: argparse.Namespace) -> None: + """Require every active output artifact to own a distinct path.""" + artifacts = [ + ("--profile-path", parsed.profile_path), + ("--stats-path", parsed.stats_path), + ( + "--output-path", + parsed.output_path if parsed.mode == "mp4" else None, + ), + ] + owners: dict[Path, str] = {} + for flag, path in artifacts: + if path is None: + continue + resolved = path.expanduser().resolve() + existing = owners.get(resolved) + if existing is not None: + raise ValueError(f"{existing} and {flag} must use different paths.") + owners[resolved] = flag + + +def _close_unowned_profiler( + profiler: RuntimeProfiler, + *, + setup_failed: bool, +) -> None: + """Close a profiler retained by CLI setup.""" + try: + profiler.close() + except Exception: + if not setup_failed: + raise + _LOGGER.exception("The runtime profiler failed to close during CLI setup.") + + def _session_desc( application: IApplication, parsed_args: argparse.Namespace ) -> SessionDesc: diff --git a/flashdreams/flashdreams/runtime_v2/native_window_client_window.py b/flashdreams/flashdreams/runtime_v2/native_window_client_window.py index cc41ed085..003510a1f 100644 --- a/flashdreams/flashdreams/runtime_v2/native_window_client_window.py +++ b/flashdreams/flashdreams/runtime_v2/native_window_client_window.py @@ -91,6 +91,16 @@ class NativeWindowClientWindow(IClientWindow): """Present UI output through a main-thread GLFW window.""" + @property + def profile_endpoint(self) -> str: + """Name the completed native presentation boundary.""" + return "native_presenter_return" + + @property + def input_timestamp_origin_ns(self) -> int | None: + """Return the native session's host monotonic timestamp origin.""" + return self._session_started_ns + def __init__( self, *, diff --git a/flashdreams/flashdreams/runtime_v2/presentation_manager.py b/flashdreams/flashdreams/runtime_v2/presentation_manager.py index ee712220e..0ab1d1583 100644 --- a/flashdreams/flashdreams/runtime_v2/presentation_manager.py +++ b/flashdreams/flashdreams/runtime_v2/presentation_manager.py @@ -15,6 +15,7 @@ from flashdreams.runtime_v2.cuda_utils import resolve_cuda_device from flashdreams.runtime_v2.recent_frame_rate import RecentFrameRateTracker +from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler from flashdreams.runtime_v2.session_desc import BackpressureMode from flashdreams.runtime_v2.step_result import StepResult from flashdreams.runtime_v2.video_tensor import VideoTensorLayout @@ -185,6 +186,7 @@ def __init__(self, *, device: torch.device | None = None) -> None: self._stream_lock = threading.Lock() self._infer_stream_device = device is None self._trace_chunk_lifecycle = False + self._runtime_profiler: RuntimeProfiler | None = None self._presentation_stream: torch.cuda.Stream | None = None if device is not None: device = torch.device(device) @@ -205,6 +207,7 @@ def configure( stop: threading.Event, put_timeout: float, trace_chunk_lifecycle: bool = False, + runtime_profiler: RuntimeProfiler | None = None, frames_per_second: int = 30, maximum_frames_per_second: int | None = None, ) -> None: @@ -218,6 +221,7 @@ def configure( put_timeout: How long a blocked publish waits before rechecking ``stop``, in seconds. trace_chunk_lifecycle: Emit chunk lifecycle diagnostics. + runtime_profiler: Record model-chunk publication, selection, and drops. frames_per_second: Initial video presentation rate. maximum_frames_per_second: Upper bound for presentation cadence; ``None`` uses ``frames_per_second``. @@ -231,6 +235,7 @@ def configure( self._stop = stop self._put_timeout = put_timeout self._trace_chunk_lifecycle = trace_chunk_lifecycle + self._runtime_profiler = runtime_profiler def publish( self, @@ -288,15 +293,26 @@ def publish( buffered_chunks=self.buffered_chunk_count, chunk_capacity=self.buffered_chunk_capacity, ) + profile_started_ns = ( + None + if self._runtime_profiler is None + else self._runtime_profiler.timestamp_ns() + ) pending = (generation, chunk) if self._backpressure_mode is BackpressureMode.DROP_OLDEST: - self._publish_latest(pending) - self._trace_publish_completed(pending, started_ns) + if self._publish_latest(pending): + self._record_publish_completed(pending, started_ns, profile_started_ns) + elif self._runtime_profiler is not None: + self._runtime_profiler.chunk_dropped( + generation=generation, + step=chunk[0].step_index, + reason="publish_stopped", + ) return while not self._stop.is_set(): try: self._bufferedChunks.put(pending, timeout=self._put_timeout) - self._trace_publish_completed(pending, started_ns) + self._record_publish_completed(pending, started_ns, profile_started_ns) return except queue.Full: continue @@ -309,6 +325,12 @@ def publish( buffered_chunks=self.buffered_chunk_count, chunk_capacity=self.buffered_chunk_capacity, ) + if self._runtime_profiler is not None: + self._runtime_profiler.chunk_dropped( + generation=generation, + step=chunk[0].step_index, + reason="publish_stopped", + ) @contextmanager def presentation_context(self) -> Iterator[None]: @@ -359,7 +381,7 @@ def advance( """ if generation != self._generation: if self._presented_chunk is not None: - self._trace_drop( + self._record_drop( self._generation, self._presented_chunk, reason="generation_changed_active", @@ -380,7 +402,7 @@ def advance( ): self._frame_index += 1 self._presented_frame_count += 1 - self._trace_presented_frame(generation) + self._record_presented_frame(generation) self._presentation_clock.mark_advanced(now, backlog=backlog) return True, None @@ -393,7 +415,7 @@ def advance( self._presented_chunk = chunk self._frame_index = 0 self._presented_frame_count += 1 - self._trace_presented_frame(generation) + self._record_presented_frame(generation) self._presentation_clock.mark_advanced(now, backlog=backlog) return True, chunk @@ -578,11 +600,11 @@ def clear(self) -> None: def _reset_buffered_chunks(self) -> None: self._bufferedChunks = queue.Queue(maxsize=1) - def _publish_latest(self, pending: tuple[int, list[StepResult]]) -> None: + def _publish_latest(self, pending: tuple[int, list[StepResult]]) -> bool: while not self._stop.is_set(): try: self._bufferedChunks.put_nowait(pending) - return + return True except queue.Full: try: dropped_generation, dropped_chunk = ( @@ -590,7 +612,7 @@ def _publish_latest(self, pending: tuple[int, list[StepResult]]) -> None: ) with self._counter_lock: self._dropped_for_space += 1 - self._trace_drop( + self._record_drop( dropped_generation, dropped_chunk, reason="queue_full", @@ -598,6 +620,7 @@ def _publish_latest(self, pending: tuple[int, list[StepResult]]) -> None: ) except queue.Empty: continue + return False def _take_buffered_chunk( self, generation: int, *, latest: bool @@ -611,7 +634,7 @@ def _take_buffered_chunk( if chunk_generation != generation: with self._counter_lock: self._discarded_at_reset += 1 - self._trace_drop( + self._record_drop( chunk_generation, chunk, reason="generation_mismatch", @@ -620,7 +643,7 @@ def _take_buffered_chunk( if selected is not None: with self._counter_lock: self._dropped_for_space += 1 - self._trace_drop( + self._record_drop( generation, selected, reason="take_latest", @@ -630,50 +653,77 @@ def _take_buffered_chunk( if not latest: return selected - def _trace_publish_completed( + def _record_publish_completed( self, pending: tuple[int, list[StepResult]], started_ns: int | None, + profile_started_ns: int | None, ) -> None: - if started_ns is None: - return generation, chunk = pending - self._trace( - "publish_completed", - generation=generation, - step=chunk[0].step_index, - frames=chunk[0].frame_count, - wait_ms=(time.monotonic_ns() - started_ns) / 1_000_000.0, - buffered_chunks=self.buffered_chunk_count, - chunk_capacity=self.buffered_chunk_capacity, + profile_published_at_ns = ( + None + if self._runtime_profiler is None or profile_started_ns is None + else self._runtime_profiler.timestamp_ns() ) + if started_ns is not None: + self._trace( + "publish_completed", + generation=generation, + step=chunk[0].step_index, + frames=chunk[0].frame_count, + wait_ms=(time.monotonic_ns() - started_ns) / 1_000_000.0, + buffered_chunks=self.buffered_chunk_count, + chunk_capacity=self.buffered_chunk_capacity, + ) + if self._runtime_profiler is not None and profile_published_at_ns is not None: + assert profile_started_ns is not None + self._runtime_profiler.chunk_published( + generation=generation, + step=chunk[0].step_index, + frame_count=chunk[0].frame_count, + wait_s=(profile_published_at_ns - profile_started_ns) / 1_000_000_000, + time_ns=profile_published_at_ns, + ) - def _trace_presented_frame(self, generation: int) -> None: - if not self._trace_chunk_lifecycle: - return + def _record_presented_frame(self, generation: int) -> None: chunk = self._presented_chunk if chunk is None: return - self._trace( - "frame_presented", - generation=generation, - step=chunk[0].step_index, - frame=self._frame_index, - frames=chunk[0].frame_count, - edge=( - "both" - if chunk[0].frame_count == 1 - else "first" - if self._frame_index == 0 - else "last" - if self._frame_index + 1 == chunk[0].frame_count - else "middle" - ), - buffered_chunks=self.buffered_chunk_count, - chunk_capacity=self.buffered_chunk_capacity, + profile_selected_at_ns = ( + None + if self._runtime_profiler is None + else self._runtime_profiler.timestamp_ns() ) + if self._trace_chunk_lifecycle: + self._trace( + "frame_presented", + generation=generation, + step=chunk[0].step_index, + frame=self._frame_index, + frames=chunk[0].frame_count, + edge=( + "both" + if chunk[0].frame_count == 1 + else "first" + if self._frame_index == 0 + else "last" + if self._frame_index + 1 == chunk[0].frame_count + else "middle" + ), + buffered_chunks=self.buffered_chunk_count, + chunk_capacity=self.buffered_chunk_capacity, + ) + if self._runtime_profiler is not None: + assert profile_selected_at_ns is not None + self._runtime_profiler.frame_selected( + generation=generation, + step=chunk[0].step_index, + frame=self._frame_index, + frame_count=chunk[0].frame_count, + time_ns=profile_selected_at_ns, + ) - def _trace_drop( + def _record_drop( self, generation: int, chunk: list[StepResult], @@ -681,20 +731,25 @@ def _trace_drop( reason: str, replacement: tuple[int, list[StepResult]] | None = None, ) -> None: - if not self._trace_chunk_lifecycle: - return - fields: dict[str, object] = { - "generation": generation, - "step": chunk[0].step_index, - "frames": chunk[0].frame_count, - "reason": reason, - "buffered_chunks": self.buffered_chunk_count, - } - if replacement is not None: - replacement_generation, replacement_chunk = replacement - fields["replacement_generation"] = replacement_generation - fields["replacement_step"] = replacement_chunk[0].step_index - self._trace("chunk_dropped", **fields) + if self._trace_chunk_lifecycle: + fields: dict[str, object] = { + "generation": generation, + "step": chunk[0].step_index, + "frames": chunk[0].frame_count, + "reason": reason, + "buffered_chunks": self.buffered_chunk_count, + } + if replacement is not None: + replacement_generation, replacement_chunk = replacement + fields["replacement_generation"] = replacement_generation + fields["replacement_step"] = replacement_chunk[0].step_index + self._trace("chunk_dropped", **fields) + if self._runtime_profiler is not None: + self._runtime_profiler.chunk_dropped( + generation=generation, + step=chunk[0].step_index, + reason=reason, + ) def _trace(self, phase: str, **fields: object) -> None: if not self._trace_chunk_lifecycle: diff --git a/flashdreams/flashdreams/runtime_v2/runtime_profiler.py b/flashdreams/flashdreams/runtime_v2/runtime_profiler.py new file mode 100644 index 000000000..91529efa7 --- /dev/null +++ b/flashdreams/flashdreams/runtime_v2/runtime_profiler.py @@ -0,0 +1,471 @@ +# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +# SPDX-License-Identifier: Apache-2.0 +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Correlated host-side latency profiling for the V2 runtime.""" + +from __future__ import annotations + +import json +import math +import statistics +import threading +import time +from collections.abc import Callable +from dataclasses import dataclass +from pathlib import Path +from typing import IO, Any + +from flashdreams.runtime_v2.user_input_events import UserInputEvents + +_SCHEMA_VERSION = 1 +"""Runtime profile JSONL schema version.""" + + +@dataclass(frozen=True, slots=True) +class _ClaimedInput: + """One input event claimed by a UI step.""" + + received_at_ns: int + timestamp_us: int + event_type: str + generation: int + ui_step: int + + +@dataclass(frozen=True, slots=True) +class _PendingOutput: + """One selected model frame waiting for a client-window write.""" + + generation: int + step: int + frame: int + selected_at_ns: int + + +class RuntimeProfiler: + """Write correlated V2 runtime latency records as line-delimited JSON. + + Input events use their session-relative timestamp as the causal origin. The + profiler follows each event from its first UI step to the next observable + client-window write. Model and presentation stages carry independent + ``(generation, step)`` identities. All durations use one host monotonic + clock. A profiler instance belongs to one session and is thread-safe. + """ + + def __init__( + self, + path: str | Path, + *, + clock_ns: Callable[[], int] = time.monotonic_ns, + ) -> None: + """Open a new runtime profile. + + Args: + path: JSONL output path. Parent directories are created. + clock_ns: Monotonic clock used for every runtime observation. + """ + self._path = Path(path).expanduser() + self._path.parent.mkdir(parents=True, exist_ok=True) + self._output: IO[str] = self._path.open("w", encoding="utf-8") + self._clock_ns = clock_ns + self._lock = threading.Lock() + self._input_timestamp_origin_ns: int | None = None + self._pending_inputs: list[_ClaimedInput] = [] + self._input_generation: int | None = None + self._pending_output: _PendingOutput | None = None + self._samples: dict[str, list[float]] = { + "input_to_ui_step_s": [], + "input_to_window_write_s": [], + "model_step_s": [], + "ui_step_s": [], + "publish_wait_s": [], + "frame_to_window_write_s": [], + } + self._closed = False + with self._lock: + self._write_locked("profile_started", self._clock_ns()) + + @property + def path(self) -> Path: + """Return the profile output path.""" + return self._path + + def timestamp_ns(self) -> int: + """Return the profiler's monotonic timestamp.""" + return self._clock_ns() + + def session_started( + self, + *, + input_timestamp_origin_ns: int | None, + time_ns: int | None = None, + ) -> None: + """Set the host-clock origin for session-relative input timestamps.""" + observed_at_ns = self._clock_ns() if time_ns is None else time_ns + with self._lock: + self._ensure_open_locked() + self._input_timestamp_origin_ns = input_timestamp_origin_ns + self._write_locked( + "session_started", + observed_at_ns, + input_timestamp_origin_ns=input_timestamp_origin_ns, + ) + + def record(self, phase: str, *, time_ns: int | None = None, **fields: Any) -> None: + """Write one timestamped runtime phase.""" + if not phase.strip(): + raise ValueError("Runtime profile phases must be non-empty.") + observed_at_ns = self._clock_ns() if time_ns is None else time_ns + with self._lock: + self._ensure_open_locked() + self._write_locked(phase, observed_at_ns, **fields) + + def model_step_started( + self, + *, + generation: int, + step: int, + time_ns: int | None = None, + ) -> None: + """Record one model-step entry.""" + started_at_ns = self._clock_ns() if time_ns is None else time_ns + with self._lock: + self._ensure_open_locked() + self._write_locked( + "model_step_started", + started_at_ns, + generation=generation, + step=step, + ) + + def model_step_completed( + self, + *, + generation: int, + step: int, + duration_s: float, + time_ns: int | None = None, + ) -> None: + """Record one completed model step.""" + duration_s = _duration(duration_s) + completed_at_ns = self._clock_ns() if time_ns is None else time_ns + with self._lock: + self._ensure_open_locked() + self._samples["model_step_s"].append(duration_s) + self._write_locked( + "model_step_completed", + completed_at_ns, + generation=generation, + step=step, + duration_s=duration_s, + ) + + def ui_step_started( + self, + events: UserInputEvents, + *, + generation: int, + step: int, + time_ns: int | None = None, + ) -> None: + """Record one UI-step entry and the input events it claims.""" + started_at_ns = self._clock_ns() if time_ns is None else time_ns + event_list = events.get_events() + with self._lock: + self._ensure_open_locked() + if generation != self._input_generation: + self._pending_inputs.clear() + self._input_generation = generation + origin_ns = self._input_timestamp_origin_ns + observations = ( + () + if origin_ns is None + else tuple( + _ClaimedInput( + received_at_ns=origin_ns + int(event.get_timestamp()) * 1_000, + timestamp_us=int(event.get_timestamp()), + event_type=type(event).__name__, + generation=generation, + ui_step=step, + ) + for event in event_list + ) + ) + self._pending_inputs.extend(observations) + self._write_locked( + "ui_step_started", + started_at_ns, + generation=generation, + step=step, + input_count=len(event_list), + timed_input_count=len(observations), + ) + for observation in observations: + duration_s = _elapsed_s(observation.received_at_ns, started_at_ns) + self._samples["input_to_ui_step_s"].append(duration_s) + self._write_locked( + "input_to_ui_step", + started_at_ns, + generation=generation, + step=step, + input_type=observation.event_type, + input_timestamp_us=observation.timestamp_us, + duration_s=duration_s, + ) + + def ui_step_completed( + self, + *, + generation: int, + step: int, + duration_s: float, + presented: bool, + time_ns: int | None = None, + ) -> None: + """Record one completed UI step.""" + duration_s = _duration(duration_s) + completed_at_ns = self._clock_ns() if time_ns is None else time_ns + with self._lock: + self._ensure_open_locked() + self._samples["ui_step_s"].append(duration_s) + self._write_locked( + "ui_step_completed", + completed_at_ns, + generation=generation, + step=step, + duration_s=duration_s, + presented=presented, + ) + + def chunk_published( + self, + *, + generation: int, + step: int, + frame_count: int, + wait_s: float, + time_ns: int | None = None, + ) -> None: + """Record admission to the presentation queue.""" + wait_s = _duration(wait_s) + published_at_ns = self._clock_ns() if time_ns is None else time_ns + with self._lock: + self._ensure_open_locked() + self._samples["publish_wait_s"].append(wait_s) + self._write_locked( + "chunk_published", + published_at_ns, + generation=generation, + step=step, + frame_count=frame_count, + wait_s=wait_s, + ) + + def chunk_dropped( + self, + *, + generation: int, + step: int, + reason: str, + time_ns: int | None = None, + ) -> None: + """Discard stage state for a dropped model chunk.""" + dropped_at_ns = self._clock_ns() if time_ns is None else time_ns + with self._lock: + self._ensure_open_locked() + if self._pending_output is not None and ( + self._pending_output.generation, + self._pending_output.step, + ) == (generation, step): + self._pending_output = None + self._write_locked( + "chunk_dropped", + dropped_at_ns, + generation=generation, + step=step, + reason=reason, + ) + + def frame_selected( + self, + *, + generation: int, + step: int, + frame: int, + frame_count: int, + time_ns: int | None = None, + ) -> None: + """Record model-frame selection for the next client-window write.""" + selected_at_ns = self._clock_ns() if time_ns is None else time_ns + with self._lock: + self._ensure_open_locked() + self._write_locked( + "frame_selected", + selected_at_ns, + generation=generation, + step=step, + frame=frame, + frame_count=frame_count, + ) + self._pending_output = _PendingOutput( + generation=generation, + step=step, + frame=frame, + selected_at_ns=selected_at_ns, + ) + + def window_write_completed( + self, + *, + endpoint: str | None, + generation: int, + ui_step: int, + time_ns: int | None = None, + ) -> None: + """Record a client-window write and finish successful correlations.""" + completed_at_ns = self._clock_ns() if time_ns is None else time_ns + with self._lock: + self._ensure_open_locked() + self._write_locked( + "window_write_completed", + completed_at_ns, + endpoint=endpoint, + generation=generation, + ui_step=ui_step, + ) + if endpoint is None: + return + pending_output = self._pending_output + self._pending_output = None + if pending_output is not None: + frame_duration_s = _elapsed_s( + pending_output.selected_at_ns, completed_at_ns + ) + self._samples["frame_to_window_write_s"].append(frame_duration_s) + self._write_locked( + "frame_to_window_write", + completed_at_ns, + generation=pending_output.generation, + step=pending_output.step, + frame=pending_output.frame, + endpoint=endpoint, + duration_s=frame_duration_s, + ) + pending_inputs = tuple(self._pending_inputs) + self._pending_inputs.clear() + for observation in pending_inputs: + duration_s = _elapsed_s(observation.received_at_ns, completed_at_ns) + self._samples["input_to_window_write_s"].append(duration_s) + self._write_locked( + "input_to_window_write", + completed_at_ns, + generation=observation.generation, + claimed_ui_step=observation.ui_step, + presented_ui_step=ui_step, + endpoint=endpoint, + input_type=observation.event_type, + input_timestamp_us=observation.timestamp_us, + duration_s=duration_s, + ) + + def summary(self) -> dict[str, dict[str, float | int]]: + """Return summary statistics for every recorded duration.""" + with self._lock: + return {name: _summarize(values) for name, values in self._samples.items()} + + def close(self) -> None: + """Write summary records and close the profile once.""" + with self._lock: + if self._closed: + return + observed_at_ns = self._clock_ns() + failure: BaseException | None = None + try: + for metric, values in self._samples.items(): + self._write_locked( + "profile_summary", + observed_at_ns, + metric=metric, + **_summarize(values), + ) + except BaseException as error: + failure = error + self._pending_inputs.clear() + self._pending_output = None + self._closed = True + try: + self._output.close() + except BaseException as error: + if failure is None: + failure = error + if failure is not None: + raise failure + + def _write_locked(self, phase: str, time_ns: int, **fields: Any) -> None: + record = { + **fields, + "schema_version": _SCHEMA_VERSION, + "phase": phase, + "time_ns": time_ns, + } + self._output.write(json.dumps(record, sort_keys=True, separators=(",", ":"))) + self._output.write("\n") + + def _ensure_open_locked(self) -> None: + if self._closed: + raise RuntimeError("RuntimeProfiler is closed.") + + +def _summarize(values: list[float]) -> dict[str, float | int]: + """Summarize one duration distribution.""" + if not values: + return {"count": 0} + ordered = sorted(values) + return { + "count": len(ordered), + "mean_s": statistics.fmean(ordered), + "median_s": statistics.median(ordered), + "p90_s": _percentile(ordered, 0.9), + "max_s": ordered[-1], + } + + +def _elapsed_s(start_ns: int, end_ns: int) -> float: + """Return a valid elapsed duration on one monotonic clock.""" + if end_ns < start_ns: + raise ValueError("A runtime profile observation moved backward in time.") + return (end_ns - start_ns) / 1_000_000_000 + + +def _duration(value: float) -> float: + """Return a finite nonnegative duration.""" + value = float(value) + if not math.isfinite(value) or value < 0: + raise ValueError("Runtime profile durations must be finite and nonnegative.") + return value + + +def _percentile(ordered: list[float], percentile: float) -> float: + """Return a linearly interpolated percentile from sorted samples.""" + if len(ordered) == 1: + return ordered[0] + index = percentile * (len(ordered) - 1) + lower = int(index) + upper = min(lower + 1, len(ordered) - 1) + fraction = index - lower + return ordered[lower] * (1.0 - fraction) + ordered[upper] * fraction + + +__all__ = ["RuntimeProfiler"] diff --git a/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py b/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py index 5ee1b6be7..cb89c7e67 100644 --- a/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py +++ b/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py @@ -16,7 +16,7 @@ from dataclasses import dataclass from fractions import Fraction from importlib.resources import files -from typing import Any, Literal, TypeAlias, cast +from typing import Any, Literal, cast import numpy as np import torch @@ -334,6 +334,11 @@ def url(self) -> str: """Return the browser URL for this server.""" return f"http://{self._host}:{self._port}/" + @property + def input_timestamp_origin_ns(self) -> int | None: + """Return the active session's host monotonic input timestamp origin.""" + return self._session_start_ns + def metrics_snapshot(self) -> dict[str, float | int]: """Return non-blocking sender diagnostics.""" track = self._video_track @@ -389,13 +394,16 @@ def register_input_callback( raise RuntimeError("An input callback is already registered.") self._input_callback = callback - def write(self, result: StepResult) -> None: + def write(self, result: StepResult) -> bool: """Materialize and admit one generated result to the sender mailbox. Args: result: Generated frames matching the description passed to :meth:`open`. + Returns: + Whether a connected sender admitted the frame. + Raises: RuntimeError: The server is not open or has been closed. ValueError: The result shape, layout, or frame count is invalid. @@ -412,9 +420,9 @@ def write(self, result: StepResult) -> None: ) track = self._video_track if track is None: - return + return False queued_frame = self._materialize_video_frame(result, frames[0]) - track.enqueue(queued_frame) + return track.enqueue(queued_frame) def close(self) -> None: """Close the peer connection and stop the WebRTC server.""" diff --git a/flashdreams/flashdreams/runtime_v2/session_runner.py b/flashdreams/flashdreams/runtime_v2/session_runner.py index 79cf2c572..8cf09cd8a 100644 --- a/flashdreams/flashdreams/runtime_v2/session_runner.py +++ b/flashdreams/flashdreams/runtime_v2/session_runner.py @@ -15,6 +15,7 @@ from flashdreams.api_v2.session import ISession from flashdreams.api_v2.user_input_event import UserInputEvent from flashdreams.runtime_v2.event_buffer import EventBuffer +from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler from flashdreams.runtime_v2.session_desc import PresentationMode from flashdreams.runtime_v2.step_result import StepResult from flashdreams.runtime_v2.user_input_event import CloseUserInputEvent @@ -55,6 +56,7 @@ def run_session( window: IClientWindow, *, metrics_output_sink: OutputSink | None = None, + profiler: RuntimeProfiler | None = None, steps: int | None = None, ) -> None: """Run a session's UI and model loops. @@ -72,6 +74,7 @@ def run_session( window: Source of input and destination for UI output. metrics_output_sink: Sink for model measurements, if requested. Receives the model loop's results rather than the UI loop's. + profiler: Optional correlated host-side runtime profiler. steps: Maximum model steps; ``None`` runs until stopped. Raises: @@ -89,20 +92,12 @@ def run_session( stop = session._shutdown_event presentation_manager = session._presentation_manager trace_chunk_lifecycle = session_desc.metadata.get(_TRACE_METADATA_KEY) is True - presentation_manager.configure( - backpressure_mode=session_desc.backpressure_mode, - stop=stop, - put_timeout=tick_seconds, - trace_chunk_lifecycle=trace_chunk_lifecycle, - frames_per_second=session_desc.frames_per_second_for_step, - maximum_frames_per_second=session_desc.frames_per_second_for_ui, - ) model_thread_handle: threading.Thread | None = None ui_loop: IUILoop[object] | None = None model_loop: IModelLoop[object] | None = None high_level_failures: BaseException | None = None cleanup_failures: list[BaseException] = [] - attempted_output_sinks: list[OutputSink] = [] + attempted_output_sinks: list[OutputSink] = [window] def collect_input() -> None: events = window.get_user_input_events() @@ -119,12 +114,43 @@ def run_ui_once() -> None: step_index = ui_loop._begin_run(events, generation) if step_index is None or stop.is_set(): return + profile_started_at_ns = None if profiler is None else profiler.timestamp_ns() + step_started_at = time.monotonic() result = ui_loop.step(step_index, events) + step_elapsed_s = time.monotonic() - step_started_at + profile_completed_at_ns = None if profiler is None else profiler.timestamp_ns() if result is not None and not isinstance(result, StepResult): raise TypeError("A UI loop must return StepResult or None.") ui_loop._finish_run(result) + profile_window_completed_at_ns: int | None = None if result is not None: window.write(result) + if profiler is not None: + profile_window_completed_at_ns = profiler.timestamp_ns() + if profiler is not None: + assert profile_started_at_ns is not None + assert profile_completed_at_ns is not None + profiler.ui_step_started( + events, + generation=generation, + step=step_index, + time_ns=profile_started_at_ns, + ) + profiler.ui_step_completed( + generation=generation, + step=step_index, + duration_s=step_elapsed_s, + presented=result is not None, + time_ns=profile_completed_at_ns, + ) + if result is not None: + assert profile_window_completed_at_ns is not None + profiler.window_write_completed( + endpoint=window.profile_endpoint, + generation=generation, + ui_step=step_index, + time_ns=profile_window_completed_at_ns, + ) def publish_model_results( generation: int, @@ -153,12 +179,21 @@ def tick_ui() -> None: return run_ui_once() - trace_log = ( - _open_chunk_trace(session_desc.metadata.get(_TRACE_PATH_METADATA_KEY)) - if trace_chunk_lifecycle - else None - ) + trace_log: _ChunkTraceLog | None = None try: + presentation_manager.configure( + backpressure_mode=session_desc.backpressure_mode, + stop=stop, + put_timeout=tick_seconds, + trace_chunk_lifecycle=trace_chunk_lifecycle, + runtime_profiler=profiler, + frames_per_second=session_desc.frames_per_second_for_step, + maximum_frames_per_second=session_desc.frames_per_second_for_ui, + ) + if trace_chunk_lifecycle: + trace_log = _open_chunk_trace( + session_desc.metadata.get(_TRACE_PATH_METADATA_KEY) + ) if trace_chunk_lifecycle: _TRACE_LOGGER.info( "%s phase=session_config time_ns=%d backpressure=%s " @@ -182,8 +217,22 @@ def tick_ui() -> None: event_buffer.register(_UI_READER_ID) event_buffer.register(_MODEL_READER_ID) - attempted_output_sinks.append(window) window.open(session_desc) + if profiler is not None: + profiler.session_started( + input_timestamp_origin_ns=window.input_timestamp_origin_ns, + ) + profiler.record( + "session_config", + backpressure=session_desc.backpressure_mode.value, + presentation=session_desc.presentation_mode.value, + step_fps=session_desc.frames_per_second_for_step, + ui_fps=session_desc.frames_per_second_for_ui, + width=session_desc.video_width, + height=session_desc.video_height, + window=type(window).__name__, + endpoint=window.profile_endpoint, + ) if metrics_output_sink is not None: attempted_output_sinks.append(metrics_output_sink) metrics_output_sink.open(session_desc) @@ -197,6 +246,7 @@ def tick_ui() -> None: "event_buffer": event_buffer, "reader_id": _MODEL_READER_ID, "publish": publish_model_results, + "profiler": profiler, "max_steps": steps, }, name=_MODEL_THREAD_NAME, @@ -261,6 +311,11 @@ def tick_ui() -> None: _close_chunk_trace(trace_log) except BaseException as error: cleanup_failures.append(error) + if profiler is not None: + try: + profiler.close() + except BaseException as error: + cleanup_failures.append(error) loop_failures = ( None if session._failure_queue.empty() else session._failure_queue.get() diff --git a/flashdreams/flashdreams/runtime_v2/webrtc_client_window.py b/flashdreams/flashdreams/runtime_v2/webrtc_client_window.py index a1af36e98..6a49ec137 100644 --- a/flashdreams/flashdreams/runtime_v2/webrtc_client_window.py +++ b/flashdreams/flashdreams/runtime_v2/webrtc_client_window.py @@ -10,7 +10,7 @@ from flashdreams.runtime_v2.serving.webrtc_server import WebRTCServer from flashdreams.runtime_v2.session_desc import SessionDesc from flashdreams.runtime_v2.step_result import StepResult -from flashdreams.runtime_v2.user_input_event import MouseUserInputEvent, UserInputEvent +from flashdreams.runtime_v2.user_input_event import UserInputEvent from flashdreams.runtime_v2.user_input_events import UserInputEvents @@ -26,6 +26,16 @@ class WebRTCClientWindow(IClientWindow): window ends on its own even when the session would generate forever. """ + @property + def profile_endpoint(self) -> str | None: + """Name the observable WebRTC boundary reached by the latest write.""" + return self._profile_endpoint + + @property + def input_timestamp_origin_ns(self) -> int | None: + """Return the server session's host monotonic timestamp origin.""" + return self.server.input_timestamp_origin_ns + def __init__( self, *, @@ -45,6 +55,7 @@ def __init__( """ self._input_events: deque[UserInputEvent] = deque() self._input_lock = threading.Lock() + self._profile_endpoint: str | None = None self.server = WebRTCServer( host=host, port=port, @@ -54,7 +65,8 @@ def __init__( def handle_input(event: UserInputEvent) -> None: """Buffer one backend event for the ``InputSource`` protocol.""" # TODO: do we really need to buffer all events? Some mouse moves may be superseded by later ones. - self._input_events.append(event) + with self._input_lock: + self._input_events.append(event) self.server.register_input_callback(handle_input) @@ -83,7 +95,9 @@ def write(self, result: StepResult) -> None: Args: result: One UI-composited frame matching the opened session. """ - self.server.write(result) + self._profile_endpoint = ( + "webrtc_sender_admission" if self.server.write(result) else None + ) def metrics_snapshot(self) -> dict[str, float | int]: """Return sender-queue diagnostics.""" diff --git a/flashdreams/test_v2/test_client_window_factory.py b/flashdreams/test_v2/test_client_window_factory.py index c4f9c67da..4d0ad3d55 100644 --- a/flashdreams/test_v2/test_client_window_factory.py +++ b/flashdreams/test_v2/test_client_window_factory.py @@ -11,7 +11,7 @@ from pathlib import Path import pytest - +from flashdreams.runtime_v2.cli import _parser, _validate_artifact_paths from flashdreams.runtime_v2.client_window_factory import ( add_client_window_arguments, client_window_mode, @@ -69,6 +69,51 @@ def test_a_native_window_mode_is_lazy_and_keeps_its_title() -> None: assert window.title == "World model" +@pytest.mark.parametrize( + ("first_flag", "second_flag"), + [ + ("--profile-path", "--stats-path"), + ("--profile-path", "--output-path"), + ("--stats-path", "--output-path"), + ], +) +def test_output_artifacts_require_distinct_paths( + tmp_path: Path, + first_flag: str, + second_flag: str, +) -> None: + shared = tmp_path / "run-artifact" + arguments = [ + "demo", + "--output-path", + str(tmp_path / "output.mp4"), + first_flag, + str(shared), + second_flag, + str(shared), + ] + parsed = _parser().parse_args(arguments) + + with pytest.raises(ValueError, match="must use different paths"): + _validate_artifact_paths(parsed) + + +def test_output_artifacts_accept_distinct_paths(tmp_path: Path) -> None: + parsed = _parser().parse_args( + [ + "demo", + "--profile-path", + str(tmp_path / "profile.jsonl"), + "--stats-path", + str(tmp_path / "stats.json"), + "--output-path", + str(tmp_path / "output.mp4"), + ] + ) + + _validate_artifact_paths(parsed) + + class TestWebRTC: """Modes that serve a client, which need the serving stack installed.""" diff --git a/flashdreams/test_v2/test_native_window_client_window.py b/flashdreams/test_v2/test_native_window_client_window.py index f5d390ebb..0fac23f0e 100644 --- a/flashdreams/test_v2/test_native_window_client_window.py +++ b/flashdreams/test_v2/test_native_window_client_window.py @@ -13,7 +13,6 @@ import pytest import torch - from flashdreams.runtime_v2 import native_window_client_window as native_window_module from flashdreams.runtime_v2.native_window_client_window import ( NativeWindowClientWindow, @@ -360,6 +359,7 @@ def test_native_window_reports_input_and_close_from_event_pump() -> None: clock_ns=lambda: next(clock_values), ) window.open(_session_desc()) + assert window.input_timestamp_origin_ns == 1_000_000 presenter.pending_events.put(("keyboard", _KeyboardEvent("up", pressed=True))) presenter.pending_events.put( ( diff --git a/flashdreams/test_v2/test_runtime_profiler.py b/flashdreams/test_v2/test_runtime_profiler.py new file mode 100644 index 000000000..496119b3b --- /dev/null +++ b/flashdreams/test_v2/test_runtime_profiler.py @@ -0,0 +1,189 @@ +# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +# SPDX-License-Identifier: Apache-2.0 +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""CPU checks for correlated V2 runtime profiles.""" + +import json + +import pytest +from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler +from flashdreams.runtime_v2.user_input_event import ( + KeyboardInputState, + KeyboardUserInputEvent, +) +from flashdreams.runtime_v2.user_input_events import UserInputEvents +from numpy import uint64 + +pytestmark = pytest.mark.ci_cpu + + +class _Clock: + def __init__(self, now_ns: int = 0) -> None: + self.now_ns = now_ns + + def __call__(self) -> int: + return self.now_ns + + +def _input(timestamp_us: int = 1_000) -> UserInputEvents: + return UserInputEvents( + [ + KeyboardUserInputEvent( + timestamp=uint64(timestamp_us), + key="w", + state=KeyboardInputState.PRESSED, + ) + ] + ) + + +def test_profile_correlates_ui_claim_through_first_window_write(tmp_path) -> None: + clock = _Clock() + path = tmp_path / "runtime.jsonl" + profiler = RuntimeProfiler(path, clock_ns=clock) + profiler.session_started(input_timestamp_origin_ns=0, time_ns=0) + + profiler.model_step_started(generation=2, step=3, time_ns=11_000_000) + profiler.model_step_completed( + generation=2, + step=3, + duration_s=0.02, + time_ns=31_000_000, + ) + profiler.chunk_published( + generation=2, + step=3, + frame_count=4, + wait_s=0.003, + time_ns=34_000_000, + ) + profiler.frame_selected( + generation=2, + step=3, + frame=0, + frame_count=4, + time_ns=41_000_000, + ) + profiler.ui_step_started( + _input(), + generation=2, + step=9, + time_ns=11_000_000, + ) + profiler.ui_step_completed( + generation=2, + step=9, + duration_s=0.004, + presented=True, + time_ns=15_000_000, + ) + profiler.window_write_completed( + endpoint="native_presenter_return", + generation=2, + ui_step=9, + time_ns=51_000_000, + ) + + summary = profiler.summary() + assert summary["input_to_ui_step_s"]["median_s"] == pytest.approx(0.01) + assert summary["input_to_window_write_s"]["median_s"] == pytest.approx(0.05) + assert summary["model_step_s"]["median_s"] == pytest.approx(0.02) + assert summary["ui_step_s"]["median_s"] == pytest.approx(0.004) + assert summary["publish_wait_s"]["median_s"] == pytest.approx(0.003) + assert summary["frame_to_window_write_s"]["median_s"] == pytest.approx(0.01) + + profiler.close() + profiler.close() + records = [json.loads(line) for line in path.read_text().splitlines()] + phases = [record["phase"] for record in records] + assert { + "session_started", + "input_to_ui_step", + "input_to_window_write", + "frame_to_window_write", + } <= set(phases) + output_record = next( + record for record in records if record["phase"] == "input_to_window_write" + ) + assert output_record == { + "schema_version": 1, + "phase": "input_to_window_write", + "time_ns": 51_000_000, + "generation": 2, + "claimed_ui_step": 9, + "presented_ui_step": 9, + "endpoint": "native_presenter_return", + "input_type": "KeyboardUserInputEvent", + "input_timestamp_us": 1_000, + "duration_s": 0.05, + } + assert phases.count("profile_summary") == 6 + + +def test_disconnected_write_preserves_correlations_until_sender_admission( + tmp_path, +) -> None: + profiler = RuntimeProfiler(tmp_path / "runtime.jsonl") + profiler.session_started(input_timestamp_origin_ns=0, time_ns=0) + profiler.ui_step_started(_input(), generation=0, step=0, time_ns=2_000_000) + profiler.frame_selected( + generation=0, + step=0, + frame=0, + frame_count=1, + time_ns=3_000_000, + ) + + profiler.window_write_completed( + endpoint=None, + generation=0, + ui_step=0, + time_ns=4_000_000, + ) + assert profiler.summary()["input_to_window_write_s"] == {"count": 0} + assert profiler.summary()["frame_to_window_write_s"] == {"count": 0} + + profiler.window_write_completed( + endpoint="webrtc_sender_admission", + generation=0, + ui_step=1, + time_ns=5_000_000, + ) + assert profiler.summary()["input_to_window_write_s"]["median_s"] == pytest.approx( + 0.004 + ) + assert profiler.summary()["frame_to_window_write_s"]["median_s"] == pytest.approx( + 0.002 + ) + profiler.close() + + +def test_close_is_final_after_a_summary_write_failure(tmp_path) -> None: + class _FailingOutput: + def write(self, value: str) -> int: + del value + raise OSError("profile write failed") + + def close(self) -> None: + return + + profiler = RuntimeProfiler(tmp_path / "runtime.jsonl") + profiler._output.close() + profiler._output = _FailingOutput() # type: ignore[assignment] + + with pytest.raises(OSError, match="profile write failed"): + profiler.close() + + profiler.close() diff --git a/flashdreams/test_v2/test_session_runner.py b/flashdreams/test_v2/test_session_runner.py index 4f87af25d..f0980ed39 100644 --- a/flashdreams/test_v2/test_session_runner.py +++ b/flashdreams/test_v2/test_session_runner.py @@ -3,6 +3,7 @@ """CPU test for the v2 session loop, independent of any application.""" +import json import logging import queue import threading @@ -12,8 +13,6 @@ import pytest import torch -from numpy import uint64 - from flashdreams.api_v2.client_window import IClientWindow from flashdreams.api_v2.loop import IModelLoop, IUILoop, invoke_async from flashdreams.api_v2.session import ISession @@ -27,6 +26,7 @@ PresentationManager, _PresentationClock, ) +from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler from flashdreams.runtime_v2.session_desc import ( BackpressureMode, PresentationMode, @@ -42,6 +42,7 @@ ) from flashdreams.runtime_v2.user_input_events import UserInputEvents from flashdreams.runtime_v2.video_tensor import VideoTensorLayout +from numpy import uint64 pytestmark = pytest.mark.ci_cpu @@ -474,8 +475,13 @@ def __init__( self._hold_writes = hold_writes self._lock = threading.Lock() self.session_desc: SessionDesc | None = None + self._input_timestamp_origin_ns: int | None = None self.results: list[StepResult] = [] + @property + def input_timestamp_origin_ns(self) -> int | None: + return self._input_timestamp_origin_ns + def get_user_input_events(self) -> UserInputEvents: self._log.record("window.get_user_input_events") with self._lock: @@ -488,6 +494,7 @@ def open(self, session_desc: SessionDesc) -> None: if self._fail_to_open: raise RuntimeError("open failed") self.session_desc = session_desc + self._input_timestamp_origin_ns = time.monotonic_ns() def write(self, result: StepResult) -> None: if self._hold_writes is not None: @@ -548,6 +555,33 @@ def test_run_session_presents_every_step_in_order() -> None: assert steps == ["session.step(0)", "session.step(1)", "session.step(2)"] +def test_run_session_profiles_input_through_window_write(tmp_path) -> None: + log = CallLog() + session = FakeSession(_session_desc(), log) + window = RecordingClientWindow(log, [_key_event()]) + profile_path = tmp_path / "runtime.jsonl" + + run_session( + session, + window, + profiler=RuntimeProfiler(profile_path), + steps=1, + ) + + records = [json.loads(line) for line in profile_path.read_text().splitlines()] + phases = {record["phase"] for record in records} + assert { + "input_to_ui_step", + "input_to_window_write", + "profile_summary", + } <= phases + output_record = next( + record for record in records if record["phase"] == "input_to_window_write" + ) + assert output_record["endpoint"] == "window_write_return" + assert output_record["input_type"] == "KeyboardUserInputEvent" + + def test_run_session_opens_before_writing_and_closes_after() -> None: log = CallLog() session = FakeSession(_session_desc(), log) @@ -1097,9 +1131,33 @@ def init(self) -> None: with pytest.raises(RuntimeError, match="init failed"): run_session(session, window, steps=1) - # A session that got halfway through starting still has to be released, and - # the window is never opened for a session that cannot run. - assert log.calls == ["session.init", "session.close"] + # A session and its constructor-owned window are released together. + assert log.calls == ["session.init", "window.close", "session.close"] + + +def test_run_session_closes_owned_resources_when_trace_open_fails(tmp_path) -> None: + log = CallLog() + session_desc = _session_desc() + session_desc.metadata.update( + { + "trace_chunk_lifecycle": True, + "trace_chunk_lifecycle_path": tmp_path, + } + ) + session = FakeSession(session_desc, log) + window = RecordingClientWindow(log) + profile_path = tmp_path / "runtime.jsonl" + + with pytest.raises(IsADirectoryError): + run_session( + session, + window, + profiler=RuntimeProfiler(profile_path), + steps=1, + ) + + assert log.calls == ["window.close", "session.close"] + assert '"phase":"profile_summary"' in profile_path.read_text() def test_run_session_gives_the_step_after_a_reset_the_whole_batch() -> None: diff --git a/flashdreams/test_v2/test_webrtc_client_window.py b/flashdreams/test_v2/test_webrtc_client_window.py index 4760d47d7..530bef8a0 100644 --- a/flashdreams/test_v2/test_webrtc_client_window.py +++ b/flashdreams/test_v2/test_webrtc_client_window.py @@ -28,7 +28,6 @@ ) from aiortc.mediastreams import MediaStreamError from av import VideoFrame - from flashdreams.runtime_v2.serving import webrtc_server from flashdreams.runtime_v2.serving.webrtc_server import _VideoTrack from flashdreams.runtime_v2.session_desc import PresentationMode, SessionDesc @@ -444,6 +443,7 @@ def test_window_write_materializes_before_synchronous_sender_admission( source = torch.full((1, 3, 16, 16), 31, dtype=torch.uint8) try: window.open(_session_desc()) + assert window.input_timestamp_origin_ns is not None window.server._video_track = cast(Any, track) window.server._media_connected.set() with monkeypatch.context() as patch: @@ -465,6 +465,7 @@ def test_window_write_materializes_before_synchronous_sender_admission( track.enqueue.assert_called_once() assert len(captured) == 1 assert _frame_mean(captured[0]) == 31.0 + assert window.profile_endpoint == "webrtc_sender_admission" finally: window.server._video_track = None window.server._media_connected.clear() @@ -491,6 +492,7 @@ def test_window_write_queues_during_media_negotiation() -> None: track.enqueue.assert_called_once() assert [_frame_mean(frame) for frame in captured] == [0.0] + assert window.profile_endpoint == "webrtc_sender_admission" finally: window.server._video_track = None window.close() From 1b6cc195f1c8d27ed3aac3b9bd5c8387a55e364a Mon Sep 17 00:00:00 2001 From: Ziming Wang Date: Thu, 3 Sep 2026 10:01:45 -0700 Subject: [PATCH 2/6] Reject WebRTC admission while disconnected Linearize peer availability and frame admission under the track state lock. Preserve negotiation queuing and reopen admission after peer recovery. Signed-off-by: Ziming Wang --- .../developer_guides/latency_tuning.rst | 11 ++-- .../runtime_v2/serving/webrtc_server.py | 16 ++++-- .../test_v2/test_webrtc_client_window.py | 52 +++++++++++++++++-- 3 files changed, 66 insertions(+), 13 deletions(-) diff --git a/docs/source/developer_guides/latency_tuning.rst b/docs/source/developer_guides/latency_tuning.rst index 50b5ff9df..27c10ef4d 100644 --- a/docs/source/developer_guides/latency_tuning.rst +++ b/docs/source/developer_guides/latency_tuning.rst @@ -186,11 +186,12 @@ median, p90, and maximum values for these measurements: The ``endpoint`` field defines the final boundary. Native-window records use ``native_presenter_return`` after the presenter returns. WebRTC records use ``webrtc_sender_admission`` after frame materialization and sender admission. -Writes completed without a connected WebRTC sender carry a null endpoint. Input -and selected-frame correlations remain pending until a sender admits a later -write. Browser decode, network transit, compositor scheduling, and physical -scanout form a client-side continuation and can be joined with browser -telemetry. +The sender mailbox is active during WebRTC negotiation. An explicit +``disconnected`` state gives writes a null endpoint until the same peer reaches +``connected`` again. Input and selected-frame correlations remain pending until +a sender admits a later write. Browser decode, network transit, compositor +scheduling, and physical scanout form a client-side continuation and can be +joined with browser telemetry. Profiles add host timestamping and JSONL writes to the measured run. Keep the same profile setting across candidate and reference measurements. Use Nsight diff --git a/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py b/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py index cb89c7e67..ccb76ba84 100644 --- a/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py +++ b/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py @@ -143,6 +143,7 @@ def __init__(self, frames_per_second: int) -> None: self._first_enqueued_at: float | None = None self._next_pts = 0 self._frame_in_flight = False + self._sender_available = True self._closed = False def metrics_snapshot(self) -> dict[str, float | int]: @@ -170,10 +171,11 @@ def enqueue(self, frame: VideoFrame) -> bool: """Synchronously admit one real frame and wake the sender. Returns: - Whether the frame was admitted. A closed track rejects it. + Whether the active sender mailbox admitted the frame. Closed and + explicitly disconnected tracks reject it. """ with self._state_lock: - if self._closed: + if self._closed or not self._sender_available: return False enqueued_at = time.monotonic() queued_frame = _QueuedRGBFrame( @@ -192,6 +194,11 @@ def enqueue(self, frame: VideoFrame) -> bool: self._sender_loop.call_soon_threadsafe(self._finish_enqueue) return True + def set_sender_available(self, available: bool) -> None: + """Update whether the peer can admit newly produced frames.""" + with self._state_lock: + self._sender_available = available + async def recv(self) -> VideoFrame: """Serialize aiortc demand for the bounded frame queue.""" async with self._recv_lock: @@ -402,7 +409,7 @@ def write(self, result: StepResult) -> bool: :meth:`open`. Returns: - Whether a connected sender admitted the frame. + Whether the active sender mailbox admitted the frame. Raises: RuntimeError: The server is not open or has been closed. @@ -643,10 +650,13 @@ def on_close() -> None: @peer_connection.on("connectionstatechange") async def on_connectionstatechange() -> None: if peer_connection.connectionState == "connected": + video_track.set_sender_available(True) self._media_connected.set() elif peer_connection.connectionState == "disconnected": + video_track.set_sender_available(False) self._media_connected.clear() elif peer_connection.connectionState in {"failed", "closed"}: + video_track.set_sender_available(False) self._media_connected.clear() self._record_client_disconnect() diff --git a/flashdreams/test_v2/test_webrtc_client_window.py b/flashdreams/test_v2/test_webrtc_client_window.py index 530bef8a0..7ab9db5e2 100644 --- a/flashdreams/test_v2/test_webrtc_client_window.py +++ b/flashdreams/test_v2/test_webrtc_client_window.py @@ -324,12 +324,54 @@ async def transition(connection_state: str) -> None: server_loop = window.server._loop assert server_loop is not None - for connection_state in ("connected", "disconnected", "connected"): - future = asyncio.run_coroutine_threadsafe( - transition(connection_state), - server_loop, + future = asyncio.run_coroutine_threadsafe(transition("connected"), server_loop) + await asyncio.wrap_future(future) + window.write( + StepResult( + step_index=0, + output=torch.zeros((1, 3, 16, 16), dtype=torch.uint8), + frame_count=1, + output_layout=VideoTensorLayout.tchw, ) - await asyncio.wrap_future(future) + ) + assert window.profile_endpoint == "webrtc_sender_admission" + admitted_before_disconnect = window.metrics_snapshot()[ + "webrtc_sender_enqueued_count" + ] + + future = asyncio.run_coroutine_threadsafe( + transition("disconnected"), server_loop + ) + await asyncio.wrap_future(future) + window.write( + StepResult( + step_index=1, + output=torch.ones((1, 3, 16, 16), dtype=torch.uint8), + frame_count=1, + output_layout=VideoTensorLayout.tchw, + ) + ) + assert window.profile_endpoint is None + assert ( + window.metrics_snapshot()["webrtc_sender_enqueued_count"] + == admitted_before_disconnect + ) + + future = asyncio.run_coroutine_threadsafe(transition("connected"), server_loop) + await asyncio.wrap_future(future) + window.write( + StepResult( + step_index=2, + output=torch.full((1, 3, 16, 16), 2, dtype=torch.uint8), + frame_count=1, + output_layout=VideoTensorLayout.tchw, + ) + ) + assert window.profile_endpoint == "webrtc_sender_admission" + assert ( + window.metrics_snapshot()["webrtc_sender_enqueued_count"] + == admitted_before_disconnect + 1 + ) assert window.server._media_connected.is_set() assert window.server._client_connected From 1f5251b35ea40ae7bac53772bc7319bcbd7da449 Mon Sep 17 00:00:00 2001 From: Ziming Wang Date: Thu, 3 Sep 2026 11:21:37 -0700 Subject: [PATCH 3/6] Narrow V2 profiling to perceived input latency Keep the timestamp clock bridge on a dedicated input-source extension. Measure IUILoop claim and the first following window write. Remove transport-specific and duplicated stage instrumentation. Signed-off-by: Ziming Wang --- AGENTS.md | 2 +- .../developer_guides/latency_tuning.rst | 52 +- .../flashdreams/api_v2/client_window.py | 10 - .../flashdreams/api_v2/input_source.py | 14 + flashdreams/flashdreams/api_v2/loop.py | 23 - flashdreams/flashdreams/runtime_v2/README.md | 15 +- .../runtime_v2/application_runner.py | 14 +- flashdreams/flashdreams/runtime_v2/cli.py | 91 ++-- .../runtime_v2/native_window_client_window.py | 13 +- .../runtime_v2/presentation_manager.py | 169 +++--- .../runtime_v2/runtime_profiler.py | 480 +++++------------- .../runtime_v2/serving/webrtc_server.py | 25 +- .../flashdreams/runtime_v2/session_runner.py | 107 ++-- .../runtime_v2/webrtc_client_window.py | 18 +- .../test_v2/test_client_window_factory.py | 42 +- .../test_native_window_client_window.py | 4 +- flashdreams/test_v2/test_runtime_profiler.py | 158 ++---- flashdreams/test_v2/test_session_runner.py | 58 +-- .../test_v2/test_webrtc_client_window.py | 55 +- 19 files changed, 426 insertions(+), 924 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index c38f58b7f..b93644db6 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -85,7 +85,7 @@ Use `--no-instantiate` before GPU work to inspect the resolved runner config wit - Inspect available runners with `uv run flashdreams-run --help`, then inspect a specific runner with `uv run flashdreams-run --no-instantiate `. - Prefer CPU checks first: config imports, checkpoint key-remap shape/bijection tests on CPU or meta tensors, docs builds, `pytest -m ci_cpu`, and static assertions about runner names and pipeline wiring. -- For interactive V2 latency work, capture `--profile-path artifacts/.jsonl` and use `docs/source/developer_guides/latency_tuning.rst` to interpret each host-side endpoint. +- For interactive V2 input latency, capture `--profile-path artifacts/.jsonl` and read `docs/source/developer_guides/latency_tuning.rst` for the two measurement boundaries. - Avoid `ci_gpu`, generation, `torchrun`, Docker GPU tests, large Hugging Face downloads, rollout parity, CUDA graph, WebRTC runtime, and quality-regression tests on CPU-only hosts unless the user requests them or the test explicitly skips cleanly. ## Testing Guidance diff --git a/docs/source/developer_guides/latency_tuning.rst b/docs/source/developer_guides/latency_tuning.rst index 27c10ef4d..48df1e29a 100644 --- a/docs/source/developer_guides/latency_tuning.rst +++ b/docs/source/developer_guides/latency_tuning.rst @@ -157,45 +157,31 @@ resolution, and native-acceleration knobs first. Profiling and validated reference --------------------------------- -V2 runtime input latency profile -~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +V2 perceived input latency +~~~~~~~~~~~~~~~~~~~~~~~~~~ -Use ``--profile-path`` with any V2 application to write a correlated JSONL -profile under ``artifacts/``: +Use ``--profile-path`` with a V2 application to write a JSONL profile: .. code-block:: bash uv run flashdreams-run-v2 interactive-drive-omnidreams-perf \ --mode native-window \ - --profile-path artifacts/interactive-drive-runtime.jsonl - -Every record uses the host monotonic clock. Input latency starts at the existing -session-relative ``UserInputEvent.timestamp`` and follows the UI step that first -claims the event. The final ``profile_summary`` records report count, mean, -median, p90, and maximum values for these measurements: - -- ``input_to_ui_step_s`` measures event receipt through UI-step entry. -- ``input_to_window_write_s`` measures event receipt through the first - observable client-window write after its UI claim. -- ``model_step_s`` measures the model loop's ``step`` call. -- ``ui_step_s`` measures the UI loop's ``step`` call. -- ``publish_wait_s`` measures admission to the bounded presentation queue. -- ``frame_to_window_write_s`` measures UI composition and the observable - client-window write. - -The ``endpoint`` field defines the final boundary. Native-window records use -``native_presenter_return`` after the presenter returns. WebRTC records use -``webrtc_sender_admission`` after frame materialization and sender admission. -The sender mailbox is active during WebRTC negotiation. An explicit -``disconnected`` state gives writes a null endpoint until the same peer reaches -``connected`` again. Input and selected-frame correlations remain pending until -a sender admits a later write. Browser decode, network transit, compositor -scheduling, and physical scanout form a client-side continuation and can be -joined with browser telemetry. - -Profiles add host timestamping and JSONL writes to the measured run. Keep the -same profile setting across candidate and reference measurements. Use Nsight -Systems for CUDA kernel, stream, and CPU/GPU overlap analysis. + --profile-path artifacts/interactive-drive-input-latency.jsonl + +The input source publishes the monotonic origin for its session-relative +``UserInputEvent.timestamp`` values. ``run_session`` then records two metrics: + +- ``input_to_ui_step_s`` ends when the IUILoop claims the event. +- ``input_to_window_write_s`` ends when the first following client-window + ``write`` call returns. + +Native-window and WebRTC writes expose different host-side delivery boundaries. +Browser decode, network transit, compositor scheduling, and physical scanout +require matching client telemetry. The final ``profile_summary`` records report +count, median, p90, and maximum values. + +JSONL writes add host overhead to the measured run. Keep profiling enabled for +every run in a direct comparison. Use Nsight Systems for GPU stage attribution. Set ``output.profile_world_model: true`` to enable FlashDreams CUDA-event profiling for the world-model runtime. Set ``output.sync_gpu_timing: true`` only diff --git a/flashdreams/flashdreams/api_v2/client_window.py b/flashdreams/flashdreams/api_v2/client_window.py index 9463dcd63..8befe1c02 100644 --- a/flashdreams/flashdreams/api_v2/client_window.py +++ b/flashdreams/flashdreams/api_v2/client_window.py @@ -24,13 +24,3 @@ class IClientWindow(InputSource, OutputSink, ABC): Created by the runtime, never by an application. """ - - @property - def profile_endpoint(self) -> str | None: - """Name the observable boundary reached when ``write`` returns.""" - return "window_write_return" - - @property - def input_timestamp_origin_ns(self) -> int | None: - """Return the host monotonic origin for input-event timestamps.""" - return None diff --git a/flashdreams/flashdreams/api_v2/input_source.py b/flashdreams/flashdreams/api_v2/input_source.py index d64a4df88..f61c6ed3b 100644 --- a/flashdreams/flashdreams/api_v2/input_source.py +++ b/flashdreams/flashdreams/api_v2/input_source.py @@ -31,3 +31,17 @@ def get_user_input_events(self) -> UserInputEvents: Events in timestamp order, empty when nothing arrived. """ ... + + +@runtime_checkable +class TimestampedInputSource(InputSource, Protocol): + """Input source whose event timestamps share the runtime monotonic clock.""" + + @property + @abstractmethod + def input_timestamp_origin_ns(self) -> int | None: + """Return the runtime-clock origin for session-relative timestamps.""" + ... + + +__all__ = ["InputSource", "TimestampedInputSource"] diff --git a/flashdreams/flashdreams/api_v2/loop.py b/flashdreams/flashdreams/api_v2/loop.py index 841285b38..491703b0b 100644 --- a/flashdreams/flashdreams/api_v2/loop.py +++ b/flashdreams/flashdreams/api_v2/loop.py @@ -23,7 +23,6 @@ if TYPE_CHECKING: from flashdreams.runtime_v2.presentation_manager import PresentationManager - from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler StateT = TypeVar("StateT") @@ -220,7 +219,6 @@ def _run_model_loop( event_buffer: EventBuffer, reader_id: int, publish: Callable[[int, list[StepResult], float], None], - profiler: RuntimeProfiler | None = None, max_steps: int | None = None, ) -> None: """Run model steps until shutdown or completion. @@ -230,7 +228,6 @@ def _run_model_loop( reader_id: This loop's event reader ID. publish: Function called with each model result and the elapsed seconds spent in :meth:`step`. - profiler: Optional correlated runtime profiler. max_steps: Maximum steps; ``None`` runs until stopped. """ steps_run = 0 @@ -246,29 +243,9 @@ def _run_model_loop( last_run_started = self._pace(last_run_started) if self._shutdown_event.is_set(): break - profile_started_at_ns = ( - None if profiler is None else profiler.timestamp_ns() - ) step_started_at = time.monotonic() raw_result = self.step(step_index, events) step_elapsed_s = time.monotonic() - step_started_at - profile_completed_at_ns = ( - None if profiler is None else profiler.timestamp_ns() - ) - if profiler is not None: - assert profile_started_at_ns is not None - assert profile_completed_at_ns is not None - profiler.model_step_started( - generation=generation, - step=step_index, - time_ns=profile_started_at_ns, - ) - profiler.model_step_completed( - generation=generation, - step=step_index, - duration_s=step_elapsed_s, - time_ns=profile_completed_at_ns, - ) result = _model_results(raw_result) self._finish_run(result) publish(generation, result, step_elapsed_s) diff --git a/flashdreams/flashdreams/runtime_v2/README.md b/flashdreams/flashdreams/runtime_v2/README.md index ba8ea8bc6..09de1a2eb 100644 --- a/flashdreams/flashdreams/runtime_v2/README.md +++ b/flashdreams/flashdreams/runtime_v2/README.md @@ -111,15 +111,6 @@ presentation-queue depth/publish-wait measurements under the reserved `runtime_` metric prefix. UI and window timings are not folded into a later model record because they describe a different frame. -`--profile-path artifacts/.jsonl` adds a correlated host-side runtime -profile. It follows each input event through the UI step that claims it and the -next observable client-window write. Native-window records end at presenter -return. WebRTC records end at sender admission. The final records summarize -model-step, UI-step, publish, presentation, client-window, and input-latency -distributions. The -[latency tuning guide](../../../docs/source/developer_guides/latency_tuning.rst) -defines every field and measurement boundary. - ## Starting and stopping a run `ApplicationRunner.run` calls `init`, `create_session` and `run_session` in @@ -222,6 +213,12 @@ The default UI loop, `BlitModelOutputToScreenLoop`, composites every model channel in list order as if they were image layers and reshapes the result into the session's layout. +`--profile-path artifacts/.jsonl` records event-to-IUILoop and +event-to-window-write latency. Each input source supplies the monotonic origin +for its session-relative event timestamps. The +[latency tuning guide](../../../docs/source/developer_guides/latency_tuning.rst) +defines the JSONL records and host-side boundaries. + `SlangPyUILoop` is the alternative for SlangPy's retained widget subset. `ImGuiUILoop` exposes the complete ImGui API. Both return a `[1, C, H, W]` frame, so an `ISession` using either should declare a `tchw` output layout. diff --git a/flashdreams/flashdreams/runtime_v2/application_runner.py b/flashdreams/flashdreams/runtime_v2/application_runner.py index 4e2804d5f..bc7bf9068 100644 --- a/flashdreams/flashdreams/runtime_v2/application_runner.py +++ b/flashdreams/flashdreams/runtime_v2/application_runner.py @@ -34,7 +34,7 @@ def __init__( application: Long-lived application that creates the session. client_window: Window that supplies input and presents generated output. metrics_output_sink: Optional sink for model-step metrics. - profiler: Optional correlated host-side runtime profiler. + profiler: Optional perceived input-latency profiler. """ self._application = application self._client_window = client_window @@ -75,8 +75,6 @@ def run( _close_client_window(self._client_window) if self._metrics_output_sink is not None: _close_output_sink(self._metrics_output_sink) - if self._profiler is not None: - _close_profiler(self._profiler) _close_application( self._application, run_failed=sys.exc_info()[0] is not None ) @@ -106,16 +104,6 @@ def _close_output_sink(output_sink: OutputSink) -> None: ) -def _close_profiler(profiler: RuntimeProfiler) -> None: - """Close a runtime profile after a run that never reached the session.""" - try: - profiler.close() - except Exception: - _LOGGER.exception( - "The runtime profiler failed to close after a run that never started." - ) - - def _close_application(application: IApplication, *, run_failed: bool) -> None: """Close an application, keeping its close from hiding an earlier failure. diff --git a/flashdreams/flashdreams/runtime_v2/cli.py b/flashdreams/flashdreams/runtime_v2/cli.py index 9aeec5a66..e37026177 100644 --- a/flashdreams/flashdreams/runtime_v2/cli.py +++ b/flashdreams/flashdreams/runtime_v2/cli.py @@ -14,7 +14,6 @@ """ import argparse -import logging import sys from collections.abc import Sequence from dataclasses import replace @@ -40,8 +39,6 @@ ) from flashdreams.runtime_v2.video_tensor import VideoTensorLayout -_LOGGER = logging.getLogger(__name__) - _ARGUMENT_SEPARATOR = "--" """What separates this command's arguments from the application's. @@ -68,7 +65,7 @@ def entrypoint(argv: Sequence[str] | None = None) -> None: if not wants_application_help: try: mode.check_arguments(parsed) - _validate_artifact_paths(parsed) + _validate_profile_path(parsed) except ValueError as error: parser.error(str(error)) @@ -79,33 +76,23 @@ def entrypoint(argv: Sequence[str] | None = None) -> None: application.init(application_args) return session_desc = _session_desc(application, parsed) + window = mode.create(parsed) + _report(mode.starting(window)) + # Nothing here says how long the run is: a session reports itself finished, + # and a window ends the run when its client goes away. + metrics_output_sink = ( + None if parsed.stats_path is None else MetricsOutputSink(parsed.stats_path) + ) profiler = ( None if parsed.profile_path is None else RuntimeProfiler(parsed.profile_path) ) - runner_owns_profiler = False - try: - window = mode.create(parsed) - _report(mode.starting(window)) - # Nothing here says how long the run is: a session reports itself finished, - # and a window ends the run when its client goes away. - metrics_output_sink = ( - None if parsed.stats_path is None else MetricsOutputSink(parsed.stats_path) - ) - runner = ApplicationRunner( - application, - window, - metrics_output_sink=metrics_output_sink, - profiler=profiler, - ) - runner_owns_profiler = True - runner.run(session_desc, application_args) - _report(mode.finished(window)) - finally: - if profiler is not None and not runner_owns_profiler: - _close_unowned_profiler( - profiler, - setup_failed=sys.exc_info()[0] is not None, - ) + ApplicationRunner( + application, + window, + metrics_output_sink=metrics_output_sink, + profiler=profiler, + ).run(session_desc, application_args) + _report(mode.finished(window)) def split_arguments(arguments: Sequence[str]) -> tuple[list[str], list[str]]: @@ -160,7 +147,7 @@ def _add_session_arguments(parser: argparse.ArgumentParser) -> None: "--profile-path", type=Path, default=None, - help="Write correlated host-side runtime latency records as JSONL.", + help="Write perceived input-latency records as JSONL.", ) parser.add_argument( "--pixel-width", type=int, default=None, help="Frame width to generate." @@ -202,39 +189,19 @@ def _add_session_arguments(parser: argparse.ArgumentParser) -> None: ) -def _validate_artifact_paths(parsed: argparse.Namespace) -> None: - """Require every active output artifact to own a distinct path.""" - artifacts = [ - ("--profile-path", parsed.profile_path), - ("--stats-path", parsed.stats_path), - ( - "--output-path", - parsed.output_path if parsed.mode == "mp4" else None, - ), - ] - owners: dict[Path, str] = {} - for flag, path in artifacts: - if path is None: - continue - resolved = path.expanduser().resolve() - existing = owners.get(resolved) - if existing is not None: - raise ValueError(f"{existing} and {flag} must use different paths.") - owners[resolved] = flag - - -def _close_unowned_profiler( - profiler: RuntimeProfiler, - *, - setup_failed: bool, -) -> None: - """Close a profiler retained by CLI setup.""" - try: - profiler.close() - except Exception: - if not setup_failed: - raise - _LOGGER.exception("The runtime profiler failed to close during CLI setup.") +def _validate_profile_path(parsed: argparse.Namespace) -> None: + """Keep the profile separate from artifacts written by the same run.""" + if parsed.profile_path is None: + return + profile_path = parsed.profile_path.expanduser().resolve() + other_paths = [parsed.stats_path] + if parsed.mode == "mp4": + other_paths.append(parsed.output_path) + if any( + path is not None and path.expanduser().resolve() == profile_path + for path in other_paths + ): + raise ValueError("--profile-path must use a distinct output path.") def _session_desc( diff --git a/flashdreams/flashdreams/runtime_v2/native_window_client_window.py b/flashdreams/flashdreams/runtime_v2/native_window_client_window.py index 003510a1f..265fe2b0f 100644 --- a/flashdreams/flashdreams/runtime_v2/native_window_client_window.py +++ b/flashdreams/flashdreams/runtime_v2/native_window_client_window.py @@ -91,14 +91,11 @@ class NativeWindowClientWindow(IClientWindow): """Present UI output through a main-thread GLFW window.""" - @property - def profile_endpoint(self) -> str: - """Name the completed native presentation boundary.""" - return "native_presenter_return" - @property def input_timestamp_origin_ns(self) -> int | None: - """Return the native session's host monotonic timestamp origin.""" + """Return the native session's monotonic input timestamp origin.""" + if not self._input_timestamps_share_runtime_clock: + return None return self._session_started_ns def __init__( @@ -123,6 +120,7 @@ def __init__( self.title = title self._presenter_factory = presenter_factory self._clock_ns = clock_ns + self._input_timestamps_share_runtime_clock = clock_ns is time.monotonic_ns self._session_started_ns: int | None = None self._session_desc: SessionDesc | None = None self._input_events: queue.SimpleQueue[UserInputEvent] = queue.SimpleQueue() @@ -145,7 +143,8 @@ def open(self, session_desc: SessionDesc) -> None: """ if threading.current_thread() is not threading.main_thread(): raise RuntimeError( - "NativeWindowClientWindow.open() must run on the process main thread for event polling." + "NativeWindowClientWindow.open() must run on the process main " + "thread for event polling." ) if self._presenter is not None: raise RuntimeError("NativeWindowClientWindow is already open.") diff --git a/flashdreams/flashdreams/runtime_v2/presentation_manager.py b/flashdreams/flashdreams/runtime_v2/presentation_manager.py index 0ab1d1583..ee712220e 100644 --- a/flashdreams/flashdreams/runtime_v2/presentation_manager.py +++ b/flashdreams/flashdreams/runtime_v2/presentation_manager.py @@ -15,7 +15,6 @@ from flashdreams.runtime_v2.cuda_utils import resolve_cuda_device from flashdreams.runtime_v2.recent_frame_rate import RecentFrameRateTracker -from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler from flashdreams.runtime_v2.session_desc import BackpressureMode from flashdreams.runtime_v2.step_result import StepResult from flashdreams.runtime_v2.video_tensor import VideoTensorLayout @@ -186,7 +185,6 @@ def __init__(self, *, device: torch.device | None = None) -> None: self._stream_lock = threading.Lock() self._infer_stream_device = device is None self._trace_chunk_lifecycle = False - self._runtime_profiler: RuntimeProfiler | None = None self._presentation_stream: torch.cuda.Stream | None = None if device is not None: device = torch.device(device) @@ -207,7 +205,6 @@ def configure( stop: threading.Event, put_timeout: float, trace_chunk_lifecycle: bool = False, - runtime_profiler: RuntimeProfiler | None = None, frames_per_second: int = 30, maximum_frames_per_second: int | None = None, ) -> None: @@ -221,7 +218,6 @@ def configure( put_timeout: How long a blocked publish waits before rechecking ``stop``, in seconds. trace_chunk_lifecycle: Emit chunk lifecycle diagnostics. - runtime_profiler: Record model-chunk publication, selection, and drops. frames_per_second: Initial video presentation rate. maximum_frames_per_second: Upper bound for presentation cadence; ``None`` uses ``frames_per_second``. @@ -235,7 +231,6 @@ def configure( self._stop = stop self._put_timeout = put_timeout self._trace_chunk_lifecycle = trace_chunk_lifecycle - self._runtime_profiler = runtime_profiler def publish( self, @@ -293,26 +288,15 @@ def publish( buffered_chunks=self.buffered_chunk_count, chunk_capacity=self.buffered_chunk_capacity, ) - profile_started_ns = ( - None - if self._runtime_profiler is None - else self._runtime_profiler.timestamp_ns() - ) pending = (generation, chunk) if self._backpressure_mode is BackpressureMode.DROP_OLDEST: - if self._publish_latest(pending): - self._record_publish_completed(pending, started_ns, profile_started_ns) - elif self._runtime_profiler is not None: - self._runtime_profiler.chunk_dropped( - generation=generation, - step=chunk[0].step_index, - reason="publish_stopped", - ) + self._publish_latest(pending) + self._trace_publish_completed(pending, started_ns) return while not self._stop.is_set(): try: self._bufferedChunks.put(pending, timeout=self._put_timeout) - self._record_publish_completed(pending, started_ns, profile_started_ns) + self._trace_publish_completed(pending, started_ns) return except queue.Full: continue @@ -325,12 +309,6 @@ def publish( buffered_chunks=self.buffered_chunk_count, chunk_capacity=self.buffered_chunk_capacity, ) - if self._runtime_profiler is not None: - self._runtime_profiler.chunk_dropped( - generation=generation, - step=chunk[0].step_index, - reason="publish_stopped", - ) @contextmanager def presentation_context(self) -> Iterator[None]: @@ -381,7 +359,7 @@ def advance( """ if generation != self._generation: if self._presented_chunk is not None: - self._record_drop( + self._trace_drop( self._generation, self._presented_chunk, reason="generation_changed_active", @@ -402,7 +380,7 @@ def advance( ): self._frame_index += 1 self._presented_frame_count += 1 - self._record_presented_frame(generation) + self._trace_presented_frame(generation) self._presentation_clock.mark_advanced(now, backlog=backlog) return True, None @@ -415,7 +393,7 @@ def advance( self._presented_chunk = chunk self._frame_index = 0 self._presented_frame_count += 1 - self._record_presented_frame(generation) + self._trace_presented_frame(generation) self._presentation_clock.mark_advanced(now, backlog=backlog) return True, chunk @@ -600,11 +578,11 @@ def clear(self) -> None: def _reset_buffered_chunks(self) -> None: self._bufferedChunks = queue.Queue(maxsize=1) - def _publish_latest(self, pending: tuple[int, list[StepResult]]) -> bool: + def _publish_latest(self, pending: tuple[int, list[StepResult]]) -> None: while not self._stop.is_set(): try: self._bufferedChunks.put_nowait(pending) - return True + return except queue.Full: try: dropped_generation, dropped_chunk = ( @@ -612,7 +590,7 @@ def _publish_latest(self, pending: tuple[int, list[StepResult]]) -> bool: ) with self._counter_lock: self._dropped_for_space += 1 - self._record_drop( + self._trace_drop( dropped_generation, dropped_chunk, reason="queue_full", @@ -620,7 +598,6 @@ def _publish_latest(self, pending: tuple[int, list[StepResult]]) -> bool: ) except queue.Empty: continue - return False def _take_buffered_chunk( self, generation: int, *, latest: bool @@ -634,7 +611,7 @@ def _take_buffered_chunk( if chunk_generation != generation: with self._counter_lock: self._discarded_at_reset += 1 - self._record_drop( + self._trace_drop( chunk_generation, chunk, reason="generation_mismatch", @@ -643,7 +620,7 @@ def _take_buffered_chunk( if selected is not None: with self._counter_lock: self._dropped_for_space += 1 - self._record_drop( + self._trace_drop( generation, selected, reason="take_latest", @@ -653,77 +630,50 @@ def _take_buffered_chunk( if not latest: return selected - def _record_publish_completed( + def _trace_publish_completed( self, pending: tuple[int, list[StepResult]], started_ns: int | None, - profile_started_ns: int | None, ) -> None: + if started_ns is None: + return generation, chunk = pending - profile_published_at_ns = ( - None - if self._runtime_profiler is None or profile_started_ns is None - else self._runtime_profiler.timestamp_ns() + self._trace( + "publish_completed", + generation=generation, + step=chunk[0].step_index, + frames=chunk[0].frame_count, + wait_ms=(time.monotonic_ns() - started_ns) / 1_000_000.0, + buffered_chunks=self.buffered_chunk_count, + chunk_capacity=self.buffered_chunk_capacity, ) - if started_ns is not None: - self._trace( - "publish_completed", - generation=generation, - step=chunk[0].step_index, - frames=chunk[0].frame_count, - wait_ms=(time.monotonic_ns() - started_ns) / 1_000_000.0, - buffered_chunks=self.buffered_chunk_count, - chunk_capacity=self.buffered_chunk_capacity, - ) - if self._runtime_profiler is not None and profile_published_at_ns is not None: - assert profile_started_ns is not None - self._runtime_profiler.chunk_published( - generation=generation, - step=chunk[0].step_index, - frame_count=chunk[0].frame_count, - wait_s=(profile_published_at_ns - profile_started_ns) / 1_000_000_000, - time_ns=profile_published_at_ns, - ) - def _record_presented_frame(self, generation: int) -> None: + def _trace_presented_frame(self, generation: int) -> None: + if not self._trace_chunk_lifecycle: + return chunk = self._presented_chunk if chunk is None: return - profile_selected_at_ns = ( - None - if self._runtime_profiler is None - else self._runtime_profiler.timestamp_ns() + self._trace( + "frame_presented", + generation=generation, + step=chunk[0].step_index, + frame=self._frame_index, + frames=chunk[0].frame_count, + edge=( + "both" + if chunk[0].frame_count == 1 + else "first" + if self._frame_index == 0 + else "last" + if self._frame_index + 1 == chunk[0].frame_count + else "middle" + ), + buffered_chunks=self.buffered_chunk_count, + chunk_capacity=self.buffered_chunk_capacity, ) - if self._trace_chunk_lifecycle: - self._trace( - "frame_presented", - generation=generation, - step=chunk[0].step_index, - frame=self._frame_index, - frames=chunk[0].frame_count, - edge=( - "both" - if chunk[0].frame_count == 1 - else "first" - if self._frame_index == 0 - else "last" - if self._frame_index + 1 == chunk[0].frame_count - else "middle" - ), - buffered_chunks=self.buffered_chunk_count, - chunk_capacity=self.buffered_chunk_capacity, - ) - if self._runtime_profiler is not None: - assert profile_selected_at_ns is not None - self._runtime_profiler.frame_selected( - generation=generation, - step=chunk[0].step_index, - frame=self._frame_index, - frame_count=chunk[0].frame_count, - time_ns=profile_selected_at_ns, - ) - def _record_drop( + def _trace_drop( self, generation: int, chunk: list[StepResult], @@ -731,25 +681,20 @@ def _record_drop( reason: str, replacement: tuple[int, list[StepResult]] | None = None, ) -> None: - if self._trace_chunk_lifecycle: - fields: dict[str, object] = { - "generation": generation, - "step": chunk[0].step_index, - "frames": chunk[0].frame_count, - "reason": reason, - "buffered_chunks": self.buffered_chunk_count, - } - if replacement is not None: - replacement_generation, replacement_chunk = replacement - fields["replacement_generation"] = replacement_generation - fields["replacement_step"] = replacement_chunk[0].step_index - self._trace("chunk_dropped", **fields) - if self._runtime_profiler is not None: - self._runtime_profiler.chunk_dropped( - generation=generation, - step=chunk[0].step_index, - reason=reason, - ) + if not self._trace_chunk_lifecycle: + return + fields: dict[str, object] = { + "generation": generation, + "step": chunk[0].step_index, + "frames": chunk[0].frame_count, + "reason": reason, + "buffered_chunks": self.buffered_chunk_count, + } + if replacement is not None: + replacement_generation, replacement_chunk = replacement + fields["replacement_generation"] = replacement_generation + fields["replacement_step"] = replacement_chunk[0].step_index + self._trace("chunk_dropped", **fields) def _trace(self, phase: str, **fields: object) -> None: if not self._trace_chunk_lifecycle: diff --git a/flashdreams/flashdreams/runtime_v2/runtime_profiler.py b/flashdreams/flashdreams/runtime_v2/runtime_profiler.py index 91529efa7..95d8bf03d 100644 --- a/flashdreams/flashdreams/runtime_v2/runtime_profiler.py +++ b/flashdreams/flashdreams/runtime_v2/runtime_profiler.py @@ -13,16 +13,13 @@ # See the License for the specific language governing permissions and # limitations under the License. -"""Correlated host-side latency profiling for the V2 runtime.""" +"""Perceived input-latency profiling for the V2 runtime.""" from __future__ import annotations import json -import math import statistics -import threading import time -from collections.abc import Callable from dataclasses import dataclass from pathlib import Path from typing import IO, Any @@ -30,147 +27,64 @@ from flashdreams.runtime_v2.user_input_events import UserInputEvents _SCHEMA_VERSION = 1 -"""Runtime profile JSONL schema version.""" @dataclass(frozen=True, slots=True) class _ClaimedInput: - """One input event claimed by a UI step.""" - received_at_ns: int + claimed_at_ns: int + claim_duration_s: float timestamp_us: int event_type: str generation: int ui_step: int -@dataclass(frozen=True, slots=True) -class _PendingOutput: - """One selected model frame waiting for a client-window write.""" - - generation: int - step: int - frame: int - selected_at_ns: int - - class RuntimeProfiler: - """Write correlated V2 runtime latency records as line-delimited JSON. + """Write input-to-UI and input-to-output latency records as JSONL. - Input events use their session-relative timestamp as the causal origin. The - profiler follows each event from its first UI step to the next observable - client-window write. Model and presentation stages carry independent - ``(generation, step)`` identities. All durations use one host monotonic - clock. A profiler instance belongs to one session and is thread-safe. + One runtime UI thread owns an instance. Input timestamps and runtime + observations share ``time.monotonic_ns`` through the source-provided session + origin. Each claimed input remains pending through the first subsequent + client-window write. """ - def __init__( - self, - path: str | Path, - *, - clock_ns: Callable[[], int] = time.monotonic_ns, - ) -> None: - """Open a new runtime profile. - - Args: - path: JSONL output path. Parent directories are created. - clock_ns: Monotonic clock used for every runtime observation. - """ + def __init__(self, path: str | Path) -> None: + """Configure a profile artifact that opens with the session.""" self._path = Path(path).expanduser() - self._path.parent.mkdir(parents=True, exist_ok=True) - self._output: IO[str] = self._path.open("w", encoding="utf-8") - self._clock_ns = clock_ns - self._lock = threading.Lock() + self._output: IO[str] | None = None self._input_timestamp_origin_ns: int | None = None - self._pending_inputs: list[_ClaimedInput] = [] self._input_generation: int | None = None - self._pending_output: _PendingOutput | None = None + self._pending_inputs: list[_ClaimedInput] = [] self._samples: dict[str, list[float]] = { "input_to_ui_step_s": [], "input_to_window_write_s": [], - "model_step_s": [], - "ui_step_s": [], - "publish_wait_s": [], - "frame_to_window_write_s": [], } self._closed = False - with self._lock: - self._write_locked("profile_started", self._clock_ns()) @property def path(self) -> Path: """Return the profile output path.""" return self._path - def timestamp_ns(self) -> int: - """Return the profiler's monotonic timestamp.""" - return self._clock_ns() - def session_started( self, *, input_timestamp_origin_ns: int | None, time_ns: int | None = None, ) -> None: - """Set the host-clock origin for session-relative input timestamps.""" - observed_at_ns = self._clock_ns() if time_ns is None else time_ns - with self._lock: - self._ensure_open_locked() - self._input_timestamp_origin_ns = input_timestamp_origin_ns - self._write_locked( - "session_started", - observed_at_ns, - input_timestamp_origin_ns=input_timestamp_origin_ns, - ) - - def record(self, phase: str, *, time_ns: int | None = None, **fields: Any) -> None: - """Write one timestamped runtime phase.""" - if not phase.strip(): - raise ValueError("Runtime profile phases must be non-empty.") - observed_at_ns = self._clock_ns() if time_ns is None else time_ns - with self._lock: - self._ensure_open_locked() - self._write_locked(phase, observed_at_ns, **fields) - - def model_step_started( - self, - *, - generation: int, - step: int, - time_ns: int | None = None, - ) -> None: - """Record one model-step entry.""" - started_at_ns = self._clock_ns() if time_ns is None else time_ns - with self._lock: - self._ensure_open_locked() - self._write_locked( - "model_step_started", - started_at_ns, - generation=generation, - step=step, - ) - - def model_step_completed( - self, - *, - generation: int, - step: int, - duration_s: float, - time_ns: int | None = None, - ) -> None: - """Record one completed model step.""" - duration_s = _duration(duration_s) - completed_at_ns = self._clock_ns() if time_ns is None else time_ns - with self._lock: - self._ensure_open_locked() - self._samples["model_step_s"].append(duration_s) - self._write_locked( - "model_step_completed", - completed_at_ns, - generation=generation, - step=step, - duration_s=duration_s, - ) + """Open the artifact and bind input timestamps to the runtime clock.""" + if self._output is not None: + raise RuntimeError("RuntimeProfiler session already started.") + self._ensure_open() + self._path.parent.mkdir(parents=True, exist_ok=True) + self._output = self._path.open("w", encoding="utf-8") + self._input_timestamp_origin_ns = input_timestamp_origin_ns + self._write( + "session_started", + _now_ns(time_ns), + input_timestamp_origin_ns=input_timestamp_origin_ns, + ) def ui_step_started( self, @@ -180,285 +94,159 @@ def ui_step_started( step: int, time_ns: int | None = None, ) -> None: - """Record one UI-step entry and the input events it claims.""" - started_at_ns = self._clock_ns() if time_ns is None else time_ns - event_list = events.get_events() - with self._lock: - self._ensure_open_locked() - if generation != self._input_generation: - self._pending_inputs.clear() - self._input_generation = generation - origin_ns = self._input_timestamp_origin_ns - observations = ( - () - if origin_ns is None - else tuple( - _ClaimedInput( - received_at_ns=origin_ns + int(event.get_timestamp()) * 1_000, - timestamp_us=int(event.get_timestamp()), - event_type=type(event).__name__, - generation=generation, - ui_step=step, - ) - for event in event_list - ) - ) - self._pending_inputs.extend(observations) - self._write_locked( - "ui_step_started", - started_at_ns, - generation=generation, - step=step, - input_count=len(event_list), - timed_input_count=len(observations), - ) - for observation in observations: - duration_s = _elapsed_s(observation.received_at_ns, started_at_ns) - self._samples["input_to_ui_step_s"].append(duration_s) - self._write_locked( - "input_to_ui_step", - started_at_ns, + """Record the UI step that first claims each input event.""" + started_at_ns = _now_ns(time_ns) + self._ensure_started() + if generation != self._input_generation: + self._write_claims(self._pending_inputs) + self._pending_inputs.clear() + self._input_generation = generation + + origin_ns = self._input_timestamp_origin_ns + if origin_ns is None: + return + for event in events.get_events(): + received_at_ns = origin_ns + int(event.get_timestamp()) * 1_000 + claim_duration_s = _elapsed_s(received_at_ns, started_at_ns) + self._pending_inputs.append( + _ClaimedInput( + received_at_ns=received_at_ns, + claimed_at_ns=started_at_ns, + claim_duration_s=claim_duration_s, + timestamp_us=int(event.get_timestamp()), + event_type=type(event).__name__, generation=generation, - step=step, - input_type=observation.event_type, - input_timestamp_us=observation.timestamp_us, - duration_s=duration_s, + ui_step=step, ) - - def ui_step_completed( - self, - *, - generation: int, - step: int, - duration_s: float, - presented: bool, - time_ns: int | None = None, - ) -> None: - """Record one completed UI step.""" - duration_s = _duration(duration_s) - completed_at_ns = self._clock_ns() if time_ns is None else time_ns - with self._lock: - self._ensure_open_locked() - self._samples["ui_step_s"].append(duration_s) - self._write_locked( - "ui_step_completed", - completed_at_ns, - generation=generation, - step=step, - duration_s=duration_s, - presented=presented, - ) - - def chunk_published( - self, - *, - generation: int, - step: int, - frame_count: int, - wait_s: float, - time_ns: int | None = None, - ) -> None: - """Record admission to the presentation queue.""" - wait_s = _duration(wait_s) - published_at_ns = self._clock_ns() if time_ns is None else time_ns - with self._lock: - self._ensure_open_locked() - self._samples["publish_wait_s"].append(wait_s) - self._write_locked( - "chunk_published", - published_at_ns, - generation=generation, - step=step, - frame_count=frame_count, - wait_s=wait_s, - ) - - def chunk_dropped( - self, - *, - generation: int, - step: int, - reason: str, - time_ns: int | None = None, - ) -> None: - """Discard stage state for a dropped model chunk.""" - dropped_at_ns = self._clock_ns() if time_ns is None else time_ns - with self._lock: - self._ensure_open_locked() - if self._pending_output is not None and ( - self._pending_output.generation, - self._pending_output.step, - ) == (generation, step): - self._pending_output = None - self._write_locked( - "chunk_dropped", - dropped_at_ns, - generation=generation, - step=step, - reason=reason, - ) - - def frame_selected( - self, - *, - generation: int, - step: int, - frame: int, - frame_count: int, - time_ns: int | None = None, - ) -> None: - """Record model-frame selection for the next client-window write.""" - selected_at_ns = self._clock_ns() if time_ns is None else time_ns - with self._lock: - self._ensure_open_locked() - self._write_locked( - "frame_selected", - selected_at_ns, - generation=generation, - step=step, - frame=frame, - frame_count=frame_count, - ) - self._pending_output = _PendingOutput( - generation=generation, - step=step, - frame=frame, - selected_at_ns=selected_at_ns, ) + self._samples["input_to_ui_step_s"].append(claim_duration_s) def window_write_completed( self, *, - endpoint: str | None, generation: int, ui_step: int, time_ns: int | None = None, ) -> None: - """Record a client-window write and finish successful correlations.""" - completed_at_ns = self._clock_ns() if time_ns is None else time_ns - with self._lock: - self._ensure_open_locked() - self._write_locked( - "window_write_completed", + """Finish pending input correlations at the next window write return.""" + completed_at_ns = _now_ns(time_ns) + self._ensure_started() + pending = tuple( + observation + for observation in self._pending_inputs + if observation.generation == generation + ) + self._pending_inputs.clear() + self._write_claims(pending) + for observation in pending: + duration_s = _elapsed_s(observation.received_at_ns, completed_at_ns) + self._samples["input_to_window_write_s"].append(duration_s) + self._write( + "input_to_window_write", completed_at_ns, - endpoint=endpoint, generation=generation, - ui_step=ui_step, + claimed_ui_step=observation.ui_step, + presented_ui_step=ui_step, + input_type=observation.event_type, + input_timestamp_us=observation.timestamp_us, + duration_s=duration_s, ) - if endpoint is None: - return - pending_output = self._pending_output - self._pending_output = None - if pending_output is not None: - frame_duration_s = _elapsed_s( - pending_output.selected_at_ns, completed_at_ns - ) - self._samples["frame_to_window_write_s"].append(frame_duration_s) - self._write_locked( - "frame_to_window_write", - completed_at_ns, - generation=pending_output.generation, - step=pending_output.step, - frame=pending_output.frame, - endpoint=endpoint, - duration_s=frame_duration_s, - ) - pending_inputs = tuple(self._pending_inputs) - self._pending_inputs.clear() - for observation in pending_inputs: - duration_s = _elapsed_s(observation.received_at_ns, completed_at_ns) - self._samples["input_to_window_write_s"].append(duration_s) - self._write_locked( - "input_to_window_write", - completed_at_ns, - generation=observation.generation, - claimed_ui_step=observation.ui_step, - presented_ui_step=ui_step, - endpoint=endpoint, - input_type=observation.event_type, - input_timestamp_us=observation.timestamp_us, - duration_s=duration_s, - ) def summary(self) -> dict[str, dict[str, float | int]]: - """Return summary statistics for every recorded duration.""" - with self._lock: - return {name: _summarize(values) for name, values in self._samples.items()} + """Return summary statistics for both perceived-latency metrics.""" + return {name: _summarize(values) for name, values in self._samples.items()} def close(self) -> None: - """Write summary records and close the profile once.""" - with self._lock: - if self._closed: - return - observed_at_ns = self._clock_ns() - failure: BaseException | None = None - try: - for metric, values in self._samples.items(): - self._write_locked( - "profile_summary", - observed_at_ns, - metric=metric, - **_summarize(values), - ) - except BaseException as error: + """Write summaries and close the profile once.""" + if self._closed: + return + self._closed = True + output = self._output + if output is None: + return + failure: BaseException | None = None + try: + self._write_claims(self._pending_inputs) + observed_at_ns = time.monotonic_ns() + for metric, values in self._samples.items(): + self._write( + "profile_summary", + observed_at_ns, + metric=metric, + **_summarize(values), + ) + except BaseException as error: + failure = error + self._pending_inputs.clear() + try: + output.close() + except BaseException as error: + if failure is None: failure = error - self._pending_inputs.clear() - self._pending_output = None - self._closed = True - try: - self._output.close() - except BaseException as error: - if failure is None: - failure = error - if failure is not None: - raise failure - - def _write_locked(self, phase: str, time_ns: int, **fields: Any) -> None: + if failure is not None: + raise failure + + def _write_claims( + self, + observations: list[_ClaimedInput] | tuple[_ClaimedInput, ...], + ) -> None: + for observation in observations: + self._write( + "input_to_ui_step", + observation.claimed_at_ns, + generation=observation.generation, + step=observation.ui_step, + input_type=observation.event_type, + input_timestamp_us=observation.timestamp_us, + duration_s=observation.claim_duration_s, + ) + + def _write(self, phase: str, time_ns: int, **fields: Any) -> None: + output = self._output + if output is None: + raise RuntimeError("RuntimeProfiler session has not started.") record = { **fields, "schema_version": _SCHEMA_VERSION, "phase": phase, "time_ns": time_ns, } - self._output.write(json.dumps(record, sort_keys=True, separators=(",", ":"))) - self._output.write("\n") + output.write(json.dumps(record, sort_keys=True, separators=(",", ":"))) + output.write("\n") + + def _ensure_started(self) -> None: + self._ensure_open() + if self._output is None: + raise RuntimeError("RuntimeProfiler session has not started.") - def _ensure_open_locked(self) -> None: + def _ensure_open(self) -> None: if self._closed: raise RuntimeError("RuntimeProfiler is closed.") +def _now_ns(value: int | None) -> int: + return time.monotonic_ns() if value is None else value + + +def _elapsed_s(start_ns: int, end_ns: int) -> float: + if end_ns < start_ns: + raise ValueError("A runtime profile observation moved backward in time.") + return (end_ns - start_ns) / 1_000_000_000 + + def _summarize(values: list[float]) -> dict[str, float | int]: - """Summarize one duration distribution.""" if not values: return {"count": 0} ordered = sorted(values) return { "count": len(ordered), - "mean_s": statistics.fmean(ordered), "median_s": statistics.median(ordered), "p90_s": _percentile(ordered, 0.9), "max_s": ordered[-1], } -def _elapsed_s(start_ns: int, end_ns: int) -> float: - """Return a valid elapsed duration on one monotonic clock.""" - if end_ns < start_ns: - raise ValueError("A runtime profile observation moved backward in time.") - return (end_ns - start_ns) / 1_000_000_000 - - -def _duration(value: float) -> float: - """Return a finite nonnegative duration.""" - value = float(value) - if not math.isfinite(value) or value < 0: - raise ValueError("Runtime profile durations must be finite and nonnegative.") - return value - - def _percentile(ordered: list[float], percentile: float) -> float: - """Return a linearly interpolated percentile from sorted samples.""" if len(ordered) == 1: return ordered[0] index = percentile * (len(ordered) - 1) diff --git a/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py b/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py index ccb76ba84..2e0b7bdd6 100644 --- a/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py +++ b/flashdreams/flashdreams/runtime_v2/serving/webrtc_server.py @@ -143,7 +143,6 @@ def __init__(self, frames_per_second: int) -> None: self._first_enqueued_at: float | None = None self._next_pts = 0 self._frame_in_flight = False - self._sender_available = True self._closed = False def metrics_snapshot(self) -> dict[str, float | int]: @@ -171,11 +170,10 @@ def enqueue(self, frame: VideoFrame) -> bool: """Synchronously admit one real frame and wake the sender. Returns: - Whether the active sender mailbox admitted the frame. Closed and - explicitly disconnected tracks reject it. + Whether the frame was admitted. A closed track rejects it. """ with self._state_lock: - if self._closed or not self._sender_available: + if self._closed: return False enqueued_at = time.monotonic() queued_frame = _QueuedRGBFrame( @@ -194,11 +192,6 @@ def enqueue(self, frame: VideoFrame) -> bool: self._sender_loop.call_soon_threadsafe(self._finish_enqueue) return True - def set_sender_available(self, available: bool) -> None: - """Update whether the peer can admit newly produced frames.""" - with self._state_lock: - self._sender_available = available - async def recv(self) -> VideoFrame: """Serialize aiortc demand for the bounded frame queue.""" async with self._recv_lock: @@ -343,7 +336,7 @@ def url(self) -> str: @property def input_timestamp_origin_ns(self) -> int | None: - """Return the active session's host monotonic input timestamp origin.""" + """Return the active session's monotonic input timestamp origin.""" return self._session_start_ns def metrics_snapshot(self) -> dict[str, float | int]: @@ -401,16 +394,13 @@ def register_input_callback( raise RuntimeError("An input callback is already registered.") self._input_callback = callback - def write(self, result: StepResult) -> bool: + def write(self, result: StepResult) -> None: """Materialize and admit one generated result to the sender mailbox. Args: result: Generated frames matching the description passed to :meth:`open`. - Returns: - Whether the active sender mailbox admitted the frame. - Raises: RuntimeError: The server is not open or has been closed. ValueError: The result shape, layout, or frame count is invalid. @@ -427,9 +417,9 @@ def write(self, result: StepResult) -> bool: ) track = self._video_track if track is None: - return False + return queued_frame = self._materialize_video_frame(result, frames[0]) - return track.enqueue(queued_frame) + track.enqueue(queued_frame) def close(self) -> None: """Close the peer connection and stop the WebRTC server.""" @@ -650,13 +640,10 @@ def on_close() -> None: @peer_connection.on("connectionstatechange") async def on_connectionstatechange() -> None: if peer_connection.connectionState == "connected": - video_track.set_sender_available(True) self._media_connected.set() elif peer_connection.connectionState == "disconnected": - video_track.set_sender_available(False) self._media_connected.clear() elif peer_connection.connectionState in {"failed", "closed"}: - video_track.set_sender_available(False) self._media_connected.clear() self._record_client_disconnect() diff --git a/flashdreams/flashdreams/runtime_v2/session_runner.py b/flashdreams/flashdreams/runtime_v2/session_runner.py index 8cf09cd8a..c4655b984 100644 --- a/flashdreams/flashdreams/runtime_v2/session_runner.py +++ b/flashdreams/flashdreams/runtime_v2/session_runner.py @@ -10,13 +10,14 @@ from pathlib import Path from flashdreams.api_v2.client_window import IClientWindow +from flashdreams.api_v2.input_source import TimestampedInputSource from flashdreams.api_v2.loop import IModelLoop, IUILoop from flashdreams.api_v2.output_sink import OutputSink from flashdreams.api_v2.session import ISession from flashdreams.api_v2.user_input_event import UserInputEvent from flashdreams.runtime_v2.event_buffer import EventBuffer from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler -from flashdreams.runtime_v2.session_desc import PresentationMode +from flashdreams.runtime_v2.session_desc import PresentationMode, SessionDesc from flashdreams.runtime_v2.step_result import StepResult from flashdreams.runtime_v2.user_input_event import CloseUserInputEvent from flashdreams.runtime_v2.user_input_events import UserInputEvents @@ -74,7 +75,7 @@ def run_session( window: Source of input and destination for UI output. metrics_output_sink: Sink for model measurements, if requested. Receives the model loop's results rather than the UI loop's. - profiler: Optional correlated host-side runtime profiler. + profiler: Optional perceived input-latency profiler. steps: Maximum model steps; ``None`` runs until stopped. Raises: @@ -87,17 +88,27 @@ def run_session( raise ValueError(f"steps must be >= 0 or None, got {steps}.") session_desc = session.session_desc + if profiler is not None: + _validate_profile_path(session_desc, profiler.path) tick_seconds = 1.0 / session_desc.frames_per_second_for_ui event_buffer = EventBuffer() stop = session._shutdown_event presentation_manager = session._presentation_manager trace_chunk_lifecycle = session_desc.metadata.get(_TRACE_METADATA_KEY) is True + presentation_manager.configure( + backpressure_mode=session_desc.backpressure_mode, + stop=stop, + put_timeout=tick_seconds, + trace_chunk_lifecycle=trace_chunk_lifecycle, + frames_per_second=session_desc.frames_per_second_for_step, + maximum_frames_per_second=session_desc.frames_per_second_for_ui, + ) model_thread_handle: threading.Thread | None = None ui_loop: IUILoop[object] | None = None model_loop: IModelLoop[object] | None = None high_level_failures: BaseException | None = None cleanup_failures: list[BaseException] = [] - attempted_output_sinks: list[OutputSink] = [window] + attempted_output_sinks: list[OutputSink] = [] def collect_input() -> None: events = window.get_user_input_events() @@ -110,46 +121,30 @@ def run_ui_once() -> None: if ui_loop is None: return events, generation = event_buffer.read(_UI_READER_ID) + input_claimed_at_ns = time.monotonic_ns() if profiler is not None else None step_index = ui_loop._begin_run(events, generation) if step_index is None or stop.is_set(): return - profile_started_at_ns = None if profiler is None else profiler.timestamp_ns() - step_started_at = time.monotonic() + if profiler is not None: + profiler.ui_step_started( + events, + generation=generation, + step=step_index, + time_ns=input_claimed_at_ns, + ) result = ui_loop.step(step_index, events) - step_elapsed_s = time.monotonic() - step_started_at - profile_completed_at_ns = None if profiler is None else profiler.timestamp_ns() if result is not None and not isinstance(result, StepResult): raise TypeError("A UI loop must return StepResult or None.") ui_loop._finish_run(result) - profile_window_completed_at_ns: int | None = None if result is not None: window.write(result) if profiler is not None: - profile_window_completed_at_ns = profiler.timestamp_ns() - if profiler is not None: - assert profile_started_at_ns is not None - assert profile_completed_at_ns is not None - profiler.ui_step_started( - events, - generation=generation, - step=step_index, - time_ns=profile_started_at_ns, - ) - profiler.ui_step_completed( - generation=generation, - step=step_index, - duration_s=step_elapsed_s, - presented=result is not None, - time_ns=profile_completed_at_ns, - ) - if result is not None: - assert profile_window_completed_at_ns is not None + window_write_completed_at_ns = time.monotonic_ns() profiler.window_write_completed( - endpoint=window.profile_endpoint, generation=generation, ui_step=step_index, - time_ns=profile_window_completed_at_ns, + time_ns=window_write_completed_at_ns, ) def publish_model_results( @@ -179,21 +174,12 @@ def tick_ui() -> None: return run_ui_once() - trace_log: _ChunkTraceLog | None = None + trace_log = ( + _open_chunk_trace(session_desc.metadata.get(_TRACE_PATH_METADATA_KEY)) + if trace_chunk_lifecycle + else None + ) try: - presentation_manager.configure( - backpressure_mode=session_desc.backpressure_mode, - stop=stop, - put_timeout=tick_seconds, - trace_chunk_lifecycle=trace_chunk_lifecycle, - runtime_profiler=profiler, - frames_per_second=session_desc.frames_per_second_for_step, - maximum_frames_per_second=session_desc.frames_per_second_for_ui, - ) - if trace_chunk_lifecycle: - trace_log = _open_chunk_trace( - session_desc.metadata.get(_TRACE_PATH_METADATA_KEY) - ) if trace_chunk_lifecycle: _TRACE_LOGGER.info( "%s phase=session_config time_ns=%d backpressure=%s " @@ -217,21 +203,15 @@ def tick_ui() -> None: event_buffer.register(_UI_READER_ID) event_buffer.register(_MODEL_READER_ID) + attempted_output_sinks.append(window) window.open(session_desc) if profiler is not None: profiler.session_started( - input_timestamp_origin_ns=window.input_timestamp_origin_ns, - ) - profiler.record( - "session_config", - backpressure=session_desc.backpressure_mode.value, - presentation=session_desc.presentation_mode.value, - step_fps=session_desc.frames_per_second_for_step, - ui_fps=session_desc.frames_per_second_for_ui, - width=session_desc.video_width, - height=session_desc.video_height, - window=type(window).__name__, - endpoint=window.profile_endpoint, + input_timestamp_origin_ns=( + window.input_timestamp_origin_ns + if isinstance(window, TimestampedInputSource) + else None + ), ) if metrics_output_sink is not None: attempted_output_sinks.append(metrics_output_sink) @@ -246,7 +226,6 @@ def tick_ui() -> None: "event_buffer": event_buffer, "reader_id": _MODEL_READER_ID, "publish": publish_model_results, - "profiler": profiler, "max_steps": steps, }, name=_MODEL_THREAD_NAME, @@ -342,6 +321,22 @@ def tick_ui() -> None: raise primary_failure +def _validate_profile_path(session_desc: SessionDesc, profile_path: Path) -> None: + """Keep the profile separate from an enabled chunk lifecycle trace.""" + metadata = session_desc.metadata + if metadata.get(_TRACE_METADATA_KEY) is not True: + return + trace_path = metadata.get(_TRACE_PATH_METADATA_KEY) + if ( + isinstance(trace_path, str | Path) + and Path(trace_path).expanduser().resolve() + == profile_path.expanduser().resolve() + ): + raise ValueError( + "Runtime profile and chunk lifecycle trace must use distinct paths." + ) + + def _open_chunk_trace(path_value: object) -> _ChunkTraceLog: """Open a line-buffered lifecycle trace for one session.""" if not isinstance(path_value, str | Path): diff --git a/flashdreams/flashdreams/runtime_v2/webrtc_client_window.py b/flashdreams/flashdreams/runtime_v2/webrtc_client_window.py index 6a49ec137..87cf21945 100644 --- a/flashdreams/flashdreams/runtime_v2/webrtc_client_window.py +++ b/flashdreams/flashdreams/runtime_v2/webrtc_client_window.py @@ -26,14 +26,9 @@ class WebRTCClientWindow(IClientWindow): window ends on its own even when the session would generate forever. """ - @property - def profile_endpoint(self) -> str | None: - """Name the observable WebRTC boundary reached by the latest write.""" - return self._profile_endpoint - @property def input_timestamp_origin_ns(self) -> int | None: - """Return the server session's host monotonic timestamp origin.""" + """Return the server session's monotonic input timestamp origin.""" return self.server.input_timestamp_origin_ns def __init__( @@ -55,7 +50,6 @@ def __init__( """ self._input_events: deque[UserInputEvent] = deque() self._input_lock = threading.Lock() - self._profile_endpoint: str | None = None self.server = WebRTCServer( host=host, port=port, @@ -64,9 +58,9 @@ def __init__( def handle_input(event: UserInputEvent) -> None: """Buffer one backend event for the ``InputSource`` protocol.""" - # TODO: do we really need to buffer all events? Some mouse moves may be superseded by later ones. - with self._input_lock: - self._input_events.append(event) + # TODO: do we need to buffer every event? Later mouse moves may + # supersede earlier ones. + self._input_events.append(event) self.server.register_input_callback(handle_input) @@ -95,9 +89,7 @@ def write(self, result: StepResult) -> None: Args: result: One UI-composited frame matching the opened session. """ - self._profile_endpoint = ( - "webrtc_sender_admission" if self.server.write(result) else None - ) + self.server.write(result) def metrics_snapshot(self) -> dict[str, float | int]: """Return sender-queue diagnostics.""" diff --git a/flashdreams/test_v2/test_client_window_factory.py b/flashdreams/test_v2/test_client_window_factory.py index 4d0ad3d55..a59c3ff35 100644 --- a/flashdreams/test_v2/test_client_window_factory.py +++ b/flashdreams/test_v2/test_client_window_factory.py @@ -11,7 +11,8 @@ from pathlib import Path import pytest -from flashdreams.runtime_v2.cli import _parser, _validate_artifact_paths + +from flashdreams.runtime_v2.cli import _parser, _validate_profile_path from flashdreams.runtime_v2.client_window_factory import ( add_client_window_arguments, client_window_mode, @@ -69,49 +70,24 @@ def test_a_native_window_mode_is_lazy_and_keeps_its_title() -> None: assert window.title == "World model" -@pytest.mark.parametrize( - ("first_flag", "second_flag"), - [ - ("--profile-path", "--stats-path"), - ("--profile-path", "--output-path"), - ("--stats-path", "--output-path"), - ], -) -def test_output_artifacts_require_distinct_paths( +@pytest.mark.parametrize("other_flag", ["--stats-path", "--output-path"]) +def test_profile_path_stays_distinct_from_run_outputs( tmp_path: Path, - first_flag: str, - second_flag: str, + other_flag: str, ) -> None: shared = tmp_path / "run-artifact" arguments = [ "demo", "--output-path", str(tmp_path / "output.mp4"), - first_flag, + "--profile-path", str(shared), - second_flag, + other_flag, str(shared), ] - parsed = _parser().parse_args(arguments) - - with pytest.raises(ValueError, match="must use different paths"): - _validate_artifact_paths(parsed) - - -def test_output_artifacts_accept_distinct_paths(tmp_path: Path) -> None: - parsed = _parser().parse_args( - [ - "demo", - "--profile-path", - str(tmp_path / "profile.jsonl"), - "--stats-path", - str(tmp_path / "stats.json"), - "--output-path", - str(tmp_path / "output.mp4"), - ] - ) - _validate_artifact_paths(parsed) + with pytest.raises(ValueError, match="distinct output path"): + _validate_profile_path(_parser().parse_args(arguments)) class TestWebRTC: diff --git a/flashdreams/test_v2/test_native_window_client_window.py b/flashdreams/test_v2/test_native_window_client_window.py index 0fac23f0e..9053ca9b1 100644 --- a/flashdreams/test_v2/test_native_window_client_window.py +++ b/flashdreams/test_v2/test_native_window_client_window.py @@ -13,6 +13,7 @@ import pytest import torch + from flashdreams.runtime_v2 import native_window_client_window as native_window_module from flashdreams.runtime_v2.native_window_client_window import ( NativeWindowClientWindow, @@ -309,6 +310,7 @@ def record_conversion(result: StepResult, desc: SessionDesc) -> torch.Tensor: ) window = NativeWindowClientWindow(presenter_factory=cast(Any, create_presenter)) window.open(_session_desc()) + assert window.input_timestamp_origin_ns is not None window.get_user_input_events() window.write(_result()) window.close() @@ -359,7 +361,7 @@ def test_native_window_reports_input_and_close_from_event_pump() -> None: clock_ns=lambda: next(clock_values), ) window.open(_session_desc()) - assert window.input_timestamp_origin_ns == 1_000_000 + assert window.input_timestamp_origin_ns is None presenter.pending_events.put(("keyboard", _KeyboardEvent("up", pressed=True))) presenter.pending_events.put( ( diff --git a/flashdreams/test_v2/test_runtime_profiler.py b/flashdreams/test_v2/test_runtime_profiler.py index 496119b3b..dca046c04 100644 --- a/flashdreams/test_v2/test_runtime_profiler.py +++ b/flashdreams/test_v2/test_runtime_profiler.py @@ -13,30 +13,23 @@ # See the License for the specific language governing permissions and # limitations under the License. -"""CPU checks for correlated V2 runtime profiles.""" +"""CPU checks for V2 perceived input-latency profiles.""" import json import pytest +from numpy import uint64 + from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler from flashdreams.runtime_v2.user_input_event import ( KeyboardInputState, KeyboardUserInputEvent, ) from flashdreams.runtime_v2.user_input_events import UserInputEvents -from numpy import uint64 pytestmark = pytest.mark.ci_cpu -class _Clock: - def __init__(self, now_ns: int = 0) -> None: - self.now_ns = now_ns - - def __call__(self) -> int: - return self.now_ns - - def _input(timestamp_us: int = 1_000) -> UserInputEvents: return UserInputEvents( [ @@ -49,141 +42,90 @@ def _input(timestamp_us: int = 1_000) -> UserInputEvents: ) -def test_profile_correlates_ui_claim_through_first_window_write(tmp_path) -> None: - clock = _Clock() +def test_profile_correlates_claimed_input_with_first_following_write(tmp_path) -> None: path = tmp_path / "runtime.jsonl" - profiler = RuntimeProfiler(path, clock_ns=clock) - profiler.session_started(input_timestamp_origin_ns=0, time_ns=0) + profiler = RuntimeProfiler(path) + profiler.session_started(input_timestamp_origin_ns=1_000_000, time_ns=1_000_000) - profiler.model_step_started(generation=2, step=3, time_ns=11_000_000) - profiler.model_step_completed( - generation=2, - step=3, - duration_s=0.02, - time_ns=31_000_000, - ) - profiler.chunk_published( - generation=2, - step=3, - frame_count=4, - wait_s=0.003, - time_ns=34_000_000, - ) - profiler.frame_selected( - generation=2, - step=3, - frame=0, - frame_count=4, - time_ns=41_000_000, - ) profiler.ui_step_started( _input(), generation=2, step=9, - time_ns=11_000_000, + time_ns=5_000_000, ) - profiler.ui_step_completed( + profiler.ui_step_started( + UserInputEvents([]), generation=2, - step=9, - duration_s=0.004, - presented=True, - time_ns=15_000_000, + step=10, + time_ns=6_000_000, ) profiler.window_write_completed( - endpoint="native_presenter_return", generation=2, - ui_step=9, - time_ns=51_000_000, + ui_step=10, + time_ns=9_000_000, ) - summary = profiler.summary() - assert summary["input_to_ui_step_s"]["median_s"] == pytest.approx(0.01) - assert summary["input_to_window_write_s"]["median_s"] == pytest.approx(0.05) - assert summary["model_step_s"]["median_s"] == pytest.approx(0.02) - assert summary["ui_step_s"]["median_s"] == pytest.approx(0.004) - assert summary["publish_wait_s"]["median_s"] == pytest.approx(0.003) - assert summary["frame_to_window_write_s"]["median_s"] == pytest.approx(0.01) + assert profiler.summary() == { + "input_to_ui_step_s": { + "count": 1, + "median_s": pytest.approx(0.003), + "p90_s": pytest.approx(0.003), + "max_s": pytest.approx(0.003), + }, + "input_to_window_write_s": { + "count": 1, + "median_s": pytest.approx(0.007), + "p90_s": pytest.approx(0.007), + "max_s": pytest.approx(0.007), + }, + } profiler.close() profiler.close() records = [json.loads(line) for line in path.read_text().splitlines()] - phases = [record["phase"] for record in records] - assert { - "session_started", - "input_to_ui_step", - "input_to_window_write", - "frame_to_window_write", - } <= set(phases) output_record = next( record for record in records if record["phase"] == "input_to_window_write" ) assert output_record == { "schema_version": 1, "phase": "input_to_window_write", - "time_ns": 51_000_000, + "time_ns": 9_000_000, "generation": 2, "claimed_ui_step": 9, - "presented_ui_step": 9, - "endpoint": "native_presenter_return", + "presented_ui_step": 10, "input_type": "KeyboardUserInputEvent", "input_timestamp_us": 1_000, - "duration_s": 0.05, + "duration_s": 0.007, } - assert phases.count("profile_summary") == 6 + assert sum(record["phase"] == "profile_summary" for record in records) == 2 -def test_disconnected_write_preserves_correlations_until_sender_admission( - tmp_path, -) -> None: +def test_profile_skips_sources_without_a_shared_clock_origin(tmp_path) -> None: profiler = RuntimeProfiler(tmp_path / "runtime.jsonl") - profiler.session_started(input_timestamp_origin_ns=0, time_ns=0) - profiler.ui_step_started(_input(), generation=0, step=0, time_ns=2_000_000) - profiler.frame_selected( - generation=0, - step=0, - frame=0, - frame_count=1, - time_ns=3_000_000, - ) + profiler.session_started(input_timestamp_origin_ns=None, time_ns=1_000_000) - profiler.window_write_completed( - endpoint=None, - generation=0, - ui_step=0, - time_ns=4_000_000, - ) - assert profiler.summary()["input_to_window_write_s"] == {"count": 0} - assert profiler.summary()["frame_to_window_write_s"] == {"count": 0} + profiler.ui_step_started(_input(), generation=0, step=0, time_ns=5_000_000) + profiler.window_write_completed(generation=0, ui_step=0, time_ns=9_000_000) - profiler.window_write_completed( - endpoint="webrtc_sender_admission", - generation=0, - ui_step=1, - time_ns=5_000_000, - ) - assert profiler.summary()["input_to_window_write_s"]["median_s"] == pytest.approx( - 0.004 - ) - assert profiler.summary()["frame_to_window_write_s"]["median_s"] == pytest.approx( - 0.002 - ) + assert profiler.summary() == { + "input_to_ui_step_s": {"count": 0}, + "input_to_window_write_s": {"count": 0}, + } profiler.close() -def test_close_is_final_after_a_summary_write_failure(tmp_path) -> None: - class _FailingOutput: - def write(self, value: str) -> int: - del value - raise OSError("profile write failed") - - def close(self) -> None: - return - +def test_generation_change_discards_unpresented_input(tmp_path) -> None: profiler = RuntimeProfiler(tmp_path / "runtime.jsonl") - profiler._output.close() - profiler._output = _FailingOutput() # type: ignore[assignment] + profiler.session_started(input_timestamp_origin_ns=0, time_ns=0) + profiler.ui_step_started(_input(), generation=0, step=0, time_ns=2_000_000) - with pytest.raises(OSError, match="profile write failed"): - profiler.close() + profiler.ui_step_started( + UserInputEvents([]), + generation=1, + step=0, + time_ns=3_000_000, + ) + profiler.window_write_completed(generation=1, ui_step=0, time_ns=4_000_000) + assert profiler.summary()["input_to_window_write_s"] == {"count": 0} profiler.close() diff --git a/flashdreams/test_v2/test_session_runner.py b/flashdreams/test_v2/test_session_runner.py index f0980ed39..345986f9d 100644 --- a/flashdreams/test_v2/test_session_runner.py +++ b/flashdreams/test_v2/test_session_runner.py @@ -10,9 +10,12 @@ import time from collections.abc import Iterator from contextlib import contextmanager +from dataclasses import replace import pytest import torch +from numpy import uint64 + from flashdreams.api_v2.client_window import IClientWindow from flashdreams.api_v2.loop import IModelLoop, IUILoop, invoke_async from flashdreams.api_v2.session import ISession @@ -42,7 +45,6 @@ ) from flashdreams.runtime_v2.user_input_events import UserInputEvents from flashdreams.runtime_v2.video_tensor import VideoTensorLayout -from numpy import uint64 pytestmark = pytest.mark.ci_cpu @@ -578,10 +580,32 @@ def test_run_session_profiles_input_through_window_write(tmp_path) -> None: output_record = next( record for record in records if record["phase"] == "input_to_window_write" ) - assert output_record["endpoint"] == "window_write_return" assert output_record["input_type"] == "KeyboardUserInputEvent" +def test_run_session_keeps_profile_separate_from_chunk_trace(tmp_path) -> None: + log = CallLog() + shared_path = tmp_path / "runtime.jsonl" + session_desc = replace( + _session_desc(), + metadata={ + "trace_chunk_lifecycle": True, + "trace_chunk_lifecycle_path": str(shared_path), + }, + ) + + with pytest.raises(ValueError, match="must use distinct paths"): + run_session( + FakeSession(session_desc, log), + RecordingClientWindow(log, []), + profiler=RuntimeProfiler(shared_path), + steps=1, + ) + + assert log.calls == [] + assert not shared_path.exists() + + def test_run_session_opens_before_writing_and_closes_after() -> None: log = CallLog() session = FakeSession(_session_desc(), log) @@ -1131,33 +1155,9 @@ def init(self) -> None: with pytest.raises(RuntimeError, match="init failed"): run_session(session, window, steps=1) - # A session and its constructor-owned window are released together. - assert log.calls == ["session.init", "window.close", "session.close"] - - -def test_run_session_closes_owned_resources_when_trace_open_fails(tmp_path) -> None: - log = CallLog() - session_desc = _session_desc() - session_desc.metadata.update( - { - "trace_chunk_lifecycle": True, - "trace_chunk_lifecycle_path": tmp_path, - } - ) - session = FakeSession(session_desc, log) - window = RecordingClientWindow(log) - profile_path = tmp_path / "runtime.jsonl" - - with pytest.raises(IsADirectoryError): - run_session( - session, - window, - profiler=RuntimeProfiler(profile_path), - steps=1, - ) - - assert log.calls == ["window.close", "session.close"] - assert '"phase":"profile_summary"' in profile_path.read_text() + # A session that got halfway through starting still has to be released, and + # the window is never opened for a session that cannot run. + assert log.calls == ["session.init", "session.close"] def test_run_session_gives_the_step_after_a_reset_the_whole_batch() -> None: diff --git a/flashdreams/test_v2/test_webrtc_client_window.py b/flashdreams/test_v2/test_webrtc_client_window.py index 7ab9db5e2..64661fb34 100644 --- a/flashdreams/test_v2/test_webrtc_client_window.py +++ b/flashdreams/test_v2/test_webrtc_client_window.py @@ -28,6 +28,7 @@ ) from aiortc.mediastreams import MediaStreamError from av import VideoFrame + from flashdreams.runtime_v2.serving import webrtc_server from flashdreams.runtime_v2.serving.webrtc_server import _VideoTrack from flashdreams.runtime_v2.session_desc import PresentationMode, SessionDesc @@ -324,54 +325,12 @@ async def transition(connection_state: str) -> None: server_loop = window.server._loop assert server_loop is not None - future = asyncio.run_coroutine_threadsafe(transition("connected"), server_loop) - await asyncio.wrap_future(future) - window.write( - StepResult( - step_index=0, - output=torch.zeros((1, 3, 16, 16), dtype=torch.uint8), - frame_count=1, - output_layout=VideoTensorLayout.tchw, - ) - ) - assert window.profile_endpoint == "webrtc_sender_admission" - admitted_before_disconnect = window.metrics_snapshot()[ - "webrtc_sender_enqueued_count" - ] - - future = asyncio.run_coroutine_threadsafe( - transition("disconnected"), server_loop - ) - await asyncio.wrap_future(future) - window.write( - StepResult( - step_index=1, - output=torch.ones((1, 3, 16, 16), dtype=torch.uint8), - frame_count=1, - output_layout=VideoTensorLayout.tchw, - ) - ) - assert window.profile_endpoint is None - assert ( - window.metrics_snapshot()["webrtc_sender_enqueued_count"] - == admitted_before_disconnect - ) - - future = asyncio.run_coroutine_threadsafe(transition("connected"), server_loop) - await asyncio.wrap_future(future) - window.write( - StepResult( - step_index=2, - output=torch.full((1, 3, 16, 16), 2, dtype=torch.uint8), - frame_count=1, - output_layout=VideoTensorLayout.tchw, + for connection_state in ("connected", "disconnected", "connected"): + future = asyncio.run_coroutine_threadsafe( + transition(connection_state), + server_loop, ) - ) - assert window.profile_endpoint == "webrtc_sender_admission" - assert ( - window.metrics_snapshot()["webrtc_sender_enqueued_count"] - == admitted_before_disconnect + 1 - ) + await asyncio.wrap_future(future) assert window.server._media_connected.is_set() assert window.server._client_connected @@ -507,7 +466,6 @@ def test_window_write_materializes_before_synchronous_sender_admission( track.enqueue.assert_called_once() assert len(captured) == 1 assert _frame_mean(captured[0]) == 31.0 - assert window.profile_endpoint == "webrtc_sender_admission" finally: window.server._video_track = None window.server._media_connected.clear() @@ -534,7 +492,6 @@ def test_window_write_queues_during_media_negotiation() -> None: track.enqueue.assert_called_once() assert [_frame_mean(frame) for frame in captured] == [0.0] - assert window.profile_endpoint == "webrtc_sender_admission" finally: window.server._video_track = None window.close() From f3459fa4953d933437fb6ca93873501855e61e04 Mon Sep 17 00:00:00 2001 From: Ziming Wang Date: Thu, 3 Sep 2026 11:29:15 -0700 Subject: [PATCH 4/6] Clarify host-side profile endpoints Define WebRTC timing at the existing single-slot sender mailbox write. Keep active-peer delivery and display timing in matching client telemetry. Signed-off-by: Ziming Wang --- AGENTS.md | 2 +- docs/source/developer_guides/latency_tuning.rst | 12 +++++++----- flashdreams/flashdreams/runtime_v2/README.md | 2 +- .../flashdreams/runtime_v2/application_runner.py | 2 +- flashdreams/flashdreams/runtime_v2/cli.py | 2 +- .../flashdreams/runtime_v2/runtime_profiler.py | 6 +++--- flashdreams/flashdreams/runtime_v2/session_runner.py | 2 +- flashdreams/test_v2/test_runtime_profiler.py | 2 +- 8 files changed, 16 insertions(+), 14 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index b93644db6..be40a387a 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -85,7 +85,7 @@ Use `--no-instantiate` before GPU work to inspect the resolved runner config wit - Inspect available runners with `uv run flashdreams-run --help`, then inspect a specific runner with `uv run flashdreams-run --no-instantiate `. - Prefer CPU checks first: config imports, checkpoint key-remap shape/bijection tests on CPU or meta tensors, docs builds, `pytest -m ci_cpu`, and static assertions about runner names and pipeline wiring. -- For interactive V2 input latency, capture `--profile-path artifacts/.jsonl` and read `docs/source/developer_guides/latency_tuning.rst` for the two measurement boundaries. +- For interactive V2 host-side input latency, capture `--profile-path artifacts/.jsonl` and read `docs/source/developer_guides/latency_tuning.rst` for the two measurement boundaries. - Avoid `ci_gpu`, generation, `torchrun`, Docker GPU tests, large Hugging Face downloads, rollout parity, CUDA graph, WebRTC runtime, and quality-regression tests on CPU-only hosts unless the user requests them or the test explicitly skips cleanly. ## Testing Guidance diff --git a/docs/source/developer_guides/latency_tuning.rst b/docs/source/developer_guides/latency_tuning.rst index 48df1e29a..600a636ef 100644 --- a/docs/source/developer_guides/latency_tuning.rst +++ b/docs/source/developer_guides/latency_tuning.rst @@ -157,7 +157,7 @@ resolution, and native-acceleration knobs first. Profiling and validated reference --------------------------------- -V2 perceived input latency +V2 host-side input latency ~~~~~~~~~~~~~~~~~~~~~~~~~~ Use ``--profile-path`` with a V2 application to write a JSONL profile: @@ -175,10 +175,12 @@ The input source publishes the monotonic origin for its session-relative - ``input_to_window_write_s`` ends when the first following client-window ``write`` call returns. -Native-window and WebRTC writes expose different host-side delivery boundaries. -Browser decode, network transit, compositor scheduling, and physical scanout -require matching client telemetry. The final ``profile_summary`` records report -count, median, p90, and maximum values. +The native-window measurement ends after its presenter call returns. The WebRTC +measurement ends after the host writes the latest frame into the existing +single-slot sender mailbox. Active-peer delivery, RTP transit, browser decode, +compositor scheduling, and physical scanout require matching client telemetry. +The final ``profile_summary`` records report count, median, p90, and maximum +values. JSONL writes add host overhead to the measured run. Keep profiling enabled for every run in a direct comparison. Use Nsight Systems for GPU stage attribution. diff --git a/flashdreams/flashdreams/runtime_v2/README.md b/flashdreams/flashdreams/runtime_v2/README.md index 09de1a2eb..c78eb1eb9 100644 --- a/flashdreams/flashdreams/runtime_v2/README.md +++ b/flashdreams/flashdreams/runtime_v2/README.md @@ -213,7 +213,7 @@ The default UI loop, `BlitModelOutputToScreenLoop`, composites every model channel in list order as if they were image layers and reshapes the result into the session's layout. -`--profile-path artifacts/.jsonl` records event-to-IUILoop and +`--profile-path artifacts/.jsonl` records host-side event-to-IUILoop and event-to-window-write latency. Each input source supplies the monotonic origin for its session-relative event timestamps. The [latency tuning guide](../../../docs/source/developer_guides/latency_tuning.rst) diff --git a/flashdreams/flashdreams/runtime_v2/application_runner.py b/flashdreams/flashdreams/runtime_v2/application_runner.py index bc7bf9068..c3d09c0d7 100644 --- a/flashdreams/flashdreams/runtime_v2/application_runner.py +++ b/flashdreams/flashdreams/runtime_v2/application_runner.py @@ -34,7 +34,7 @@ def __init__( application: Long-lived application that creates the session. client_window: Window that supplies input and presents generated output. metrics_output_sink: Optional sink for model-step metrics. - profiler: Optional perceived input-latency profiler. + profiler: Optional host-side input-latency profiler. """ self._application = application self._client_window = client_window diff --git a/flashdreams/flashdreams/runtime_v2/cli.py b/flashdreams/flashdreams/runtime_v2/cli.py index e37026177..61f3f038d 100644 --- a/flashdreams/flashdreams/runtime_v2/cli.py +++ b/flashdreams/flashdreams/runtime_v2/cli.py @@ -147,7 +147,7 @@ def _add_session_arguments(parser: argparse.ArgumentParser) -> None: "--profile-path", type=Path, default=None, - help="Write perceived input-latency records as JSONL.", + help="Write host-side input-latency records as JSONL.", ) parser.add_argument( "--pixel-width", type=int, default=None, help="Frame width to generate." diff --git a/flashdreams/flashdreams/runtime_v2/runtime_profiler.py b/flashdreams/flashdreams/runtime_v2/runtime_profiler.py index 95d8bf03d..d2d3df124 100644 --- a/flashdreams/flashdreams/runtime_v2/runtime_profiler.py +++ b/flashdreams/flashdreams/runtime_v2/runtime_profiler.py @@ -13,7 +13,7 @@ # See the License for the specific language governing permissions and # limitations under the License. -"""Perceived input-latency profiling for the V2 runtime.""" +"""Host-side input-latency profiling for the V2 runtime.""" from __future__ import annotations @@ -41,7 +41,7 @@ class _ClaimedInput: class RuntimeProfiler: - """Write input-to-UI and input-to-output latency records as JSONL. + """Write input-to-IUILoop and input-to-window-write records as JSONL. One runtime UI thread owns an instance. Input timestamps and runtime observations share ``time.monotonic_ns`` through the source-provided session @@ -153,7 +153,7 @@ def window_write_completed( ) def summary(self) -> dict[str, dict[str, float | int]]: - """Return summary statistics for both perceived-latency metrics.""" + """Return summary statistics for both host-side latency metrics.""" return {name: _summarize(values) for name, values in self._samples.items()} def close(self) -> None: diff --git a/flashdreams/flashdreams/runtime_v2/session_runner.py b/flashdreams/flashdreams/runtime_v2/session_runner.py index c4655b984..c896c193a 100644 --- a/flashdreams/flashdreams/runtime_v2/session_runner.py +++ b/flashdreams/flashdreams/runtime_v2/session_runner.py @@ -75,7 +75,7 @@ def run_session( window: Source of input and destination for UI output. metrics_output_sink: Sink for model measurements, if requested. Receives the model loop's results rather than the UI loop's. - profiler: Optional perceived input-latency profiler. + profiler: Optional host-side input-latency profiler. steps: Maximum model steps; ``None`` runs until stopped. Raises: diff --git a/flashdreams/test_v2/test_runtime_profiler.py b/flashdreams/test_v2/test_runtime_profiler.py index dca046c04..15a381664 100644 --- a/flashdreams/test_v2/test_runtime_profiler.py +++ b/flashdreams/test_v2/test_runtime_profiler.py @@ -13,7 +13,7 @@ # See the License for the specific language governing permissions and # limitations under the License. -"""CPU checks for V2 perceived input-latency profiles.""" +"""CPU checks for V2 host-side input-latency profiles.""" import json From 0e00799514e24489a75a844779d7ac2daac43282 Mon Sep 17 00:00:00 2001 From: Ziming Wang Date: Thu, 3 Sep 2026 21:31:27 -0700 Subject: [PATCH 5/6] Update WebRTC profile endpoint after queue change Signed-off-by: Ziming Wang --- docs/source/developer_guides/latency_tuning.rst | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/source/developer_guides/latency_tuning.rst b/docs/source/developer_guides/latency_tuning.rst index a35c8e399..da5a9d15a 100644 --- a/docs/source/developer_guides/latency_tuning.rst +++ b/docs/source/developer_guides/latency_tuning.rst @@ -179,8 +179,8 @@ The input source publishes the monotonic origin for its session-relative ``write`` call returns. The native-window measurement ends after its presenter call returns. The WebRTC -measurement ends after the host writes the latest frame into the existing -single-slot sender mailbox. Active-peer delivery, RTP transit, browser decode, +measurement ends after the host admits the latest frame to the bounded two-frame +sender queue. Active-peer delivery, RTP transit, browser decode, compositor scheduling, and physical scanout require matching client telemetry. The final ``profile_summary`` records report count, median, p90, and maximum values. From 020fddb48987e001ffef96a4c02e933908d6ef3b Mon Sep 17 00:00:00 2001 From: Ziming Wang Date: Fri, 4 Sep 2026 10:46:24 -0700 Subject: [PATCH 6/6] Bound and describe runtime latency profiles Signed-off-by: Ziming Wang --- .../developer_guides/latency_tuning.rst | 21 ++-- flashdreams/flashdreams/runtime_v2/README.md | 3 +- .../runtime_v2/runtime_profiler.py | 96 ++++++++++++++----- .../flashdreams/runtime_v2/session_runner.py | 2 + flashdreams/test_v2/test_runtime_profiler.py | 93 +++++++++++++++++- flashdreams/test_v2/test_session_runner.py | 2 +- 6 files changed, 182 insertions(+), 35 deletions(-) diff --git a/docs/source/developer_guides/latency_tuning.rst b/docs/source/developer_guides/latency_tuning.rst index da5a9d15a..11379be03 100644 --- a/docs/source/developer_guides/latency_tuning.rst +++ b/docs/source/developer_guides/latency_tuning.rst @@ -169,7 +169,9 @@ Use ``--profile-path`` with a V2 application to write a JSONL profile: --profile-path artifacts/interactive-drive-input-latency.jsonl Replacement sessions append separate ``session_started`` and summary segments -to the same artifact. +to the same artifact. Each ``session_started`` record identifies the concrete +client-window type, output layout, UI and model rates, resolution, presentation +mode, backpressure mode, and both measurement endpoints. The input source publishes the monotonic origin for its session-relative ``UserInputEvent.timestamp`` values. ``run_session`` then records two metrics: @@ -178,12 +180,17 @@ The input source publishes the monotonic origin for its session-relative - ``input_to_window_write_s`` ends when the first following client-window ``write`` call returns. -The native-window measurement ends after its presenter call returns. The WebRTC -measurement ends after the host admits the latest frame to the bounded two-frame -sender queue. Active-peer delivery, RTP transit, browser decode, -compositor scheduling, and physical scanout require matching client telemetry. -The final ``profile_summary`` records report count, median, p90, and maximum -values. +The native-window measurement ends when its window ``write`` returns, normally +after the presenter call. The WebRTC measurement also ends when ``write`` +returns. An active video track returns after host materialization and admission +to the bounded two-frame sender queue. A server waiting for a video track +returns after shape validation. Active-peer delivery, RTP transit, browser +decode, compositor scheduling, and physical scanout require matching client +telemetry. +The final ``profile_summary`` records report an exact count and maximum. +Median and p90 use every sample through 1,024 observations, then use a uniform +bounded reservoir. ``quantile_sample_count`` and ``quantiles_approximate`` make +that transition explicit in the artifact. JSONL writes add host overhead to the measured run. Keep profiling enabled for every run in a direct comparison. Use Nsight Systems for GPU stage attribution. diff --git a/flashdreams/flashdreams/runtime_v2/README.md b/flashdreams/flashdreams/runtime_v2/README.md index c5af7e01e..f2f7b4aa3 100644 --- a/flashdreams/flashdreams/runtime_v2/README.md +++ b/flashdreams/flashdreams/runtime_v2/README.md @@ -227,7 +227,8 @@ the session's layout. `--profile-path artifacts/.jsonl` records host-side event-to-IUILoop and event-to-window-write latency. Each input source supplies the monotonic origin for its session-relative event timestamps. Replacement sessions append distinct -segments to the same JSONL artifact. The +segments with measurement endpoints and runtime settings to the same JSONL +artifact. The [latency tuning guide](../../../docs/source/developer_guides/latency_tuning.rst) defines the JSONL records and host-side boundaries. diff --git a/flashdreams/flashdreams/runtime_v2/runtime_profiler.py b/flashdreams/flashdreams/runtime_v2/runtime_profiler.py index a67a179c6..1eab638c1 100644 --- a/flashdreams/flashdreams/runtime_v2/runtime_profiler.py +++ b/flashdreams/flashdreams/runtime_v2/runtime_profiler.py @@ -18,15 +18,24 @@ from __future__ import annotations import json +import random import statistics import time from dataclasses import dataclass from pathlib import Path from typing import IO, Any +from flashdreams.runtime_v2.session_desc import SessionDesc from flashdreams.runtime_v2.user_input_events import UserInputEvents +_ARTIFACT_TYPE = "flashdreams.runtime_v2.input_latency_profile" +"""Artifact type for V2 host-side input-latency records.""" + _SCHEMA_VERSION = 1 +"""Input-latency artifact schema version.""" + +_SUMMARY_SAMPLE_LIMIT = 1_024 +"""Maximum observations retained for session quantiles.""" @dataclass(frozen=True, slots=True) @@ -40,6 +49,43 @@ class _ClaimedInput: ui_step: int +class _MetricAccumulator: + """Keep exact counts and maxima with bounded quantile samples.""" + + def __init__(self) -> None: + self._count = 0 + self._maximum: float | None = None + self._samples: list[float] = [] + self._random = random.Random(0) + + def add(self, value: float) -> None: + """Add one sample using deterministic reservoir sampling.""" + self._count += 1 + self._maximum = value if self._maximum is None else max(self._maximum, value) + if len(self._samples) < _SUMMARY_SAMPLE_LIMIT: + self._samples.append(value) + return + replacement = self._random.randrange(self._count) + if replacement < _SUMMARY_SAMPLE_LIMIT: + self._samples[replacement] = value + + def summary(self) -> dict[str, float | int | bool]: + """Return bounded-memory summary statistics.""" + if self._count == 0: + return {"count": 0} + ordered = sorted(self._samples) + maximum = self._maximum + assert maximum is not None + return { + "count": self._count, + "median_s": statistics.median(ordered), + "p90_s": _percentile(ordered, 0.9), + "max_s": maximum, + "quantile_sample_count": len(ordered), + "quantiles_approximate": self._count > len(ordered), + } + + class RuntimeProfiler: """Write input-to-IUILoop and input-to-window-write records as JSONL. @@ -57,10 +103,7 @@ def __init__(self, path: str | Path) -> None: self._input_timestamp_origin_ns: int | None = None self._input_generation: int | None = None self._pending_inputs: list[_ClaimedInput] = [] - self._samples: dict[str, list[float]] = { - "input_to_ui_step_s": [], - "input_to_window_write_s": [], - } + self._samples = _metric_accumulators() self._opened_once = False @property @@ -72,6 +115,8 @@ def session_started( self, *, input_timestamp_origin_ns: int | None, + session_desc: SessionDesc, + client_window_type: str, time_ns: int | None = None, ) -> None: """Open the artifact and bind input timestamps to the runtime clock.""" @@ -84,14 +129,25 @@ def session_started( self._input_timestamp_origin_ns = input_timestamp_origin_ns self._input_generation = None self._pending_inputs.clear() - self._samples = { - "input_to_ui_step_s": [], - "input_to_window_write_s": [], - } + self._samples = _metric_accumulators() self._write( "session_started", _now_ns(time_ns), input_timestamp_origin_ns=input_timestamp_origin_ns, + measurement_endpoints={ + "input_to_ui_step_s": "ui_loop_begin_run", + "input_to_window_write_s": "client_window_write_return", + }, + runtime_settings={ + "client_window_type": client_window_type, + "output_layout": session_desc.output_layout.value, + "frames_per_second_for_ui": session_desc.frames_per_second_for_ui, + "frames_per_second_for_step": session_desc.frames_per_second_for_step, + "video_width": session_desc.video_width, + "video_height": session_desc.video_height, + "presentation_mode": session_desc.presentation_mode.value, + "backpressure_mode": session_desc.backpressure_mode.value, + }, ) def ui_step_started( @@ -122,12 +178,12 @@ def ui_step_started( claimed_at_ns=started_at_ns, claim_duration_s=claim_duration_s, timestamp_us=int(event.get_timestamp()), - event_type=type(event).__name__, + event_type=event.get_type_name(), generation=generation, ui_step=step, ) ) - self._samples["input_to_ui_step_s"].append(claim_duration_s) + self._samples["input_to_ui_step_s"].add(claim_duration_s) def window_write_completed( self, @@ -148,7 +204,7 @@ def window_write_completed( self._write_claims(pending) for observation in pending: duration_s = _elapsed_s(observation.received_at_ns, completed_at_ns) - self._samples["input_to_window_write_s"].append(duration_s) + self._samples["input_to_window_write_s"].add(duration_s) self._write( "input_to_window_write", completed_at_ns, @@ -160,9 +216,9 @@ def window_write_completed( duration_s=duration_s, ) - def summary(self) -> dict[str, dict[str, float | int]]: + def summary(self) -> dict[str, dict[str, float | int | bool]]: """Return summary statistics for both host-side latency metrics.""" - return {name: _summarize(values) for name, values in self._samples.items()} + return {name: values.summary() for name, values in self._samples.items()} def close(self) -> None: """Write summaries and close the active session segment.""" @@ -178,7 +234,7 @@ def close(self) -> None: "profile_summary", observed_at_ns, metric=metric, - **_summarize(values), + **values.summary(), ) except BaseException as error: failure = error @@ -215,6 +271,7 @@ def _write(self, phase: str, time_ns: int, **fields: Any) -> None: raise RuntimeError("RuntimeProfiler session has not started.") record = { **fields, + "artifact_type": _ARTIFACT_TYPE, "schema_version": _SCHEMA_VERSION, "phase": phase, "time_ns": time_ns, @@ -237,15 +294,10 @@ def _elapsed_s(start_ns: int, end_ns: int) -> float: return (end_ns - start_ns) / 1_000_000_000 -def _summarize(values: list[float]) -> dict[str, float | int]: - if not values: - return {"count": 0} - ordered = sorted(values) +def _metric_accumulators() -> dict[str, _MetricAccumulator]: return { - "count": len(ordered), - "median_s": statistics.median(ordered), - "p90_s": _percentile(ordered, 0.9), - "max_s": ordered[-1], + "input_to_ui_step_s": _MetricAccumulator(), + "input_to_window_write_s": _MetricAccumulator(), } diff --git a/flashdreams/flashdreams/runtime_v2/session_runner.py b/flashdreams/flashdreams/runtime_v2/session_runner.py index 52cb7e8ad..261d9bb4b 100644 --- a/flashdreams/flashdreams/runtime_v2/session_runner.py +++ b/flashdreams/flashdreams/runtime_v2/session_runner.py @@ -251,6 +251,8 @@ def tick_ui() -> None: if isinstance(window, TimestampedInputSource) else None ), + session_desc=session_desc, + client_window_type=type(window).__name__, ) if metrics_output_sink is not None: metrics_output_sink.open(session_desc) diff --git a/flashdreams/test_v2/test_runtime_profiler.py b/flashdreams/test_v2/test_runtime_profiler.py index 8c98ba153..4cd1b2af1 100644 --- a/flashdreams/test_v2/test_runtime_profiler.py +++ b/flashdreams/test_v2/test_runtime_profiler.py @@ -21,6 +21,11 @@ from numpy import uint64 from flashdreams.runtime_v2.runtime_profiler import RuntimeProfiler +from flashdreams.runtime_v2.session_desc import ( + BackpressureMode, + PresentationMode, + SessionDesc, +) from flashdreams.runtime_v2.user_input_event import ( KeyboardInputState, KeyboardUserInputEvent, @@ -29,6 +34,15 @@ pytestmark = pytest.mark.ci_cpu +_SESSION_DESC = SessionDesc( + backpressure_mode=BackpressureMode.DROP_OLDEST, + presentation_mode=PresentationMode.ON_DEMAND, + frames_per_second_for_ui=60, + frames_per_second_for_step=24, + video_width=640, + video_height=360, +) + def _input(timestamp_us: int = 1_000) -> UserInputEvents: return UserInputEvents( @@ -45,7 +59,12 @@ def _input(timestamp_us: int = 1_000) -> UserInputEvents: def test_profile_correlates_claimed_input_with_first_following_write(tmp_path) -> None: path = tmp_path / "runtime.jsonl" profiler = RuntimeProfiler(path) - profiler.session_started(input_timestamp_origin_ns=1_000_000, time_ns=1_000_000) + profiler.session_started( + input_timestamp_origin_ns=1_000_000, + session_desc=_SESSION_DESC, + client_window_type="NativeWindowClientWindow", + time_ns=1_000_000, + ) profiler.ui_step_started( _input(), @@ -71,12 +90,16 @@ def test_profile_correlates_claimed_input_with_first_following_write(tmp_path) - "median_s": pytest.approx(0.003), "p90_s": pytest.approx(0.003), "max_s": pytest.approx(0.003), + "quantile_sample_count": 1, + "quantiles_approximate": False, }, "input_to_window_write_s": { "count": 1, "median_s": pytest.approx(0.007), "p90_s": pytest.approx(0.007), "max_s": pytest.approx(0.007), + "quantile_sample_count": 1, + "quantiles_approximate": False, }, } @@ -87,22 +110,43 @@ def test_profile_correlates_claimed_input_with_first_following_write(tmp_path) - record for record in records if record["phase"] == "input_to_window_write" ) assert output_record == { + "artifact_type": "flashdreams.runtime_v2.input_latency_profile", "schema_version": 1, "phase": "input_to_window_write", "time_ns": 9_000_000, "generation": 2, "claimed_ui_step": 9, "presented_ui_step": 10, - "input_type": "KeyboardUserInputEvent", + "input_type": "keyboard", "input_timestamp_us": 1_000, "duration_s": 0.007, } assert sum(record["phase"] == "profile_summary" for record in records) == 2 + session_record = records[0] + assert session_record["measurement_endpoints"] == { + "input_to_ui_step_s": "ui_loop_begin_run", + "input_to_window_write_s": "client_window_write_return", + } + assert session_record["runtime_settings"] == { + "client_window_type": "NativeWindowClientWindow", + "output_layout": "tchw", + "frames_per_second_for_ui": 60, + "frames_per_second_for_step": 24, + "video_width": 640, + "video_height": 360, + "presentation_mode": "on_demand", + "backpressure_mode": "drop_oldest", + } def test_profile_skips_sources_without_a_shared_clock_origin(tmp_path) -> None: profiler = RuntimeProfiler(tmp_path / "runtime.jsonl") - profiler.session_started(input_timestamp_origin_ns=None, time_ns=1_000_000) + profiler.session_started( + input_timestamp_origin_ns=None, + session_desc=_SESSION_DESC, + client_window_type="UnknownWindow", + time_ns=1_000_000, + ) profiler.ui_step_started(_input(), generation=0, step=0, time_ns=5_000_000) profiler.window_write_completed(generation=0, ui_step=0, time_ns=9_000_000) @@ -116,7 +160,12 @@ def test_profile_skips_sources_without_a_shared_clock_origin(tmp_path) -> None: def test_generation_change_discards_unpresented_input(tmp_path) -> None: profiler = RuntimeProfiler(tmp_path / "runtime.jsonl") - profiler.session_started(input_timestamp_origin_ns=0, time_ns=0) + profiler.session_started( + input_timestamp_origin_ns=0, + session_desc=_SESSION_DESC, + client_window_type="UnknownWindow", + time_ns=0, + ) profiler.ui_step_started(_input(), generation=0, step=0, time_ns=2_000_000) profiler.ui_step_started( @@ -138,6 +187,8 @@ def test_replacement_sessions_append_independent_profile_segments(tmp_path) -> N for origin_ns in (1_000_000, 10_000_000): profiler.session_started( input_timestamp_origin_ns=origin_ns, + session_desc=_SESSION_DESC, + client_window_type="NativeWindowClientWindow", time_ns=origin_ns, ) profiler.ui_step_started( @@ -157,3 +208,37 @@ def test_replacement_sessions_append_independent_profile_segments(tmp_path) -> N and record["metric"] == "input_to_ui_step_s" ] assert [record["count"] for record in summaries] == [1, 1] + + +def test_profile_summary_bounds_quantile_storage(tmp_path) -> None: + profiler = RuntimeProfiler(tmp_path / "runtime.jsonl") + profiler.session_started( + input_timestamp_origin_ns=0, + session_desc=_SESSION_DESC, + client_window_type="WebRTCClientWindow", + time_ns=0, + ) + + for index in range(1_100): + profiler.ui_step_started( + _input(index), + generation=0, + step=index, + time_ns=index * 1_000 + 1, + ) + profiler.window_write_completed( + generation=0, + ui_step=index, + time_ns=index * 1_000 + 2, + ) + + for summary, maximum in zip( + profiler.summary().values(), + (1e-9, 2e-9), + strict=True, + ): + assert summary["count"] == 1_100 + assert summary["quantile_sample_count"] == 1_024 + assert summary["quantiles_approximate"] is True + assert summary["max_s"] == pytest.approx(maximum) + profiler.close() diff --git a/flashdreams/test_v2/test_session_runner.py b/flashdreams/test_v2/test_session_runner.py index ef5db008c..c5bd7ff66 100644 --- a/flashdreams/test_v2/test_session_runner.py +++ b/flashdreams/test_v2/test_session_runner.py @@ -605,7 +605,7 @@ def test_run_session_profiles_input_through_window_write(tmp_path) -> None: output_record = next( record for record in records if record["phase"] == "input_to_window_write" ) - assert output_record["input_type"] == "KeyboardUserInputEvent" + assert output_record["input_type"] == "keyboard" def test_run_session_keeps_profile_separate_from_chunk_trace(tmp_path) -> None: