diff --git a/crates/anyrender_vello/Cargo.toml b/crates/anyrender_vello/Cargo.toml index 6df65d2..a4ec74a 100644 --- a/crates/anyrender_vello/Cargo.toml +++ b/crates/anyrender_vello/Cargo.toml @@ -9,7 +9,7 @@ license.workspace = true edition.workspace = true [features] -log_frame_times = ["debug_timer/enable"] +log_frame_times = ["debug_timer/enable", "wgpu_context/log_frame_times"] [dependencies] anyrender = { workspace = true } diff --git a/crates/anyrender_vello/src/window_renderer.rs b/crates/anyrender_vello/src/window_renderer.rs index cbb0b29..83423cd 100644 --- a/crates/anyrender_vello/src/window_renderer.rs +++ b/crates/anyrender_vello/src/window_renderer.rs @@ -16,7 +16,7 @@ use wgpu::{ TextureUsages, }; use wgpu_context::{ - AlphaConversion, DeviceHandle, SurfaceRenderer, SurfaceRendererConfiguration, + AlphaConversion, DeviceHandle, GpuFrameTimer, SurfaceRenderer, SurfaceRendererConfiguration, TextureConfiguration, WGPUContext, }; @@ -164,6 +164,7 @@ pub struct VelloWindowRenderer { wgpu_context: WGPUContext, scene: VelloScene, config: VelloRendererOptions, + gpu_timer: GpuFrameTimer, // Resources texture_handles: FxHashMap, @@ -181,6 +182,7 @@ impl VelloWindowRenderer { render_state: RenderState::Suspended, wgpu_context: build_wgpu_context(&config), config, + gpu_timer: GpuFrameTimer::new(), window_handle: None, scene: VelloScene::new(), texture_handles: FxHashMap::default(), @@ -464,6 +466,7 @@ impl WindowRenderer for VelloWindowRenderer { state.renderer.mark_override_image_dirty(handle); } + self.gpu_timer.start(); state .renderer .render_to_texture( @@ -479,23 +482,33 @@ impl WindowRenderer for VelloWindowRenderer { }, ) .expect("failed to render to texture"); + self.gpu_timer + .submitted("render", render_surface.device(), render_surface.queue()); timer.record_time("render"); drop(texture_view); + if render_surface.ensure_current_surface_texture().is_err() { + return; + } + timer.record_time("acquire"); + + self.gpu_timer.start(); + if render_surface.maybe_blit_and_present().is_err() { self.scene.reset(); return; } + self.gpu_timer + .submitted("blit", render_surface.device(), render_surface.queue()); timer.record_time("present"); - render_surface - .device() - .poll(wgpu::PollType::wait_indefinitely()) - .unwrap(); - - timer.record_time("wait"); + // Progress cleanup and callbacks without serializing the next frame + // behind completion of this frame's GPU work. Surface acquisition + // provides bounded backpressure via desired_maximum_frame_latency. + render_surface.device().poll(wgpu::PollType::Poll).unwrap(); timer.print_times("vello: "); + self.gpu_timer.print_completed("vello: "); // Empty the Vello scene (memory optimisation) self.scene.reset(); diff --git a/crates/anyrender_vello_hybrid/Cargo.toml b/crates/anyrender_vello_hybrid/Cargo.toml index 495935c..ec03852 100644 --- a/crates/anyrender_vello_hybrid/Cargo.toml +++ b/crates/anyrender_vello_hybrid/Cargo.toml @@ -9,7 +9,7 @@ license.workspace = true edition.workspace = true [features] -log_frame_times = ["debug_timer/enable"] +log_frame_times = ["debug_timer/enable", "wgpu_context/log_frame_times"] webgl = ["vello_gpu/webgl"] [dependencies] diff --git a/crates/anyrender_vello_hybrid/src/window_renderer.rs b/crates/anyrender_vello_hybrid/src/window_renderer.rs index 89d63ba..cc85bb5 100644 --- a/crates/anyrender_vello_hybrid/src/window_renderer.rs +++ b/crates/anyrender_vello_hybrid/src/window_renderer.rs @@ -16,7 +16,9 @@ use wgpu::{ CommandEncoderDescriptor, CompositeAlphaMode, Features, Limits, PresentMode, Texture, TextureFormat, TextureView, TextureViewDescriptor, }; -use wgpu_context::{DeviceHandle, SurfaceRenderer, SurfaceRendererConfiguration, WGPUContext}; +use wgpu_context::{ + DeviceHandle, GpuFrameTimer, SurfaceRenderer, SurfaceRendererConfiguration, WGPUContext, +}; use crate::{VelloHybridScenePainter, scene::ImageManager}; @@ -173,6 +175,7 @@ pub struct VelloHybridWindowRenderer { wgpu_context: WGPUContext, scene: VelloHybridScene, config: VelloHybridRendererOptions, + gpu_timer: GpuFrameTimer, cached_images: FxHashMap, } impl VelloHybridWindowRenderer { @@ -188,6 +191,7 @@ impl VelloHybridWindowRenderer { Self { render_state: RenderState::Suspended, config, + gpu_timer: GpuFrameTimer::new(), wgpu_context, window_handle: None, scene: VelloHybridScene::new_with(0, 0, render_settings.level), @@ -543,6 +547,10 @@ impl WindowRenderer for VelloHybridWindowRenderer { self.scene.reset(); return; }; + // Without an intermediate texture the surface texture was just acquired above + if !render_surface.has_intermediate_texture() { + timer.record_time("acquire"); + } // Construct Vello Hybrid TextureBindings let mut texture_bindings = TextureBindings::new(); @@ -568,24 +576,36 @@ impl WindowRenderer for VelloHybridWindowRenderer { TargetInit::Clear(ClearSettings::default()), ) .expect("failed to render to texture"); + self.gpu_timer.start(); render_surface.queue().submit([encoder.finish()]); + self.gpu_timer + .submitted("render", render_surface.device(), render_surface.queue()); timer.record_time("render"); drop(texture_view); + if render_surface.has_intermediate_texture() { + if render_surface.ensure_current_surface_texture().is_err() { + return; + } + timer.record_time("acquire"); + self.gpu_timer.start(); + } + if render_surface.maybe_blit_and_present().is_err() { self.scene.reset(); return; } + self.gpu_timer + .submitted("blit", render_surface.device(), render_surface.queue()); timer.record_time("present"); - render_surface - .device() - .poll(wgpu::PollType::wait_indefinitely()) - .unwrap(); - - timer.record_time("wait"); + // Progress cleanup and callbacks without serializing the next frame + // behind completion of this frame's GPU work. Surface acquisition + // provides bounded backpressure via desired_maximum_frame_latency. + render_surface.device().poll(wgpu::PollType::Poll).unwrap(); timer.print_times("vello_hybrid: "); + self.gpu_timer.print_completed("vello_hybrid: "); // Empty the Vello scene (memory optimisation) self.scene.reset(); diff --git a/crates/wgpu_context/Cargo.toml b/crates/wgpu_context/Cargo.toml index 769a825..380530d 100644 --- a/crates/wgpu_context/Cargo.toml +++ b/crates/wgpu_context/Cargo.toml @@ -8,6 +8,9 @@ repository.workspace = true license.workspace = true edition.workspace = true +[features] +log_frame_times = [] + [dependencies] wgpu = { workspace = true } futures-intrusive = { workspace = true } diff --git a/crates/wgpu_context/src/gpu_frame_timer.rs b/crates/wgpu_context/src/gpu_frame_timer.rs new file mode 100644 index 0000000..f0c2231 --- /dev/null +++ b/crates/wgpu_context/src/gpu_frame_timer.rs @@ -0,0 +1,138 @@ +//! Wall-clock timing of a frame's GPU work, for `log_frame_times`-style debug output. + +#[cfg(feature = "log_frame_times")] +mod real { + use std::io::{Write, stdout}; + use std::sync::atomic::{AtomicUsize, Ordering}; + use std::sync::{Arc, Mutex}; + use std::time::{Duration, Instant}; + use wgpu::{Device, Queue}; + + /// How often the polling thread checks the device while frames are in flight. + const POLL_INTERVAL: Duration = Duration::from_micros(250); + + /// Measures the wall-clock time from `start` until the GPU has finished the work submitted + /// by the following `submitted` call, using `Queue::on_submitted_work_done`. CPU work done + /// between the two calls (e.g. vello's encoding) is included, so this bounds GPU execution + /// time from above; timestamp queries are needed for exact GPU time. + /// + /// wgpu only runs the callback from `Device::poll`/`Queue::submit`, which the render loop + /// calls about once per frame, so on native a thread polls the device every + /// `POLL_INTERVAL` while frames are in flight (WebGPU polls by itself). Completed times are + /// printed on the next frame. + pub struct GpuFrameTimer { + start: Option, + shared: Arc, + poller: Option, + } + + #[derive(Default)] + struct Shared { + completed: Mutex>, + in_flight: AtomicUsize, + } + + impl GpuFrameTimer { + pub fn new() -> Self { + Self { + start: None, + shared: Arc::new(Shared::default()), + poller: None, + } + } + + /// Mark the start of a piece of GPU work. Call before it is submitted. + pub fn start(&mut self) { + self.start = Some(Instant::now()); + } + + /// Register for completion of the work submitted since `start`. Call after its submission. + pub fn submitted(&mut self, label: &'static str, device: &Device, queue: &Queue) { + let Some(start) = self.start.take() else { + return; + }; + let shared = self.shared.clone(); + shared.in_flight.fetch_add(1, Ordering::AcqRel); + queue.on_submitted_work_done(move || { + shared + .completed + .lock() + .unwrap() + .push((label, start.elapsed())); + shared.in_flight.fetch_sub(1, Ordering::AcqRel); + }); + self.wake_poller(device); + } + + /// Print the time taken by each piece of work that has completed since the last call. + pub fn print_completed(&self, message: &str) { + let completed = std::mem::take(&mut *self.shared.completed.lock().unwrap()); + if !completed.is_empty() { + let mut out = stdout().lock(); + for (label, duration) in completed { + let ms = duration.as_secs_f64() * 1000.0; + writeln!(out, "{message}gpu {label}: {ms:.2}ms (previous frame)").unwrap(); + } + } + } + + #[cfg(target_arch = "wasm32")] + fn wake_poller(&mut self, _device: &Device) {} + + #[cfg(not(target_arch = "wasm32"))] + fn wake_poller(&mut self, device: &Device) { + let poller = self.poller.get_or_insert_with(|| { + let device = device.clone(); + let shared = self.shared.clone(); + std::thread::Builder::new() + .name("gpu-frame-timer".into()) + .spawn(move || { + loop { + if shared.in_flight.load(Ordering::Acquire) == 0 { + std::thread::park(); + continue; + } + let _ = device.poll(wgpu::PollType::Poll); + std::thread::sleep(POLL_INTERVAL); + } + }) + .unwrap() + .thread() + .clone() + }); + poller.unpark(); + } + } +} + +#[cfg(not(feature = "log_frame_times"))] +mod dummy { + use wgpu::{Device, Queue}; + + /// No-op stand-in for the `log_frame_times` GPU frame timer. + pub struct GpuFrameTimer; + + impl GpuFrameTimer { + #[inline(always)] + pub fn new() -> Self { + Self + } + #[inline(always)] + pub fn start(&mut self) {} + #[inline(always)] + pub fn submitted(&mut self, _label: &'static str, _device: &Device, _queue: &Queue) {} + #[inline(always)] + pub fn print_completed(&self, _message: &str) {} + } +} + +#[cfg(not(feature = "log_frame_times"))] +pub use dummy::GpuFrameTimer; +#[cfg(feature = "log_frame_times")] +pub use real::GpuFrameTimer; + +impl Default for GpuFrameTimer { + fn default() -> Self { + Self::new() + } +} diff --git a/crates/wgpu_context/src/lib.rs b/crates/wgpu_context/src/lib.rs index 62dd1a2..eec9aec 100644 --- a/crates/wgpu_context/src/lib.rs +++ b/crates/wgpu_context/src/lib.rs @@ -10,12 +10,14 @@ use wgpu::{ mod alpha_blitter; mod buffer_renderer; mod error; +mod gpu_frame_timer; mod surface_renderer; mod util; pub use alpha_blitter::{AlphaConversion, AlphaConvertBlitter}; pub use buffer_renderer::{BufferRenderer, BufferRendererConfig}; pub use error::WgpuContextError; +pub use gpu_frame_timer::GpuFrameTimer; pub use surface_renderer::{SurfaceRenderer, SurfaceRendererConfiguration, TextureConfiguration}; pub use util::block_on_wgpu; diff --git a/crates/wgpu_context/src/surface_renderer.rs b/crates/wgpu_context/src/surface_renderer.rs index 5c7bb5b..4693d15 100644 --- a/crates/wgpu_context/src/surface_renderer.rs +++ b/crates/wgpu_context/src/surface_renderer.rs @@ -288,6 +288,12 @@ impl<'s> SurfaceRenderer<'s> { /// /// If there is an intermediate texture, this is a view of that intermediate texture, otherwise /// it is a view of the surface texture. + /// Whether rendering goes via an intermediate texture that is blitted to the surface on + /// present, rather than directly into the surface texture. + pub fn has_intermediate_texture(&self) -> bool { + self.intermediate_texture.is_some() + } + pub fn target_texture_view(&mut self) -> Result { match &self.intermediate_texture { Some(intermediate_texture) => Ok(intermediate_texture.texture_view.clone()),