fix/db-write-contention #82

Merged

nrupard merged 19 commits from fix/db-write-contention into main

2026-05-13 16:49:19 +02:00

nrupard commented

2026-05-13 16:49:12 +02:00

Owner

No description provided.

nrupard added 19 commits

2026-05-13 16:49:12 +02:00

fix(db): batch high-frequency touches through a single background writer f80bc11029

The page-load freeze under chat traffic was pool exhaustion, not lock contention. Every authed request was doing tokio::spawn for last-seen and last-active updates. With max_connections=16 and a busy SQLite writer, those spawned tasks queued for pool acquisition; once the queue grew, incoming HTTP requests waited 30+ seconds for a free connection, which is what produced the multi-minute reload symptom that resolved suddenly when the backlog drained.

Replace the per-request spawns with one long-lived worker that owns a bounded mpsc::Sender, deduplicates touches into HashSets, and flushes each set every 500 ms as a single batched UPDATE ... WHERE id IN (...). Senders only push an id onto the channel and never touch the pool, so the HTTP path can no longer block on the writer. The channel is bounded at 4096 and uses try_send: under steady load it's near-empty, and if the worker ever stalls, senders drop the touch instead of piling up. The idle->active flip path still runs inline via touch_user_activity so its broadcast remains instant.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

fix(db): prewarm pool, log slow requests, sample pool stats 4e5300605a

Three fixes after multi-fix attempts on touch_user_activity locking and the page-reload stall failed to land the symptom.

1. Prewarm four connections per pool. Opening a SQLite connection costs a parse-and-PRAGMA round-trip; serving the first burst of HTTP requests against a cold pool incurs that cost serially, which can look exactly like contention.
2. Drop acquire_timeout from the 30 s sqlx default to 3 s. A saturated pool will now surface as a fast 500 in the logs instead of stalling the response. This is intentionally aggressive: we want loud evidence the next time the symptom reproduces.
3. Skip test_before_acquire. The "SELECT 1" round-trip per acquire is unnecessary now that we trust WAL-mode connections to survive idle, and it doubles every acquire latency under pressure.

Also add two diagnostics so the next reproduction produces actionable data:
- A 30 s background task logs `auth_size / auth_idle / chat_size / chat_idle / settings_size / settings_idle`. A saturated pool will read as `size == max && idle == 0` for the duration of the stall.
- A new middleware times every request and emits a warn-level log for anything over 1 s with method, path, status, and duration_ms. This identifies the exact endpoint responsible without enabling firehose tracing across the board.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

fix(views): warm syntect at startup to stop tokio-worker starvation 11f0de144f

Root cause of the multi-minute page-load stall: syntect's bundled syntax set and theme set are large bincode-encoded blobs that take several seconds to deserialize. The render path triggered the load lazily through `OnceLock::get_or_init` inside the async render handler, so the first markdown render with a fenced code block blocked the calling tokio worker thread for the entire deserialize. Multiple concurrent renders converged on the same OnceLock, blocking additional worker threads on its internal lock; the runtime then had no free workers to advance any unrelated futures, including HTTP request handling, the WS hub, and the background writer. The whole service froze until the load finished, then resumed in a burst, which is the "stuck for minutes, suddenly loads" symptom the user reported.

Add `views::markdown::warm_syntect` that populates both OnceLocks, and call it from `main` on a `spawn_blocking` worker before binding the HTTP listener. The deserialization cost is paid once on a thread that's dedicated to blocking work, and the runtime workers are never starved.

Pool stats during the stall showed `auth_size=4 auth_idle=4`: pool exhaustion was not the cause, which is why the earlier WAL / busy_timeout / background-writer fixes did not change the symptom.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

diag(routes): watchdog log fires while a request is still in-flight 8c4cc85a7e

