shuyi_playdate/
report.rs

1//! [`RunReport`]: what a shipped game says in its console on every run, when
2//! it turns the report on ([`Driver::with_report`](crate::Driver::with_report)):
3//! how its start went, and then how fast it runs, so a tester's log shows a
4//! slow start or a stutter without a bench build.
5//!
6//! - **The start:** when the loading card and the game's first frame were
7//!   shown (milliseconds after `init`), how long the load took, the game
8//!   stack's deepest use after it, and the files the load read: how many,
9//!   which the bundle lacks, and the slowest. A loader names a step that
10//!   reads no file with [`mark`], so its time is its own.
11//! - **Each minute** (or [`RunReport::every_seconds`]): the top screen, the
12//!   frames a second, the times of `App::frame` and of the draw, the stack,
13//!   the music; and, with [`RunReport::phases`], each phase of the draw.
14//!
15//! Off, nothing is measured or logged. Times are whole microseconds from the
16//! SDK's high-resolution timer, shown in milliseconds.
17
18use alloc::borrow::ToOwned;
19use alloc::collections::BTreeMap;
20use alloc::format;
21use alloc::string::String;
22use alloc::vec::Vec;
23
24use core::sync::atomic::{AtomicBool, Ordering};
25
26use shuyi_assets::bundle::Watcher;
27use shuyi_ui::frame::onebit::Phase;
28
29/// What the report says, and where else it writes the start: off until a
30/// game makes one.
31#[derive(Debug, Clone, PartialEq, Eq)]
32#[non_exhaustive]
33pub struct RunReport {
34    pub(crate) file: Option<String>,
35    pub(crate) every_seconds: u32,
36    pub(crate) slowest: usize,
37    pub(crate) phases: bool,
38    /// The game stack's size, which `main!` knows.
39    pub(crate) stack_bytes: Option<usize>,
40}
41
42impl Default for RunReport {
43    fn default() -> Self {
44        Self::new()
45    }
46}
47
48impl RunReport {
49    /// The report in the console only: the running lines every 60 seconds,
50    /// the 10 slowest reads, no draw phases.
51    pub const fn new() -> Self {
52        Self {
53            file: None,
54            every_seconds: 60,
55            slowest: 10,
56            phases: false,
57            stack_bytes: None,
58        }
59    }
60
61    /// Writes the start's lines and every read to `path` in the game's data
62    /// folder too, once the first frame is shown: the Simulator has no
63    /// console to read.
64    #[must_use]
65    pub fn file(mut self, path: &str) -> Self {
66        self.file = Some(path.to_owned());
67        self
68    }
69
70    /// Logs the running lines every `seconds` (at least 1).
71    #[must_use]
72    pub const fn every_seconds(mut self, seconds: u32) -> Self {
73        self.every_seconds = if seconds == 0 { 1 } else { seconds };
74        self
75    }
76
77    /// Names the `count` slowest reads.
78    #[must_use]
79    pub const fn slowest(mut self, count: usize) -> Self {
80        self.slowest = count;
81        self
82    }
83
84    /// Times each phase of the draw ([`Phase`]), for a measuring build: the
85    /// backend then draws every changed frame whole, through
86    /// `onebit::render_marked`, instead of only where it changed.
87    #[must_use]
88    pub const fn phases(mut self, on: bool) -> Self {
89        self.phases = on;
90        self
91    }
92
93    /// The game stack is `bytes` long, for the stack line.
94    #[doc(hidden)]
95    #[must_use]
96    pub const fn stack_bytes(mut self, bytes: usize) -> Self {
97        self.stack_bytes = Some(bytes);
98        self
99    }
100}
101
102/// `n` with its thousands grouped: `1,234,567`.
103pub(crate) fn grouped(n: u64) -> String {
104    let digits = format!("{n}");
105    let mut out = String::new();
106    for (i, digit) in digits.chars().enumerate() {
107        if i > 0 && (digits.len() - i) % 3 == 0 {
108            out.push(',');
109        }
110        out.push(digit);
111    }
112    out
113}
114
115/// `us` microseconds in milliseconds, to a tenth: `12.5`.
116fn ms_tenths(us: u64) -> String {
117    let tenths = us.saturating_add(50) / 100;
118    format!("{}.{}", grouped(tenths / 10), tenths % 10)
119}
120
121/// `us` microseconds in whole milliseconds, rounded: `1,235`.
122fn ms(us: u64) -> String {
123    grouped(us.saturating_add(500) / 1000)
124}
125
126/// How long something took, time after time: the fewest, the most and the
127/// average microseconds.
128#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)]
129#[non_exhaustive]
130pub struct Timing {
131    count: u32,
132    min_us: u64,
133    max_us: u64,
134    total_us: u64,
135}
136
137impl Timing {
138    /// No times yet.
139    pub const fn new() -> Self {
140        Self {
141            count: 0,
142            min_us: 0,
143            max_us: 0,
144            total_us: 0,
145        }
146    }
147
148    /// Counts one more time of `us` microseconds.
149    pub fn add(&mut self, us: u64) {
150        if self.count == 0 {
151            self.min_us = us;
152            self.max_us = us;
153        } else {
154            self.min_us = self.min_us.min(us);
155            self.max_us = self.max_us.max(us);
156        }
157        self.count = self.count.saturating_add(1);
158        self.total_us = self.total_us.saturating_add(us);
159    }
160
161    /// How many times were counted.
162    pub const fn count(&self) -> u32 {
163        self.count
164    }
165
166    /// The fewest microseconds, 0 before any.
167    pub const fn min_us(&self) -> u64 {
168        self.min_us
169    }
170
171    /// The most microseconds, 0 before any.
172    pub const fn max_us(&self) -> u64 {
173        self.max_us
174    }
175
176    /// The average microseconds, rounded down; 0 before any.
177    pub fn avg_us(&self) -> u64 {
178        self.total_us / u64::from(self.count.max(1))
179    }
180
181    /// `name: min 1.0 / avg 1.5 / max 3.0 ms, 1,800 times`, or `name: none`
182    /// before any.
183    pub fn line(&self, name: &str) -> String {
184        if self.count == 0 {
185            return format!("{name}: none");
186        }
187        format!(
188            "{name}: min {} / avg {} / max {} ms, {} times",
189            ms_tenths(self.min_us),
190            ms_tenths(self.avg_us()),
191            ms_tenths(self.max_us),
192            grouped(u64::from(self.count))
193        )
194    }
195}
196
197/// Each phase of the draw, time after time, in [`Phase::ALL`]'s order.
198#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)]
199pub(crate) struct Phases([Timing; Phase::ALL.len()]);
200
201impl Phases {
202    /// Counts `us` microseconds of `phase`.
203    pub(crate) fn add(&mut self, phase: Phase, us: u64) {
204        if let Some(i) = Phase::ALL.iter().position(|&p| p == phase) {
205            self.0[i].add(us);
206        }
207    }
208
209    /// Each phase's average and most.
210    pub(crate) fn line(&self) -> String {
211        let each: Vec<String> = Phase::ALL
212            .iter()
213            .zip(&self.0)
214            .map(|(phase, t)| {
215                format!(
216                    "{} {} / {}",
217                    phase.name(),
218                    ms_tenths(t.avg_us()),
219                    ms_tenths(t.max_us)
220                )
221            })
222            .collect();
223        format!("Draw by phase, avg / max ms: {}", each.join(", "))
224    }
225}
226
227/// What the backend measured of its draws since the last take.
228#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)]
229pub(crate) struct Measured {
230    /// Each draw that reached the SDK's frame buffer: rendered and copied.
231    pub(crate) draw: Timing,
232    /// Each phase of those draws, when phases are timed.
233    pub(crate) phases: Option<Phases>,
234}
235
236/// One entry of the reads: a file read, or a step [`mark`]ed.
237#[derive(Debug, Clone, PartialEq, Eq)]
238struct Read {
239    /// The path, or the step's name in brackets.
240    name: String,
241    /// Whether the bundle has it; `None` for a step.
242    found: Option<bool>,
243    /// When, in the timer's microseconds.
244    at_us: u64,
245}
246
247/// The files the load reads from the bundle (`shuyi_assets::bundle::watch`),
248/// each with when: a file's time is from its read to the next read, the
249/// parsing and checking of what it holds. Only roughly so: a loader may read
250/// several files before it parses them.
251#[derive(Debug, Clone)]
252pub(crate) struct Reads {
253    /// The timer.
254    clock: fn() -> u64,
255    reads: Vec<Read>,
256}
257
258/// One file's reads, or one step, summed.
259#[derive(Debug, Clone, Copy, PartialEq, Eq)]
260struct FileTime {
261    /// From each of its reads to the next read.
262    us: u64,
263    /// How many times it was read.
264    reads: u32,
265    found: Option<bool>,
266}
267
268impl Reads {
269    /// No reads yet, timed by `clock`.
270    pub(crate) const fn new(clock: fn() -> u64) -> Self {
271        Self {
272            clock,
273            reads: Vec::new(),
274        }
275    }
276
277    /// Notes a read of `path` now.
278    fn add(&mut self, path: &str, found: bool) {
279        let at_us = (self.clock)();
280        self.reads.push(Read {
281            name: path.to_owned(),
282            found: Some(found),
283            at_us,
284        });
285    }
286
287    /// Notes that the step `name` began now.
288    fn mark(&mut self, name: &str) {
289        let at_us = (self.clock)();
290        self.reads.push(Read {
291            name: format!("({name})"),
292            found: None,
293            at_us,
294        });
295    }
296
297    /// Each file and step by name, the last one's time running to `end_us`.
298    fn files(&self, end_us: u64) -> BTreeMap<&str, FileTime> {
299        let mut files: BTreeMap<&str, FileTime> = BTreeMap::new();
300        let ends = self.reads.iter().skip(1).map(|r| r.at_us).chain([end_us]);
301        for (read, end) in self.reads.iter().zip(ends) {
302            let file = files.entry(&read.name).or_insert(FileTime {
303                us: 0,
304                reads: 0,
305                found: read.found,
306            });
307            file.us += end.saturating_sub(read.at_us);
308            file.reads += 1;
309        }
310        files
311    }
312
313    /// The files and steps by time, the slowest first, by name where equal.
314    fn by_time(&self, end_us: u64) -> Vec<(&str, FileTime)> {
315        let mut files: Vec<(&str, FileTime)> = self.files(end_us).into_iter().collect();
316        files.sort_by(|a, b| b.1.us.cmp(&a.1.us).then(a.0.cmp(b.0)));
317        files
318    }
319
320    /// How many reads of how many files, which the bundle lacks, and the
321    /// `slowest` slowest files and steps.
322    pub(crate) fn summary(&self, end_us: u64, slowest: usize) -> Vec<String> {
323        let files = self.by_time(end_us);
324        let missing: Vec<&str> = files
325            .iter()
326            .filter(|(_, f)| f.found == Some(false))
327            .map(|(name, _)| *name)
328            .collect();
329        let reads = self.reads.iter().filter(|r| r.found.is_some()).count();
330        let read = files.iter().filter(|(_, f)| f.found.is_some()).count();
331        let mut lines = Vec::from([format!(
332            "Bundle: {} reads of {} files, {} not in the bundle",
333            grouped(reads as u64),
334            grouped(read as u64),
335            grouped(missing.len() as u64)
336        )]);
337        if !missing.is_empty() {
338            lines.push(format!("Not in the bundle: {}", missing.join(", ")));
339        }
340        let names: Vec<String> = files
341            .iter()
342            .take(slowest)
343            .map(|(name, f)| format!("{name} {}", ms(f.us)))
344            .collect();
345        if !names.is_empty() {
346            lines.push(format!(
347                "Slowest reads, ms to the next read: {}",
348                names.join(", ")
349            ));
350        }
351        lines
352    }
353
354    /// Every file and step, the slowest first: its time, and how many times
355    /// it was read when more than once.
356    pub(crate) fn each(&self, end_us: u64) -> Vec<String> {
357        self.by_time(end_us)
358            .into_iter()
359            .map(|(name, f)| {
360                let reads = if f.reads > 1 {
361                    format!(", {} reads", grouped(u64::from(f.reads)))
362                } else {
363                    String::new()
364                };
365                let missing = if f.found == Some(false) {
366                    ", not in the bundle"
367                } else {
368                    ""
369                };
370                format!("  {name}: {} ms{reads}{missing}", ms_tenths(f.us))
371            })
372            .collect()
373    }
374}
375
376/// Runs `f` on the reads being noted, if any: the bundle's watcher is a
377/// plain function, so they live outside the driver. The tests keep one per
378/// thread, as each runs a game of its own.
379#[cfg(test)]
380pub(crate) fn with_reads<R>(f: impl FnOnce(&mut Option<Reads>) -> R) -> R {
381    std::thread_local! {
382        static READS: core::cell::RefCell<Option<Reads>> = const { core::cell::RefCell::new(None) };
383    }
384    READS.with_borrow_mut(f)
385}
386
387/// On the device the reads are a static of its own.
388#[cfg(all(not(test), shuyi_playdate_sdk))]
389pub(crate) use crate::device::with_reads;
390
391/// Off the device no game runs, so there are no reads to note.
392#[cfg(all(not(test), not(shuyi_playdate_sdk)))]
393pub(crate) fn with_reads<R>(f: impl FnOnce(&mut Option<Reads>) -> R) -> R {
394    f(&mut None)
395}
396
397/// Whether [`noted`] is the bundle's watcher.
398static WATCHING: AtomicBool = AtomicBool::new(false);
399
400/// Sets [`noted`] as the bundle's watcher (`shuyi_assets::bundle::watch`):
401/// `Ok` if it is, from now or from an earlier report; else the other
402/// watcher, which was set first.
403pub(crate) fn watch_bundle(watcher: Watcher) -> Result<(), Watcher> {
404    watch_once(shuyi_assets::bundle::watch, &WATCHING, watcher)
405}
406
407/// Sets `watcher` with `set`, `watching` saying whether it was set before:
408/// a refusal then is of the report's own watcher, and no refusal.
409fn watch_once(
410    set: fn(Watcher) -> Result<(), Watcher>,
411    watching: &AtomicBool,
412    watcher: Watcher,
413) -> Result<(), Watcher> {
414    match set(watcher) {
415        Ok(()) => {
416            watching.store(true, Ordering::Relaxed);
417            Ok(())
418        }
419        Err(_) if watching.load(Ordering::Relaxed) => Ok(()),
420        Err(other) => Err(other),
421    }
422}
423
424/// The bundle's watcher while the report is on: notes the read, during the
425/// load.
426pub(crate) fn noted(path: &str, found: bool) {
427    with_reads(|reads| {
428        if let Some(reads) = reads {
429            reads.add(path, found);
430        }
431    });
432}
433
434/// Names the step `name` of the game's load, which reads no file: the time
435/// from here to the next read is its own, not the last file's. Nothing
436/// happens unless the report is on and the game is loading.
437pub fn mark(name: &str) {
438    with_reads(|reads| {
439        if let Some(reads) = reads {
440            reads.mark(name);
441        }
442    });
443}
444
445/// The line of the game stack's deepest use.
446pub(crate) fn stack_line(used: Option<usize>, size: Option<usize>) -> String {
447    match (used, size) {
448        (Some(used), Some(size)) => format!(
449            "Game stack used: {} of {} bytes",
450            grouped(used as u64),
451            grouped(size as u64)
452        ),
453        (Some(used), None) => format!("Game stack used: {} bytes", grouped(used as u64)),
454        (None, _) => "Game stack: measured on the device only".to_owned(),
455    }
456}
457
458/// The start's line of when `what` reached the screen, `us` after `init`.
459pub(crate) fn shown_line(what: &str, us: u64) -> String {
460    format!("{what} shown {} ms after start", ms(us))
461}
462
463/// The start's line of the load's length.
464pub(crate) fn load_line(us: u64) -> String {
465    format!("Game data loaded in {} ms", ms(us))
466}
467
468/// The line said when another watcher of the bundle was set first.
469// check-text: not player text (for the console)
470pub(crate) const REFUSED: &str = "Bundle reads: not timed, as another watcher was set first";
471
472/// The running numbers over one stretch ([`RunReport::every_seconds`]).
473#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)]
474pub(crate) struct Stretch {
475    /// Each `App::frame`.
476    pub(crate) frame: Timing,
477}
478
479/// What the running lines name besides the stretch's own numbers.
480#[derive(Debug, Clone, Copy)]
481pub(crate) struct Now<'a> {
482    /// The top screen, if one is open.
483    pub(crate) screen: Option<&'a str>,
484    /// The stretch's length in milliseconds.
485    pub(crate) ms: u64,
486    pub(crate) stack_used: Option<usize>,
487    /// The music heard, if any.
488    pub(crate) music: Option<&'a str>,
489    /// Whether a file player ran out of data in the stretch.
490    pub(crate) underran: bool,
491}
492
493impl Stretch {
494    /// The running lines.
495    pub(crate) fn lines(
496        &self,
497        now: &Now<'_>,
498        measured: &Measured,
499        report: &RunReport,
500    ) -> Vec<String> {
501        let frames = u64::from(self.frame.count());
502        let tenths = frames * 10_000 / now.ms.max(1);
503        let screen = now.screen.unwrap_or("no screen");
504        let music = match (now.music, now.underran) {
505            (Some(cue), true) => format!("Music: {cue}, and a file player ran out of data"),
506            (Some(cue), false) => format!("Music: {cue}, no file player ran out of data"),
507            (None, true) => "Music: none, and a file player ran out of data".to_owned(),
508            (None, false) => "Music: none".to_owned(),
509        };
510        let mut lines = Vec::from([
511            format!(
512                "On {screen} for {} seconds: {}.{} frames a second",
513                grouped((now.ms + 500) / 1000),
514                grouped(tenths / 10),
515                tenths % 10
516            ),
517            self.frame.line("App::frame"),
518            measured.draw.line("Draw and flush"),
519        ]);
520        if let Some(phases) = &measured.phases {
521            lines.push(phases.line());
522        }
523        lines.push(stack_line(now.stack_used, report.stack_bytes));
524        lines.push(music);
525        lines
526    }
527}
528
529#[cfg(test)]
530mod tests;
shuyi_playdate/report.rs

shuyi_playdate/
report.rs
