test(model_testing): log run stages and fix nightly failure reporting (#10163)

This commit is contained in:
Arnaud Gourlay
2026-09-03 12:36:34 +02:00
committed by timvisee
parent 33ed96135b
commit 848f97c956
3 changed files with 48 additions and 2 deletions
@@ -9,5 +9,9 @@ The nightly model testing job failed.
- Seed: `{{ env.SEED }}` (reproduce with `--seed {{ env.SEED }}`)
- Date: {{ date | date('DD.MM.YYYY HH:mm') }}
- Failed: {{ env.FAILED_PASSES }}
- [Failed run](https://github.com/{{ env.REPOSITORY }}/actions/runs/{{ env.RUN_ID }})
- [Commit](https://github.com/{{ env.REPOSITORY }}/tree/{{ env.SHA }})
- [Commit](https://github.com/{{ env.REPOSITORY }}/tree/{{ env.SHA }}) (the `dev` commit under test)
Note: this issue is reused for every nightly failure, so the details above describe the
**latest** one only. Consecutive failures are often unrelated bugs; check the linked run.
+30 -1
View File
@@ -21,6 +21,7 @@ permissions:
env:
CARGO_TERM_COLOR: always
RUST_BACKTRACE: 1
RUST_LOG: info
OP_NUM: 200000
SHARD_COUNT: 2
RESTART_PROBABILITY: 0.001
@@ -73,6 +74,10 @@ jobs:
INPUT_OP_NUM: ${{ inputs.op_num }}
INPUT_SEED: ${{ inputs.seed }}
run: |
# The commit actually under test. `github.sha` is the default branch (master) on a
# scheduled run, but the checkout above forces `dev`, so reporting `github.sha` points
# the failure issue at code that was never run.
echo "TESTED_SHA=$(git rev-parse HEAD)" >> "$GITHUB_ENV"
if [ -n "$INPUT_OP_NUM" ]; then
echo "OP_NUM=$INPUT_OP_NUM" >> "$GITHUB_ENV"
fi
@@ -84,6 +89,7 @@ jobs:
shell: bash
# Both runs reuse the single binary built above and share the same seed.
- name: Run model testing (async scorer)
id: async_scorer
run: |
target/perf/model_testing \
--seed "$SEED" \
@@ -96,6 +102,7 @@ jobs:
shell: bash
timeout-minutes: 300
- name: Run model testing (no io_uring)
id: no_io_uring
# Run even if the async-scorer pass failed, so both signals are collected.
if: ${{ !cancelled() }}
run: |
@@ -108,6 +115,27 @@ jobs:
--on-disk
shell: bash
timeout-minutes: 300
# Which of the two passes broke is the first thing triage needs: one failing while the
# other survives the same seed points at the io_uring read path (or rules it out), and
# every failure so far has split that way. Rendered here rather than in the issue template
# so the template stays a plain fill-in-the-blanks form.
- name: Describe which passes failed
if: ${{ failure() && github.event_name == 'schedule' }}
env:
ASYNC: ${{ steps.async_scorer.conclusion }}
PLAIN: ${{ steps.no_io_uring.conclusion }}
run: |
if [ "$ASYNC" = failure ] && [ "$PLAIN" = failure ]; then
summary="both passes"
elif [ "$ASYNC" = failure ]; then
summary="async scorer only (no io_uring passed the same seed)"
elif [ "$PLAIN" = failure ]; then
summary="no io_uring only (async scorer passed the same seed)"
else
summary="neither pass, the job broke around them (async=$ASYNC, no-io_uring=$PLAIN)"
fi
echo "FAILED_PASSES=$summary" >> "$GITHUB_ENV"
shell: bash
# Only alert for unattended nightly failures; dispatch/PR runs are watched live.
- name: Open issue on failure
if: ${{ failure() && github.event_name == 'schedule' }}
@@ -118,7 +146,8 @@ jobs:
SEED: ${{ env.SEED }}
REPOSITORY: ${{ github.repository }}
RUN_ID: ${{ github.run_id }}
SHA: ${{ github.sha }}
# Falls back to github.sha if we failed before resolving the checked-out commit.
SHA: ${{ env.TESTED_SHA || github.sha }}
with:
filename: .github/ISSUE_TEMPLATE/model_testing_failure.md
update_existing: true
+13
View File
@@ -727,11 +727,14 @@ pub async fn run(
// the `drop` below wouldn't actually close the collection (releasing its files) until
// the task ends — and reopening the same dir with the old collection still open is
// unsafe.
log::info!("op:{i} restart: drain_snapshot");
drain_snapshot(&collection, &snapshots_dir, &mut pending_snapshot, i).await;
// Newest-clocks recovery point must survive the close+reopen exactly; captured here
// (snapshot drained, op loop idle) and compared after the reload below. See
// [`verify::assert_clocks_match`] for why both mismatch directions are bugs.
log::info!("op:{i} restart: collect_clock_ticks");
let pre_clocks = verify::collect_clock_ticks(&collection).await;
log::info!("op:{i} restart: stop_gracefully");
collection.stop_gracefully().await;
// `into_inner` makes the invariant checked, not assumed: if any background task still
// holds an `Arc` clone here, panic loudly instead of reopening the same dir while the
@@ -740,13 +743,16 @@ pub async fn run(
Arc::into_inner(collection)
.expect("collection still referenced at restart (undrained background task?)"),
);
log::info!("op:{i} restart: reopen");
collection =
Arc::new(fixture::reopen_collection(&collection_dir, &snapshots_dir).await);
// `Collection::load` returns before tail-of-WAL ops queued to the
// update worker have been applied — that's an intentional fast-start
// feature. Wait for the queue to drain so the scroll below observes
// all WAL-replayed state.
log::info!("op:{i} restart: wait_for_pending_updates");
verify::wait_for_pending_updates(&collection).await;
log::info!("op:{i} restart: scroll + verify");
let live = verify::collect_model_from_collection(&collection).await;
verify::assert_matches_model(&live, &model, &format!("restart at op:{i}"));
// Clock check AFTER the model check: a lost WAL tail trips both, and the model diff
@@ -817,6 +823,7 @@ pub async fn run(
eprintln!("model_testing: verifying live state...");
}
log::debug!("all ops applied, verifying live collection against model");
log::info!("live: scroll + verify");
let live = verify::collect_model_from_collection(&collection).await;
let (live_extra, live_missing) = verify::id_diff(&live, &model);
let (mut segments, mut optimized) = verify::run_summary(&collection).await;
@@ -838,6 +845,7 @@ pub async fn run(
// not have triggered), when the optimizer is intentionally disabled, or when we
// already observed optimization earlier in the run (counter resets on restart).
if !interrupted && !disable_optimizer && !optimizer_ran_during_run {
log::info!("live: wait_for_optimizer");
verify::wait_for_optimizer(&collection).await;
(segments, optimized) = verify::run_summary(&collection).await;
}
@@ -853,19 +861,24 @@ pub async fn run(
}
// Finish any background snapshot before closing (it holds an `Arc` clone — see the restart
// path), then close and reopen and re-verify — mirrors blobstore tests.rs:488-516.
log::info!("reload: drain_snapshot");
drain_snapshot(&collection, &snapshots_dir, &mut pending_snapshot, applied).await;
// Same clock-durability capture as the mid-run restart path, for the final reload.
let pre_clocks = verify::collect_clock_ticks(&collection).await;
log::info!("reload: stop_gracefully");
collection.stop_gracefully().await;
// Checked close-before-reopen, same as the mid-run restart path.
drop(
Arc::into_inner(collection)
.expect("collection still referenced at final reload (undrained background task?)"),
);
log::info!("reload: reopen");
let collection = fixture::reopen_collection(&collection_dir, &snapshots_dir).await;
// Same reason as the mid-run restart above — drain deferred WAL ops before scrolling.
log::info!("reload: wait_for_pending_updates");
verify::wait_for_pending_updates(&collection).await;
log::info!("reload: scroll + verify");
let reloaded = verify::collect_model_from_collection(&collection).await;
let (reload_extra, reload_missing) = verify::id_diff(&reloaded, &model);
trace.reload_verify(