fix(engine): bound the capture drain held under the state lock - #59
Conversation
engine_tick drained the ring with `while (auto ev = capture_.next_event())` while holding mutex_. That loop ends only when the consumer outruns the producer, so sustained input made the critical section as long as the typing: session and settings commands blocked on mutex_, and the idle poll, the Pomodoro poll, the persistence flush, and every UI emission -- all of which follow the drain -- were deferred for the same stretch. A stop request could not shorten a drain already in progress either. Cap one tick at kEngineDrainBudget (2,048) events, plus a 20 ms wall-clock ceiling checked every 128 events for the case where per-event work (window extraction, ONNX inference) makes even 2,048 too many. The count budget is the primary bound precisely because it needs no clock, which keeps ManualClock-driven ticks deterministic. Truncating drops nothing: the rest of the ring stays queued for the next tick, and engine_tick now returns whether it stopped on a budget so the engine loop re-ticks after 1 ms instead of sleeping out its usual 100. Throughput therefore stays limited by processing speed, not by budget-per-tick -- what changes is that mutex_ is released between slices, so a waiting command thread can take it. A saturated drain logs at most once per 30 s, since during a backlog the loop runs every millisecond. Tests drive this through a new capture-only start seam, which fills the ring with no engine thread racing the drain: an over-budget burst is bounded and resumable across ticks, a truncated drain still persists and emits what it computed, and an under-budget drain reports no backlog. 642 cases pass.
The three cases added with the drain bound check the mechanism -- the budget, the backlog flag, the resumption -- but not the symptom that motivated it: a UI command waiting on mutex_ for as long as the user keeps typing. That is an interaction between the real engine thread and a real producer, so it needs both. FloodHook pushes events for three seconds, faster than the engine can consume them, so the ring never runs dry. The test polls settings() -- an in-memory read that still needs mutex_ -- throughout and records the worst wait. Verified against the defect rather than only against the fix: with the budgets raised to effectively infinite (the old unbounded drain) the worst wait is 3,708 ms across 2 samples; with them restored it is a few milliseconds across hundreds. The 1,000 ms threshold sits far from both so a loaded CI machine cannot flip it. 643 cases pass.
There was a problem hiding this comment.
🟡 Changes recommended
Unresolved critical stale-event handling and moderate shutdown, logging, and throttle-sentinel issues prevent approval.
Get a fresh assessment by requesting another Copilot review.
Pull request overview
This PR bounds capture-event draining under AppState::mutex_ to reduce lock contention during sustained input.
Changes:
- Adds event-count and time-based drain limits with faster backlog re-ticks.
- Throttles saturated-drain logging.
- Adds test seams and regression coverage for draining, persistence, and starvation.
File summaries
| File | Summary |
|---|---|
tests/test_app_state.cpp |
Adds bounded-drain, persistence, resumability, and starvation tests. |
tests/app_state_test_access.hpp |
Adds synchronous capture/drain test seams. |
src/app/state.hpp |
Defines drain limits and updates the tick API. Moderate: using 0 as the log timestamp sentinel defeats throttling when the clock reads zero. |
src/app/state.cpp |
Implements bounded draining and backlog scheduling. Critical: pre-deletion queued events can be processed after deletion. Moderate: remaining events can be lost at shutdown; synchronous logging can extend lock holding; the zero timestamp sentinel can defeat log throttling. |
Review details
Suppressed comments (5)
src/app/state.cpp:1900
- The bounded drain can leave work unprocessed at shutdown. If
stop_engine()stops the producer after a saturated tick, the engine exits after that slice whileCaptureThread::stop()leaves the remaining ring entries queued; destruction then discards them without persistence, so captured events can be lost. Add a final drain/flush after joining the producer, or explicitly define and handle this shutdown loss.
// Leftover events stay in the ring (single consumer, so nobody else takes them) and
// are picked up by the next tick, which follows in kEngineBacklogTickIntervalMs.
std::size_t drained = 0;
src/app/state.cpp:1917
- Reaching the count boundary does not prove that the ring still has an event: a burst of exactly
kEngineDrainBudgetentries is fully consumed, but this unconditionally reports a backlog and causes the engine to run an unnecessary 1 ms tick (and log a false backlog). The return contract saystruemeans work remains, so use a non-destructive pending-event check before setting this flag.
if (drained >= kEngineDrainBudget) drain_truncated = true;
src/app/state.cpp:1926
- This synchronous log call runs while
mutex_is held.Logger::logformats the timestamp and writes to its sink synchronously, so a slow or blocked file/stderr sink can keep the state lock held well beyond the advertised drain bound and reintroduce command starvation. Record the throttling decision under the state lock, but defer the actual log write until after that lock is released.
log().info("engine: capture backlog, drained " + std::to_string(drained) +
" events this tick and yielded the state lock");
src/app/state.cpp:1923
- The throttle uses
0as the “never logged” sentinel, butClock::steady_ms()is allowed to return zero andManualClockcan be constructed with a zero origin. With such a clock, every saturated tick stores0, the condition remains true, and a sustained backlog logs once per millisecond instead of once per 30 seconds. Use a separate boolean/optional state (or another sentinel outside the clock domain) for whether a log has been emitted.
if (last_drain_backlog_log_ms_ == 0 ||
log_now_ms - last_drain_backlog_log_ms_ >= kEngineBacklogLogIntervalMs) {
src/app/state.hpp:549
Clock::steady_ms()is defined relative to an arbitrary epoch, so 0 is a valid reading (and the test ManualClock uses it). With a saturated backlog while the clock remains at 0, this member is assigned 0 every tick and the== 0check below logs on every 1 ms tick, defeating the 30-second throttle and adding logger/lock contention. Use an optional or a sentinel outside the clock's value domain.
// Uptime at the last "capture backlog" log line. Guarded by mutex_ (written inside the
// drain phase); 0 means never logged, and the first saturated drain always reports.
std::int64_t last_drain_backlog_log_ms_ = 0;
- Files reviewed: 4/4 changed files
- Comments generated: 1
- Review effort level: Lite
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
| // Leftover events stay in the ring (single consumer, so nobody else takes them) and | ||
| // are picked up by the next tick, which follows in kEngineBacklogTickIntervalMs. | ||
| std::size_t drained = 0; |
Four defects in the bounded drain, found in review of #59. **Deleting activity left it in the queue.** The activity epoch fences the rows a tick was about to write; it does not reach into capture. Events recorded before the user asked for deletion stayed queued, and the next tick filed them -- into a session started after the deletion, no less, so pre-deletion window titles came back on disk. This window exists without the drain bound too (events accumulate between ticks), but a bounded drain widens it from one tick's worth to potentially a full ring, and "delete my activity" has to mean the activity still in flight. delete_all_activity_data and delete_session now drop the queue through a capacity-bounded discard. Scoped deliberately: delete_session drops it only when the session being erased is the active one, because deleting some other session must not throw away input from the session the user is still running. **Shutdown dropped the tail.** The unbounded drain always left the ring empty, so stopping the engine persisted everything captured. The bounded one exits after a slice, and the loop stopped the moment engine_running_ went false -- silently discarding whatever that slice did not reach. Backlog is now part of the exit condition, not just the pacing: the loop keeps ticking while work remains, which terminates because stop_engine stops the producer before joining. It is a do-while because stop_engine can flip the flag before this thread is ever scheduled, and a plain loop would then exit having drained nothing at all. **The backlog flag lied at the boundary.** Spending the budget is not the same as leaving work behind: a burst of exactly kEngineDrainBudget events is fully consumed, and reporting a backlog for it bought a needless 1 ms tick and a log line about an empty queue. RingBuffer::has_pending answers the question non-destructively instead of inferring it from the counter. **The log write held mutex_.** Logger formats and writes to its sink synchronously, so a slow disk would extend exactly the critical section this work exists to bound. The throttle decision stays under the lock; the write happens after it is released. The throttle also no longer uses 0 as its "never logged" sentinel -- steady_ms() counts from an arbitrary epoch, so 0 is a value the clock can hold (ManualClock routinely does), and a sentinel inside the clock's own domain defeats the throttle for as long as it sits there. Three new cases: shutdown leaves the ring empty with the whole burst persisted, deleting activity erases what was queued, and deleting one session leaves another's queued events alone. 646 cases pass.
|
Reviewed each finding against the code. Three were valid as stated, one was valid but under-rated, and the "critical" one describes a real defect with the wrong attribution. All four are fixed in 707a1dd. Deleting activity left it in the queue (flagged critical)The defect is real: the activity epoch fences the rows a tick was about to write, not what capture has already queued, so pre-deletion events could be filed into a session started after the deletion. The attribution is not. This window does not appear "now" — it exists without the drain bound, because events accumulate between ticks regardless of how the drain terminates. What the bound changes is its size: from one tick's worth to potentially a full ring. That is enough to be worth fixing on its own terms — captured window titles surviving "delete my activity" is a privacy problem, not a bookkeeping one.
Shutdown dropped the tail (flagged moderate)Under-rated — this was the more serious of the two, and a regression the PR introduced. The unbounded drain always left the ring empty, so a stop persisted everything captured; the bounded one exited after a single slice. Backlog is now part of the loop's exit condition rather than only its pacing: it keeps ticking while work remains, which terminates because The backlog flag lied at the boundaryCorrect. A burst of exactly The log write held
|
The maintenance worker blocks on maintenance_ready_ with a predicate over maintenance_stopping_/pending_/paused_. Every site that changed one of those flags stored it and called notify_all() without holding maintenance_mutex_, so the notification could land in the window after the worker evaluated the predicate and before it was actually blocked on the condition variable. A lost wakeup. For `paused` and `pending` that is a delay. For `stopping` it is a hang: the worker never wakes, the join() in stop_engine() never returns, and the process cannot exit. Since the worker is started in the constructor, every AppState test carries one -- which is what has been killing one random AppState test per CI job on a 120 s ctest timeout, on whichever platform lost the race that run. It reproduces on master (run 34777824788: windows-gcc hung on "AppState still uses the real clock when none is injected", ONNX/linux on "delete_session reports a missing session"), so it predates the drain work; it surfaced here because that run is what made me read the logs. All six sites now go through signal_maintenance(), which applies the change under maintenance_mutex_ and notifies after releasing it. The pending path notifies unconditionally rather than only when the CAS won: a spurious wake costs one predicate evaluation, and the CAS result was never worth a second code path. Not directly testable without instrumenting the race -- the fix is that the state change and the wait predicate now agree on a lock. 646 cases pass.
CI caught this on macOS: the shutdown test asserted an empty ring and the whole burst persisted, and got a full ring and zero rows. The previous fix made `backlog` part of the loop's exit condition, but that flag describes the tick that already ran. An engine thread asleep between ticks when stop_engine() flips engine_running_ holds a stale `false` from before the events arrived, so it evaluated the condition, saw no backlog, and exited over a queue that had filled while it slept. The do-while only covered the narrower case of a thread that had not yet been scheduled. The exit condition now asks capture_ directly. Pacing deliberately still keys off `backlog` alone: an ordinary tick usually leaves a few events behind it, and treating that as urgent would run the loop at 1 ms forever for a handful of keystrokes. Also bounds the shutdown drain at 64 ticks. A tick that throws reports no backlog but drains nothing either, so a permanently failing tick over a non-empty ring would have spun here and never let the process exit. The whole ring is 32 ticks' worth, so this cannot cut a healthy drain short. 646 cases pass.
…udit npm audit --audit-level=high was red on this branch and on master: browserslist <=4.28.6 carries two high advisories (unbounded cache growth -> OOM, and a prototype write via untrusted browserslist-stats). baseline-browser-mapping <2.11.0 adds a moderate DoS on invalid input. npm audit fix resolves both with transitive patch/minor bumps only -- browserslist, baseline-browser-mapping, caniuse-lite, electron-to-chromium, node-releases, update-browserslist-db. No direct dependency and no package.json range changes. Typecheck, build, and test:ci (31 files, 165 tests) all pass. The three remaining moderate vitest/@vitest/mocker advisories are below the CI threshold and would need a vitest 5 major bump, left for its own change.
Problem
AppState::engine_tickdrained the capture ring withwhile (auto ev = capture_.next_event())while holdingmutex_. That loop exits only when the consumer outruns the producer, so sustained input made the critical section as long as the typing. For its duration:mutex_Shutdown still terminated (the producer is stopped and joined first), so this is a latency defect during ordinary operation, not a hang.
Change
kEngineDrainBudget(2,048) events, plus a 20 ms wall-clock ceiling checked every 128 events for when per-event work (window extraction, ONNX inference) makes even 2,048 too many. The count budget is primary because it needs no clock, which keepsManualClock-driven ticks deterministic.engine_ticknow returns whether it stopped on a budget, and the engine loop re-ticks after 1 ms instead of its usual 100, so throughput stays bound by processing speed rather than budget-per-tick. What changes is thatmutex_is released between slices.Verification
Four new cases, driven through a tests-only capture-start seam that fills the ring with no engine thread racing the drain:
settings()call is not starved while a producer floods the ring for 3 secondsCase 4 was validated against the defect, not just the fix: with the budgets raised to effectively infinite (the old unbounded drain) the worst wait is 3,708 ms across 2 samples; with them restored it is a few milliseconds across hundreds. The 1,000 ms threshold sits far from both.
Full suite: 643 cases / 388,368 assertions passing. App target builds clean.