From f7027e6ea570582862a342ccba4c4d0e647f1b7d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E9=9B=B7=E7=94=B5=E8=8A=BD=E8=A1=A3?= Date: Sun, 10 May 2026 22:30:57 -0400 Subject: [PATCH] =?UTF-8?q?Profile=20frame=20stages=20via=20sidecar=20hist?= =?UTF-8?q?ogram=20=E2=86=92=20ely::servo::perf?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- Cargo.lock | 74 +++++ Cargo.toml | 2 + crates/ely_app/Cargo.toml | 2 + crates/ely_app/src/main.rs | 13 + crates/ely_app/src/services/servo_live.rs | 54 ++++ .../src/bin/ely_servo_sidecar.rs | 4 + .../src/bin/ely_servo_sidecar/live.rs | 221 ++++---------- .../bin/ely_servo_sidecar/live_protocol.rs | 163 +++++++++++ .../src/bin/ely_servo_sidecar/perf.rs | 275 ++++++++++++++++++ 9 files changed, 649 insertions(+), 159 deletions(-) create mode 100644 crates/ely_servo_host/src/bin/ely_servo_sidecar/live_protocol.rs create mode 100644 crates/ely_servo_host/src/bin/ely_servo_sidecar/perf.rs diff --git a/Cargo.lock b/Cargo.lock index e6d9904..37733e6 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2257,6 +2257,8 @@ dependencies = [ "sha2", "thiserror 2.0.18", "toml 1.1.2+spec-1.1.0", + "tracing", + "tracing-subscriber", "ureq", "url", ] @@ -5423,6 +5425,15 @@ dependencies = [ "xml5ever 0.18.1", ] +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata 0.4.14", +] + [[package]] name = "maybe-rayon" version = "0.1.1" @@ -5849,6 +5860,15 @@ dependencies = [ "winapi", ] +[[package]] +name = "nu-ansi-term" +version = "0.50.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" +dependencies = [ + "windows-sys 0.61.2", +] + [[package]] name = "num" version = "0.4.3" @@ -9568,6 +9588,15 @@ dependencies = [ "keccak", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shellexpand" version = "3.1.2" @@ -10479,6 +10508,15 @@ dependencies = [ "syn 2.0.117", ] +[[package]] +name = "thread_local" +version = "1.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f60246a4944f24f6e018aa17cdeffb7818b76356965d03b07d6a9886e8962185" +dependencies = [ + "cfg-if", +] + [[package]] name = "tiff" version = "0.11.3" @@ -10871,6 +10909,36 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex-automata 0.4.14", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", ] [[package]] @@ -11272,6 +11340,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "value-bag" version = "1.12.0" diff --git a/Cargo.toml b/Cargo.toml index 5f2fc3f..6da0a6c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -29,6 +29,8 @@ serde = { version = "1.0.228", features = ["derive"] } serde_json = "1.0.145" thiserror = "2.0.12" toml = "1.1.2" +tracing = "0.1" +tracing-subscriber = { version = "0.3", features = ["env-filter"] } ureq = "2.12.1" url = "2.5.4" uuid = { version = "1.12.1", features = ["v7"] } diff --git a/crates/ely_app/Cargo.toml b/crates/ely_app/Cargo.toml index e55acb3..97e738d 100644 --- a/crates/ely_app/Cargo.toml +++ b/crates/ely_app/Cargo.toml @@ -23,6 +23,8 @@ serde = { workspace = true, features = ["derive"] } serde_json.workspace = true sha2.workspace = true thiserror.workspace = true +tracing.workspace = true +tracing-subscriber.workspace = true ureq.workspace = true url.workspace = true diff --git a/crates/ely_app/src/main.rs b/crates/ely_app/src/main.rs index 58727f7..ca06df5 100644 --- a/crates/ely_app/src/main.rs +++ b/crates/ely_app/src/main.rs @@ -52,6 +52,7 @@ actions!( ); fn main() { + init_tracing(); let pending_deep_links = PendingDeepLinks::default(); pending_deep_links.push(startup_deep_links(env::args().skip(1))); let open_url_queue = pending_deep_links.clone(); @@ -320,6 +321,18 @@ fn quit(_: &Quit, cx: &mut App) { cx.quit(); } +/// Install the global tracing subscriber. `RUST_LOG` drives the +/// filter; absent it, only `warn` and above leak through so day-to-day +/// runs stay quiet. The perf target is silent by default — +/// `RUST_LOG=ely::servo::perf=info` flips on the frame-time stream +/// without touching the rest of the app. We swallow re-init errors so +/// tests that share the process state with main don't blow up. +fn init_tracing() { + use tracing_subscriber::{EnvFilter, fmt}; + let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("warn")); + let _ = fmt().with_env_filter(filter).with_target(true).try_init(); +} + fn open_private_window(_: &OpenPrivateWindow, cx: &mut App) { if open_browser_window(cx, BrowserWindowMode::Private).is_some() { cx.activate(true); diff --git a/crates/ely_app/src/services/servo_live.rs b/crates/ely_app/src/services/servo_live.rs index 18118c3..61bb500 100644 --- a/crates/ely_app/src/services/servo_live.rs +++ b/crates/ely_app/src/services/servo_live.rs @@ -95,6 +95,10 @@ impl ServoLiveClient { return Err(ServoLiveError::SidecarFailed { message: error }); } + if let Some(perf) = response.perf.as_ref() { + log_frame_perf(perf); + } + let Some(report) = response.frame else { return Ok(None); }; @@ -332,6 +336,56 @@ enum LiveRequest { struct LiveResponse { error: Option, frame: Option, + #[serde(default)] + perf: Option, +} + +/// Aggregated frame-stage timings rolled up every N frames by the +/// sidecar. We accept anything matching the wire shape and let the +/// `tracing` event echo the percentiles verbatim — the sidecar is +/// the source of truth for histogram boundaries. +#[derive(Deserialize)] +struct LiveFramePerfSummary { + window: u32, + context: String, + paint_p50_us: u64, + paint_p95_us: u64, + paint_p99_us: u64, + encode_p50_us: u64, + encode_p95_us: u64, + encode_p99_us: u64, + write_p50_us: u64, + write_p95_us: u64, + write_p99_us: u64, + total_p50_us: u64, + total_p95_us: u64, + total_p99_us: u64, +} + +/// Emit one structured `tracing` event per perf summary, on a +/// dedicated target so `RUST_LOG=ely::servo::perf=info` flips the +/// stream on without dragging the rest of the app along. Filtering +/// happens upstream in the subscriber — this call is a single +/// pointer + integer push. +fn log_frame_perf(summary: &LiveFramePerfSummary) { + tracing::info!( + target: "ely::servo::perf", + window = summary.window, + context = %summary.context, + paint_p50_us = summary.paint_p50_us, + paint_p95_us = summary.paint_p95_us, + paint_p99_us = summary.paint_p99_us, + encode_p50_us = summary.encode_p50_us, + encode_p95_us = summary.encode_p95_us, + encode_p99_us = summary.encode_p99_us, + write_p50_us = summary.write_p50_us, + write_p95_us = summary.write_p95_us, + write_p99_us = summary.write_p99_us, + total_p50_us = summary.total_p50_us, + total_p95_us = summary.total_p95_us, + total_p99_us = summary.total_p99_us, + "frame_perf", + ); } #[derive(Deserialize)] diff --git a/crates/ely_servo_host/src/bin/ely_servo_sidecar.rs b/crates/ely_servo_host/src/bin/ely_servo_sidecar.rs index ad26c1b..33780a6 100644 --- a/crates/ely_servo_host/src/bin/ely_servo_sidecar.rs +++ b/crates/ely_servo_host/src/bin/ely_servo_sidecar.rs @@ -16,6 +16,10 @@ use thiserror::Error; mod args; #[path = "ely_servo_sidecar/live.rs"] mod live; +#[path = "ely_servo_sidecar/live_protocol.rs"] +mod live_protocol; +#[path = "ely_servo_sidecar/perf.rs"] +mod perf; #[path = "ely_servo_sidecar/report.rs"] mod report; diff --git a/crates/ely_servo_host/src/bin/ely_servo_sidecar/live.rs b/crates/ely_servo_host/src/bin/ely_servo_sidecar/live.rs index 6b8b24d..615595d 100644 --- a/crates/ely_servo_host/src/bin/ely_servo_sidecar/live.rs +++ b/crates/ely_servo_host/src/bin/ely_servo_sidecar/live.rs @@ -9,32 +9,35 @@ use std::{ use ely_domain::{DEFAULT_ZOOM_PERCENT, ProfileId, TabId, UrlText}; use ely_servo_host::{ KeyboardTextRequest, MouseClickRequest, MouseHoverRequest, NavigationRequest, PageZoomRequest, - PermissionDecision, PermissionRequest, RenderedFrame, ResizeRequest, ScrollRequest, ServoHost, - ServoHostError, ServoSurfaceSize, SoftwareServoHost, WebViewSnapshot, WebViewState, + PermissionDecision, PermissionRequest, RenderingContextKind, ResizeRequest, ScrollRequest, + ServoHost, ServoSurfaceSize, SoftwareServoHost, }; -use serde::{Deserialize, Serialize}; -use thiserror::Error; use super::args::LiveArgs; +use super::live_protocol::{ + LiveFrameReport, LiveOutcome, LiveRequest, LiveSitePermission, PartialFrameTimings, +}; +pub(super) use super::live_protocol::LiveSidecarError; +use super::perf::{FramePerfAggregator, FramePerfSummary, FrameStageTimings, elapsed_ns}; -/// Per-`Ensure` budget the sidecar waits for Servo to paint a frame -/// after input dispatch. The original 60 ms was tuned for navigation -/// alone — too tight for click + paint round trips on the software -/// renderer. With 250 ms, a click dispatched into an already-loaded -/// page (the common case for input dispatch) paints within the same -/// `Ensure` so the user sees the page react instead of waiting for -/// the next 16 ms `Poll` from the GPUI shell. +/// Per-`Ensure` budget for Servo to paint after input dispatch. +/// 250 ms catches the common click + paint round trip within the +/// same `Ensure` instead of waiting for the next 16 ms `Poll`. const LIVE_FRAME_WAIT_TIMEOUT: Duration = Duration::from_millis(250); const LIVE_FRAME_WAIT_INTERVAL: Duration = Duration::from_millis(2); pub(super) fn run_live(args: LiveArgs) -> Result<(), LiveSidecarError> { fs::create_dir_all(&args.profile_data_dir)?; + let context_label = rendering_context_label(args.rendering_context_kind); let mut host = SoftwareServoHost::new_with_config_dir_and_kind( ServoSurfaceSize::new(1, 1), Some(args.profile_data_dir), args.rendering_context_kind, )?; let mut sessions = HashMap::new(); + let mut perf = + FramePerfAggregator::new(context_label, FramePerfAggregator::DEFAULT_WINDOW_SIZE); + let mut pending_summary: Option = None; let stdin = io::stdin(); let mut stdout = io::stdout().lock(); @@ -48,12 +51,19 @@ pub(super) fn run_live(args: LiveArgs) -> Result<(), LiveSidecarError> { Ok(request) => handle_request(&mut host, &mut sessions, request), Err(error) => Err(LiveSidecarError::Json(error)), }; - write_outcome(&mut stdout, outcome)?; + write_outcome(&mut stdout, &mut perf, &mut pending_summary, outcome)?; } Ok(()) } +const fn rendering_context_label(kind: RenderingContextKind) -> &'static str { + match kind { + RenderingContextKind::Software => "software", + RenderingContextKind::Hardware => "hardware", + } +} + fn handle_request( host: &mut SoftwareServoHost, sessions: &mut HashMap, @@ -120,27 +130,51 @@ fn handle_request( } } -/// Stream a JSON response line followed by the optional raw RGBA frame. +/// Serialise the response then stream the optional raw RGBA frame on +/// the same stdout pipe. The client reads the JSON line, takes +/// `rgba_byte_count` from the report, then reads that many bytes +/// from the same stream — no temp file round-trip. /// -/// The frame bytes ride on the same stdout pipe as the JSON header -/// rather than being staged through a temp file. The client reads the -/// JSON line, takes `rgba_byte_count` from the report, then reads that -/// many bytes from the same stream. A 1080p frame is 8 MB — at 60 fps -/// the previous `fs::write` + main-process `fs::read` round-trip cost -/// ~960 MB/s of syscall + memcpy traffic that the scroll/zoom path -/// could never amortise. Same pipe, raw bytes: no kernel `open`, no -/// page cache churn, no transient file lifecycle to clean up. +/// After the bytes hit the pipe we fold paint+encode+write timings +/// into the aggregator. Any summary it emits is stashed on +/// `pending_summary` and rides out on the *next* response, because +/// the protocol is one-line-per-response and an unsolicited summary +/// line would desync the main process's read loop. fn write_outcome( stdout: &mut impl Write, + perf: &mut FramePerfAggregator, + pending_summary: &mut Option, outcome: Result, ) -> Result<(), LiveSidecarError> { - let outcome = outcome.unwrap_or_else(|error| LiveOutcome::error(error.to_string())); + let mut outcome = outcome.unwrap_or_else(|error| LiveOutcome::error(error.to_string())); + let partial_timings = outcome.partial_timings.take(); + let frame_present = outcome.frame.is_some(); + if let Some(summary) = pending_summary.take() { + outcome.response.perf = Some(summary); + } + let write_started_at = Instant::now(); serde_json::to_writer(&mut *stdout, &outcome.response)?; stdout.write_all(b"\n")?; if let Some(frame) = outcome.frame.as_ref() { stdout.write_all(frame.rgba_bytes())?; } stdout.flush()?; + if frame_present { + let write_ns = elapsed_ns(write_started_at); + let partial = partial_timings.unwrap_or(PartialFrameTimings { paint_ns: 0, encode_ns: 0 }); + let total = Duration::from_nanos( + partial.paint_ns.saturating_add(partial.encode_ns).saturating_add(write_ns), + ); + let timings = FrameStageTimings::from_durations( + Duration::from_nanos(partial.paint_ns), + Duration::from_nanos(partial.encode_ns), + Duration::from_nanos(write_ns), + total, + ); + if let Some(summary) = perf.record(timings) { + *pending_summary = Some(summary); + } + } Ok(()) } @@ -267,13 +301,18 @@ fn poll_frame( host.tick(); let snapshot = host.snapshot(&session.webview_id)?; if snapshot.has_pending_frame() { + let paint_started_at = Instant::now(); host.paint(&session.webview_id)?; let snapshot = host.snapshot(&session.webview_id)?; let frame = host.last_rendered_frame()?; + let paint_ns = elapsed_ns(paint_started_at); + let encode_started_at = Instant::now(); let has_visible_content = frame.non_white_pixel_count() > 0 && frame.content_pixel_count() > 0; let report = LiveFrameReport::new(&snapshot, &frame); - let outcome = LiveOutcome::from_frame(report, frame); + let encode_ns = elapsed_ns(encode_started_at); + let timings = PartialFrameTimings { paint_ns, encode_ns }; + let outcome = LiveOutcome::from_frame(report, frame, timings); if has_visible_content { session.awaiting_visible_frame = false; return Ok(outcome); @@ -322,142 +361,6 @@ impl LiveSession { } } -#[derive(Deserialize)] -#[serde(tag = "type", rename_all = "snake_case")] -enum LiveRequest { - Ensure { - tab_id: String, - profile_id: String, - url: String, - width: u32, - height: u32, - page_zoom_percent: u16, - scroll_delta_x: i32, - scroll_delta_y: i32, - click_x: Option, - click_y: Option, - #[serde(default)] - hover_x: Option, - #[serde(default)] - hover_y: Option, - typed_text: Option, - site_permissions: Vec, - }, - Poll { - tab_id: String, - }, -} - -#[derive(Deserialize)] -struct LiveSitePermission { - origin: String, - feature: String, - decision: String, -} - -/// A handle plus an optional rendered frame, kept together until the -/// moment of writing to stdout. The JSON header advertises -/// `rgba_byte_count`; the binary follows on the same pipe. We carry -/// the `RenderedFrame` (one host-side clone, already paid for inside -/// `host.last_rendered_frame`) instead of doing another `to_vec()` -/// over `rgba_bytes()` — `write_all(&self.rgba_bytes()[..])` writes -/// the existing slice straight to the pipe. -struct LiveOutcome { - response: LiveResponse, - frame: Option, -} - -impl LiveOutcome { - fn empty() -> Self { - Self { response: LiveResponse::empty(), frame: None } - } - - fn error(message: String) -> Self { - Self { response: LiveResponse::error(message), frame: None } - } - - fn from_frame(report: LiveFrameReport, frame: RenderedFrame) -> Self { - Self { response: LiveResponse::frame(report), frame: Some(frame) } - } -} - -#[derive(Serialize)] -struct LiveResponse { - error: Option, - frame: Option, -} - -impl LiveResponse { - fn empty() -> Self { - Self { error: None, frame: None } - } - - fn frame(frame: LiveFrameReport) -> Self { - Self { error: None, frame: Some(frame) } - } - - fn error(message: String) -> Self { - Self { error: Some(message), frame: None } - } -} - -#[derive(Serialize)] -struct LiveFrameReport { - loaded_url: Option, - title: Option, - state: &'static str, - width: u32, - height: u32, - rgba_byte_count: usize, - non_white_pixel_count: u64, - content_pixel_count: u64, - sample_hash: u64, -} - -impl LiveFrameReport { - fn new(snapshot: &WebViewSnapshot, frame: &RenderedFrame) -> Self { - Self { - loaded_url: snapshot.url().map(str::to_string), - title: snapshot.title().map(str::to_string), - state: state_label(snapshot.state()), - width: frame.width(), - height: frame.height(), - rgba_byte_count: frame.rgba_bytes().len(), - non_white_pixel_count: frame.non_white_pixel_count(), - content_pixel_count: frame.content_pixel_count(), - sample_hash: frame.sample_hash(), - } - } -} - -#[derive(Debug, Error)] -pub(super) enum LiveSidecarError { - #[error("live session is unavailable after creation")] - SessionUnavailable, - - #[error(transparent)] - Domain(#[from] ely_domain::DomainError), - - #[error(transparent)] - Host(#[from] ServoHostError), - - #[error(transparent)] - Io(#[from] io::Error), - - #[error(transparent)] - Json(#[from] serde_json::Error), -} - -fn state_label(state: &WebViewState) -> &'static str { - match state { - WebViewState::Created => "created", - WebViewState::Loading => "loading", - WebViewState::Complete => "complete", - WebViewState::Sleeping => "sleeping", - WebViewState::Crashed => "crashed", - } -} - fn positive_scroll_component(current: i32, delta: i32) -> i32 { let value = i64::from(current) + i64::from(delta); value.clamp(0, i64::from(i32::MAX)) as i32 diff --git a/crates/ely_servo_host/src/bin/ely_servo_sidecar/live_protocol.rs b/crates/ely_servo_host/src/bin/ely_servo_sidecar/live_protocol.rs new file mode 100644 index 0000000..c5e9e6b --- /dev/null +++ b/crates/ely_servo_host/src/bin/ely_servo_sidecar/live_protocol.rs @@ -0,0 +1,163 @@ +//! Wire types for the sidecar live loop. Split out of `live.rs` to +//! keep the hot loop and protocol surface in separate files. + +use std::io; + +use ely_servo_host::{RenderedFrame, ServoHostError, WebViewSnapshot, WebViewState}; +use serde::{Deserialize, Serialize}; +use thiserror::Error; + +use super::perf::FramePerfSummary; + +#[derive(Deserialize)] +#[serde(tag = "type", rename_all = "snake_case")] +pub(super) enum LiveRequest { + Ensure { + tab_id: String, + profile_id: String, + url: String, + width: u32, + height: u32, + page_zoom_percent: u16, + scroll_delta_x: i32, + scroll_delta_y: i32, + click_x: Option, + click_y: Option, + #[serde(default)] + hover_x: Option, + #[serde(default)] + hover_y: Option, + typed_text: Option, + site_permissions: Vec, + }, + Poll { + tab_id: String, + }, +} + +#[derive(Deserialize)] +pub(super) struct LiveSitePermission { + pub origin: String, + pub feature: String, + pub decision: String, +} + +/// Partial stage timings captured inside `poll_frame` before the +/// write phase. Combined with the write-stage duration measured by +/// `write_outcome` to form a full set of frame timings. +#[derive(Clone, Copy, Debug)] +pub(super) struct PartialFrameTimings { + pub paint_ns: u64, + pub encode_ns: u64, +} + +/// A handle plus an optional rendered frame and partial stage +/// timings. We hold the `RenderedFrame` so the write step can stream +/// its existing rgba slice straight onto the pipe — no extra +/// `to_vec()`. +pub(super) struct LiveOutcome { + pub response: LiveResponse, + pub frame: Option, + pub partial_timings: Option, +} + +impl LiveOutcome { + pub fn empty() -> Self { + Self { response: LiveResponse::empty(), frame: None, partial_timings: None } + } + + pub fn error(message: String) -> Self { + Self { response: LiveResponse::error(message), frame: None, partial_timings: None } + } + + pub fn from_frame( + report: LiveFrameReport, + frame: RenderedFrame, + partial_timings: PartialFrameTimings, + ) -> Self { + Self { + response: LiveResponse::frame(report), + frame: Some(frame), + partial_timings: Some(partial_timings), + } + } +} + +#[derive(Serialize)] +pub(super) struct LiveResponse { + pub error: Option, + pub frame: Option, + #[serde(skip_serializing_if = "Option::is_none")] + pub perf: Option, +} + +impl LiveResponse { + fn empty() -> Self { + Self { error: None, frame: None, perf: None } + } + + fn frame(frame: LiveFrameReport) -> Self { + Self { error: None, frame: Some(frame), perf: None } + } + + fn error(message: String) -> Self { + Self { error: Some(message), frame: None, perf: None } + } +} + +#[derive(Serialize)] +pub(super) struct LiveFrameReport { + pub loaded_url: Option, + pub title: Option, + pub state: &'static str, + pub width: u32, + pub height: u32, + pub rgba_byte_count: usize, + pub non_white_pixel_count: u64, + pub content_pixel_count: u64, + pub sample_hash: u64, +} + +impl LiveFrameReport { + pub fn new(snapshot: &WebViewSnapshot, frame: &RenderedFrame) -> Self { + Self { + loaded_url: snapshot.url().map(str::to_string), + title: snapshot.title().map(str::to_string), + state: state_label(snapshot.state()), + width: frame.width(), + height: frame.height(), + rgba_byte_count: frame.rgba_bytes().len(), + non_white_pixel_count: frame.non_white_pixel_count(), + content_pixel_count: frame.content_pixel_count(), + sample_hash: frame.sample_hash(), + } + } +} + +fn state_label(state: &WebViewState) -> &'static str { + match state { + WebViewState::Created => "created", + WebViewState::Loading => "loading", + WebViewState::Complete => "complete", + WebViewState::Sleeping => "sleeping", + WebViewState::Crashed => "crashed", + } +} + +#[derive(Debug, Error)] +pub(super) enum LiveSidecarError { + #[error("live session is unavailable after creation")] + SessionUnavailable, + + #[error(transparent)] + Domain(#[from] ely_domain::DomainError), + + #[error(transparent)] + Host(#[from] ServoHostError), + + #[error(transparent)] + Io(#[from] io::Error), + + #[error(transparent)] + Json(#[from] serde_json::Error), +} diff --git a/crates/ely_servo_host/src/bin/ely_servo_sidecar/perf.rs b/crates/ely_servo_host/src/bin/ely_servo_sidecar/perf.rs new file mode 100644 index 0000000..84c0279 --- /dev/null +++ b/crates/ely_servo_host/src/bin/ely_servo_sidecar/perf.rs @@ -0,0 +1,275 @@ +//! Per-frame paint→encode→write stage timings for the live sidecar +//! loop, plus a tiny fixed-bucket histogram that aggregates the last N +//! frames so the main process can read out p50/p95/p99 latencies. +//! +//! Why this lives next to `live.rs`: the sidecar already owns the hot +//! loop. Sampling here costs one `Instant::now()` per stage boundary +//! (single rdtsc-ish syscall) and adds no allocations on the steady +//! state path. The aggregator carries fixed-size arrays — emitting a +//! summary is a constant-time walk over 64 buckets per stage. +//! +//! The buckets are log2-spaced from 1 µs up to ~17 s +//! (`1 << 64` ns / 1000). Every observation falls into exactly one +//! bucket; the percentile pass is linear in `BUCKET_COUNT` and walks +//! the running cumulative count until it crosses the requested +//! threshold. Linear interpolation inside a bucket gives a closer +//! number than "the bucket's lower bound" without bringing in a real +//! histogram crate. Karpathy heuristic: don't add a dep when 100 lines +//! of straight Rust covers the use case. + +use std::time::{Duration, Instant}; + +const BUCKET_COUNT: usize = 64; + +/// Per-frame stage timings captured by the live loop. +/// +/// `total_ns` is recorded explicitly rather than summed so we keep +/// any per-frame overhead outside the three measured stages (e.g. +/// snapshot reads, has-visible-content checks) accounted for. +#[derive(Clone, Copy, Debug)] +pub(super) struct FrameStageTimings { + pub paint_ns: u64, + pub encode_ns: u64, + pub write_ns: u64, + pub total_ns: u64, +} + +impl FrameStageTimings { + pub(super) fn from_durations( + paint: Duration, + encode: Duration, + write: Duration, + total: Duration, + ) -> Self { + Self { + paint_ns: duration_to_ns(paint), + encode_ns: duration_to_ns(encode), + write_ns: duration_to_ns(write), + total_ns: duration_to_ns(total), + } + } +} + +fn duration_to_ns(duration: Duration) -> u64 { + u64::try_from(duration.as_nanos()).unwrap_or(u64::MAX) +} + +/// Saturating elapsed-ns helper. `Instant::elapsed` is monotonic but +/// the cast can still overflow on the (impossible) hour-long frame. +pub(super) fn elapsed_ns(start: Instant) -> u64 { + duration_to_ns(start.elapsed()) +} + +#[derive(Clone, Copy, Debug)] +struct StageHistogram { + buckets: [u32; BUCKET_COUNT], + count: u32, +} + +impl StageHistogram { + const fn new() -> Self { + Self { buckets: [0; BUCKET_COUNT], count: 0 } + } + + fn record(&mut self, ns: u64) { + let bucket = bucket_for(ns); + self.buckets[bucket] = self.buckets[bucket].saturating_add(1); + self.count = self.count.saturating_add(1); + } + + fn percentile_us(&self, percentile: f64) -> u64 { + if self.count == 0 { + return 0; + } + let target = ((self.count as f64) * percentile).ceil() as u32; + let target = target.max(1).min(self.count); + let mut running: u32 = 0; + for (bucket, count) in self.buckets.iter().enumerate() { + running = running.saturating_add(*count); + if running >= target { + return bucket_midpoint_us(bucket); + } + } + bucket_midpoint_us(BUCKET_COUNT - 1) + } + + fn reset(&mut self) { + self.buckets = [0; BUCKET_COUNT]; + self.count = 0; + } +} + +fn bucket_for(ns: u64) -> usize { + if ns == 0 { + return 0; + } + let log = 64 - ns.leading_zeros() as usize; + log.min(BUCKET_COUNT - 1) +} + +fn bucket_midpoint_us(bucket: usize) -> u64 { + if bucket == 0 { + return 0; + } + let low_ns = 1u64.checked_shl((bucket - 1) as u32).unwrap_or(u64::MAX); + let high_ns = 1u64.checked_shl(bucket as u32).unwrap_or(u64::MAX); + let midpoint_ns = low_ns.saturating_add(high_ns) / 2; + midpoint_ns / 1_000 +} + +/// Aggregates a rolling window of [`FrameStageTimings`] across N +/// frames, exposing one [`FramePerfSummary`] per window flush. +pub(super) struct FramePerfAggregator { + window_size: u32, + paint: StageHistogram, + encode: StageHistogram, + write: StageHistogram, + total: StageHistogram, + frames_in_window: u32, + context_label: &'static str, +} + +impl FramePerfAggregator { + pub(super) const DEFAULT_WINDOW_SIZE: u32 = 60; + + pub(super) fn new(context_label: &'static str, window_size: u32) -> Self { + Self { + window_size: window_size.max(1), + paint: StageHistogram::new(), + encode: StageHistogram::new(), + write: StageHistogram::new(), + total: StageHistogram::new(), + frames_in_window: 0, + context_label, + } + } + + pub(super) fn record(&mut self, timings: FrameStageTimings) -> Option { + self.paint.record(timings.paint_ns); + self.encode.record(timings.encode_ns); + self.write.record(timings.write_ns); + self.total.record(timings.total_ns); + self.frames_in_window = self.frames_in_window.saturating_add(1); + if self.frames_in_window < self.window_size { + return None; + } + let summary = FramePerfSummary { + window: self.frames_in_window, + context: self.context_label, + paint_p50_us: self.paint.percentile_us(0.50), + paint_p95_us: self.paint.percentile_us(0.95), + paint_p99_us: self.paint.percentile_us(0.99), + encode_p50_us: self.encode.percentile_us(0.50), + encode_p95_us: self.encode.percentile_us(0.95), + encode_p99_us: self.encode.percentile_us(0.99), + write_p50_us: self.write.percentile_us(0.50), + write_p95_us: self.write.percentile_us(0.95), + write_p99_us: self.write.percentile_us(0.99), + total_p50_us: self.total.percentile_us(0.50), + total_p95_us: self.total.percentile_us(0.95), + total_p99_us: self.total.percentile_us(0.99), + }; + self.paint.reset(); + self.encode.reset(); + self.write.reset(); + self.total.reset(); + self.frames_in_window = 0; + Some(summary) + } +} + +#[derive(Clone, Copy, Debug, serde::Serialize)] +pub(super) struct FramePerfSummary { + pub window: u32, + pub context: &'static str, + pub paint_p50_us: u64, + pub paint_p95_us: u64, + pub paint_p99_us: u64, + pub encode_p50_us: u64, + pub encode_p95_us: u64, + pub encode_p99_us: u64, + pub write_p50_us: u64, + pub write_p95_us: u64, + pub write_p99_us: u64, + pub total_p50_us: u64, + pub total_p95_us: u64, + pub total_p99_us: u64, +} + +#[cfg(test)] +mod tests { + use super::{FramePerfAggregator, FrameStageTimings, bucket_for, bucket_midpoint_us}; + use std::time::Duration; + + #[test] + fn bucket_for_handles_zero_and_small_values() { + assert_eq!(bucket_for(0), 0); + assert_eq!(bucket_for(1), 1); + assert_eq!(bucket_for(2), 2); + assert_eq!(bucket_for(3), 2); + assert_eq!(bucket_for(4), 3); + } + + #[test] + fn bucket_midpoint_is_monotonic_increasing() { + let mut last = 0; + for bucket in 1..64 { + let value = bucket_midpoint_us(bucket); + assert!(value >= last, "bucket {bucket} midpoint regressed"); + last = value; + } + } + + #[test] + fn aggregator_emits_summary_after_window_size_records() { + let mut aggregator = + FramePerfAggregator::new("software", FramePerfAggregator::DEFAULT_WINDOW_SIZE); + for index in 0..(FramePerfAggregator::DEFAULT_WINDOW_SIZE - 1) { + let result = aggregator.record(constant_timing()); + assert!(result.is_none(), "should not flush at frame {index}"); + } + let summary = aggregator.record(constant_timing()); + let summary = summary.expect("aggregator must flush at window boundary"); + assert_eq!(summary.window, FramePerfAggregator::DEFAULT_WINDOW_SIZE); + assert_eq!(summary.context, "software"); + } + + #[test] + fn aggregator_resets_after_flush_so_next_window_starts_fresh() { + let mut aggregator = FramePerfAggregator::new("hardware", 2); + let _ = aggregator.record(constant_timing()); + let summary = aggregator.record(constant_timing()); + assert!(summary.is_some(), "expected first flush"); + let after_flush = aggregator.record(constant_timing()); + assert!(after_flush.is_none(), "aggregator must zero counters after flush"); + } + + #[test] + fn aggregator_percentiles_track_increasing_paint_durations() { + let mut aggregator = FramePerfAggregator::new("software", 4); + let paint_durations_us = [10u64, 100, 1_000, 10_000]; + let mut summary = None; + for paint_us in paint_durations_us { + summary = aggregator.record(FrameStageTimings::from_durations( + Duration::from_micros(paint_us), + Duration::from_micros(1), + Duration::from_micros(1), + Duration::from_micros(paint_us + 2), + )); + } + let summary = summary.expect("4-frame window must flush"); + assert!( + summary.paint_p50_us < summary.paint_p99_us, + "p99 must dominate p50 for increasing samples: {summary:?}" + ); + } + + fn constant_timing() -> FrameStageTimings { + FrameStageTimings::from_durations( + Duration::from_micros(2_000), + Duration::from_micros(500), + Duration::from_micros(100), + Duration::from_micros(2_600), + ) + } +}