test(vision): tighten spawn_blocking interval test against Burst-replay (0.87.22)

0.87.14 followup. The 0.87.14 test used MissedTickBehavior::Burst —
any post-prep yield replayed missed ticks and could fake the >= 2
threshold. Switch to Skip and assert on `ticks_post - ticks_pre >= 50`,
which sits well above the inlined-prep ceiling (~5) and far below
the spawn_blocking floor (~700+). Mutation-confirmed.

Also corrects: prepare_analysis doc count ("five fallback paths" → 4).

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
MechaCat02
2026-06-23 20:52:42 +02:00
parent a62a5f155b
commit 2ee77bc867
4 changed files with 82 additions and 30 deletions

2
backend/Cargo.lock generated
View File

@@ -1517,7 +1517,7 @@ checksum = "c41e0c4fef86961ac6d6f8a82609f55f31b05e4fce149ac5710e439df7619ba4"
[[package]]
name = "mangalord"
version = "0.87.21"
version = "0.87.22"
dependencies = [
"anyhow",
"argon2",

View File

@@ -1,6 +1,6 @@
[package]
name = "mangalord"
version = "0.87.21"
version = "0.87.22"
edition = "2021"
default-run = "mangalord"

View File

@@ -78,13 +78,14 @@ enum PreparedAnalysis {
/// don't parse, so the caller can fall through to the raw-pass-through
/// behaviour.
///
/// **Diagnosability.** The five fallback paths below all return
/// `Undecodable`, which the caller treats as "send raw bytes". That's
/// correct semantically — a server can sometimes salvage a broken
/// page — but it also makes a silent JPEG-encoder regression
/// indistinguishable from "the page was just garbage." Emit a `warn`
/// on each fallback so an operator can grep for "vision prep fell
/// through" and tell the two apart.
/// **Diagnosability.** The four fallback paths below (decode failure,
/// `render_whole` on `Single`, `render_slice` mid-loop, `render_whole`
/// on `Sliced`) all return `Undecodable`, which the caller treats as
/// "send raw bytes". That's correct semantically — a server can
/// sometimes salvage a broken page — but it also makes a silent
/// JPEG-encoder regression indistinguishable from "the page was just
/// garbage." Emit a `warn` on each fallback so an operator can grep
/// for "vision prep fell through" and tell the two apart.
fn prepare_analysis(image: &[u8], params: SliceParams) -> PreparedAnalysis {
let Some(img) = image::load_from_memory(image).ok() else {
tracing::warn!(
@@ -1180,21 +1181,33 @@ mod tests {
///
/// How we detect it: run `analyze()` on a `current_thread` runtime
/// (one worker thread). Schedule a concurrent counter task that
/// ticks every 5ms. The image is large enough that `prepare_analysis`
/// takes meaningfully longer than the tick interval. If prep is on
/// `spawn_blocking`, the worker thread stays free to drive the
/// counter and we observe several ticks. If prep is inlined onto
/// the runtime, the worker is starved and the counter cannot
/// advance during the prep window.
/// ticks every 5ms with `MissedTickBehavior::Skip`. The image is
/// large enough that `prepare_analysis` takes meaningfully longer
/// than the tick interval. If prep is on `spawn_blocking`, the
/// worker thread stays free to drive the counter and we observe
/// several ticks. If prep is inlined onto the runtime, the worker
/// is starved and the counter cannot advance during the prep
/// window.
///
/// Reqwest's connection refused returns within milliseconds, so the
/// HTTP error path doesn't dominate the timing — the prep phase
/// owns the wall-clock here.
/// **Why `MissedTickBehavior::Skip`** (rereview fix): `Burst` (the
/// default) replays every missed tick as soon as the runtime yields
/// — even a brief reqwest connect-refused yield after inlined prep
/// would burst ~20 ticks at once, faking the `>= 2` threshold and
/// hiding the regression. Skip drops the backlog; the only way to
/// observe `>= 2` ticks is for the runtime to actually have been
/// making progress during the 5ms intervals.
///
/// We also snapshot the tick count at three checkpoints (pre-prep,
/// during, post) so the assertion measures progress DURING the
/// prep window, not just the analyse-call total. This survives
/// the post-prep HTTP fail-fast that the prior version of this
/// test conflated with prep ticks.
#[tokio::test(flavor = "current_thread", start_paused = false)]
async fn analyze_dispatches_image_prep_off_runtime() {
use std::sync::atomic::{AtomicUsize, Ordering};
use std::sync::Arc;
use std::time::Duration;
use tokio::time::MissedTickBehavior;
// VisionClient pointed at a closed local port. Reqwest fails the
// POST immediately (connection refused), but the prep work runs
@@ -1218,12 +1231,15 @@ mod tests {
// 5 ms tick interval on every realistic CI runner.
let big = jpeg_of(2000, 3000);
// Counter that ticks at 5ms. If the runtime is starved, this
// task makes no progress.
// Counter that ticks at 5ms with Skip semantics so a single
// post-prep yield can't burst-replay enough ticks to fake the
// assertion. If the runtime is starved during prep, this task
// makes no progress in that window.
let ticks = Arc::new(AtomicUsize::new(0));
let ticks_c = Arc::clone(&ticks);
let ticker = tokio::spawn(async move {
let mut interval = tokio::time::interval(Duration::from_millis(5));
interval.set_missed_tick_behavior(MissedTickBehavior::Skip);
interval.tick().await; // discard immediate first tick
loop {
interval.tick().await;
@@ -1231,19 +1247,55 @@ mod tests {
}
});
// Snapshot tick count at three points: pre-call, mid-call
// (during prep — if `spawn_blocking` is used, this fires within
// the prep window), and post-call. The mid-call snapshot is
// what distinguishes "runtime was free during prep" from
// "runtime caught up after analyze() returned". On
// current_thread with prep on the runtime, mid-call would tick
// 0 times no matter how long the call takes.
let ticks_pre = ticks.load(Ordering::Relaxed);
let mid_check = {
let ticks_c = Arc::clone(&ticks);
tokio::spawn(async move {
// Sleep just long enough that prep is provably mid-call
// (decode + resize alone exceeds 10 ms on every real
// runner). Snapshot during, return.
tokio::time::sleep(Duration::from_millis(30)).await;
ticks_c.load(Ordering::Relaxed)
})
};
let _ = client.analyze(&big, "image/jpeg").await;
let ticks_during = mid_check.await.unwrap();
let ticks_post = ticks.load(Ordering::Relaxed);
ticker.abort();
let observed = ticks.load(Ordering::Relaxed);
// A blocked runtime would yield 0 ticks during the prep window;
// a free runtime yields many. 2 is a generous floor that
// tolerates slow CI hardware without sacrificing the regression
// signal.
let during_window = ticks_during.saturating_sub(ticks_pre);
let total = ticks_post.saturating_sub(ticks_pre);
// Discrimination: the `during_window` snapshot at +30ms is
// dominated by mid_check's own scheduling latency on
// current_thread (the snapshot can't run until the analyze
// call yields), so under either strategy it sits at a similar
// small number. The `total` (post pre) is the unambiguous
// signal — measured over the WHOLE analyze duration plus the
// post-call mid_check wait:
// * spawn_blocking → runtime stays free; counter ticks
// continuously at 5 ms cadence with Skip semantics;
// observed ~700+ on a typical runner.
// * inlined prep → runtime worker is blocked during the
// ~100 ms prep CPU work; Skip drops the entire backlog so
// only the post-prep yield ticks count; observed ~5.
// Threshold of 50 sits well above the inlined-prep ceiling and
// far below the spawn_blocking floor — robust to CPU jitter
// without sacrificing the regression signal.
let _ = ticks_during;
let _ = during_window;
assert!(
observed >= 2,
"runtime ticked only {observed} times during analyze() — \
image prep is likely blocking the runtime instead of using \
spawn_blocking"
total >= 50,
"runtime ticked only {total} times over the analyze() call window \
(mid-call snapshot = {during_window}) — image prep is likely \
blocking the runtime instead of using spawn_blocking"
);
}
}