Attribute event-loop stalls to the work that blocked them - #1437
Conversation
|
🚨 SLOP COP 🚨 · I am SlopCop, and I am reviewing this pull request now. I will check security, code quality, performance, architecture, and practical behavior. |
| ), | ||
| resolutionMs: DEFAULT_EVENT_LOOP_STALL_MONITOR_RESOLUTION_MS, | ||
| thresholdMs: DEFAULT_EVENT_LOOP_STALL_LOG_THRESHOLD_MS, | ||
| ...getEventLoopWorkSnapshot(), |
There was a problem hiding this comment.
🚨 slopcop/review — High: keep the blocking work linked to the maximum delay
histogram.max covers the full five-second window, but this snapshot reads only the later work state. A worker reproduced a 650 ms block followed by a short heartbeat. The report named the heartbeat and showed lastWorkMs: 0. Record time-stamped candidates for the sample window, or log slow synchronous work directly. Please test a real block with later work before the report.
There was a problem hiding this comment.
Fixed on 3bf1a86. The stall tick now snapshots slowestWork from every unit in the histogram window before it resets that window. A later heartbeat still shows as lastWork; the long block remains slowestWork. Added a test that records a 650 ms sweep then a 1 ms heartbeat.
| } | ||
|
|
||
| function leaveEventLoopWork(): void { | ||
| const frame = workStack.pop(); |
There was a problem hiding this comment.
🚨 slopcop/review — High: remove the correct frame when concurrent work ends
runEventLoopWork() remains active across await, but this pop always removes the newest global frame. Request A can finish before request B and remove B's frame. A direct probe then reported B as complete and A as active. Track each frame by identity, and store parent links for each asynchronous task. Please add a test where sibling tasks finish out of order.
There was a problem hiding this comment.
Fixed on 3bf1a86. Frames are now keyed by id and stored in AsyncLocalStorage, so one request cannot pop another request's frame. Added a test where sibling requests finish out of order.
SawyerHood
left a comment
SawyerHood
left a comment
There was a problem hiding this comment.
🚨 SLOP COP 🚨 · review
ELI5: This change gives each server job a name tag. When the server freezes, the log should show the responsible job. Two timing errors can show the wrong job instead.
I found two high-confidence correctness problems. I added inline comments for both.
- The global stack breaks during normal request overlap. One request can remove another request's frame and reverse their labels.
- The five-second maximum delay does not remain linked to its cause. Later quick work can replace the recorded label.
I found no medium-or-higher security issue. SQL logs omit bound values, limit SQL text, and use structured fields.
The architecture scan found related gaps. Manual labels omit plugin background services and startup recovery. The host daemon has a similar monitor, but server and daemon policy should stay separate. An identity-based frame registry and time-stamped samples would reduce incorrect labels and manual gaps. Some test variables still use old debug-log names, but that issue has no runtime effect.
Validation passed:
- All
@bb/serverand@bb/dbtests passed. The server suite ran 1,461 tests. - Both package type checks passed.
- The app loaded in a browser without page errors. The projects API returned HTTP 200.
- A direct concurrency probe reproduced reversed labels.
- A real-stall probe reproduced the unrelated heartbeat label.
- All required GitHub checks passed.
The checks do not cover the two core timing failures. I recommend fixing both inline findings before the team relies on these logs.
Promote slow-query logs to info so packaged servers record them, and label stall reports with the in-flight route, sweep, or plugin handler so later pragma and query changes can be measured.
Concurrent requests kept a shared LIFO stack, so one finish could pop another request's frame. Keep frames by id in AsyncLocalStorage and report the slowest unit in the histogram window so a later heartbeat cannot hide the block.
86a3efc to
3bf1a86
Compare
## Why `better-sqlite3` is synchronous and every query runs on the server event loop. The live database is ~1.9 GB with a 2 MiB page cache, no mmap, and `synchronous = FULL` (fsync on every commit). Cold page reads and per-commit fsync are the main source of sub-second stalls, not a missing index. This is layer 2 of the event-loop stall stack. It depends on layer 1 (#1437) so the new pragmas can be confirmed from stall and slow-query logs. ## What `createConnection` now sets: | pragma | value | reason | | --- | --- | --- | | `cache_size` | `-262144` (256 MiB) | replace the 2 MiB default in front of a multi-GB file | | `synchronous` | `NORMAL` | WAL-standard; no fsync per commit. Power loss can drop the last transactions; it cannot corrupt the file | | `mmap_size` | `1073741824` (1 GiB) | avoid a `pread` + copy on every page | | `busy_timeout` | `5000` | wait for a lock instead of failing immediately | | `temp_store` | `MEMORY` | keep temp sorts off disk | `wal_autocheckpoint` is left unchanged. A 38 MB WAL is a reader-starvation problem, not an autocheckpoint setting problem. ## Test plan - [x] File-backed pragma test asserts the live values - [x] `@bb/db` typecheck + full test suite - [x] Server database-maintenance sweep tests (busy_timeout save/restore) Prerequisite: #1437. > AGENT GENERATED: by Grok 4.6
1 participant
Why
The packaged server logs at
info. Slow-query instrumentation useddebug, so 82,590 production log lines covering 2,609 event-loop stall windows had zero slow-query lines. The stall report also named no unit of work, so a stall could not be attributed to a route, sweep, or plugin handler.This is layer 1 of the event-loop stall stack. Later layers (pragmas, timeline, outline cache) need these lines so their effect can be measured rather than argued.
What
Slow DB queryatinfo(threshold stays 100 ms).currentWork,lastWork, andlastWorkMson eachEvent loop stalledline./api/v1and/internalrequests, periodic sweeps, daemon websocket messages, timeline/outline builds, and plugin handler invocations.currentWorkis sampled after the stall: the interval cannot run while the loop is blocked, so the in-flight label is the unit still on the stack.lastWorkis the unit that just finished.Test plan
@bb/dbtypecheck + tests@bb/serverstall-monitor, periodic-sweep, timeline, and daemon-message testsPrerequisite: none (targets
main).