fix(scheduler): --sim-verify false-flagged every DISPATCH decision on wall-clock drift (bug-1842)

sim_verify_alloc_eq() compared xce_alloc_t.from, which make_alloc()
(xcealloc.c) stamps with the real OS wall clock (time(NULL)), not
core.c's virtualized sim clock. The recorded (expected) value is
whatever real second the original run happened to execute in; the
freshly-rebuilt (actual) value is whatever real second the replay
executes in -- two unrelated real-world timestamps, so every
otherwise-correct DISPATCH decision failed verification whenever a
replay ran even one wall-clock second away from its own recording.

Drop `from` from the comparison -- it's reservation bookkeeping, not
part of a decision's semantic identity. Verified against a real
captured .replay file: 120/120 false DISPATCH mismatches -> 0.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
Rongsong Shen 2026-09-23 03:07:47 +00:00
parent e592e92178
commit 7901db57d4
No known key found for this signature in database
GPG key ID: 5BCDAAE0123E9FE2
4 changed files with 126 additions and 8 deletions

View file

@ -24957,6 +24957,70 @@
],
"occurrences": 1,
"last_seen": "2026-09-22T09:00:00Z"
},
{
"id": "bug-1842",
"timestamp": "2026-09-22T19:35:00Z",
"error_message": "User-reported: replaying a real captured .replay file (scheduler-replay-20260922-095207.replay) via --sim --sim-verify logged a MISMATCH for every single DISPATCH decision, even though the printed 'expected:'/'actual:' summaries (jobid, nhosts) were byte-for-byte identical on both sides -- e.g. 'expected: DISPATCH jobid=0-13-1790071174-0[44] nhosts=1 -- actual: DISPATCH jobid=0-13-1790071174-0[44] nhosts=1' still reported as MISMATCH. User asked whether the comparison should stop using a timestamp as part of its check condition.",
"file": "src/scheduler/src/sim_verify.c (sim_verify_alloc_eq, the fix), src/lib/xcealloc.c (make_alloc, the field's origin), src/scheduler/testsuite/test_sim_verify.c (new regression test), src/scheduler/testsuite/test_sim_live_allocation.c (stale-comment cleanup)",
"root_cause": "sim_decision_eq()/sim_log_mismatch() (sim_verify.c) never compare the decision's own `ts` field (only log it for diagnostics) -- the user's timestamp hypothesis was right in spirit but aimed at the wrong field. The REAL culprit is buried one level deeper: sim_verify_alloc_eq() compares xce_alloc_t field-by-field including `from`, and make_alloc() (xcealloc.c:30) unconditionally stamps `alloc->from = time(NULL)` -- the real OS wall clock, not core.c's virtualized sim clock -- every time an allocation is built. `expected->from` (decoded from the .replay file) is whatever real second the ORIGINAL recording ran in; `actual->from` (freshly rebuilt by the live seqjob_allocator.c/parjob_allocator.c -> sched_make_allocs() -> make_alloc() chain during THIS replay) is whatever real second THIS replay runs in. Two independent real-world timestamps that essentially never coincide for any replay of a real recording, even though the decision itself (job/host/resource/value/duration) is exactly what was recorded. Confirmed empirically: a clean run of xce_scheduler --sim --sim-verify against the user's own replay file mismatched 120/120 DISPATCH decisions, 100% on this field, zero relation to real-time-vs-batch simulation speed (reproduced identically at --sim-speed=0, 1, and 20). The codebase already had a documented workaround for the same footgun elsewhere: dup_alloc() (xcealloc.c:179) has to re-stamp ->from/->duration from its source AFTER calling make_alloc(), specifically because make_alloc() clobbers them with the current wall time otherwise. A prior session (2026-09-21, see this same discovery independently reached and left unfixed) had already isolated this exact mechanism via test_sim_verify_no_false_mismatch_after_live_dispatch_and_later_confirmation's own header comment, which explicitly (and accurately, until this fix) documented it as accepted 'practically negligible' same-second-window flakiness.",
"fix": "FIXED (2026-09-22). Dropped the `a->from == b->from` clause from sim_verify_alloc_eq() (sim_verify.c) with a doc comment explaining why: `from` is reservation-start bookkeeping (real wall-clock, for expiry/accounting purposes), not part of a DISPATCH decision's semantic identity -- unlike `duration`, which is a genuine request-derived value and stays part of the comparison. TDD: new test test_dispatch_decisions_differing_from_timestamp_still_match (test_sim_verify.c) builds two structurally-identical dispatch allocations with deliberately far-apart `from` values (1790000000 vs 1) and asserts sim_decision_eq() still reports a match. Also updated test_sim_live_allocation.c's test_sim_verify_no_false_mismatch_after_live_dispatch_and_later_confirmation header comment, which previously described this as accepted same-second-window flakiness -- now accurately states the flakiness is eliminated by construction. Full scheduler suite: 85/85 Ok, zero regressions (xce-build.sh scheduler asan --incremental). Live-verified against the user's own real replay file: DISPATCH-vs-DISPATCH false mismatches dropped from 120/120 to 0/120 (--sim-speed=0, --sim-verify, --logfile capture, before/after diff). A separate, distinct issue remains in the same file (61 'expected: <none> -- actual: PEND ... main_reason=0' mismatches) -- see bug-1843, not touched by this fix.",
"tags": [
"scheduler",
"sim",
"sim-verify",
"replay",
"from-field",
"wall-clock",
"make_alloc",
"xcealloc",
"decision-verification",
"false-positive",
"user-reported",
"fixed",
"tdd"
],
"related_bugs": [
"bug-1611",
"bug-1613",
"bug-1779",
"bug-1759",
"bug-1838"
],
"occurrences": 1,
"last_seen": "2026-09-22T19:35:00Z"
},
{
"id": "bug-1843",
"timestamp": "2026-09-22T19:35:00Z",
"error_message": "Same user report as bug-1842: replaying scheduler-replay-20260922-095207.replay via --sim --sim-verify also logs a small number of 'expected: <none> -- actual: PEND jobid=... main_reason=0' mismatches -- live decisions with no recorded counterpart at all (beyond decoded_session->n_decisions), distinct from bug-1842's DISPATCH-vs-DISPATCH false positives (already fixed). 61 occurrences total across the full 643-session replay file (0.02% of the 3431 live PEND decisions produced).",
"file": "src/scheduler/src/sim_loop.c (sched_sim_driver_run()'s decision-drain loop, sim_reconcile_unaccounted_jobs()), src/scheduler/src/sched_election.c (sched_job_picker()/sched_allocator())",
"root_cause": "NOT YET ROOT-CAUSED -- investigated but not fixed. Confirmed NOT the same mechanism as the historical bug-1611/bug-1613/bug-1779/bug-1759 family (all independently re-verified FIXED as of 2026-09-19 per .kiro/steering/scheduler-driver-equivalence.md -- sim_reconcile_unaccounted_jobs() does call on_dispatch() via sim_reconcile_invoke_on_dispatch(), and normal-mode/sim-mode now share the identical sched_job_picker()/sched_allocator() thread pair). Empirical characterization from a clean reproduction (xce_scheduler --sim --sim-verify --sim-speed=0 against the user's replay file, --logfile capture): every occurrence is a job's FIRST-ever appearance as a live PEND candidate landing exactly one round earlier during replay than the session it was recorded in -- every SUBSEQUENT round for the same job (it stays genuinely PEND, apparently resource-contention-bound, for many further rounds -- confirmed via repeated identical '[sim] PEND jobid=...' lines every round thereafter) matches the recording perfectly; only the very first appearance mismatches. The picker thread's own per-round loop (sched_job_picker(), sched_election.c: cbuf_get(wbuf) -> begin_session() -> next_job() until NULL -> end_session(), one full deterministic sweep per xce_core_signal_go() token) is not inherently racy in isolation, which argues against 'live thread free-running past the round boundary' as the mechanism. Leading hypothesis, NOT confirmed: sched_sim_driver_run()'s main loop buffers ALL ReplayEvent messages between two ReplaySession markers and applies them atomically via one xce_core_push_events() call immediately before the NEXT session begins (sim_loop.c ~line 1521) -- this is a strictly coarser, round-granular discretization than how the ORIGINAL live recording's normal-mode driver actually received the corresponding JOBS_PUSH/JOB_STATE_CHANGE events (over a real network connection, at whatever real-time instant they actually arrived relative to the live picker's own session-begin instant) and recorded them into the SAME or a DIFFERENT ReplaySession's event window depending on live timing down to the millisecond. If the live picker's round-N session had already begun (begin_session() already called) at the exact real moment the recording process received a newly-arriving job's JOBS_PUSH, that job would correctly miss round N and only appear round N+1 in the recording, even though the .replay file's own coarser round-boundary bookkeeping could group its JOBS_PUSH event into round N's pre-session batch instead -- making it visible to replay's round-N sweep, one round earlier than the live original saw it. Correlates in the user's log with clusters of 'xce_core_push_events JOBS_PUSH: refusing resync state 0x1 ... existing job is RUN' WARN lines for already-dispatched sibling jobs arriving in overlapping/duplicate batches shortly after -- consistent with, but not proof of, this event-batching-granularity theory. NOT YET verified by direct .replay file inspection (would need to correlate each mismatching jobid's exact recorded ReplayEvent position against its enclosing ReplaySession boundaries in the raw capnp stream) or by comparing against the ORIGINAL live (normal-mode, non-replay) recording run's own real-time event-arrival log, neither of which this session had available.",
"fix": "NOT FIXED -- open, reported for follow-up. Low apparent severity: does not affect actual scheduling correctness in either mode (the affected jobs correctly stay PEND under real resource contention and are eventually correctly dispatched in both the recording and the replay -- only --sim-verify's own reporting is affected, with one spurious MISMATCH line per affected job's first-round appearance). Before attempting a fix: (1) confirm the event-batching-granularity hypothesis by direct inspection of the .replay file's raw ReplayEvent/ReplaySession boundaries around one of the 61 mismatching jobids, or by instrumenting sim_loop.c's event-buffering loop to log which round each event lands in; (2) if confirmed, decide whether the fix belongs in the RECORDER (recording_events.c -- capture live event-arrival timing with round-boundary precision the replay can reproduce) or is instead an accepted, documented limitation of round-granular replay (no code change, just a --sim-verify caveat in scheduler-driver-equivalence.md). Do not attempt a speculative fix to sim_loop.c's event-buffering or session-boundary sequencing without that confirmation first -- this logic is shared by the project's own documented driver-equivalence invariant (scheduler-driver-equivalence.md) and any change here needs the resource-contention-fixture testing discipline that doc already mandates.",
"tags": [
"scheduler",
"sim",
"sim-verify",
"replay",
"reconciliation",
"picker",
"round-boundary",
"event-batching",
"user-reported",
"unfixed",
"needs-diagnosis",
"low-severity",
"reporting-only"
],
"related_bugs": [
"bug-1842",
"bug-1611",
"bug-1613",
"bug-1779",
"bug-1759"
],
"occurrences": 1,
"last_seen": "2026-09-22T19:35:00Z"
}
]
}