concinnity-engine 0.19.119

// Rendering a reduced run as the text a person reads.

use std::fmt::Write;

use crate::frame_report::reduce::{FrameCost, Report, SegmentReport, SlowFrame};

const MICROS_PER_MILLI: f32 = 1_000.0;
const BYTES_PER_MIB: f32 = (1 << 20) as f32;

/// Render a report as plain text.
///
/// Frame time leads every row because it is the number a player feels; the
/// budget count beside it is what a mean would hide.
pub fn to_text(report: &Report) -> String {
    let mut out = String::new();
    let _ = writeln!(
        out,
        "frame report: {} measured frame(s), {} warm-up frame(s) dropped, budget {:.2} ms",
        report.overall.frame.count,
        report.warmup_dropped,
        report.budget_us as f32 / MICROS_PER_MILLI,
    );
    if !report.completed {
        let _ = writeln!(
            out,
            "  NOTE: the camera track did not finish, so this covers part of the path only",
        );
    }
    let _ = writeln!(out);
    let _ = writeln!(
        out,
        "{:<16} {:>7} {:>8} {:>8} {:>8} {:>8} {:>9} {:>8} {:>8}",
        "segment", "frames", "p50 ms", "p95 ms", "p99 ms", "max ms", "over bgt", "cpu ms", "gpu ms",
    );
    write_row(&mut out, &report.overall);
    for segment in &report.segments {
        write_row(&mut out, segment);
    }

    let _ = writeln!(out);
    let _ = writeln!(
        out,
        "peak GPU memory {:.0} MiB, mean blocked-on-GPU {:.2} ms, mean {} draw call(s) over {} object(s)",
        report.overall.vram_peak_bytes as f32 / BYTES_PER_MIB,
        report.overall.gpu_wait_mean_us as f32 / MICROS_PER_MILLI,
        report.overall.draw_calls_mean,
        report.overall.objects_mean,
    );
    write_slowest(&mut out, &report.slowest);

    // The pass block is medians, like the table above it, because a backend
    // that mistimes one frame does it by orders of magnitude. The system block
    // is means, so that its shares add up to the work the systems did. Each
    // heading carries the total its shares are taken against.
    for segment in &report.segments {
        write_block(
            &mut out,
            &format!(
                "{} GPU passes, median {:.2} ms",
                segment.name,
                segment.gpu.p50_us as f32 / MICROS_PER_MILLI,
            ),
            "of the GPU frame",
            segment.passes.iter().map(|p| {
                // A pass timed inside the one above it is indented under it.
                let name = match p.within {
                    Some(_) => format!("  {}", p.name),
                    None => p.name.clone(),
                };
                (name, p.median_us, p.share)
            }),
        );
        write_block(
            &mut out,
            &format!(
                "{} CPU work, mean {:.2} ms",
                segment.name,
                segment.cpu.mean_us as f32 / MICROS_PER_MILLI,
            ),
            "of the CPU work",
            segment
                .systems
                .iter()
                .map(|s| (s.name.clone(), s.mean_us, s.share)),
        );
    }
    out
}

// A named cost breakdown, or nothing at all when there is none to show. An
// empty CPU block is the report saying the CPU was not what limited the
// stretch, which is worth more than a ranking of noise.
fn write_block(
    out: &mut String,
    heading: &str,
    of_what: &str,
    rows: impl Iterator<Item = (String, u32, f32)>,
) {
    let mut started = false;
    for (name, mean_us, share) in rows {
        if !started {
            let _ = writeln!(out);
            let _ = writeln!(out, "{heading}:");
            started = true;
        }
        let _ = writeln!(
            out,
            "  {:<20} {:>7.3} ms  {:>5.1}% {of_what}",
            name,
            mean_us as f32 / MICROS_PER_MILLI,
            share * 100.0,
        );
    }
}

// The slowest frames, each with the costs that say where its time went.
fn write_slowest(out: &mut String, frames: &[SlowFrame]) {
    if frames.is_empty() {
        return;
    }
    let ms = |us: u32| us as f32 / MICROS_PER_MILLI;
    let _ = writeln!(out);
    let _ = writeln!(out, "slowest frames:");
    for frame in frames {
        let _ = writeln!(
            out,
            "  {:.2} ms at {:.2} s in {}: cpu {:.2} ms, blocked on GPU {:.2} ms, gpu {:.2} ms",
            ms(frame.frame_us),
            frame.run_seconds,
            frame.segment,
            ms(frame.cpu_us),
            ms(frame.gpu_wait_us),
            ms(frame.gpu_frame_us),
        );
        write_costs(out, "cpu", &frame.cpu);
        write_costs(out, "gpu", &frame.passes);
    }
}

// One `label: name ms, name ms` line, or nothing when there are no costs.
fn write_costs(out: &mut String, label: &str, costs: &[FrameCost]) {
    if costs.is_empty() {
        return;
    }
    let _ = write!(out, "    {label}:");
    for (i, cost) in costs.iter().enumerate() {
        let separator = if i == 0 { "" } else { "," };
        let _ = write!(
            out,
            "{separator} {} {:.2}",
            cost.name,
            cost.us as f32 / MICROS_PER_MILLI
        );
    }
    let _ = writeln!(out);
}

// One line of the summary table.
fn write_row(out: &mut String, segment: &SegmentReport) {
    let ms = |us: u32| us as f32 / MICROS_PER_MILLI;
    let _ = writeln!(
        out,
        "{:<16} {:>7} {:>8.2} {:>8.2} {:>8.2} {:>8.2} {:>8.1}% {:>8.2} {:>8.2}",
        segment.name,
        segment.frame.count,
        ms(segment.frame.p50_us),
        ms(segment.frame.p95_us),
        ms(segment.frame.p99_us),
        ms(segment.frame.max_us),
        segment.frame.over_budget_share() * 100.0,
        ms(segment.cpu.p50_us),
        ms(segment.gpu.p50_us),
    );
}

#[cfg(test)]
mod tests {
    use super::*;
    use crate::frame_report::reduce::ReduceOptions;
    use crate::frame_report::sample::MAX_SYSTEM_TIMINGS;
    use crate::frame_report::sample::{FrameRun, FrameSample};
    use concinnity_core::profile::MAX_PASS_TIMINGS;

    fn sample(run_seconds: f32, segment: Option<u32>, frame_us: u32) -> FrameSample {
        FrameSample {
            run_seconds,
            segment,
            frame_us,
            gpu_frame_us: frame_us / 2,
            gpu_wait_us: 250,
            render_cpu_us: 0,
            draw_calls: 64,
            objects: 512,
            vram_bytes: 512 << 20,
            pass_us: [0; MAX_PASS_TIMINGS],
            system_us: [0; MAX_SYSTEM_TIMINGS],
        }
    }

    fn report_of(run: FrameRun) -> Report {
        Report::of(
            &run,
            ReduceOptions {
                warmup_seconds: 0.0,
                ..Default::default()
            },
        )
        .expect("measured frames")
    }

    fn rendered() -> String {
        let mut first = sample(0.0, Some(0), 10_000);
        first.pass_us[0] = 3_000;
        let run = FrameRun {
            samples: vec![first, sample(1.0, Some(1), 40_000)],
            segments: vec!["approach".to_string(), "rays".to_string()],
            pass_names: vec!["main".to_string()],
            system_names: Vec::new(),
            completed: true,
        };
        to_text(&report_of(run))
    }

    #[test]
    fn the_header_states_what_was_measured_and_what_was_thrown_away() {
        let text = rendered();
        assert!(text.contains("2 measured frame(s)"), "{text}");
        assert!(text.contains("0 warm-up frame(s) dropped"), "{text}");
        assert!(text.contains("budget 16.67 ms"), "{text}");
    }

    #[test]
    fn every_segment_gets_a_row_under_the_overall_one() {
        let text = rendered();
        assert!(text.contains("\nall "), "{text}");
        assert!(text.contains("approach"), "{text}");
        assert!(text.contains("rays"), "{text}");
    }

    #[test]
    fn microseconds_are_rendered_as_milliseconds() {
        // 40_000us is the slowest frame, so the max column reads 40.00.
        assert!(rendered().contains("40.00"), "{}", rendered());
    }

    #[test]
    fn a_pass_is_listed_with_its_share_of_the_gpu_frame() {
        // 3_000us of a 5_000us GPU frame is 60 percent.
        let text = rendered();
        assert!(text.contains("main"), "{text}");
        assert!(text.contains("60.0%"), "{text}");
        // The share is of the mean, which the table above reports the median
        // of, so the heading names the total it was taken against.
        assert!(text.contains("GPU passes, median 5.00 ms"), "{text}");
    }