The previous slow-request middleware only logged after the handler returned, so a handler that hung indefinitely produced no log line at all. Replace with an in-flight watchdog: every request spawns a task that, after 5 s, checks whether the handler is still pending and emits a warn log with method and path if so. Operators can now identify which endpoint is responsible for "Waiting for nate-chat.a8n.run..." stalls without waiting for the response to come back.

The completion log is preserved, with a watchdog_fired flag so an in-flight log and a completion log can be correlated in dashboards.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

diag(auth): time session lookup and downstream handler separately cd83f1ce0d

Watchdog logs revealed GET /settings and GET /ws both stuck for 5+ s, with the SQLite pool sitting idle at 4/4 the whole time. Both routes share inject_user middleware, so the next datapoint we need is whether the slow phase is the get_user_by_session query (DB-side) or the downstream handler (something else entirely).

Split the timing in two: emit "inject_user: session lookup slow" when the SELECT join exceeds 2 s, and "inject_user: downstream handler slow" when the rest of the request chain exceeds 2 s. The next stall will print one or the other, which tells us where to look next.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

diag(auth): per-phase watchdogs in inject_user 24ed9944b5

The previous after-the-fact slow logs only fired once the await returned, so a phase stuck forever produced no output and we could not tell whether get_user_by_session or the downstream handler was the culprit. Replace with watchdog tasks: each phase spawns a sibling that sleeps 3 s and emits a warn log only if the phase has not yet flipped its "done" flag.

The next stall will produce one of two distinct log lines: "inject_user phase still running phase=session_lookup" (DB query is hung) or "inject_user phase still running phase=downstream_handler" (the actual handler is hung). That tells us exactly which half of the stack to dig into next.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

diag: log every entry to log_slow_requests and inject_user 0bba1d3d1b

Prior diagnostics produced an apparent contradiction: log_slow_requests' outer watchdog fires at 5 s for /settings and /ws, yet inject_user's 3 s phase watchdogs never fire. Either inject_user's body never executes for those requests, or the phase watchdog spawn isn't running. Adding unconditional debug logs at both fn entries lets the next stall prove which: every request that hits log_slow_requests prints one "entering next.run" line, and every request that reaches inject_user prints one "inject_user enter" line. A stall where the first appears but the second does not pins the hang between the two layers.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

diag(routes): distinguish stuck requests from cancelled requests 868d7dd50a

The previous watchdog logged "request still in-flight" but could not tell whether the handler was actually still running or whether the request future had been dropped (client disconnect / hyper abort). Without that distinction we cannot tell whether the 5 s warn lines for /settings and /ws indicate truly stuck handlers or merely abandoned requests that the browser gave up on while reusing a wedged H2 connection.

Add a DropGuard that fires a separate warn log when the request future is dropped before completing, and rename the watchdog flag from `done` to `completed` so the two paths are clearly distinct. The next stall will produce either "request still in-flight" (truly stuck) or "request future dropped" (client gave up), pinning the failure mode to the right side of the network.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

diag(auth): use tokio::select! for phase watchdogs (reliable fire on timeout) d6f5c00487

The previous spawn-based phase watchdog never produced log output during real stalls. The replacement uses an inline tokio::select! loop: each phase races the actual work against a sleep, and the warn log fires from inside the same task as the awaited future, so there is no possibility of an independent task being delayed or dropped. The loop repeats the sleep so a phase that stays stuck for 9 s produces three log lines, giving operators a clear "this is still hung" signal rather than a one-shot fire.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

diag(auth): tighten phase watchdog to 1s and log on completion 7b4fd8d2e8

Phase watchdog at 3s has not produced any output across multiple stalls, suggesting both phases complete in under 3s individually even when the parent request takes over 5s. To pin this down, drop the watchdog threshold to 1s and add INFO-level completion logs with elapsed_ms for both session_lookup and downstream_handler.

Three patterns can result. Phase warn logs with growing elapsed_ms confirm a hung phase. Completion logs with low elapsed_ms but a missing "request completed" log indicate the gap is downstream of inject_user (response write, hyper, or socket). No logs at all means inject_user is never reaching the body, which would force investigation into tower or axum extractor behavior.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

