From 49e7e70f4b5126767665b4bdf67e57579424d30c Mon Sep 17 00:00:00 2001 From: dotCooCoo Date: Thu, 22 Oct 2026 15:50:54 -0700 Subject: [PATCH] Tests: the batched GPU timing test checks one span per command buffer a_refresh_that_submits_several_times_is_one_measurement required the summed GPU time of a refresh that submits two command buffers to be at least 0.6 times the time from render returning until the queue is idle. That interval also holds GPU work the timer does not count, such as the page uploads that Queue::write_texture runs in wgpu's own command buffer, and it leaves out batches that ran while the CPU was still encoding. On an NVIDIA GeForce RTX 5090 the test failed with 0.4 ms against 2.2 ms. The test also passed without checking the sum when the measurement held a single span. The test now takes the render's Stats through measure_with_stats and requires at least one flush and one span for each command buffer the refresh submitted (flushes + 1). It keeps the pixel count check and the upper bound against the wall clock. A new test, several_command_buffers_sum_their_gpu_time, checks the sum against GPU time alone. It doubles a run of 64 MiB buffer copies until one command buffer takes at least 2 ms, times that run in one command buffer before and after, and times it in each of four command buffers through start, split and finish. The four-buffer sum must be at least 2.5 times the larger single time. --- crates/gpu/tests/it/timing.rs | 119 ++++++++++++++++++++++++++++------ 1 file changed, 98 insertions(+), 21 deletions(-) diff --git a/crates/gpu/tests/it/timing.rs b/crates/gpu/tests/it/timing.rs index 9761a1d90d..d5ccf464ad 100644 --- a/crates/gpu/tests/it/timing.rs +++ b/crates/gpu/tests/it/timing.rs @@ -17,7 +17,7 @@ use std::time::Instant; use photocraft_color::{BlendMode, Color, ColorMode, SampleType}; use photocraft_doc::{Document, Layer, Size}; use photocraft_geom::Rect; -use photocraft_gpu::{Compositor, DeviceHealth, GpuTiming, timing}; +use photocraft_gpu::{Compositor, DeviceHealth, GpuTiming, Stats, timing}; /// Pixels in `r`, as the compositor counts them. fn area(r: Rect) -> u64 { @@ -92,8 +92,14 @@ fn document(size: Size) -> Document { /// Render `region` and return (submit ms, waited-for wall ms, the measurement). fn measure(device: &wgpu::Device, queue: &wgpu::Queue, comp: &mut Compositor, doc: &Document, region: Rect) -> (f64, f64, Option) { + let (submit_ms, wall_ms, timing, _) = measure_with_stats(device, queue, comp, doc, region); + (submit_ms, wall_ms, timing) +} + +/// [`measure`], also returning the render's [`Stats`]. +fn measure_with_stats(device: &wgpu::Device, queue: &wgpu::Queue, comp: &mut Compositor, doc: &Document, region: Rect) -> (f64, f64, Option, Stats) { let t0 = Instant::now(); - comp.render(device, queue, doc, region, |_, _| {}).expect("the document composites on the GPU"); + let stats = comp.render(device, queue, doc, region, |_, _| {}).expect("the document composites on the GPU"); let submit_ms = t0.elapsed().as_secs_f64() * 1000.0; let _ = device.poll(wgpu::PollType::Wait { submission_index: None, timeout: None }); let wall_ms = t0.elapsed().as_secs_f64() * 1000.0; @@ -106,7 +112,7 @@ fn measure(device: &wgpu::Device, queue: &wgpu::Queue, comp: &mut Compositor, do } let _ = device.poll(wgpu::PollType::Wait { submission_index: None, timeout: None }); } - (submit_ms, wall_ms, timing) + (submit_ms, wall_ms, timing, stats) } #[test] @@ -187,26 +193,97 @@ fn a_refresh_that_submits_several_times_is_one_measurement() { let full = Rect::from_xywh(0, 0, size.width, size.height); let _ = measure(&device, &queue, &mut comp, &doc, full); - let (submit_ms, wall_ms, timing) = measure(&device, &queue, &mut comp, &doc, full); + let (submit_ms, wall_ms, timing, stats) = measure_with_stats(&device, &queue, &mut comp, &doc, full); let t = timing.expect("a batched refresh is measured like any other"); - eprintln!("batched: {} command buffers, gpu {:.1} ms, submit {submit_ms:.1} ms, waited wall {wall_ms:.1} ms", t.spans, t.ms); - assert_eq!(t.px, area(full)); - if t.spans < 2 { - eprintln!("SKIP the sum: this refresh still fit one command buffer"); - return; - } - assert!(t.ms <= wall_ms * 1.25, "summed gpu time {:.1} ms exceeds the whole waited-for refresh {wall_ms:.1} ms", t.ms); - // What this bound excludes is summing only the last command buffer. A correct sum measures - // ~85 % of the waited-for GPU time here; the flush thresholds split on accumulated work, so - // no single buffer of the several carries much over half of it, and timing only the last - // would land near 40 %. 0.6 sits between the two with room on both sides for a machine - // whose split is less even than this one's. - assert!( - t.ms >= (wall_ms - submit_ms) * 0.6, - "summed gpu time {:.1} ms is far below the {:.1} ms the refresh waited: is only the last command buffer timed?", - t.ms, - wall_ms - submit_ms + eprintln!( + "batched: {} flushes, {} command buffers timed, gpu {:.1} ms, submit {submit_ms:.1} ms, waited wall {wall_ms:.1} ms", + stats.flushes, t.spans, t.ms ); + assert_eq!(t.px, area(full)); + assert!(stats.flushes >= 1, "a refresh over a 24 MiB budget submits in batches"); + // Each flush closes the span of the command buffer it submits and opens one in the next, so the + // one measurement holds a span for every command buffer the refresh submitted. + assert_eq!(t.spans as usize, stats.flushes + 1, "the measurement spans every command buffer of the refresh"); + assert!(t.ms <= wall_ms * 1.25, "summed gpu time {:.1} ms exceeds the whole waited-for refresh {wall_ms:.1} ms", t.ms); +} + +/// Submit `buffers` command buffers as one measurement, each copying `src` into `dst` `copies` +/// times, through `start`, `split` and `finish` as a refresh that flushes does. +fn time_copies( + device: &wgpu::Device, + queue: &wgpu::Queue, + timer: &mut timing::GpuTimer, + src: &wgpu::Buffer, + dst: &wgpu::Buffer, + buffers: usize, + copies: u32, +) -> GpuTiming { + let mut encoder = device.create_command_encoder(&Default::default()); + timer.start(&mut encoder, buffers as u64); + for i in 0..buffers { + for _ in 0..copies { + encoder.copy_buffer_to_buffer(src, 0, dst, 0, src.size()); + } + if i + 1 < buffers { + let mut next = device.create_command_encoder(&Default::default()); + timer.split(&mut encoder, &mut next); + queue.submit([std::mem::replace(&mut encoder, next).finish()]); + } + } + timer.finish(&mut encoder); + queue.submit([encoder.finish()]); + timer.submitted(); + let mut timing = None; + for _ in 0..8 { + let _ = device.poll(wgpu::PollType::Wait { submission_index: None, timeout: None }); + timing = timer.take(); + if timing.is_some() { + break; + } + } + let t = timing.expect("the copies are measured"); + assert_eq!(t.spans as usize, buffers, "one span per command buffer"); + t +} + +/// The measurement of several command buffers is the sum of their spans. This compares GPU time +/// with GPU time only: the same copies timed as one command buffer, and four times over in four. +#[test] +fn several_command_buffers_sum_their_gpu_time() { + let _lock = crate::GPU_LOCK.lock().unwrap_or_else(std::sync::PoisonError::into_inner); + let Some((device, queue, _)) = gpu() else { return }; + let mut timer = timing::GpuTimer::new(&device, &queue).expect("the device has timestamp queries"); + let buffer = |label| { + device.create_buffer(&wgpu::BufferDescriptor { + label: Some(label), + size: 64 << 20, + usage: wgpu::BufferUsages::COPY_SRC | wgpu::BufferUsages::COPY_DST, + mapped_at_creation: false, + }) + }; + let (src, dst) = (buffer("timing_src"), buffer("timing_dst")); + + // Double the copies until one command buffer takes at least 2 ms. + let mut copies = 1; + loop { + let t = time_copies(&device, &queue, &mut timer, &src, &dst, 1, copies); + if t.ms >= 2.0 { + break; + } + if copies >= 1024 { + eprintln!("SKIP the sum: {copies} copies of 64 MiB take {:.2} ms in one command buffer", t.ms); + return; + } + copies *= 2; + } + + let before = time_copies(&device, &queue, &mut timer, &src, &dst, 1, copies); + let four = time_copies(&device, &queue, &mut timer, &src, &dst, 4, copies); + let after = time_copies(&device, &queue, &mut timer, &src, &dst, 1, copies); + let one = before.ms.max(after.ms); + eprintln!("{copies} copies: one command buffer {:.2} / {:.2} ms, four {:.2} ms ({:.2}x)", before.ms, after.ms, four.ms, four.ms / one); + // A sum of the four spans reads about 4x; timing only the last command buffer reads about 1x. + assert!(four.ms >= 2.5 * one, "four command buffers measured {:.2} ms against {one:.2} ms for one: is only one span counted?", four.ms); } #[test]