cranpose_render_wgpu/
pass_timing.rs

1use std::{
2    cell::{Cell, RefCell},
3    sync::{
4        Arc,
5        atomic::{AtomicU8, Ordering},
6    },
7};
8
9use crate::debug_toggles::DebugToggle;
10
11const QUERY_CAPACITY: u32 = 512;
12
13const READBACK_SLOTS: usize = 4;
14
15const SLOT_FREE: u8 = 0;
16const SLOT_PENDING: u8 = 1;
17const SLOT_MAPPED: u8 = 2;
18const SLOT_FAILED: u8 = 3;
19
20const PRINT_CADENCE_FRAMES: u64 = 60;
21
22static PASS_TIMING: DebugToggle = DebugToggle::new("CRANPOSE_GPU_PASS_TIMING");
23
24pub(crate) fn pass_timing_requested() -> bool {
25    PASS_TIMING.flag()
26}
27
28/// One label's aggregate inside the current print window.
29#[derive(Clone, Debug, PartialEq)]
30pub struct GpuPassTimingEntry {
31    pub label: String,
32    pub total_ms: f64,
33    pub passes: u64,
34}
35
36/// GPU time by pass label, aggregated since the last `[GPU-PASS]` print.
37#[derive(Clone, Debug, Default, PartialEq)]
38pub struct GpuPassTimingReport {
39    /// Frames whose timestamps have been read back into this window.
40    pub frames: u32,
41    /// Total GPU busy span — first pass begin to last pass end, summed over
42    /// the window's frames. Per-label times are stage-boundary occupancy
43    /// windows that overlap on pipelined GPUs and can sum past the frame;
44    /// this span is the frame-level wall number they cannot give.
45    pub span_ms: f64,
46    /// Entries sorted by descending GPU time; zero-time labels are omitted.
47    pub entries: Vec<GpuPassTimingEntry>,
48}
49
50#[derive(Clone, Copy, Default)]
51struct LabelTotal {
52    nanoseconds: u64,
53    passes: u64,
54}
55
56struct ReadbackSlot {
57    buffer: wgpu::Buffer,
58    state: Arc<AtomicU8>,
59    passes: RefCell<Vec<(u16, u32)>>,
60}
61
62pub(crate) struct PassTimer {
63    query_set: wgpu::QuerySet,
64    resolve_buffer: wgpu::Buffer,
65    period_ns: f32,
66    cursor: Cell<u32>,
67    frame_passes: RefCell<Vec<(u16, u32)>>,
68    labels: RefCell<Vec<String>>,
69    totals: RefCell<Vec<LabelTotal>>,
70    slots: Vec<ReadbackSlot>,
71    frame_index: Cell<u64>,
72    frames_harvested: Cell<u32>,
73    span_nanoseconds: Cell<u64>,
74    dropped_passes: Cell<u64>,
75    dropped_frames: Cell<u64>,
76}
77
78impl PassTimer {
79    pub(crate) fn for_device(device: &wgpu::Device, queue: &wgpu::Queue) -> Option<Self> {
80        if !device.features().contains(wgpu::Features::TIMESTAMP_QUERY) {
81            eprintln!(
82                "[GPU-PASS] CRANPOSE_GPU_PASS_TIMING is set but the adapter lacks TIMESTAMP_QUERY; passes will not be timed"
83            );
84            return None;
85        }
86        let query_set = device.create_query_set(&wgpu::QuerySetDescriptor {
87            label: Some("Pass Timing Query Set"),
88            ty: wgpu::QueryType::Timestamp,
89            count: QUERY_CAPACITY,
90        });
91        let buffer_size = u64::from(QUERY_CAPACITY) * u64::from(wgpu::QUERY_SIZE);
92        let resolve_buffer = device.create_buffer(&wgpu::BufferDescriptor {
93            label: Some("Pass Timing Resolve Buffer"),
94            size: buffer_size,
95            usage: wgpu::BufferUsages::QUERY_RESOLVE | wgpu::BufferUsages::COPY_SRC,
96            mapped_at_creation: false,
97        });
98        let slots = (0..READBACK_SLOTS)
99            .map(|_| ReadbackSlot {
100                buffer: device.create_buffer(&wgpu::BufferDescriptor {
101                    label: Some("Pass Timing Readback Buffer"),
102                    size: buffer_size,
103                    usage: wgpu::BufferUsages::COPY_DST | wgpu::BufferUsages::MAP_READ,
104                    mapped_at_creation: false,
105                }),
106                state: Arc::new(AtomicU8::new(SLOT_FREE)),
107                passes: RefCell::new(Vec::new()),
108            })
109            .collect();
110        Some(Self {
111            query_set,
112            resolve_buffer,
113            period_ns: queue.get_timestamp_period(),
114            cursor: Cell::new(0),
115            frame_passes: RefCell::new(Vec::new()),
116            labels: RefCell::new(Vec::new()),
117            totals: RefCell::new(Vec::new()),
118            slots,
119            frame_index: Cell::new(0),
120            frames_harvested: Cell::new(0),
121            span_nanoseconds: Cell::new(0),
122            dropped_passes: Cell::new(0),
123            dropped_frames: Cell::new(0),
124        })
125    }
126
127    pub(crate) fn query_set(&self) -> &wgpu::QuerySet {
128        &self.query_set
129    }
130
131    pub(crate) fn begin_pass(&self, label: &str) -> Option<(u32, u32)> {
132        let begin = self.cursor.get();
133        if begin + 2 > QUERY_CAPACITY {
134            self.dropped_passes.set(self.dropped_passes.get() + 1);
135            return None;
136        }
137        self.cursor.set(begin + 2);
138        let label_id = self.intern(label);
139        self.frame_passes.borrow_mut().push((label_id, begin));
140        Some((begin, begin + 1))
141    }
142
143    fn intern(&self, label: &str) -> u16 {
144        let mut labels = self.labels.borrow_mut();
145        if let Some(id) = labels.iter().position(|known| known == label) {
146            return id as u16;
147        }
148        labels.push(label.to_string());
149        self.totals.borrow_mut().push(LabelTotal::default());
150        (labels.len() - 1) as u16
151    }
152
153    pub(crate) fn harvest_completed(&self) {
154        for slot in &self.slots {
155            match slot.state.load(Ordering::Acquire) {
156                SLOT_MAPPED => {
157                    match slot.buffer.slice(..).get_mapped_range() {
158                        Ok(mapped) => {
159                            let span = accumulate_frame(
160                                &mut self.totals.borrow_mut(),
161                                &slot.passes.borrow(),
162                                &mapped,
163                                self.period_ns,
164                            );
165                            self.span_nanoseconds
166                                .set(self.span_nanoseconds.get().saturating_add(span));
167                        }
168                        Err(error) => log::debug!("pass timings could not be read: {error}"),
169                    }
170                    slot.buffer.unmap();
171                    slot.passes.borrow_mut().clear();
172                    slot.state.store(SLOT_FREE, Ordering::Release);
173                    self.frames_harvested.set(self.frames_harvested.get() + 1);
174                }
175                SLOT_FAILED => {
176                    slot.passes.borrow_mut().clear();
177                    slot.state.store(SLOT_FREE, Ordering::Release);
178                }
179                _ => {}
180            }
181        }
182    }
183
184    pub(crate) fn frame_resolve(&self) -> Option<PendingResolve<'_>> {
185        let used = self.cursor.get();
186        if used == 0 {
187            return None;
188        }
189        let Some(slot_index) = self
190            .slots
191            .iter()
192            .position(|slot| slot.state.load(Ordering::Acquire) == SLOT_FREE)
193        else {
194            self.dropped_frames.set(self.dropped_frames.get() + 1);
195            return None;
196        };
197        Some(PendingResolve {
198            timer: self,
199            slot_index,
200            used,
201        })
202    }
203
204    pub(crate) fn finish_frame(&self) {
205        self.cursor.set(0);
206        self.frame_passes.borrow_mut().clear();
207        let frame = self.frame_index.get() + 1;
208        self.frame_index.set(frame);
209        if frame.is_multiple_of(PRINT_CADENCE_FRAMES) {
210            self.print_and_reset_window(frame);
211        }
212    }
213
214    pub(crate) fn report(&self) -> GpuPassTimingReport {
215        let labels = self.labels.borrow();
216        let totals = self.totals.borrow();
217        let mut entries: Vec<GpuPassTimingEntry> = labels
218            .iter()
219            .zip(totals.iter())
220            .filter(|(_, total)| total.passes > 0)
221            .map(|(label, total)| GpuPassTimingEntry {
222                label: label.clone(),
223                total_ms: total.nanoseconds as f64 / 1_000_000.0,
224                passes: total.passes,
225            })
226            .collect();
227        entries.sort_by(|a, b| b.total_ms.total_cmp(&a.total_ms));
228        GpuPassTimingReport {
229            frames: self.frames_harvested.get(),
230            span_ms: self.span_nanoseconds.get() as f64 / 1_000_000.0,
231            entries,
232        }
233    }
234
235    fn print_and_reset_window(&self, frame: u64) {
236        let report = self.report();
237        if report.frames > 0 {
238            let frames = f64::from(report.frames);
239            let total_ms: f64 = report.entries.iter().map(|entry| entry.total_ms).sum();
240            let mut line = format!(
241                "[GPU-PASS f#{frame}] frames={} span={:.2}ms/frame occupancy={:.2}ms/frame",
242                report.frames,
243                report.span_ms / frames,
244                total_ms / frames,
245            );
246            for entry in &report.entries {
247                line.push_str(&format!(
248                    " | {} {:.2}ms x{:.1}",
249                    entry.label,
250                    entry.total_ms / frames,
251                    entry.passes as f64 / frames,
252                ));
253            }
254            if self.dropped_passes.get() > 0 || self.dropped_frames.get() > 0 {
255                line.push_str(&format!(
256                    " | dropped: passes={} frames={}",
257                    self.dropped_passes.get(),
258                    self.dropped_frames.get(),
259                ));
260            }
261            eprintln!("{line}");
262        }
263        for total in self.totals.borrow_mut().iter_mut() {
264            *total = LabelTotal::default();
265        }
266        self.frames_harvested.set(0);
267        self.span_nanoseconds.set(0);
268        self.dropped_passes.set(0);
269        self.dropped_frames.set(0);
270    }
271}
272
273pub(crate) struct PendingResolve<'timer> {
274    timer: &'timer PassTimer,
275    slot_index: usize,
276    used: u32,
277}
278
279impl PendingResolve<'_> {
280    pub(crate) fn encode(&self, encoder: &mut wgpu::CommandEncoder) {
281        let slot = &self.timer.slots[self.slot_index];
282        encoder.resolve_query_set(
283            &self.timer.query_set,
284            0..self.used,
285            &self.timer.resolve_buffer,
286            0,
287        );
288        encoder.copy_buffer_to_buffer(
289            &self.timer.resolve_buffer,
290            0,
291            &slot.buffer,
292            0,
293            u64::from(self.used) * u64::from(wgpu::QUERY_SIZE),
294        );
295    }
296
297    pub(crate) fn arm_readback(self) {
298        let slot = &self.timer.slots[self.slot_index];
299        slot.passes
300            .borrow_mut()
301            .clone_from(&self.timer.frame_passes.borrow());
302        slot.state.store(SLOT_PENDING, Ordering::Release);
303        let state = Arc::clone(&slot.state);
304        slot.buffer
305            .slice(..)
306            .map_async(wgpu::MapMode::Read, move |result| {
307                let outcome = if result.is_ok() {
308                    SLOT_MAPPED
309                } else {
310                    SLOT_FAILED
311                };
312                state.store(outcome, Ordering::Release);
313            });
314    }
315}
316
317pub(crate) fn begin_timed_render_pass<'encoder>(
318    pass_timer: Option<&PassTimer>,
319    encoder: &'encoder mut wgpu::CommandEncoder,
320    descriptor: &wgpu::RenderPassDescriptor<'_>,
321) -> wgpu::RenderPass<'encoder> {
322    crate::frame_graph::note_render_pass(descriptor);
323    let timing = pass_timer.and_then(|timer| {
324        timer
325            .begin_pass(descriptor.label.unwrap_or("<unlabeled pass>"))
326            .map(|(begin, end)| (timer, begin, end))
327    });
328    let timestamp_writes = timing.map(|(timer, begin, end)| wgpu::RenderPassTimestampWrites {
329        query_set: timer.query_set(),
330        beginning_of_pass_write_index: Some(begin),
331        end_of_pass_write_index: Some(end),
332    });
333    encoder.begin_render_pass(&wgpu::RenderPassDescriptor {
334        timestamp_writes,
335        ..descriptor.clone()
336    })
337}
338
339fn accumulate_frame(
340    totals: &mut [LabelTotal],
341    passes: &[(u16, u32)],
342    mapped: &[u8],
343    period_ns: f32,
344) -> u64 {
345    let read_tick = |index: u32| -> Option<u64> {
346        let offset = index as usize * 8;
347        let bytes = mapped.get(offset..offset + 8)?;
348        Some(u64::from_le_bytes(bytes.try_into().expect("8-byte slice")))
349    };
350    let mut first_begin = u64::MAX;
351    let mut last_end = 0u64;
352    for &(label_id, begin_index) in passes {
353        let Some(total) = totals.get_mut(usize::from(label_id)) else {
354            continue;
355        };
356        let (Some(begin), Some(end)) = (read_tick(begin_index), read_tick(begin_index + 1)) else {
357            continue;
358        };
359        if end < begin {
360            continue;
361        }
362        first_begin = first_begin.min(begin);
363        last_end = last_end.max(end);
364        total.nanoseconds = total
365            .nanoseconds
366            .saturating_add(((end - begin) as f64 * f64::from(period_ns)) as u64);
367        total.passes += 1;
368    }
369    if last_end <= first_begin {
370        return 0;
371    }
372    ((last_end - first_begin) as f64 * f64::from(period_ns)) as u64
373}
374
375#[cfg(test)]
376mod tests {
377    use super::*;
378
379    fn ticks(values: &[u64]) -> Vec<u8> {
380        values.iter().flat_map(|v| v.to_le_bytes()).collect()
381    }
382
383    #[test]
384    fn accumulate_frame_attributes_ticks_by_label() {
385        let mut totals = vec![LabelTotal::default(); 2];
386        let mapped = ticks(&[1_000, 1_100, 1_100, 1_150, 1_150, 1_160]);
387        accumulate_frame(&mut totals, &[(0, 0), (1, 2), (0, 4)], &mapped, 2.0);
388        assert_eq!(totals[0].nanoseconds, 220);
389        assert_eq!(totals[0].passes, 2);
390        assert_eq!(totals[1].nanoseconds, 100);
391        assert_eq!(totals[1].passes, 1);
392    }
393
394    #[test]
395    fn accumulate_frame_skips_backwards_and_out_of_range_pairs() {
396        let mut totals = vec![LabelTotal::default(); 1];
397        let mapped = ticks(&[500, 400]);
398        accumulate_frame(&mut totals, &[(0, 0)], &mapped, 1.0);
399        assert_eq!(totals[0].passes, 0, "an end before its begin is skipped");
400
401        accumulate_frame(&mut totals, &[(0, 6)], &mapped, 1.0);
402        assert_eq!(totals[0].passes, 0, "indices past the mapping are skipped");
403
404        let mapped = ticks(&[100, 250]);
405        accumulate_frame(&mut totals, &[(9, 0)], &mapped, 1.0);
406        assert_eq!(totals[0].passes, 0, "an unknown label id is skipped");
407    }
408}
cranpose_render_wgpu/pass_timing.rs

cranpose_render_wgpu/
pass_timing.rs