fix(views): render templates with block_in_place to free the tokio worker eee6a4bb58

Phase-watchdog diagnostics confirmed the multi-minute reload stalls were not pool exhaustion or upstream cancellation: every authed request that ran its handler emitted "phase done: session_lookup elapsed_ms=0" but no matching "phase done: downstream_handler" log, and the in-task tokio::select! sleep that should have logged "phase still running" never fired. The only explanation is that the parent task was wedged in synchronous CPU work between two await points, so the runtime never got to poll the sleep branch.

Source of the CPU work: Askama template renders call `body_html()` per message, which runs `markdown::render` and `highlight_code` (syntect) inline. A page with several code-laden messages can keep a worker thread occupied for seconds at a time. With multiple workers all pinned by concurrent renders, no worker is free to poll incoming requests; the request future for /ws or a reload of / sits in the runtime queue until a worker frees, which is what the user perceived as "stuck for minutes, then suddenly loads".

Wrap the synchronous `template.render()` call in `tokio::task::block_in_place` so the runtime can hand other tasks off to a sibling worker while the render runs. Detect the multi-thread runtime via `Handle::try_current()` so the call path is safe under `#[tokio::test]` (current-thread runtime), where `block_in_place` would panic.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

fix(views): cache markdown render to stop tokio worker pinning under broadcast load 928b73c2c3

Diagnostic logs after the block_in_place template fix showed /ws and other paths still stuck for >5s with no per-phase progress: the in-task tokio::select! sleep watchdog never fired during stalls, which only happens when the task is itself busy in synchronous CPU work. The block_in_place wrap in html() helped HTTP paths but did not cover the WS broadcast path, which calls .render() directly on per-event Askama fragments. Each WS subscriber re-runs markdown rendering of the same message body on its send task; a code-heavy message broadcast to N subscribers pins N worker threads for the duration of the render.

Cache markdown::render output keyed on a 64-bit hash of (body, mentions, custom_emojis). Re-renders for the same message across viewers become a HashMap lookup. Bounded at 4096 entries; on overflow we clear the whole map rather than implement per-entry LRU, which is fine for the access pattern (recent messages get re-rendered when scrolled into view, older ones rarely).

Also expose `render_template()` in views::mod that wraps `template.render()` in `block_in_place` so future WS render call sites can opt in without manually conditionally invoking the runtime helper, and rewrite `html()` to use it.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

fix(ws): wrap message renders with render_template so block_in_place applies 8f3d8b64c7

NewMessageFragment and EditedMessageFragment both invoke `body_html()`, which runs the syntect-heavy markdown render. Each WS subscriber re-runs that render on its own send task; under broadcast load the worker pool gets pinned. Cache from the previous commit collapses repeated renders, but the first-render path still does the CPU work inline. Switch the two body-heavy fragment renders in ws.rs to the new `render_template()` helper so the first render hands off via block_in_place too, leaving sibling worker threads free to poll incoming requests.

Other fragment renders (typing indicators, seen markers, sidebar counters) skip body_html and stay fast, so they keep the direct .render() call.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

fix(main): bump tokio worker pool to 32 to survive CPU bursts 775b8b7f82

block_in_place hands the running task's worker over to the runtime,
but it can only move *other* tasks onto sibling workers - if every
worker is already in block_in_place at the same instant, no sibling
exists and queued tasks wait. The default worker_threads value
(num_cpus, typically 4 in this container) is small enough that a
short burst of concurrent message-fragment renders can occupy every
worker simultaneously, leaving no thread to poll a fresh /ws upgrade
or HTTP reload.

Raise the pool to 32. The extra threads cost only stack pages while
idle and give the runtime real headroom under broadcast load.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

diag: per-step tracing in get_settings and ws_handler 8f14709023

