Add previous-frame GPU time and acquire stages to log_frame_times

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 }

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<ResourceId, ImageData>,
@@ -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();

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]

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<u64, ImageId>,
 }
 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();

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 }

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<Instant>,
+        shared: Arc<Shared>,
+        poller: Option<std::thread::Thread>,
+    }
+
+    #[derive(Default)]
+    struct Shared {
+        completed: Mutex<Vec<(&'static str, Duration)>>,
+        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()
+    }
+}

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;
 

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<TextureView, GetCurrentSurfaceTextureErr> {
         match &self.intermediate_texture {
             Some(intermediate_texture) => Ok(intermediate_texture.texture_view.clone()),