Repository navigation
fix(metrics): stop the metrics drain from stalling requests - #386
Conversation
…e points The flush calls MetricsCollector::drain once a minute. Its first phase held the collector's write lock while it partitioned every buffered data point (about 120 s of them) into old and new vectors. Every request records its points through the same lock, so the server served almost nothing for the whole partition: about 0.2 to 0.5 s at 16000 to 38000 GetItem/s on a 16 vCPU host, 7 points per request. The drain now takes the lock twice and copies no buffered point under it. The first step swaps the map out. The split by cutoff runs on the swapped-out map without the lock. The second step swaps the younger points back and appends the points recorded meanwhile, moving only their chunks. The drain takes and keeps the same points as before, in the same order. A mutex serializes drains; record and prune never take it. While the split runs, an in-memory query does not see the buffered points; the server reads its metrics from the store. Each key's points are kept in chunks of at most 1024, with the oldest and newest timestamp of each chunk. The split moves whole chunks and splits only the chunks that straddle the cutoff. A record call can now reallocate at most one chunk under the lock, not the whole vector of its key. The prune uses the same split, so its pass under the lock is now over chunks, not points. The flush buckets are summed per key, so a drained point no longer clones its key. Tests check that the write lock is free and every point is still unsplit when the split starts, that drains are serialized, and that the second step moves only the chunks recorded in between, the same with 4000 and 400000 points per key. They also compare the drained, kept, pruned, and aggregated points with a plain partition by cutoff, with points recorded out of order. Assisted-by: pi claude-opus-5-5
The flush worker called MetricsCollector::drain inline on a tokio worker thread. The drain splits and aggregates every point it takes, 0.2 to 0.7 s of CPU at 10000 to 39000 GetItem/s, and that worker runs no other task meanwhile. Run the drain with spawn_blocking. A drain task that fails is logged and counted as a worker error for the cycle. Assisted-by: pi claude-opus-5-5
| keys.len() * per_key, | ||
| "split ran before the write lock was released" | ||
| ); | ||
| assert!(c.data.try_write().is_ok(), "lock held before the split"); |
There was a problem hiding this comment.
The lock probes (data.try_write().is_ok() and drain_lock.try_lock().is_err()) run inside the between hook, which drain_points calls after the first swap and before take_expired. That pins the property at that instant, but a future change that re-acquired the write lock around the split itself, or released drain_lock right after the hook, would still pass. If it's cheap, a second probe placed after the split (for instance by having the test record a point from another thread during take_expired and asserting it isn't blocked, or by checking the moved count against a drain started concurrently) would make the test guard the interval the PR is actually about rather than the moment before it.
There was a problem hiding this comment.
Good catch, you're right. I tried both of those (taking the write lock again around the split, and dropping drain_lock right after the hook) and the test still passed. I added a second hook right after take_expired that checks the write lock is still free and drain_lock is still held, and records a point there that has to land after the kept ones.
| /// step touches the points held, so `record_*` calls wait a bounded time | ||
| /// however many points are buffered. Between the two steps an in-memory | ||
| /// `query` does not see the buffered points; the server reads metrics | ||
| /// from its store. Concurrent drains run one at a time. The split and the |
There was a problem hiding this comment.
The doc comment says "Concurrent drains run one at a time", but _serial is dropped when drain_points returns, so aggregate in the public drain runs outside the mutex. The extraction and reattach are what need serializing and those are covered, so the behaviour is fine; the sentence might just read more precisely as "the swap, split and reattach of concurrent drains run one at a time".
There was a problem hiding this comment.
Agreed, aggregate runs after the mutex is dropped. Reworded.
The drain test checked the write lock and the drain mutex only before the split. A change that took the write lock again around the split, or released the drain mutex right after that check, still passed. A second check after the split now asserts that the write lock is still free and the drain mutex is still held, and records a point there that must land after the kept ones. Both changes now fail the test. The drain doc said concurrent drains run one at a time, but the aggregation runs after the mutex is released. It now says that the swap, split, and put-back are what run one at a time. Both from review by @robinnsc. Assisted-by: pi claude-opus-5-5
2 participants
What
Once a minute the metrics flush calls
MetricsCollector::drain. On main, the drain held the collector's write lock while it split about 120 s of buffered points by age. Every request records its metrics through that lock, so the server served almost nothing for the whole split.drain()incrates/core/src/metrics/collector_query.rsnow takes the write lock twice, each time only to swap a map. The split runs between the two steps, without the lock. A mutex serializes drains;recordandprunenever take it.crates/core/src/metrics/accumulator.rs). Arecordcall reallocates at most one chunk, and the second step moves only the chunks recorded during the split.crates/server/src/workers.rsruns the drain withspawn_blocking, so the split no longer holds a tokio worker.The metric names, dimensions, and values do not change. One thing does: while the split runs (under 1 ms), an in-memory
MetricsCollector::querydoes not see the buffered points. The server does not use that path; it reads/metricsand the console metrics from the catalog store. The latency segments kept in memory for 24 h are a separate issue, not changed here.Why
Found with a GetItem load test. The stall repeats about every 61 s and grows with the request rate: about 0.2 to 0.5 s per flush at 16,000 to 38,000 GetItem/s on a 16 vCPU host. In the runs below, from 18,900 GetItem/s on main, each flush filled the load generator's in-flight limit, and that set the knee.
Fixes: n/a, found by a load test, no issue filed
Result
cargo test --workspace: 1,231 passed.Locally, the longest wait for the metrics lock during a flush went from 158 to 382 ms to 0.6 ms or less at 10,000 and 20,000 GetItem/s.
Testing done
crates/core/src/metrics/drain_tests.rs(new, 9 tests, none timing-based): the write lock is free and every point is still unsplit when the split starts; drains are serialized; the second step moves only the chunks recorded in between, with 4,000 and 400,000 points per key; and the drained, kept, pruned, and aggregated points match a plain partition by cutoff, with points recorded out of order./metricsafter 400 PutItem, 200 GetItem, and two flushes: the same names, dimensions, counts, and sums on main and on this branch.tests/test_metrics.py,test_console_integration.py,test_console_cache_coherence.py,test_cache_coherence.py, andtest_cross_account_isolation.pyagainst a release build of this branch: 65 passed.Checklist
cargo test --workspace)cargo fmt --check)cargo clippy -- -W clippy::pedantic)Storagetrait, auth model, on-diskformat, or public CLI surface, an RFC has been accepted or is linked
below. Otherwise, an ADR captures the decision (link below).
ADR / RFC: n/a. Internal to the in-memory metrics collector; no wire, trait, auth, on-disk, or CLI change.
Breaking changes
None.
By submitting this pull request, I confirm that my contribution is made under
the terms of the Apache License 2.0 and I agree to the Developer Certificate of
Origin (DCO). See CONTRIBUTING.md for details.