Skip to content

test(dream): give the approval usage e2e test a write budget for loaded runners - #2648

Open
Fengzdadi wants to merge 1 commit into
oceanbase:masterfrom
Fengzdadi:fix/dream-usage-e2e-flake
Open

Fengzdadi wants to merge 1 commit into
oceanbase:masterfrom
Fengzdadi:fix/dream-usage-e2e-flake

Conversation

@Fengzdadi

Copy link
Copy Markdown
Contributor

Which issue or RFC does this PR close?

No tracking issue. Fixes an intermittent tests (3.11, e2e) failure in tests/e2e/test_dream_usage.py::test_memory_dream_approval_embedding_usage_survives_replay_and_restart, seen on 2026-11-14 in #2550 (run 43546529259) and #2518 (run 43537990051). Usage semantics follow RFC 0072 (docs/en/rfcs/0072_scoped_statistics_and_usage.md).

Rationale for this change

Both failures assert before["totals"]["embedding"] == {"requests": 1, "input_tokens": 7, "output_tokens": None} and read all zeros. Both logs contain Model usage write failed; record will not be retried, so the recorder dropped the embedding record from atomic_memory.create.

The failure reproduces locally when the test runs repeatedly under load: 18 xdist workers, 36 CPU-bound processes, 6 processes doing F_FULLFSYNC writes, and SQLite fullfsync on. CPU load alone did not reproduce it (0 of 120 runs). A scratch probe wrapped _ModelUsageRecorder._write and AsyncDatabase.statistics_transaction. Results:

  • 10 of 432 runs failed with the same assertion. The logs matched CI: the usage warning plus Artifact processing failed (scope-discovery TimeoutError).
  • Every dropped batch raised a plain TimeoutError from _write once remaining <= 0, so the 5-second write budget had run out. No attempt failed with an unknown commit outcome or a non-contention error.
  • Business transactions hold SQLite's single writer slot for long stretches on a saturated machine. Measured from first write to commit under the same load: processing-lease renewals up to 2.7 s each (about 63 per test run), Source journal-head updates up to 1.8 s, candidate-head updates up to 1.8 s. Without load the lease renewals already take up to 0.8 s.

The test's first embedding record competes with runtime startup, Source capture and Dream processing for that slot. On SQLite the recorder's deferred transaction cannot queue for the slot: the read-to-write upgrade fails at once while another connection writes, and the recorder retries every 20 ms. On a saturated runner it can find no free gap within five seconds. RFC 0072 allows the recorder to drop such a record: usage recording is best-effort and must not retry anything that could double-count. The recorder behaves as specified. The test needed more than the best-effort contract promises under load.

The test does not exercise the write budget. It checks that exact totals survive approval, replay and restart. This PR gives it a 20 s write budget, about 3× the slowest write measured under load (6.88 s), and a 30 s flush budget, so one stats read still waits out a full write as it did before (10 s flush against 5 s write). The recorder tests in tests/builtin/runtime/test_model_usage_recorder.py still cover drops and bounded shutdown under short budgets.

What changes are included in this PR?

  • tests/e2e/test_dream_usage.py: the approval/replay/restart test uses model_usage_write_timeout_seconds=20.0 and model_usage_flush_timeout_seconds=30.0 instead of 5.0 and 10.0. Its comment now states why. Every assertion is unchanged.
  • The sibling parametrized test, test_dream_worker_usage_persists_once_in_scope_stats, keeps its 5 s budget. Under the same load it passed 200 of 200 runs, and its single usage batch, written after the Dream run completes, settled in at most 1.81 s.

No runtime code changes.

Are there any user-facing changes?

No.

How was this change tested?

Load harness (scratch, not committed): repeated runs of the test under the load described above.

Budget (write/flush) Runs Failed runs Usage batches Dropped batches Settle time of written batches, p95 / p99 / max
5 s / 10 s (master) 432 10 855 10 3.94 s / 4.88 s / 5.72 s
30 s / 30 s (headroom measurement) 324 0 648 0 4.28 s / 5.94 s / 6.69 s
20 s / 30 s (this PR) 216 0 432 0 3.93 s / 6.13 s / 6.88 s

The 30 s row measures how long writes need when the budget is not the limit: 16 of 648 batches needed more than 5 s and would have been dropped at the old budget, and none needed more than 10 s. With the final 20 s budget, 16 of 432 batches again needed more than 5 s and all were written; the slowest needed 6.88 s, so the budget leaves about 3× margin. For one of the two 20 s rounds only the probe output was kept (0 dropped writes); the other round reported 108 passed. Load on GitHub runners may differ from this local setup.

Commands:

  • uv run pytest tests/e2e/test_dream_usage.py tests/builtin/runtime/test_model_usage_recorder.py -n 8: 45 passed, 1 skipped
  • make check: passed, including ty

Self-review against REVIEW.md and an independent Opus review of the diff found no defect. Two review points are applied: the comment names only the first embedding record as competing with capture and processing, and the write budget is 20 s so the 30 s flush still outlasts one write.

Remaining notes:

  • A genuine usage-persistence regression now takes longer to report in this test. Each stats read can wait up to 30 s for its flush, and runtime shutdown can wait one write plus one flush window (50 s) before giving up on a pending record.
  • The second embedding record, offered during approval after Dream processing finishes, competes only with the runtime's background writers. The new budget covers it as well.

Design notes (non-blocking, not part of this PR):

  • On SQLite the recorder's usage transaction begins deferred, reads the Scope rows, then upgrades to write. SQLite does not call the busy handler for that upgrade, so the bounded busy_timeout that _sqlite_model_usage_transaction sets has no effect there. A contended attempt fails at once and the recorder polls through the event loop with 20 ms backoff. In the master runs above that meant 14.5 attempts per batch on average, up to 46. Beginning the usage transaction with BEGIN IMMEDIATE cut that to 1.4 attempts per batch, but did not significantly change the failure rate (5 of 432 against 10 of 432 under the same alternating load), so this PR leaves it out.
  • Processing-lease renewals holding the SQLite writer slot for 0.2–0.8 s on an idle machine, and seconds under load, may deserve a look on the artifact-processing side. They are also the likely source of the Artifact processing failed scope-discovery timeouts in the same CI logs.

AI usage statement

This change was written by Claude Code (Claude Opus 5.5). Claude Code reproduced the failure, ran the load measurements and the checks listed above, and wrote this description.

…ed runners

On a saturated runner, startup, Source capture and Dream processing can
keep SQLite's writer slot from the model usage recorder for more than
the test's 5 s write budget. The recorder then drops the embedding
record, as its best-effort contract allows, and the exact-total
assertion reads zero. Give this test a 20 s write budget, about three
times the slowest write measured under load, and a 30 s flush so a
stats read still outlasts one write. Assertions are unchanged.
@Fengzdadi
Fengzdadi requested a review from PsiACE as a code owner November 14, 2026 06:50

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant