Repository navigation
ci(*): make the idle ceiling a gate and take the last waits out - #428
Conversation
gloryfromca
left a comment
There was a problem hiding this comment.
Blocking: fix the failing strict idle gate and serialize LiteLLM initialization before merge.
I found two blockers, marked inline.
I reviewed the full diff, the affected xdist/report and server/provider call paths, and the four-commit history. I also checked the applicable AGENTS.md, CLAUDE.md, and CONTEXT architecture rules, backward compatibility, and whether the test edits weakened behavior. The timeout reductions, mocks, and timing markers retain the assertions they cover; I found no additional blocker there.
Verification:
uv run --frozen --python 3.12 --all-extras pytest tests/test_litellm_setup.py tests/test_ppt_engine_assets_fonts.py tests/test_cli_gateway_commands.py tests/test_cli_serve_commands.py -q --idle-ceiling-strict: 144 passed.- Focused rerun of GitHub's over-ceiling tests with the same strict flag: 6 passed, 1 skipped, but the session failed on two over-ceiling tests (4.40 s and 2.40 s idle).
- Fresh-process two-thread
import_litellm()reproduction: no exceptions, but all three logger levels changed from INFO (20) to WARNING (30). - GitHub CI at this head: unit shards 1/4, 2/4, and 4/4 failed on seven over-ceiling tests; coverage gates were skipped.
gloryfromca
left a comment
There was a problem hiding this comment.
Blocking: make the remaining strict shard pass, serialize LiteLLM initialization, and keep strict test startup out of the real Raven home.
The previous idle-gate blocker is narrower but still open: shards 1/4, 3/4, and 4/4 now pass, while shard 2/4 still fails and leaves coverage skipped. The LiteLLM concurrency blocker is code-identical and still reproduces. I found one new blocker in the strict-mode warm-up, marked inline.
I re-read the full current diff and the two-commit delta, relevant pytest/xdist and provider call paths, and commit history. I also rechecked AGENTS.md, CLAUDE.md, CONTEXT architecture boundaries, backward compatibility, and whether the updated mocks and removed timing markers weakened their tests. The probe isolation remains covered by dedicated probe tests, and I found no further blocker in those changes.
Verification:
- Focused rerun of the seven formerly over-ceiling tests with
--idle-ceiling-strict: 6 passed, 1 skipped locally; the skip is the unavailable Chromium system library. - GitHub CI: unit shard 2/4 fails because the browser crop test records 9.99 seconds idle; coverage is skipped.
- Fresh-process concurrent
import_litellm()reproduction still ends with logger levels[30, 30, 30]. - One strict test under a clean HOME passed but created
$HOME/.raven/oauthbefore test fixtures ran.
gloryfromca
left a comment
There was a problem hiding this comment.
Blocking: serialize LiteLLM initialization before this can merge.
The current delta fixes the strict-idle-gate objection: the two real-browser tests are legitimately marked slow, that marker does not deselect them from the default suite, and the current GitHub run reported no idle-ceiling violation. Removing the measured-unhelpful bytecode precompile is also internally consistent.
The LiteLLM initialization race remains the sole blocker. It satisfies all three round-five requirements: this PR introduces the background import; ordinary first-request traffic can overlap its multi-second initialization; and after the overlap leaves LiteLLM logger levels at WARNING, lower-level file logging is lost until the operator restarts, with the same race exposed again. The background and on-demand paths still need one shared synchronization boundary.
Named nonblocking follow-ups: strict local pytest still creates or chmods the developer's real ~/.raven/oauth before isolation fixtures run, and the PR title still promises precompilation even though this revision removes it. I withdrew and resolved the home-isolation blocker under the late-round convergence rule.
Verification: uv run --frozen --python 3.12 --all-extras pytest -q --idle-ceiling-strict tests/test_design_engine_rendering_outcome.py completed with 22 passed and 2 skipped; both skips were because local Chromium lacks libatk-1.0.so.0. GitHub unit shards 1/4, 2/4, and 3/4 passed. Shard 4/4 had no idle-ceiling failure but finished 1 failed, 5522 passed, 5 skipped on the untouched timing-sensitive test_the_first_beat_is_late_and_the_rest_are_not, so the overall workflow is not green; I treated that as out-of-scope verification evidence rather than a finding introduced by this revision.
Coverage: I read the full github/main...HEAD diff and the delta from the prior reviewed head, checked the repository rules, relevant callers and commit history, backward compatibility, test-selection semantics, whether the new marks weakened coverage, and the warm-up architecture. No dependency, CLI, asset, or domain-term rules are implicated.
gloryfromca
left a comment
There was a problem hiding this comment.
Blocking: synchronize LiteLLM initialization and make the new warm-up calls satisfy diff coverage.
The new heartbeat-test delta is sound: it now checks the initial and recurring gaps that the implementation actually promises, without depending on how many callbacks a loaded runner schedules. It introduces no additional blocker.
The existing LiteLLM initialization race remains unchanged and open. The current CI run also surfaced the new inline blocker now that every strict-idle unit shard completes: PR diff coverage is 78.57%, below the required 90% gate.
Verification: uv run --frozen --python 3.12 --all-extras pytest -q tests/test_tool_registry_timeout.py passed all 14 tests. GitHub CI passed all four strict-idle unit shards and every other completed check except the required diff-coverage gate.
Coverage: I read the full github/main...HEAD diff and the delta from the prior reviewed head, checked the affected heartbeat implementation and test history, the unchanged LiteLLM callers and synchronization architecture, repository rules, compatibility, and whether the test rewrite weakened the behavior being guarded. No dependency, asset, CLI-naming, or domain-term rule is newly implicated.
gloryfromca
left a comment
There was a problem hiding this comment.
Blocking: stabilize the strict idle ceiling and serialize LiteLLM initialization before this can merge.
The current delta fixes the prior diff-coverage objection. Moving the serve import to module scope and documenting the two long-lived boot calls as coverage exclusions is supported here by source-presence assertions plus direct helper tests; isolated exact-head coverage confirms those are the intended exclusions. I replied and resolved that thread.
Two blockers remain. The LiteLLM logger-level race is unchanged. The strict gate is also not portable yet: exact-head shards 3/4 and 4/4 fail solely on new 2.19 s and 2.09 s idle hits, although the prior revision passed all four shards and both named tests pass alone under the same strict option. This branch introduces the required gate, normal PR execution reaches it, and there is no merge path when it fails and skips coverage, so all three late-round blocker conditions are met. I reopened the original gate thread rather than filing a duplicate.
Verification: four focused warm-up call-site/helper tests passed in an isolated exact-head snapshot; the two exact CI idle hits passed there under --idle-ceiling-strict; git diff --check github/main...HEAD passed. GitHub shards 1/4 and 2/4 passed, shards 3/4 and 4/4 failed only at the strict idle summary, and coverage was skipped.
Review coverage: I bound the full github/main...HEAD patch at base a5f84b7164fe and head 0008ff0813a8 (SHA-256 e678b5c7684c4d6cf7072d15b6d7ffbdc9520a26e41f1c3ec19c14d4cbaf4c2b), read the current delta, and checked repository rules, callers and history, compatibility, test weakening, concurrency, filesystem side effects, performance caching, CI rollout, and recoverability. Patch-risk assessment: revise; moderate impact, high regression likelihood, partial protection, easy recovery, high confidence.
gloryfromca
left a comment
There was a problem hiding this comment.
Blocking: serialize LiteLLM initialization before this can merge.
The current delta fixes the strict-idle instability: exact-head CI run 34983686574 passed all four strict unit shards and the coverage gate, and I closed that thread. No additional finding survived review.
The existing LiteLLM race remains the sole blocker. For the late-round bar: this change introduces the competing background import; gateway or serve startup followed by an ordinary first request can reach the overlap; and after it corrupts the process-global logger levels there is no reliable in-process recovery, while restarting reopens the same race. The background and on-demand paths still need one shared serialization boundary.
I covered the repository rules, full diff and current delta, callers and history, backward compatibility, test-strength changes, concurrency, filesystem side effects, performance intent, and required-CI behavior. Verification: exact-head CI passed in full; git diff --check github/main...HEAD passed.
Patch-risk assessment: revise; moderate impact, high regression likelihood, partial protection, easy recovery, high confidence. Immutable patch: a5f84b7164fe24acc17e8802c1113d2cb249a8e2...cf7199c5a74748fefff9b947cf9663c81689fe48, SHA-256 4c92c6c9742608b715f43c242f1b2e085723e27d089de6dbfb1365ecbb43d3ff.
The ceiling measured wall clock, which is the wrong quantity on a runner three to four times slower than a laptop: on CI it listed 70 unmarked tests, and half of them were tree-walking guards that compute for 1.5 s here and 5 s there. The class the ceiling exists for is a test waiting, on a production sleep or a subprocess it did not need, and a wait is the same seconds on every machine. The hook now records wall clock and this process's CPU time around each test and judges the difference; the numbers ride on the teardown report's user_properties so the xdist controller can judge them. The options are --idle-ceiling and --idle-ceiling-strict; the markers keep their meaning. The remaining waits go the same way the first ten did. The fixture that shortens production ladders takes in the ACP cancel settle (5 s) and the gateway's delivery grace (2 s). The CLI agent tests stub the one-shot command's unconditional 2 s hand-off grace in their shared helpers, since their stub sub-agents are never busy; the rpc subagent tests no longer spawn a login shell to learn a PATH they do not check; saving a key in the rpc model test no longer probes a real endpoint; three literal timeouts shrink where the stub on the other side never answers anyway. Two tests whose assertion is the wait itself carry production_timing; tests that drive a real subprocess or a real render carry slow. Co-authored-by: Claude (claude-fable-5-1) <noreply@anthropic.com>
Each shard passes --idle-ceiling-strict on the make line, so a test that waits more than two seconds without a marker turns the shard red. The flag stays off addopts: the Windows job runs pytest with --noconftest, where the option does not exist. Two minutes of every run were the four xdist workers compiling modules on import into a fresh venv: on a laptop 25 s of a 40 s cold collection was compilation, 10 s of it in modules a plain compile covers. The install step now sets UV_COMPILE_BYTECODE so site-packages arrives compiled, and a compileall pass over the checkout runs before pytest; the run on this branch measures whether the install step's extra time is paid back. Co-authored-by: Claude (claude-fable-5-1) <noreply@anthropic.com>
…t first MeasuredWidth.width ran freetype for every call; a template measurement asks it sixty thousand times and a deck build's QA gates ask for the same (bold, size, text) over and over -- one 15-slide template's gates made 1848 calls over 162 distinct keys. A bounded memo in front of the freetype call, oldest key evicted, cap sized for a deck's worth of strings. capacity.py bound text_metrics.measurer at import, and text_metrics imports the measure package, which reaches capacity through template.house: importing text_metrics first raised ImportError on a partially initialised module. Nothing in production imports it first, but the test that covers the memo does. capacity imports the module and resolves the name at call time. Co-authored-by: Claude (claude-fable-5-1) <noreply@anthropic.com>
Every raven import of litellm is deferred, so the first request that needed it paid the three to five second import inline: saving a key from the settings page waited that long for its response. litellm_setup gains warm_up_in_background, a daemon thread running import_litellm, and both serving entry points, raven gateway and raven web, start it at boot. A failed import is logged and left for the on-demand import to report to the caller that needs litellm; the boot never fails on it. Co-authored-by: Claude (claude-fable-5-1) <noreply@anthropic.com>
The first sharded run with the gate on failed three shards, and every test it named was doing real work rather than waiting: a browser laying out a page (13 s), eight spawned processes contending for a lock, six python subprocesses running raven doctor. Idle counted only this process's CPU, so a child's work looked like a wait. os.times reports the CPU of children this process has reaped, and POSIX makes that recursive, so the browser and the eight workers now land on the account of the test that waited for them. Measured with that: the browser test drops off the list entirely, the spawned-process tests drop off, doctor drops from 4.2 s to 1.2 s, and what remains over the ceiling is a checkpoint test that really waits on a thousand files, two real LibreOffice renders, an ACP connection proving a dead pipe, and the two tests whose assertion is a timeout. The markers the first run needed are gone from the eight tests that no longer need them. Two things the run exposed that were not the metric's fault. Six rpc subagent tests reached api.miromind.ai on every call, because the fixture config holds an openai-kind agent and listing probes by default; the skip is autouse now, so a unit test here cannot answer differently when a vendor is down. And litellm's import costs 1.7 s of file opens that no CPU accounts for, landing on whichever test in the shard imports it first -- a target a gate cannot be held to -- so a strict session warms it before the first test, which most runs have already done during collection anyway. Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
Two runs of this workflow say what the plan said to measure. Compiling site-packages at install time (UV_COMPILE_BYTECODE) took that step from 3 s to 14 s per shard and the whole pre-test stretch only came down 8 s, so it was a net loss of about 5 s a shard. The compileall pass over the checkout costs 2 s and covers the modules a laptop measurement put at 10 s of a cold collection, so it stays; the next run says what it is worth on a runner. Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
Seconds from the start of the pytest step to the first test, per shard, over three runs of this workflow: no precompile at all 52.7 46.5 45.9 46.0 mean 47.8 site-packages and checkout 39.8 39.3 35.6 45.5 mean 40.1 checkout only 55.5 50.1 44.4 53.8 mean 51.0 Compiling site-packages at install time is the half that moved the number, and it took that step from 3 s to 14 s to do it: a net loss of about 2 s a shard. Compiling the checkout on its own is inside the noise of doing nothing, which reads as no effect: the four workers share one .pyc cache, so the first to import a module already writes it for the rest, and what a laptop measured as 25 s of cold compilation is mostly pytest rewriting test files through a cache compileall cannot fill. Two tests that drive a real browser are marked slow. Playwright starts chromium behind its own node driver, so on the runner the browser's CPU does not reach this process's children account and eleven seconds of layout read as a wait. Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
…ived The test set the first interval to 0.30 s and the rest to 0.02 s, ran a 0.60 s tool, and asked for five beats of the fifteen that should produce. Four workers on a small runner delivered three, and the shard went red on a test that had passed on the same commit an hour earlier. How many beats arrive is the runner's to decide. The two gaps are not: whatever the load, the wait before the first beat is the first interval and the wait after it is the second. The log records when each beat landed, and the assertion is that the first gap waited out HEARTBEAT_FIRST_S and the next is less than half of it. Checked against the bug it guards, a loop that keeps the first interval for every beat: that produces one beat in this window and the assertion fails on it. The flake is older than the gate that surfaced it; nothing in this branch touches the registry or its intervals. Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
… calls The diff gate counted three lines the suite cannot execute: the warm-up call in each of the two serving boot paths, and the import beside one of them. Both coroutines bind a port and serve until they are killed, which is why the tests pin what they schedule by reading their source instead of running them. The import moves to module scope, where importing the module covers it and where the rest of that file's imports already are. The two calls carry a no-cover pragma naming the test that pins each one, the way this repo marks a line a test cannot reach. Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
Two seconds was a guess, and two shards failed on it over tests that were waiting exactly as long as they meant to: an ACP turn interrupted after 0.8 s, a picker row read behind a signed-in account. Both come in at about 1.5 s here and 2.2 s on a runner. Measured across the suite, at a one second line, 25 unmarked tests wait that long. Nineteen of them are between 1.00 s and 1.19 s, which is what a test that sets a one second timeout and lets it expire costs. Three sit at 1.5 s. Nothing at all sits between there and the renders that carry a marker. So the population has a gap, and the line belongs in it rather than at its edge. Three seconds is inside that gap with room for a runner, and still under every ladder this guards against: the shortest constant the audit found was a three second grace, and the rest run 5, 15, 30 and 60 seconds. Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
import_litellm raises three logger levels for the duration of the import and puts the captured values back afterwards, which holds only while one thread is doing it. A second caller arriving inside that window captures WARNING as the level to restore and restores it after the first caller has put the real one back, and litellm's DEBUG and INFO stop reaching raven's file sink until the process restarts. The window was narrow while every import sat on a startup path. It is an ordinary one now that a server warms the import in the background while it serves, so the two callers meet. A module lock is the boundary they share; the second caller waits out the first and then finds the module in sys.modules. The test holds the first caller inside the import and starts a second, and fails on [30, 30, 30] without the lock. The strict-mode warm-up in the suite runs before the fixtures that redirect the home, and publishing the OAuth token directories creates them, so it put an oauth directory in the developer's own ~/.raven. It warms under a temporary home now and puts the environment back. Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
cf7199c to
609b2d3
Compare
gloryfromca
left a comment
There was a problem hiding this comment.
No blockers; this can merge as far as I am concerned.
The new commit fixes the remaining LiteLLM race by serializing the complete initialization sequence, and it also isolates strict-mode warm-up from the developer's real Raven home. The two-thread regression test and a clean-HOME strict reproduction both pass; all four exact-head unit shards and the coverage gate pass in CI run 35049479697. All threads I opened are resolved.
I covered the repository rules, the full diff and new-head delta, callers and history, backward compatibility, whether tests were weakened, concurrency and failure behavior, filesystem isolation, and the CI/architecture constraints. git range-diff shows the rebase preserved every previously reviewed commit and added only this fix; git diff --check github/main...HEAD passes. No additional finding survived refutation.
Local verification: uv run pytest tests/test_litellm_setup.py -q -> 15 passed; strict clean-HOME reproduction -> 1 passed with no .raven/oauth created.
… busy runner (#466) ## Summary Since the idle ceiling became a gate (#428), a unit shard has failed on `main` and on most pull requests with every test passing: the ceiling reads wall clock minus CPU and calls the difference waiting, and a thread that is runnable and not on a CPU spends it the same way. With four workers, the controller and coverage on a four-vCPU runner that queueing reached three to four seconds inside one long test, so the shard died on whichever test was executing when contention peaked, a different one each run. Warming the catalogue (#452) did not stop it. #449 halves the workers per shard, which pays for the same measurement with every shard's wall clock. This changes the measurement instead. Idle now subtracts the time the test's threads spent queued for a CPU, read from the scheduler's own account in `/proc/self/task/<tid>/schedstat`: - every thread of the process is read, not only the one running the test, because the rpc model handlers do their catalogue reads on `asyncio.to_thread`; - a thread writes its own last reading on the way out, through a wrapper on `Thread._bootstrap_inner`, because the per-test event loop is closed at the end of the test and takes its executor threads with it, and `/proc` forgets a thread the moment it ends; - CPU stays on `os.times`, which keeps the CPU of ended threads and of reaped children; the scheduler's per-thread run time would have been lost the same way the queue time was. A sleeping thread is not on a run queue, so a test that waits on purpose is still charged the whole wait. Without `schedstat` (macOS, Windows) the arithmetic is the old one; the strict gate only runs on Linux, and a Linux-only test fails loudly if the runner's kernel stops keeping the statistics rather than letting the gate degrade quietly. `-n 4`, the 3 s ceiling and the four shards are unchanged. If this lands, #449 is not needed. ## Type - [ ] Fix - [ ] Feature - [ ] Docs - [x] CI / tooling - [ ] Refactor - [ ] Other ## Verification Unit tests for the clocks (12 on macOS, 13 on Linux, the last one reads the live kernel): ``` uv run --frozen --all-extras pytest -q tests/test_conftest_idle_ceiling.py macOS: 12 passed, 1 skipped Linux container: 13 passed ``` Full suite on macOS, where the fallback arithmetic runs: ``` uv run --frozen --all-extras pytest -q -p no:cacheprovider 23137 passed, 109 skipped in 291.30s ``` Contrast runs in a Linux container (Docker, linux/arm64, kernel 6.12), the checkout and venv on container-local storage, `main` at 2bdc4bd against this branch. Four workers pinned to two CPUs stands in for the four-vCPU runner; the ceiling is lowered to 0.05 s so the effect shows on one file: ``` docker run --cpuset-cpus=0-1 ... pytest tests/test_rpc_model.py --idle-ceiling 0.05 -n 4 main: 70 unmarked tests over the ceiling, worst 1.67s idle of 2.89s branch: 2 unmarked tests over the ceiling, worst 0.12s idle of 0.50s (0.19s queued) docker run --cpuset-cpus=0-3 ... pytest tests/test_rpc_model.py --idle-ceiling 0.05 -n 16 main: 81 over, worst 6.11s idle of 8.16s branch: 1 over, 0.13s idle of 1.11s (0.73s queued) an unmarked test that does time.sleep(0.5), on the branch: 0.53s idle of 1.70s (0.00s queued) # an honest wait is still charged in full ``` The CI shard command, same container, four workers pinned to two CPUs: ``` pytest -q --shard 3/4 --durations=25 --idle-ceiling-strict -n 4 --cov=raven --cov=raven_everos --cov-branch --cov-report= main: 5131 passed, 10 skipped; "1 unmarked test(s) waited more than 3s (failing the session)" 3.11s idle of 6.04s tests/test_ppt_engine_template_tool.py::test_binding_a_template_by_path; exit 1 branch: 5378 passed, 11 skipped; no idle report; exit 0 branch, shards 1/4, 2/4, 4/4: no idle report in any (three failures, all `git ls-files` exit 128 because the copied worktree's gitdir is not inside the container) ``` - [x] Relevant tests pass locally - [x] Relevant lint / type checks pass locally - [ ] User-facing docs or screenshots are updated when needed (none; the option help text and the summary line say what is now subtracted) ## Risk - Behaviour change is confined to what the ceiling charges a test: less on a busy runner, the same for a real wait. Nothing under `raven/` changes. - `Thread._bootstrap_inner` is private CPython API (present from 3.8 through 3.13); the wrapper is installed once, guarded against a second import of the module, and pinned by a test. If a future interpreter drops it the module fails to import at collection, which is loud. - Rollback: revert the commit; the gate goes back to wall clock minus CPU. - [x] Security impact considered - [x] Backward compatibility considered - [x] Rollback path is clear for risky changes ## Related Issues #428 made the ceiling a gate; #452 warmed the catalogue; #449 halves the workers instead. Co-authored-by: Claude (claude-fable-5-1) <noreply@anthropic.com>
## Summary Follow-up to #413, from a measured look at what was left: a CI shard now spends 72 s on fixed cost (22 s environment, 48 s collection and worker start) against 82 s of tests, the four shards are within 15 s of each other, and 70 unmarked tests were still over the 2 s wall-clock ceiling on CI against 42 on a laptop because CPU-bound work runs three to four times slower there. This PR makes the ceiling a gate that is portable across machines, takes the remaining waits out, precompiles bytecode so the workers stop doing it four times, and fixes two product waits the same investigation surfaced. - `test(*)`: the ceiling judges idle time instead of wall clock, where idle is the wall clock minus every CPU second spent on the test's behalf, the reaped children's included (`os.times`). A test waiting on a production sleep or a process that answers nothing waits the same seconds on every machine; a test that computes for 2 s here and 7 s on CI, or drives a browser or eight spawned workers, is not the problem. The numbers ride on the teardown report so the xdist controller can judge them; options are `--idle-ceiling` / `--idle-ceiling-strict`. The fixture that shortens production ladders takes in the ACP cancel settle (5 s) and the gateway delivery grace (2 s); the CLI agent tests stub the one-shot command's unconditional 2 s hand-off grace; the rpc subagent tests no longer spawn a login shell or probe a real endpoint over the network; three literal timeouts shrink where the stub never answers anyway. What is left over the ceiling carries a marker: seven real LibreOffice renders and two tests that wait on a process answering nothing carry `slow`, two whose assertion is the wait itself carry `production_timing`. - `ci(*)`: every shard runs with `--idle-ceiling-strict` (on the make line, not in `addopts`: the Windows job runs `--noconftest`). Bytecode precompilation was tried and dropped, the numbers are below; the workflow is otherwise unchanged from #413. - `test(agent)`: a heartbeat test asked for five beats of the fifteen its intervals should produce in a 0.6 s window, and a loaded runner delivered three. It reads the two gaps instead, which the load cannot invert: the wait before the first beat is one interval, the wait after it is the other. Older than the gate that surfaced it; nothing here touches the registry. - `perf(ppt-engine)`: `MeasuredWidth.width` remembers measured widths (bounded, oldest key out); a 15-slide template's QA gates made 1848 freetype calls over 162 distinct keys. Importing `text_metrics` first raised on a circular import through `template.capacity`; capacity now imports the module and resolves the name at call time. - `perf(*)`: `raven gateway` and `raven web` start the litellm import on a daemon thread at boot, so saving a key from the settings page no longer waits three to five seconds on it. - `fix(providers)`: one thread at a time initialises litellm. It raises three logger levels for the duration of the import and puts the captured values back after, which holds only while one thread is doing it; a second caller arriving inside that window captures WARNING as the level to restore, and litellm's DEBUG and INFO stop reaching the file sink until a restart. The window was narrow while every import sat on a startup path and is ordinary now that a server warms it in the background, so the two callers share a module lock. The strict-mode warm-up also runs before the fixtures that redirect the home, and publishing the OAuth token directories created them, so it warms under a temporary home. ## Type - [ ] Fix - [ ] Feature - [ ] Docs - [x] CI / tooling - [ ] Refactor - [ ] Other ## Verification Whole suite, `uv run --frozen --all-extras pytest -q` (macOS, 4 workers), before and after the waits came out and with the ceiling strict: | run | result | idle list | |---|---|---| | main after #413 | 22052 passed, 43 skipped in 219.41 s | 39 over 2 s wall clock | | this branch, `--idle-ceiling` warning | 22057 passed, 43 skipped in 210.20 s | 14 over 2 s idle, all real render or subprocess, now marked | | this branch, `--idle-ceiling-strict` | 22058 passed, 43 skipped in 204.89 s, exit 0 | none | The ceiling is three seconds, placed from the suite's own distribution rather than guessed. Unmarked tests over one second of idle, measured across the whole suite: | idle | tests | what they are | |---|---|---| | 1.00-1.19 s | 19 | a test that sets a one second timeout and lets it expire | | 1.2-1.3 s | 3 | a subprocess handshake | | 1.5-1.6 s | 3 | an ACP turn interrupted after 0.8 s, and two like it | | above 1.6 s | 0 | the renders above this line all carry a marker | A runner stretches that 1.6 s to about 2.2 s, which is how a two second line failed two shards over tests waiting exactly as long as they meant to. Three seconds sits in the gap the population leaves, and stays under every ladder this guards against: the shortest constant the audit found was a three second grace, the rest run 5, 15, 30 and 60 seconds. What the metric separates, measured on this suite: a test that sleeps 5 s reports `4.96s idle of 5.02s`; a test that drives a headless browser for 13 s reports under 0.8 s; six `raven doctor` subprocesses report 1.2 s where wall clock said 4.2 s; eight spawned processes contending for a lock report under 0.8 s where wall clock said 3.6 s. Files touched by the product changes and the new markers (`uv run --frozen --all-extras pytest -q tests/test_litellm_setup.py tests/test_cli_gateway_commands.py tests/test_cli_serve_commands.py tests/test_ppt_engine_assets_fonts.py tests/test_ppt_engine_template_capacity.py tests/test_cli_doctor_commands.py tests/test_ppt_engine_end_to_end.py tests/test_ppt_engine_render_service.py tests/test_rpc_model.py`): `434 passed, 2 skipped in 33.39s`, none over 1 s idle. `python -c "import raven_ppt.services.assets.text_metrics"` in a fresh interpreter: ImportError before, imports after. Test-side speedups, measured per test: the ten CLI agent tests 2.0-4.4 s to 0.05-0.36 s; the three rpc subagent tests 1.4-2.6 s to 0.01-0.02 s; the rpc save-key test 2.2-2.8 s to 0.03 s; the two ACP probe tests 2.1 s to 0.2 s. Bytecode precompilation, seconds from the start of the pytest step to the first test, per shard, over three runs of this workflow: | what was compiled | shard 1 | shard 2 | shard 3 | shard 4 | mean | install step | |---|---|---|---|---|---|---| | nothing (#413) | 52.7 | 46.5 | 45.9 | 46.0 | 47.8 | 3-4 s | | site-packages and checkout | 39.8 | 39.3 | 35.6 | 45.5 | 40.1 | 12-17 s | | checkout only | 55.5 | 50.1 | 44.4 | 53.8 | 51.0 | 3-4 s | Compiling site-packages is the half that moved the number and it cost more in the install step than it returned. Compiling the checkout alone is inside the noise of doing nothing: the four workers share one `.pyc` cache, so the first to import a module writes it for the rest, and most of what a laptop measures as cold compilation is pytest rewriting test files through a cache `compileall` cannot fill. Both are gone; the comment in the workflow records it. The reworked heartbeat assertion was checked against the bug it guards by making the registry keep its first interval for every beat: one beat arrives in the window and the assertion fails on it. The diff gate is reproduced locally against `origin/main` after a full `make coverage`: `Diff coverage: 100.00% (12/12 executable changed lines)`. The two warm-up calls in the serving boot coroutines carry a no-cover pragma naming the test that pins them, because those coroutines bind a port and serve until they are killed. The lock is checked against the race it closes: with it taken away, a test that holds the first caller inside the import and starts a second fails on `[30, 30, 30] == [20, 20, 20]`. A strict session under a clean HOME now leaves no `.raven` behind. `make lint-python` clean. - [x] Relevant tests pass locally - [x] Relevant lint / type checks pass locally - [ ] User-facing docs or screenshots are updated when needed (none) ## Risk - The ceiling is now a gate on CI. A new test that waits more than 2 s without `slow` or `production_timing` turns its shard red; the summary names the test and the marker to use. A local run stays warning-only. - A subprocess that does real work is charged to the test that reaped it, so only a real wait trips the gate. A strict session imports litellm up front, because its 1.7 s of file opens would otherwise land on whichever test in the shard imports it first. - The litellm warm-up runs on a daemon thread at server boot only; unit tests never reach either boot path (their source is pinned instead), and a failed import is logged, not raised. - The width memo returns the same floats; the cap evicts the oldest key. The capacity import change resolves the same name one step later. - Rollback: revert the PR; every change is additive or a marker. - [x] Security impact considered (no security surface touched) - [x] Backward compatibility considered - [x] Rollback path is clear for risky changes ## Related Issues N/A --------- Co-authored-by: Claude (claude-fable-5-1) <noreply@anthropic.com>
… busy runner (#466) ## Summary Since the idle ceiling became a gate (#428), a unit shard has failed on `main` and on most pull requests with every test passing: the ceiling reads wall clock minus CPU and calls the difference waiting, and a thread that is runnable and not on a CPU spends it the same way. With four workers, the controller and coverage on a four-vCPU runner that queueing reached three to four seconds inside one long test, so the shard died on whichever test was executing when contention peaked, a different one each run. Warming the catalogue (#452) did not stop it. #449 halves the workers per shard, which pays for the same measurement with every shard's wall clock. This changes the measurement instead. Idle now subtracts the time the test's threads spent queued for a CPU, read from the scheduler's own account in `/proc/self/task/<tid>/schedstat`: - every thread of the process is read, not only the one running the test, because the rpc model handlers do their catalogue reads on `asyncio.to_thread`; - a thread writes its own last reading on the way out, through a wrapper on `Thread._bootstrap_inner`, because the per-test event loop is closed at the end of the test and takes its executor threads with it, and `/proc` forgets a thread the moment it ends; - CPU stays on `os.times`, which keeps the CPU of ended threads and of reaped children; the scheduler's per-thread run time would have been lost the same way the queue time was. A sleeping thread is not on a run queue, so a test that waits on purpose is still charged the whole wait. Without `schedstat` (macOS, Windows) the arithmetic is the old one; the strict gate only runs on Linux, and a Linux-only test fails loudly if the runner's kernel stops keeping the statistics rather than letting the gate degrade quietly. `-n 4`, the 3 s ceiling and the four shards are unchanged. If this lands, #449 is not needed. ## Type - [ ] Fix - [ ] Feature - [ ] Docs - [x] CI / tooling - [ ] Refactor - [ ] Other ## Verification Unit tests for the clocks (12 on macOS, 13 on Linux, the last one reads the live kernel): ``` uv run --frozen --all-extras pytest -q tests/test_conftest_idle_ceiling.py macOS: 12 passed, 1 skipped Linux container: 13 passed ``` Full suite on macOS, where the fallback arithmetic runs: ``` uv run --frozen --all-extras pytest -q -p no:cacheprovider 23137 passed, 109 skipped in 291.30s ``` Contrast runs in a Linux container (Docker, linux/arm64, kernel 6.12), the checkout and venv on container-local storage, `main` at 2bdc4bd against this branch. Four workers pinned to two CPUs stands in for the four-vCPU runner; the ceiling is lowered to 0.05 s so the effect shows on one file: ``` docker run --cpuset-cpus=0-1 ... pytest tests/test_rpc_model.py --idle-ceiling 0.05 -n 4 main: 70 unmarked tests over the ceiling, worst 1.67s idle of 2.89s branch: 2 unmarked tests over the ceiling, worst 0.12s idle of 0.50s (0.19s queued) docker run --cpuset-cpus=0-3 ... pytest tests/test_rpc_model.py --idle-ceiling 0.05 -n 16 main: 81 over, worst 6.11s idle of 8.16s branch: 1 over, 0.13s idle of 1.11s (0.73s queued) an unmarked test that does time.sleep(0.5), on the branch: 0.53s idle of 1.70s (0.00s queued) # an honest wait is still charged in full ``` The CI shard command, same container, four workers pinned to two CPUs: ``` pytest -q --shard 3/4 --durations=25 --idle-ceiling-strict -n 4 --cov=raven --cov=raven_everos --cov-branch --cov-report= main: 5131 passed, 10 skipped; "1 unmarked test(s) waited more than 3s (failing the session)" 3.11s idle of 6.04s tests/test_ppt_engine_template_tool.py::test_binding_a_template_by_path; exit 1 branch: 5378 passed, 11 skipped; no idle report; exit 0 branch, shards 1/4, 2/4, 4/4: no idle report in any (three failures, all `git ls-files` exit 128 because the copied worktree's gitdir is not inside the container) ``` - [x] Relevant tests pass locally - [x] Relevant lint / type checks pass locally - [ ] User-facing docs or screenshots are updated when needed (none; the option help text and the summary line say what is now subtracted) ## Risk - Behaviour change is confined to what the ceiling charges a test: less on a busy runner, the same for a real wait. Nothing under `raven/` changes. - `Thread._bootstrap_inner` is private CPython API (present from 3.8 through 3.13); the wrapper is installed once, guarded against a second import of the module, and pinned by a test. If a future interpreter drops it the module fails to import at collection, which is loud. - Rollback: revert the commit; the gate goes back to wall clock minus CPU. - [x] Security impact considered - [x] Backward compatibility considered - [x] Rollback path is clear for risky changes ## Related Issues #428 made the ceiling a gate; #452 warmed the catalogue; #449 halves the workers instead. Co-authored-by: Claude (claude-fable-5-1) <noreply@anthropic.com>
Summary
Follow-up to #413, from a measured look at what was left: a CI shard now spends 72 s on fixed cost (22 s environment, 48 s collection and worker start) against 82 s of tests, the four shards are within 15 s of each other, and 70 unmarked tests were still over the 2 s wall-clock ceiling on CI against 42 on a laptop because CPU-bound work runs three to four times slower there. This PR makes the ceiling a gate that is portable across machines, takes the remaining waits out, precompiles bytecode so the workers stop doing it four times, and fixes two product waits the same investigation surfaced.
test(*): the ceiling judges idle time instead of wall clock, where idle is the wall clock minus every CPU second spent on the test's behalf, the reaped children's included (os.times). A test waiting on a production sleep or a process that answers nothing waits the same seconds on every machine; a test that computes for 2 s here and 7 s on CI, or drives a browser or eight spawned workers, is not the problem. The numbers ride on the teardown report so the xdist controller can judge them; options are--idle-ceiling/--idle-ceiling-strict. The fixture that shortens production ladders takes in the ACP cancel settle (5 s) and the gateway delivery grace (2 s); the CLI agent tests stub the one-shot command's unconditional 2 s hand-off grace; the rpc subagent tests no longer spawn a login shell or probe a real endpoint over the network; three literal timeouts shrink where the stub never answers anyway. What is left over the ceiling carries a marker: seven real LibreOffice renders and two tests that wait on a process answering nothing carryslow, two whose assertion is the wait itself carryproduction_timing.ci(*): every shard runs with--idle-ceiling-strict(on the make line, not inaddopts: the Windows job runs--noconftest). Bytecode precompilation was tried and dropped, the numbers are below; the workflow is otherwise unchanged from ci(*): run unit tests as four shards and speed up the suite #413.test(agent): a heartbeat test asked for five beats of the fifteen its intervals should produce in a 0.6 s window, and a loaded runner delivered three. It reads the two gaps instead, which the load cannot invert: the wait before the first beat is one interval, the wait after it is the other. Older than the gate that surfaced it; nothing here touches the registry.perf(ppt-engine):MeasuredWidth.widthremembers measured widths (bounded, oldest key out); a 15-slide template's QA gates made 1848 freetype calls over 162 distinct keys. Importingtext_metricsfirst raised on a circular import throughtemplate.capacity; capacity now imports the module and resolves the name at call time.perf(*):raven gatewayandraven webstart the litellm import on a daemon thread at boot, so saving a key from the settings page no longer waits three to five seconds on it.fix(providers): one thread at a time initialises litellm. It raises three logger levels for the duration of the import and puts the captured values back after, which holds only while one thread is doing it; a second caller arriving inside that window captures WARNING as the level to restore, and litellm's DEBUG and INFO stop reaching the file sink until a restart. The window was narrow while every import sat on a startup path and is ordinary now that a server warms it in the background, so the two callers share a module lock. The strict-mode warm-up also runs before the fixtures that redirect the home, and publishing the OAuth token directories created them, so it warms under a temporary home.Type
Verification
Whole suite,
uv run --frozen --all-extras pytest -q(macOS, 4 workers), before and after the waits came out and with the ceiling strict:--idle-ceilingwarning--idle-ceiling-strictThe ceiling is three seconds, placed from the suite's own distribution rather than guessed. Unmarked tests over one second of idle, measured across the whole suite:
A runner stretches that 1.6 s to about 2.2 s, which is how a two second line failed two shards over tests waiting exactly as long as they meant to. Three seconds sits in the gap the population leaves, and stays under every ladder this guards against: the shortest constant the audit found was a three second grace, the rest run 5, 15, 30 and 60 seconds.
What the metric separates, measured on this suite: a test that sleeps 5 s reports
4.96s idle of 5.02s; a test that drives a headless browser for 13 s reports under 0.8 s; sixraven doctorsubprocesses report 1.2 s where wall clock said 4.2 s; eight spawned processes contending for a lock report under 0.8 s where wall clock said 3.6 s.Files touched by the product changes and the new markers (
uv run --frozen --all-extras pytest -q tests/test_litellm_setup.py tests/test_cli_gateway_commands.py tests/test_cli_serve_commands.py tests/test_ppt_engine_assets_fonts.py tests/test_ppt_engine_template_capacity.py tests/test_cli_doctor_commands.py tests/test_ppt_engine_end_to_end.py tests/test_ppt_engine_render_service.py tests/test_rpc_model.py):434 passed, 2 skipped in 33.39s, none over 1 s idle.python -c "import raven_ppt.services.assets.text_metrics"in a fresh interpreter: ImportError before, imports after.Test-side speedups, measured per test: the ten CLI agent tests 2.0-4.4 s to 0.05-0.36 s; the three rpc subagent tests 1.4-2.6 s to 0.01-0.02 s; the rpc save-key test 2.2-2.8 s to 0.03 s; the two ACP probe tests 2.1 s to 0.2 s.
Bytecode precompilation, seconds from the start of the pytest step to the first test, per shard, over three runs of this workflow:
Compiling site-packages is the half that moved the number and it cost more in the install step than it returned. Compiling the checkout alone is inside the noise of doing nothing: the four workers share one
.pyccache, so the first to import a module writes it for the rest, and most of what a laptop measures as cold compilation is pytest rewriting test files through a cachecompileallcannot fill. Both are gone; the comment in the workflow records it.The reworked heartbeat assertion was checked against the bug it guards by making the registry keep its first interval for every beat: one beat arrives in the window and the assertion fails on it.
The diff gate is reproduced locally against
origin/mainafter a fullmake coverage:Diff coverage: 100.00% (12/12 executable changed lines). The two warm-up calls in the serving boot coroutines carry a no-cover pragma naming the test that pins them, because those coroutines bind a port and serve until they are killed.The lock is checked against the race it closes: with it taken away, a test that holds the first caller inside the import and starts a second fails on
[30, 30, 30] == [20, 20, 20]. A strict session under a clean HOME now leaves no.ravenbehind.make lint-pythonclean.Risk
The ceiling is now a gate on CI. A new test that waits more than 2 s without
sloworproduction_timingturns its shard red; the summary names the test and the marker to use. A local run stays warning-only.A subprocess that does real work is charged to the test that reaped it, so only a real wait trips the gate. A strict session imports litellm up front, because its 1.7 s of file opens would otherwise land on whichever test in the shard imports it first.
The litellm warm-up runs on a daemon thread at server boot only; unit tests never reach either boot path (their source is pinned instead), and a failed import is logged, not raised.
The width memo returns the same floats; the cap evicts the oldest key. The capacity import change resolves the same name one step later.
Rollback: revert the PR; every change is additive or a marker.
Security impact considered (no security surface touched)
Backward compatibility considered
Rollback path is clear for risky changes
Related Issues
N/A