From 715f85c6121cae55e7b547100015ab40173459e5 Mon Sep 17 00:00:00 2001 From: Brandon Thomas Date: Mon, 12 Oct 2026 04:37:03 -0400 Subject: [PATCH] Tests: linear-time checks measure CPU time, not wall clock under load (#850) The five tests that assert linear layout/export/hyphenation by comparing the cost of an n-sized and a larger input (layout: unequal formats, hidden separators with auto hyphenation, hidden float anchors; pdf: fragmented hidden headings; proof: hyphenating a long word) timed both with wall clock, fastest of three. On a loaded machine (CI, shared dev boxes, the test harness running other tests in parallel) a preempted big run, timer resolution on the small run, or a tight 4x/8.0 limit (hyphenation measured ~7.2 when linear) made them fail now and then. Each now uses a shared cost_ratio helper (test-only, no production change): - CPU time of the test thread from /proc/thread-self/schedstat on Linux, so time spent waiting for a CPU is left out (wall clock elsewhere); - the small input runs `scale` times per timing so both timings are long against the clock's resolution; - small and big runs alternate, five rounds after a warm-up, cheapest kept; - 8x the input everywhere: linear ~8x, quadratic ~64x, limit 24x. Measured under load (load avg ~15-35 on 32 cores): 60 linear ratios in 7.7-8.8. With the old quadratic code injected locally each test fails: unequal formats (uncapped style bucket scan) ~90-104x, hidden separators (hyphenator rescan per point) ~36x, float anchors (run walk restarted per anchor) ~188x, PDF headings (left-out range scan per char) ~37x, hyphenation 50-65x. Co-authored-by: Claude Opus 5.5 --- crates/layout/src/tests.rs | 62 ++++++++++++++++++++++++++---------- crates/pdf/src/tests.rs | 65 +++++++++++++++++++++++++++----------- crates/proof/src/hyphen.rs | 52 ++++++++++++++++++++---------- 3 files changed, 128 insertions(+), 51 deletions(-) diff --git a/crates/layout/src/tests.rs b/crates/layout/src/tests.rs index 6f9ef2a..a65af6d 100644 --- a/crates/layout/src/tests.rs +++ b/crates/layout/src/tests.rs @@ -166,29 +166,57 @@ fn hidden_text_adds_no_line_break_opportunity_when_not_shown() { } } -/// How much longer laying out `doc(4n)` takes than `doc(n)` (fastest of three each, after a -/// warm-up): ~4 when linear, ~16 when quadratic, whatever the machine. -/// How much bigger the second document is in the linear-time tests. At 8x a linear layout takes -/// about 8x as long and a quadratic one about 64x, so a limit of 24x stays far from both, however -/// busy the machine running the tests is. +/// How much bigger the second document is in the linear-time tests. At 8x a linear layout costs +/// about 8x as much and a quadratic one about 64x, so a limit of 24x stays far from both. const SCALE: usize = 8; -fn layout_time_ratio(doc: impl Fn(usize) -> Document, n: usize, opts: &LayoutOptions) -> (f64, f64, f64) { - let fastest = |d: &Document| { - (0..3) - .map(|_| { - let t = std::time::Instant::now(); - layout(d, &mut LayoutCache::new(), opts); - t.elapsed().as_secs_f64() - }) - .fold(f64::INFINITY, f64::min) +/// The CPU time `f` takes on this thread, in seconds. On Linux it is the scheduler's count of the +/// time the thread actually ran, so the time it waits while other work on a busy machine has the +/// CPU is left out; elsewhere, wall-clock time. +fn cpu_cost(f: &mut impl FnMut()) -> f64 { + let ran = || { + let s = std::fs::read_to_string("/proc/thread-self/schedstat").ok()?; + s.split_whitespace().next()?.parse::().ok() }; - let (small, big) = (doc(n), doc(SCALE * n)); - layout(&small, &mut LayoutCache::new(), opts); - let (t1, tk) = (fastest(&small), fastest(&big)); + let (t, before) = (std::time::Instant::now(), ran()); + f(); + match (before, ran()) { + (Some(a), Some(b)) => b.saturating_sub(a) as f64 * 1e-9, + _ => t.elapsed().as_secs_f64(), + } +} + +/// How much more `big` costs than `small`, for `big` an input `scale` times the size of `small`'s: +/// (small, big, big / small), ~`scale` when linear and ~`scale`² when quadratic. Each is the +/// cheapest of several runs after a warm-up, the runs alternating so a busy spell slows both sizes +/// alike; `small` is timed `scale` times over per run, so both timings are long against the clock's +/// resolution. +fn cost_ratio(scale: usize, mut small: impl FnMut(), mut big: impl FnMut()) -> (f64, f64, f64) { + small(); + big(); + let mut small_scaled = || (0..scale).for_each(|_| small()); + let (mut t1, mut tk) = (f64::INFINITY, f64::INFINITY); + for _ in 0..5 { + t1 = t1.min(cpu_cost(&mut small_scaled) / scale as f64); + tk = tk.min(cpu_cost(&mut big)); + } (t1, tk, tk / t1.max(1e-9)) } +/// [`cost_ratio`] of laying out `doc(SCALE * n)` against `doc(n)`. +fn layout_time_ratio(doc: impl Fn(usize) -> Document, n: usize, opts: &LayoutOptions) -> (f64, f64, f64) { + let (small, big) = (doc(n), doc(SCALE * n)); + cost_ratio( + SCALE, + || { + layout(&small, &mut LayoutCache::new(), opts); + }, + || { + layout(&big, &mut LayoutCache::new(), opts); + }, + ) +} + #[test] fn hidden_separators_with_automatic_hyphenation_lay_out_in_linear_time() { // "hyphenation " n times with every space hidden: one joined word of 11n letters reaches the diff --git a/crates/pdf/src/tests.rs b/crates/pdf/src/tests.rs index 5683e11..2fd44dc 100644 --- a/crates/pdf/src/tests.rs +++ b/crates/pdf/src/tests.rs @@ -300,11 +300,44 @@ fn hidden_heading_text_stays_out_of_bookmarks_and_tags() { } } +/// The CPU time `f` takes on this thread, in seconds. On Linux it is the scheduler's count of the +/// time the thread actually ran, so the time it waits while other work on a busy machine has the +/// CPU is left out; elsewhere, wall-clock time. +fn cpu_cost(f: &mut impl FnMut()) -> f64 { + let ran = || { + let s = std::fs::read_to_string("/proc/thread-self/schedstat").ok()?; + s.split_whitespace().next()?.parse::().ok() + }; + let (t, before) = (std::time::Instant::now(), ran()); + f(); + match (before, ran()) { + (Some(a), Some(b)) => b.saturating_sub(a) as f64 * 1e-9, + _ => t.elapsed().as_secs_f64(), + } +} + +/// How much more `big` costs than `small`, for `big` an input `scale` times the size of `small`'s: +/// (small, big, big / small), ~`scale` when linear and ~`scale`² when quadratic. Each is the +/// cheapest of several runs after a warm-up, the runs alternating so a busy spell slows both sizes +/// alike; `small` is timed `scale` times over per run, so both timings are long against the clock's +/// resolution. +fn cost_ratio(scale: usize, mut small: impl FnMut(), mut big: impl FnMut()) -> (f64, f64, f64) { + small(); + big(); + let mut small_scaled = || (0..scale).for_each(|_| small()); + let (mut t1, mut tk) = (f64::INFINITY, f64::INFINITY); + for _ in 0..5 { + t1 = t1.min(cpu_cost(&mut small_scaled) / scale as f64); + tk = tk.min(cpu_cost(&mut big)); + } + (t1, tk, tk / t1.max(1e-9)) +} + #[test] fn long_fragmented_hidden_headings_export_in_linear_time() { // Headings of n chars in one-char runs: all hidden with bold alternating, and hidden and visible // alternating. Layout and the bookmark/tag titles once scanned every left-out range for every - // char, quadratic in n. Machine-independent: the time for 4n against n, linear ~4, quadratic ~16. + // char, quadratic in n. Machine-independent: the cost for 8n against n, linear ~8, quadratic ~64. let doc = |n: usize| { let heading = |visible_every_other: bool| { let mut h = Paragraph::with_text(&"abcdefg ".repeat(n / 8), CharProps::default()).styled("Heading1"); @@ -321,23 +354,19 @@ fn long_fragmented_hidden_headings_export_in_linear_time() { d }; let opts = PdfOptions { compress: false, ..Default::default() }; - // The fastest of a few runs, after a warm-up, so one slow run on a busy machine counts less. - let fastest = |d: &Document| { - (0..3) - .map(|_| { - let t = std::time::Instant::now(); - export(d, &opts).unwrap(); - t.elapsed().as_secs_f64() - }) - .fold(f64::INFINITY, f64::min) - }; - let n = 25_000; - let (small, big) = (doc(n), doc(4 * n)); - export(&small, &opts).unwrap(); - let (t1, t4) = (fastest(&small), fastest(&big)); - let ratio = t4 / t1.max(1e-9); - eprintln!("t(n) {t1:.3} s, t(4n) {t4:.3} s, ratio {ratio:.1}"); - assert!(ratio < 8.0, "4x the text took {ratio:.1}x the time ({t1:.3} s → {t4:.3} s): not linear"); + let n = 12_500; + let (small, big) = (doc(n), doc(8 * n)); + let (t1, t8, ratio) = cost_ratio( + 8, + || { + export(&small, &opts).unwrap(); + }, + || { + export(&big, &opts).unwrap(); + }, + ); + eprintln!("t(n) {t1:.3} s, t(8n) {t8:.3} s, ratio {ratio:.1}"); + assert!(ratio < 24.0, "8x the text took {ratio:.1}x the time ({t1:.3} s → {t8:.3} s): not linear"); let pdf = String::from_utf8_lossy(&export(&big, &opts).unwrap()).into_owned(); // The all-hidden heading has no bookmark; the other is titled with its visible chars only. assert!(!pdf.contains("abcd"), "hidden heading text in a title"); diff --git a/crates/proof/src/hyphen.rs b/crates/proof/src/hyphen.rs index 6462938..c244455 100644 --- a/crates/proof/src/hyphen.rs +++ b/crates/proof/src/hyphen.rs @@ -455,16 +455,37 @@ mod tests { assert!(hyphen_points("typography", &lim).is_empty()); } - /// The fastest of three timings of `f`, after a warm-up. - fn fastest(f: impl Fn()) -> f64 { + /// The CPU time `f` takes on this thread, in seconds. On Linux it is the scheduler's count of the + /// time the thread actually ran, so the time it waits while other work on a busy machine has the + /// CPU is left out; elsewhere, wall-clock time. + fn cpu_cost(f: &mut impl FnMut()) -> f64 { + let ran = || { + let s = std::fs::read_to_string("/proc/thread-self/schedstat").ok()?; + s.split_whitespace().next()?.parse::().ok() + }; + let (t, before) = (std::time::Instant::now(), ran()); f(); - (0..3) - .map(|_| { - let t = std::time::Instant::now(); - f(); - t.elapsed().as_secs_f64() - }) - .fold(f64::INFINITY, f64::min) + match (before, ran()) { + (Some(a), Some(b)) => b.saturating_sub(a) as f64 * 1e-9, + _ => t.elapsed().as_secs_f64(), + } + } + + /// How much more `big` costs than `small`, for `big` an input `scale` times the size of `small`'s: + /// (small, big, big / small), ~`scale` when linear and ~`scale`² when quadratic. Each is the + /// cheapest of several runs after a warm-up, the runs alternating so a busy spell slows both sizes + /// alike; `small` is timed `scale` times over per run, so both timings are long against the clock's + /// resolution. + fn cost_ratio(scale: usize, mut small: impl FnMut(), mut big: impl FnMut()) -> (f64, f64, f64) { + small(); + big(); + let mut small_scaled = || (0..scale).for_each(|_| small()); + let (mut t1, mut tk) = (f64::INFINITY, f64::INFINITY); + for _ in 0..5 { + t1 = t1.min(cpu_cost(&mut small_scaled) / scale as f64); + tk = tk.min(cpu_cost(&mut big)); + } + (t1, tk, tk / t1.max(1e-9)) } /// `hyphen_points`' limit checks as first written (a rescan of the letter run per point): the @@ -598,7 +619,7 @@ mod tests { #[test] fn hyphenating_a_long_word_is_linear() { - // A word of n letters against one of 4n: linear ~4x the time, the old rescans ~16x. One in + // A word of n letters against one of 8n: linear ~8x the cost, the old rescans ~64x. One in // the pattern alphabet, one outside it (the syllable heuristic). let pattern = |k: usize| "hyphenation".repeat(k); let heuristic = |k: usize| "smørrebrød".repeat(k); @@ -607,17 +628,16 @@ mod tests { let ratios: Vec<(String, f64)> = [(pattern as fn(usize) -> String, 20), (heuristic, 40)] .into_iter() .map(|(word, repeat)| { - let (small, big) = (word(400), word(1600)); - let time = |w: &str| fastest(|| (0..repeat).for_each(|_| drop(hyphen_points(w, &Limits::default())))); - let (t1, t4) = (time(&small), time(&big)); - let ratio = t4 / t1.max(1e-9); - let what = format!("{}…: t(n) {t1:.4} s, t(4n) {t4:.4} s, ratio {ratio:.1}", word(1).chars().take(10).collect::()); + let (small, big) = (word(400), word(8 * 400)); + let time = |w: &str| (0..repeat).for_each(|_| drop(hyphen_points(w, &Limits::default()))); + let (t1, t8, ratio) = cost_ratio(8, || time(&small), || time(&big)); + let what = format!("{}…: t(n) {t1:.4} s, t(8n) {t8:.4} s, ratio {ratio:.1}", word(1).chars().take(10).collect::()); eprintln!("{what}"); (what, ratio) }) .collect(); for (what, ratio) in ratios { - assert!(ratio < 8.0, "4x the letters, not linear: {what}"); + assert!(ratio < 24.0, "8x the letters, not linear: {what}"); } }