Skip to content

Commit

Permalink
thiserror errors instead of internal unwrap/except on user errors (#45)
Browse files Browse the repository at this point in the history

Co-authored-by: Imbris <[email protected]>
  • Loading branch information
Wumpf and Imberflur authored Sep 23, 2023
1 parent 8976df4 commit aa5d6db
Show file tree
Hide file tree
Showing 7 changed files with 179 additions and 35 deletions.
4 changes: 2 additions & 2 deletions Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -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"
5 changes: 3 additions & 2 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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)
Expand Down
11 changes: 5 additions & 6 deletions examples/demo.rs
Original file line number Diff line number Diff line change
Expand Up @@ -11,7 +11,9 @@ fn scopes_to_console_recursive(results: &[GpuTimerScopeResult], indentation: u32
if indentation > 0 {
print!("{:<width$}", "|", width = 4);
}
println!("{:.3}μs - {}", (scope.time.end - scope.time.start) * 1000.0 * 1000.0, scope.label);

println!("{:.3}μs - {}", (&scope.time.end - &scope.time.start) * 1000.0 * 1000.0, scope.label);

if !scope.nested_scopes.is_empty() {
scopes_to_console_recursive(&scope.nested_scopes, indentation + 1);
}
Expand Down Expand Up @@ -181,7 +183,7 @@ async fn run(event_loop: EventLoop<()>, 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
{
Expand Down Expand Up @@ -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));
}
97 changes: 77 additions & 20 deletions src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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<f64>,

/// Scopes that were opened while this scope was open.
pub nested_scopes: Vec<GpuTimerScopeResult>,
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<String>),

#[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,
Expand Down Expand Up @@ -161,16 +187,23 @@ impl GpuProfiler {
}
}

/// Returns true if a timestamp should be written to the encoder or pass.
fn timestamp_write_enabled<Recorder: ProfilerCommandRecorder>(&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<Recorder: ProfilerCommandRecorder>(&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(
Expand All @@ -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 {
Expand All @@ -193,19 +225,33 @@ 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);
}
}

/// 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<Recorder: ProfilerCommandRecorder>(&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<Recorder: ProfilerCommandRecorder>(&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,
Expand All @@ -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.
Expand Down Expand Up @@ -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
Expand All @@ -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.
Expand Down Expand Up @@ -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::<u64>())].try_into().unwrap());
let end_raw = u64::from_le_bytes(
buffer[(offset + std::mem::size_of::<u64>())..(offset + std::mem::size_of::<u64>() * 2)]
Expand Down
2 changes: 1 addition & 1 deletion src/macros.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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
}};
}
11 changes: 7 additions & 4 deletions src/scope.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand Down Expand Up @@ -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();
}
}

Expand All @@ -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();
}
}

Expand Down
84 changes: 84 additions & 0 deletions tests/errors.rs
Original file line number Diff line number Diff line change
@@ -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(()));
}

0 comments on commit aa5d6db

Please sign in to comment.