    #[test]
    fn a_pass_timed_inside_another_is_indented_under_it() {
        let mut first = sample(0.0, Some(0), 10_000);
        first.pass_us[0] = 3_000;
        first.pass_us[1] = 500;
        let run = FrameRun {
            samples: vec![first],
            segments: vec!["approach".to_string()],
            pass_names: vec!["main".to_string(), "sky".to_string()],
            system_names: Vec::new(),
            completed: true,
        };
        let text = to_text(&report_of(run));
        let main = text.find("\n  main ").expect("main row");
        let sky = text.find("\n    sky ").expect("indented sky row");
        assert!(main < sky, "{text}");
    }

    #[test]
    fn the_cpu_column_is_rendered_beside_the_wall_one() {
        // The fixture names no systems, so the CPU column falls back to the
        // wall time less the wait: 40ms less 250us on the slower frame.
        let text = rendered();
        assert!(text.contains("cpu ms"), "{text}");
        assert!(text.contains("39.75"), "{text}");
    }

    #[test]
    fn a_run_that_did_not_finish_is_flagged_before_its_numbers() {
        let run = FrameRun {
            samples: vec![sample(0.0, Some(0), 10_000)],
            segments: vec!["approach".to_string()],
            pass_names: Vec::new(),
            system_names: Vec::new(),
            completed: false,
        };
        let text = to_text(&report_of(run));
        let note = text.find("did not finish").expect("the note");
        assert!(note < text.find("segment").expect("the table"), "{text}");
    }

    #[test]
    fn the_slowest_frames_are_listed_with_their_breakdown() {
        let mut hitch = sample(1.0, Some(1), 300_000);
        hitch.gpu_wait_us = 297_000;
        hitch.render_cpu_us = 700;
        hitch.system_us[0] = 1_200;
        hitch.pass_us[0] = 4_000;
        let run = FrameRun {
            samples: vec![sample(0.0, Some(0), 10_000), hitch],
            segments: vec!["approach".to_string(), "rays".to_string()],
            pass_names: vec!["main".to_string()],
            system_names: vec!["PhysicsSystem".to_string()],
            completed: true,
        };
        let text = to_text(&report_of(run));
        let heading = text.find("slowest frames:").expect("the list");
        let hitch_line = text
            .find(
                "300.00 ms at 1.00 s in rays: cpu 1.90 ms, blocked on GPU 297.00 ms, gpu 150.00 ms",
            )
            .expect("the slowest frame, first");
        assert!(heading < hitch_line, "{text}");
        assert!(
            text.contains("    cpu: PhysicsSystem 1.20, render submit 0.70\n"),
            "{text}"
        );
        assert!(text.contains("    gpu: main 4.00\n"), "{text}");
        assert!(text.contains("10.00 ms at 0.00 s in approach"), "{text}");
    }

    #[test]
    fn the_cpu_block_names_the_work_it_shares_out() {
        let mut only = sample(0.0, Some(0), 10_000);
        only.system_us[0] = 600;
        only.render_cpu_us = 400;
        let run = FrameRun {
            samples: vec![only],
            segments: vec!["approach".to_string()],
            pass_names: Vec::new(),
            system_names: vec!["PhysicsSystem".to_string()],
            completed: true,
        };
        let text = to_text(&report_of(run));
        assert!(text.contains("approach CPU work, mean 1.00 ms:"), "{text}");
        assert!(text.contains("40.0% of the CPU work"), "{text}");
    }

    #[test]
    fn a_complete_run_carries_no_note() {
        assert!(!rendered().contains("did not finish"));
    }

    #[test]
    fn a_segment_with_no_pass_timings_lists_no_pass_block() {
        // A backend without timestamp support still gets a table, just no
        // per-pass breakdown under it.
        let run = FrameRun {
            samples: vec![sample(0.0, Some(0), 10_000)],
            segments: vec!["approach".to_string()],
            pass_names: Vec::new(),
            system_names: Vec::new(),
            completed: true,
        };
        let text = to_text(&report_of(run));
        assert!(!text.contains("GPU passes:"), "{text}");
        assert!(text.contains("approach"), "{text}");
    }
}