diff --git a/Cargo.toml b/Cargo.toml index eff0b19..b23dbbc 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -15,12 +15,12 @@ tracy = ["tracy-client", "profiling/profile-with-tracy"] [lib] [dependencies] +thiserror = "1" tracy-client = { version = "0.16", optional = true } wgpu = "0.17" [dev-dependencies] +futures-lite = "1" profiling = { version = "1" } tracy-client = "0.16.1" winit = "0.28" -futures-lite = "1" -#env_logger = "0.8.2" diff --git a/README.md b/README.md index 7374193..07160e8 100644 --- a/README.md +++ b/README.md @@ -18,7 +18,6 @@ Simple profiler scopes for wgpu using timer queries * Tracy integration (behind `tracy` feature flag) TODO: -* Better error messages * Disable via feature flag ## How to use @@ -78,7 +77,9 @@ for inclusion in the work by you, as defined in the Apache-2.0 license, shall be dual licensed as above, without any additional terms or conditions. ## Changelog - +* unreleased + * sample & doc fixes, by @waywardmonkeys in [#41](https://github.com/Wumpf/wgpu-profiler/pull/41), [#44](https://github.com/Wumpf/wgpu-profiler/pull/44) + * `end_scope` & `end_frame` return `thiserror` errors instead of internal unwrap/except on user errors, by @Wumpf in [#45](https://github.com/Wumpf/wgpu-profiler/pull/45) * 0.14.2 * Fix pointing to wrong tracy version, by @waywardmonkeys in [#36](https://github.com/Wumpf/wgpu-profiler/pull/35) * Doc fixes, by @waywardmonkeys in [#38](https://github.com/Wumpf/wgpu-profiler/pull/35) diff --git a/examples/demo.rs b/examples/demo.rs index 74f08e1..fa992d0 100644 --- a/examples/demo.rs +++ b/examples/demo.rs @@ -11,7 +11,9 @@ fn scopes_to_console_recursive(results: &[GpuTimerScopeResult], indentation: u32 if indentation > 0 { print!("{:, window: Window) { { profiler.begin_scope("fractal 2", &mut rpass, &device); rpass.draw(0..6, 2..3); - profiler.end_scope(&mut rpass); + profiler.end_scope(&mut rpass).unwrap(); } // ... or a scope object that takes ownership of the pass { @@ -244,9 +246,6 @@ fn main() { tracy_client::Client::start(); //env_logger::init_from_env(env_logger::Env::default().filter_or(env_logger::DEFAULT_FILTER_ENV, "warn")); let event_loop = EventLoop::new(); - let window = winit::window::WindowBuilder::new() - .with_fullscreen(Some(winit::window::Fullscreen::Borderless(None))) - .build(&event_loop) - .unwrap(); + let window = winit::window::WindowBuilder::new().build(&event_loop).unwrap(); futures_lite::future::block_on(run(event_loop, window)); } diff --git a/src/lib.rs b/src/lib.rs index 0051596..3738d1d 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -83,17 +83,43 @@ pub mod scope; #[cfg(feature = "tracy")] pub mod tracy; +/// The result of a gpu timer scope. pub struct GpuTimerScopeResult { + /// Label that was specified when opening the scope. pub label: String, + /// Time range of this scope in seconds. + /// /// Meaning of absolute value is not defined. pub time: Range, + /// Scopes that were opened while this scope was open. pub nested_scopes: Vec, pub pid: u32, pub tid: ThreadId, } +/// Errors that can occur during [`GpuProfiler::end_frame`]. +#[derive(thiserror::Error, Debug, PartialEq, Eq)] +pub enum EndFrameError { + #[error("All profiling scopes need to be closed before ending a frame. The following scopes were still open: {0:?}")] + UnclosedScopes(Vec), + + #[error( + "Not all queries were resolved before ending a frame.\n +Call `GpuProfiler::resolve_queries` after all profiling scopes have been closed and before ending the frame.\n +There were still {0} queries unresolved" + )] + UnresolvedQueries(u32), +} + +/// Errors that can occur during [`GpuProfiler::end_scope`]. +#[derive(thiserror::Error, Debug, PartialEq, Eq)] +pub enum ScopeError { + #[error("No profiler GpuProfiler scope was previously opened. For each call to `end_scope` you first need to call `begin_scope`.")] + NoOpenScope, +} + pub struct GpuProfiler { enable_pass_timer: bool, enable_encoder_timer: bool, @@ -161,16 +187,23 @@ impl GpuProfiler { } } + /// Returns true if a timestamp should be written to the encoder or pass. + fn timestamp_write_enabled(&self, encoder_or_pass: &mut Recorder) -> bool { + (encoder_or_pass.is_pass() && self.enable_pass_timer) || (!encoder_or_pass.is_pass() && self.enable_encoder_timer) + } + /// Starts a new debug/timer scope on a given encoder or rendering/compute pass. /// /// Scopes can be arbitrarily nested. /// - /// May create new wgpu query objects (which is why it needs a [`wgpu::Device`] reference) + /// May create new wgpu query objects (which is why it needs a [`wgpu::Device`] reference). + /// + /// If encoder/pass timer queries are disabled respectively, no scope will be opened. /// /// See also [`wgpu_profiler!`], [`GpuProfiler::end_scope`] #[track_caller] pub fn begin_scope(&mut self, label: &str, encoder_or_pass: &mut Recorder, device: &wgpu::Device) { - if (encoder_or_pass.is_pass() && self.enable_pass_timer) || (!encoder_or_pass.is_pass() && self.enable_encoder_timer) { + if self.timestamp_write_enabled(encoder_or_pass) { let start_query = self.allocate_query_pair(device); encoder_or_pass.write_timestamp( @@ -180,7 +213,6 @@ impl GpuProfiler { let pid = std::process::id(); let tid = std::thread::current().id(); - let _location = std::panic::Location::caller(); self.open_scopes.push(UnprocessedTimerScope { @@ -193,6 +225,7 @@ impl GpuProfiler { tracy_scope: self.tracy_context.span_alloc(label, "", _location.file(), _location.line()).ok(), }); } + if self.enable_debug_marker { encoder_or_pass.push_debug_group(label); } @@ -200,12 +233,25 @@ impl GpuProfiler { /// Ends a debug/timer scope. /// - /// Panics if no scope has been open previously. + /// If encoder/pass timer queries are disabled respectively, will not attempt to end a scope. + /// Returns an error if no scope has been opened previously. /// /// See also [`wgpu_profiler!`], [`GpuProfiler::begin_scope`] - pub fn end_scope(&mut self, encoder_or_pass: &mut Recorder) { - if (encoder_or_pass.is_pass() && self.enable_pass_timer) || (!encoder_or_pass.is_pass() && self.enable_encoder_timer) { - let mut open_scope = self.open_scopes.pop().expect("No profiler GpuProfiler scope was previously opened"); + pub fn end_scope(&mut self, encoder_or_pass: &mut Recorder) -> Result<(), ScopeError> { + if self.timestamp_write_enabled(encoder_or_pass) { + let mut open_scope = self.open_scopes.pop().ok_or(ScopeError::NoOpenScope)?; + + debug_assert!( + (encoder_or_pass.is_pass() && self.enable_pass_timer) || (!encoder_or_pass.is_pass() && self.enable_encoder_timer), + "Scope was opened with a query, but queries are disabled.\n + `encoder_or_pass.is_pass()`: {}\n + self.enable_pass_timer: {}\n + self.enable_encoder_timer: {}", + encoder_or_pass.is_pass(), + self.enable_pass_timer, + self.enable_encoder_timer + ); + encoder_or_pass.write_timestamp( &self.active_frame.query_pools[open_scope.start_query.pool_idx as usize].query_set, open_scope.start_query.query_idx + 1, @@ -227,6 +273,8 @@ impl GpuProfiler { if self.enable_debug_marker { encoder_or_pass.pop_debug_group(); } + + Ok(()) } /// Puts query resolve commands in the encoder for all unresolved, pending queries of the current profiler frame. @@ -257,20 +305,27 @@ impl GpuProfiler { } /// Marks the end of a frame. + /// /// Needs to be called **after** submitting any encoder used in the current frame. + /// + /// Fails if there are still open scopes or unresolved queries. + /// Warning: This validation happens only, if the profiler enabled. #[allow(clippy::result_unit_err)] - pub fn end_frame(&mut self) -> Result<(), ()> { - // TODO: Error messages + pub fn end_frame(&mut self) -> Result<(), EndFrameError> { if !self.open_scopes.is_empty() { - return Err(()); + return Err(EndFrameError::UnclosedScopes( + self.open_scopes.iter().map(|open_scope| open_scope.label.clone()).collect(), + )); } - if self + + let num_unresolved_queries = self .active_frame .query_pools .iter() - .any(|pool| pool.num_resolved_queries != pool.num_used_queries) - { - return Err(()); + .map(|pool| pool.num_used_queries - pool.num_resolved_queries) + .sum(); + if num_unresolved_queries != 0 { + return Err(EndFrameError::UnresolvedQueries(num_unresolved_queries)); } self.size_for_new_query_pools = self @@ -283,11 +338,11 @@ impl GpuProfiler { // Drop previous (!) frame. // Dropping the oldest frame could get us into an endless cycle where we're never able to complete // any pending frames as the ones closest to completion would be evicted. - let dropped_frame = self.pending_frames.pop().unwrap(); - - // Mark the frame as dropped. We'll give back the query pools once the mapping is done. - // Any previously issued map_async call that haven't finished yet, will invoke their callback with mapping abort. - self.reset_and_cache_unused_query_pools(dropped_frame.query_pools); + if let Some(dropped_frame) = self.pending_frames.pop() { + // Mark the frame as dropped. We'll give back the query pools once the mapping is done. + // Any previously issued map_async call that haven't finished yet, will invoke their callback with mapping abort. + self.reset_and_cache_unused_query_pools(dropped_frame.query_pools); + } } // Map all buffers. @@ -416,9 +471,11 @@ impl GpuProfiler { Self::process_timings_recursive(timestamp_to_sec, resolved_query_buffers, scope.nested_scopes) }; - // By design timestamps for start/end are consecutive. + // Read timestamp from buffer. let buffer = &resolved_query_buffers[scope.start_query.pool_idx as usize]; let offset = (scope.start_query.query_idx * QUERY_SIZE) as usize; + + // By design timestamps for start/end are consecutive. let start_raw = u64::from_le_bytes(buffer[offset..(offset + std::mem::size_of::())].try_into().unwrap()); let end_raw = u64::from_le_bytes( buffer[(offset + std::mem::size_of::())..(offset + std::mem::size_of::() * 2)] diff --git a/src/macros.rs b/src/macros.rs index 23c524d..d5c337a 100644 --- a/src/macros.rs +++ b/src/macros.rs @@ -11,7 +11,7 @@ macro_rules! wgpu_profiler { ($label:expr, $profiler:expr, $encoder_or_pass:expr, $device:expr, $code:expr) => {{ $profiler.begin_scope($label, $encoder_or_pass, $device); let ret = $code; - $profiler.end_scope($encoder_or_pass); + $profiler.end_scope($encoder_or_pass).unwrap(); ret }}; } diff --git a/src/scope.rs b/src/scope.rs index 701130d..116993b 100644 --- a/src/scope.rs +++ b/src/scope.rs @@ -79,13 +79,14 @@ impl<'a, W: ProfilerCommandRecorder> ManualOwningScope<'a, W> { /// Ends the scope allowing the extraction of the owned [`ProfilerCommandRecorder`] /// and the mutable reference to the [`GpuProfiler`]. - #[must_use] #[track_caller] pub fn end_scope(mut self) -> (W, &'a mut GpuProfiler) { - self.profiler.end_scope(&mut self.recorder); + // Can't fail since creation implies begin_scope. + self.profiler.end_scope(&mut self.recorder).unwrap(); (self.recorder, self.profiler) } } + impl<'a> Scope<'a, wgpu::CommandEncoder> { /// Start a render pass wrapped in a [`OwningScope`]. #[track_caller] @@ -181,7 +182,8 @@ impl<'a, W: ProfilerCommandRecorder> std::ops::DerefMut for Scope<'a, W> { impl<'a, W: ProfilerCommandRecorder> Drop for Scope<'a, W> { fn drop(&mut self) { - self.profiler.end_scope(self.recorder); + // Creation implies begin_scope, so this can't fail. + self.profiler.end_scope(self.recorder).unwrap(); } } @@ -202,7 +204,8 @@ impl<'a, W: ProfilerCommandRecorder> std::ops::DerefMut for OwningScope<'a, W> { impl<'a, W: ProfilerCommandRecorder> Drop for OwningScope<'a, W> { fn drop(&mut self) { - self.profiler.end_scope(&mut self.recorder); + // Creation implies begin_scope, so this can't fail. + self.profiler.end_scope(&mut self.recorder).unwrap(); } } diff --git a/tests/errors.rs b/tests/errors.rs new file mode 100644 index 0000000..f8857e1 --- /dev/null +++ b/tests/errors.rs @@ -0,0 +1,84 @@ +fn create_device() -> (wgpu::Adapter, wgpu::Device, wgpu::Queue) { + async fn create_default_device_async() -> (wgpu::Adapter, wgpu::Device, wgpu::Queue) { + let instance = wgpu::Instance::new(wgpu::InstanceDescriptor::default()); + let adapter = instance.request_adapter(&wgpu::RequestAdapterOptions::default()).await.unwrap(); + let (device, queue) = adapter + .request_device( + &wgpu::DeviceDescriptor { + features: wgpu::Features::TIMESTAMP_QUERY, + ..Default::default() + }, + None, + ) + .await + .unwrap(); + (adapter, device, queue) + } + + futures_lite::future::block_on(create_default_device_async()) +} + +#[test] +fn end_frame_unclosed_scope() { + let (adapter, device, queue) = create_device(); + + let mut profiler = wgpu_profiler::GpuProfiler::new(&adapter, &device, &queue, 1); + { + let mut encoder = device.create_command_encoder(&wgpu::CommandEncoderDescriptor::default()); + profiler.begin_scope("open scope", &mut encoder, &device); + profiler.resolve_queries(&mut encoder); + } + + assert_eq!( + profiler.end_frame(), + Err(wgpu_profiler::EndFrameError::UnclosedScopes(vec!["open scope".to_string()])) + ); + + // Make sure we can recover from this. + { + let mut encoder = device.create_command_encoder(&wgpu::CommandEncoderDescriptor::default()); + profiler.end_scope(&mut encoder).unwrap(); + profiler.resolve_queries(&mut encoder); + } + assert_eq!(profiler.end_frame(), Ok(())); +} + +#[test] +fn end_frame_unresolved_scope() { + let (adapter, device, queue) = create_device(); + + let mut profiler = wgpu_profiler::GpuProfiler::new(&adapter, &device, &queue, 1); + { + let mut encoder = device.create_command_encoder(&wgpu::CommandEncoderDescriptor::default()); + profiler.begin_scope("open scope", &mut encoder, &device); + profiler.end_scope(&mut encoder).unwrap(); + } + + assert_eq!(profiler.end_frame(), Err(wgpu_profiler::EndFrameError::UnresolvedQueries(2))); + + // Make sure we can recover from this! + { + let mut encoder = device.create_command_encoder(&wgpu::CommandEncoderDescriptor::default()); + profiler.resolve_queries(&mut encoder); + } + assert_eq!(profiler.end_frame(), Ok(())); +} + +#[test] +fn no_open_scope() { + let (adapter, device, queue) = create_device(); + + let mut profiler = wgpu_profiler::GpuProfiler::new(&adapter, &device, &queue, 1); + { + let mut encoder = device.create_command_encoder(&wgpu::CommandEncoderDescriptor::default()); + assert_eq!(profiler.end_scope(&mut encoder), Err(wgpu_profiler::ScopeError::NoOpenScope)); + } + // Make sure we can recover from this. + { + let mut encoder = device.create_command_encoder(&wgpu::CommandEncoderDescriptor::default()); + profiler.begin_scope("open scope", &mut encoder, &device); + assert_eq!(profiler.end_scope(&mut encoder), Ok(())); + profiler.resolve_queries(&mut encoder); + } + assert_eq!(profiler.end_frame(), Ok(())); +}