Stalls persist with 32 worker threads, block_in_place in template render, and a markdown cache: phase watchdogs inside inject_user never fire, but the outer log_slow_requests watchdog (an independent tokio::spawn'd task) does. That pattern means the request task itself isn't being polled while it's stuck. Threads on /proc all show State: S (sleeping); the runtime is not CPU-pinned.

Add step-level tracing inside ws_handler (entry + return) and get_settings (load_chrome / email / sessions / html steps with elapsed_ms) so the next stall pinpoints which await stops emitting log lines. That will tell us whether the suspended await is inside a DB query, an extractor, the upgrade response path, or template rendering.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

diag(auth): trace every entry, branch, and exit in enforce_2fa 279ab19cda

The previous round of logs proved the stall sits between
inject_user's session_lookup phase and the request handler entry:
session_lookup done logs but get_settings/ws_handler entry never
does. That gap is enforce_2fa plus axum routing plus extractor
dispatch. Add debug logs at every branch in enforce_2fa so the next
stall pins whether the suspension is in the middleware body itself
(state check, exempt check, totp check), the downstream next.run,
or the routing layer.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

diag(auth): add outer watchdog and post-lookup tracing in inject_user d76ab51299

Stalled requests log "phase done: session_lookup" but never log
"enforce_2fa enter". That window contains inject_user's sync setup
code (extension inserts, bg.touch_session), the future construction
for next.run, and the first poll of that future. Add two debug logs
inside that window so the next stall pinpoints whether the suspension
is in the sync setup or in the future poll.

Also add an independent tokio::spawn'd watchdog at inject_user entry:
the existing in-task tokio::select! sleep watchdog only fires when the
task itself is polled; a stuck task never sees it. The new watchdog
runs as its own task and reports "task suspended" so we can tell
"phase ran fine but slow" from "task isn't being polled at all".

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

fix(auth): drop DashMap Ref before re-acquiring shard write lock 630f58545b

Root cause of every multi-minute reload stall:
`should_touch_last_seen` matched on `ledger.get(session_id)`, and in the
fall-through `_` arm called `ledger.insert(...)`. DashMap's `get` returns
a `Ref` holding a read lock on the shard; that scrutinee Ref stays alive
through the entire match block, so the subsequent `insert` (in the `_`
arm) requested a write lock on the same shard while a read lock was
still held by the same task. DashMap shard locks are not reentrant -
they deadlock.

The deadlock only fires when the request reaches the
`if let (Some(u), Some(t)) = (user, token)` arm in `inject_user`, which
is exactly the authed path. Unauthenticated routes like `/login` skipped
the block, which is why `/login` always succeeded while `/settings` and
`/ws` (both authed, both go through `should_touch_last_seen`) hung
forever.

Pin-pointed by adding step-by-step debug logs inside inject_user across
the boundary: "phase done: session_lookup" logged for stalls,
"post-lookup setup done" never did. That gap is the
`if let` block, and the only DashMap interaction inside it was
`should_touch_last_seen`.

Rewrite the function to extract the bool inside `.map()`, drop the Ref
before calling `insert`. The activity ledger version in routes/mod.rs
already had the insert outside the match block, so it was safe; only
this one was broken.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

chore: remove diagnostic instrumentation now that the deadlock is fixed

Check / clippy + fmt + tests (pull_request) Failing after 10s

Details

72be514266

Pulled out everything that existed only to track down the stall:
- inject_user phase watchdogs, outer task watchdog, and step-level
  debug logs
- enforce_2fa entry/branch/exit debug logs
- ws_handler entry/exit info logs
- get_settings step-level info logs
- log_slow_requests middleware (the dropguard + watchdog wrapper)
- 30 s pool-stats logger task in main

The pool tuning (`min_connections=4`, `acquire_timeout=3s`,
`test_before_acquire=false`, WAL + busy_timeout=5s), the background
writer for last_seen/last_active, the markdown render cache,
block_in_place in template render, and the 32-worker tokio runtime all
stay - those are real perf changes that survive past the diagnostic
phase.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>