Much more accurate cpu_usage timing (#3913)

`frame.info.cpu_usage` now includes time for tessellation and rendering,
but excludes vsync and context switching.

crates/eframe/Cargo.toml

@@ -130,6 +130,7 @@ parking_lot = "0.12"
 raw-window-handle.workspace = true
 static_assertions = "1.1.0"
 thiserror.workspace = true
+web-time.workspace = true
 
 #! ### Optional dependencies
 ## Enable this when generating docs.

crates/eframe/src/epi.rs

@@ -757,7 +757,13 @@ pub struct IntegrationInfo {
     /// `None` means "don't know".
     pub system_theme: Option<Theme>,
 
-    /// Seconds of cpu usage (in seconds) of UI code on the previous frame.
+    /// Seconds of cpu usage (in seconds) on the previous frame.
+    ///
+    /// This includes [`App::update`] as well as rendering (except for vsync waiting).
+    ///
+    /// For a more detailed view of cpu usage, use the [`puffin`](https://crates.io/crates/puffin)
+    /// profiler together with the `puffin` feature of `eframe`.
+    ///
     /// `None` if this is the first frame.
     pub cpu_usage: Option<f32>,
 }

crates/eframe/src/lib.rs

@@ -150,6 +150,8 @@ mod epi;
 // Re-export everything in `epi` so `eframe` users don't have to care about what `epi` is:
 pub use epi::*;
 
+pub(crate) mod stopwatch;
+
 // ----------------------------------------------------------------------------
 // When compiling for web
 

crates/eframe/src/native/epi_integration.rs

@@ -1,7 +1,6 @@
 //! Common tools used by [`super::glow_integration`] and [`super::wgpu_integration`].
 
-use std::time::Instant;
-
+use web_time::Instant;
 use winit::event_loop::EventLoopWindowTarget;
 
 use raw_window_handle::{HasDisplayHandle as _, HasWindowHandle as _};
@@ -259,7 +258,6 @@ impl EpiIntegration {
     }
 
     pub fn pre_update(&mut self) {
-        self.frame_start = Instant::now();
         self.app_icon_setter.update();
     }
 
@@ -304,9 +302,8 @@ impl EpiIntegration {
         std::mem::take(&mut self.pending_full_output)
     }
 
-    pub fn post_update(&mut self) {
-        let frame_time = self.frame_start.elapsed().as_secs_f64() as f32;
-        self.frame.info.cpu_usage = Some(frame_time);
+    pub fn report_frame_time(&mut self, seconds: f32) {
+        self.frame.info.cpu_usage = Some(seconds);
     }
 
     pub fn post_rendering(&mut self, window: &winit::window::Window) {

crates/eframe/src/native/glow_integration.rs

@@ -493,6 +493,9 @@ impl GlowWinitRunning {
         #[cfg(feature = "puffin")]
         puffin::GlobalProfiler::lock().new_frame();
 
+        let mut frame_timer = crate::stopwatch::Stopwatch::new();
+        frame_timer.start();
+
         {
             let glutin = self.glutin.borrow();
             let viewport = &glutin.viewports[&viewport_id];
@@ -556,7 +559,11 @@ impl GlowWinitRunning {
 
             let screen_size_in_pixels: [u32; 2] = window.inner_size().into();
 
-            change_gl_context(current_gl_context, gl_surface);
+            {
+                frame_timer.pause();
+                change_gl_context(current_gl_context, gl_surface);
+                frame_timer.resume();
+            }
 
             self.painter
                 .borrow()
@@ -600,17 +607,20 @@ impl GlowWinitRunning {
 
         let viewport = viewports.get_mut(&viewport_id).unwrap();
         viewport.info.events.clear(); // they should have been processed
-        let window = viewport.window.as_ref().unwrap();
+        let window = viewport.window.clone().unwrap();
         let gl_surface = viewport.gl_surface.as_ref().unwrap();
         let egui_winit = viewport.egui_winit.as_mut().unwrap();
 
-        integration.post_update();
-        egui_winit.handle_platform_output(window, platform_output);
+        egui_winit.handle_platform_output(&window, platform_output);
 
         let clipped_primitives = integration.egui_ctx.tessellate(shapes, pixels_per_point);
 
-        // We may need to switch contexts again, because of immediate viewports:
-        change_gl_context(current_gl_context, gl_surface);
+        {
+            // We may need to switch contexts again, because of immediate viewports:
+            frame_timer.pause();
+            change_gl_context(current_gl_context, gl_surface);
+            frame_timer.resume();
+        }
 
         let screen_size_in_pixels: [u32; 2] = window.inner_size().into();
 
@@ -637,10 +647,12 @@ impl GlowWinitRunning {
                         image: screenshot.into(),
                     });
             }
-            integration.post_rendering(window);
+            integration.post_rendering(&window);
         }
 
         {
+            // vsync - don't count as frame-time:
+            frame_timer.pause();
             crate::profile_scope!("swap_buffers");
             if let Err(err) = gl_surface.swap_buffers(
                 current_gl_context
@@ -649,6 +661,7 @@ impl GlowWinitRunning {
             ) {
                 log::error!("swap_buffers failed: {err}");
             }
+            frame_timer.resume();
         }
 
         // give it time to settle:
@@ -659,7 +672,11 @@ impl GlowWinitRunning {
             }
         }
 
-        integration.maybe_autosave(app.as_mut(), Some(window));
+        glutin.handle_viewport_output(event_loop, &integration.egui_ctx, viewport_output);
+
+        integration.report_frame_time(frame_timer.total_time_sec()); // don't count auto-save time as part of regular frame time
+
+        integration.maybe_autosave(app.as_mut(), Some(&window));
 
         if window.is_minimized() == Some(true) {
             // On Mac, a minimized Window uses up all CPU:
@@ -668,8 +685,6 @@ impl GlowWinitRunning {
             std::thread::sleep(std::time::Duration::from_millis(10));
         }
 
-        glutin.handle_viewport_output(event_loop, &integration.egui_ctx, viewport_output);
-
         if integration.should_close() {
             EventResult::Exit
         } else {

crates/eframe/src/native/wgpu_integration.rs

@@ -528,6 +528,9 @@ impl WgpuWinitRunning {
             shared,
         } = self;
 
+        let mut frame_timer = crate::stopwatch::Stopwatch::new();
+        frame_timer.start();
+
         let (viewport_ui_cb, raw_input) = {
             crate::profile_scope!("Prepare");
             let mut shared_lock = shared.borrow_mut();
@@ -628,8 +631,6 @@ impl WgpuWinitRunning {
             return EventResult::Wait;
         };
 
-        integration.post_update();
-
         let FullOutput {
             platform_output,
             textures_delta,
@@ -640,27 +641,25 @@ impl WgpuWinitRunning {
 
         egui_winit.handle_platform_output(window, platform_output);
 
-        {
-            let clipped_primitives = egui_ctx.tessellate(shapes, pixels_per_point);
-
-            let screenshot_requested = std::mem::take(&mut viewport.screenshot_requested);
-            let (_vsync_secs, screenshot) = painter.paint_and_update_textures(
-                viewport_id,
-                pixels_per_point,
-                app.clear_color(&egui_ctx.style().visuals),
-                &clipped_primitives,
-                &textures_delta,
-                screenshot_requested,
-            );
-            if let Some(screenshot) = screenshot {
-                egui_winit
-                    .egui_input_mut()
-                    .events
-                    .push(egui::Event::Screenshot {
-                        viewport_id,
-                        image: screenshot.into(),
-                    });
-            }
+        let clipped_primitives = egui_ctx.tessellate(shapes, pixels_per_point);
+
+        let screenshot_requested = std::mem::take(&mut viewport.screenshot_requested);
+        let (vsync_secs, screenshot) = painter.paint_and_update_textures(
+            viewport_id,
+            pixels_per_point,
+            app.clear_color(&egui_ctx.style().visuals),
+            &clipped_primitives,
+            &textures_delta,
+            screenshot_requested,
+        );
+        if let Some(screenshot) = screenshot {
+            egui_winit
+                .egui_input_mut()
+                .events
+                .push(egui::Event::Screenshot {
+                    viewport_id,
+                    image: screenshot.into(),
+                });
         }
 
         integration.post_rendering(window);
@@ -684,6 +683,8 @@ impl WgpuWinitRunning {
             .and_then(|id| viewports.get(id))
             .and_then(|vp| vp.window.as_ref());
 
+        integration.report_frame_time(frame_timer.total_time_sec() - vsync_secs); // don't count auto-save time as part of regular frame time
+
         integration.maybe_autosave(app.as_mut(), window.map(|w| w.as_ref()));
 
         if let Some(window) = window {

crates/eframe/src/stopwatch.rs

@@ -0,0 +1,50 @@
+#![allow(dead_code)] // not everything is used on wasm
+
+use web_time::Instant;
+
+pub struct Stopwatch {
+    total_time_ns: u128,
+
+    /// None = not running
+    start: Option<Instant>,
+}
+
+impl Stopwatch {
+    pub fn new() -> Self {
+        Self {
+            total_time_ns: 0,
+            start: None,
+        }
+    }
+
+    pub fn start(&mut self) {
+        assert!(self.start.is_none());
+        self.start = Some(Instant::now());
+    }
+
+    pub fn pause(&mut self) {
+        let start = self.start.take().unwrap();
+        let duration = start.elapsed();
+        self.total_time_ns += duration.as_nanos();
+    }
+
+    pub fn resume(&mut self) {
+        assert!(self.start.is_none());
+        self.start = Some(Instant::now());
+    }
+
+    pub fn total_time_ns(&self) -> u128 {
+        if let Some(start) = self.start {
+            // Running
+            let duration = start.elapsed();
+            self.total_time_ns + duration.as_nanos()
+        } else {
+            // Paused
+            self.total_time_ns
+        }
+    }
+
+    pub fn total_time_sec(&self) -> f32 {
+        self.total_time_ns() as f32 * 1e-9
+    }
+}

crates/eframe/src/web/app_runner.rs

@@ -179,8 +179,6 @@ impl AppRunner {
     ///
     /// The result can be painted later with a call to [`Self::run_and_paint`] or [`Self::paint`].
     pub fn logic(&mut self) {
-        let frame_start = now_sec();
-
         super::resize_canvas_to_screen_size(self.canvas_id(), self.web_options.max_size_points);
         let canvas_size = super::canvas_size_in_points(self.canvas_id());
         let raw_input = self.input.new_frame(canvas_size);
@@ -211,8 +209,6 @@ impl AppRunner {
         self.handle_platform_output(platform_output);
         self.textures_delta.append(textures_delta);
         self.clipped_primitives = Some(self.egui_ctx.tessellate(shapes, pixels_per_point));
-
-        self.frame.info.cpu_usage = Some((now_sec() - frame_start) as f32);
     }
 
     /// Paint the results of the last call to [`Self::logic`].
@@ -232,6 +228,10 @@ impl AppRunner {
         }
     }
 
+    pub fn report_frame_time(&mut self, cpu_usage_seconds: f32) {
+        self.frame.info.cpu_usage = Some(cpu_usage_seconds);
+    }
+
     fn handle_platform_output(&mut self, platform_output: egui::PlatformOutput) {
         #[cfg(feature = "web_screen_reader")]
         if self.egui_ctx.options(|o| o.screen_reader) {

crates/eframe/src/web/events.rs

@@ -30,11 +30,16 @@ fn paint_if_needed(runner: &mut AppRunner) {
             // running the logic, as the logic could cause it to be set again.
             runner.needs_repaint.clear();
 
+            let mut stopwatch = crate::stopwatch::Stopwatch::new();
+            stopwatch.start();
+
             // Run user code…
             runner.logic();
 
             // …and paint the result.
             runner.paint();
+
+            runner.report_frame_time(stopwatch.total_time_sec());
         }
     }
     runner.auto_save_if_needed();

crates/egui_demo_app/src/frame_history.rs

@@ -38,8 +38,8 @@ impl FrameHistory {
             1e3 * self.mean_frame_time()
         ))
         .on_hover_text(
-            "Includes egui layout and tessellation time.\n\
-            Does not include GPU usage, nor overhead for sending data to GPU.",
+            "Includes all app logic, egui layout, tessellation, and rendering.\n\
+            Does not include waiting for vsync.",
         );
         egui::warn_if_debug_build(ui);
 

examples/puffin_profiler/src/main.rs

@@ -93,12 +93,6 @@ impl eframe::App for MyApp {
                 .store(show_deferred_viewport, Ordering::Relaxed);
         });
 
-        {
-            // Sleep a bit to emulate some work:
-            puffin::profile_scope!("small_sleep");
-            std::thread::sleep(std::time::Duration::from_millis(10));
-        }
-
         if self.show_immediate_viewport {
             ctx.show_viewport_immediate(
                 egui::ViewportId::from_hash_of("immediate_viewport"),
@@ -121,12 +115,6 @@ impl eframe::App for MyApp {
                         // Tell parent viewport that we should not show next frame:
                         self.show_immediate_viewport = false;
                     }
-
-                    {
-                        // Sleep a bit to emulate some work:
-                        puffin::profile_scope!("small_sleep");
-                        std::thread::sleep(std::time::Duration::from_millis(10));
-                    }
                 },
             );
         }
@@ -153,12 +141,6 @@ impl eframe::App for MyApp {
                         // Tell parent to close us.
                         show_deferred_viewport.store(false, Ordering::Relaxed);
                     }
-
-                    {
-                        // Sleep a bit to emulate some work:
-                        puffin::profile_scope!("small_sleep");
-                        std::thread::sleep(std::time::Duration::from_millis(10));
-                    }
                 },
             );
         }