perf(stats): stop dating every wire frame for a field nothing reads - #1103
Conversation
`SessionStats::record_frame_sent` read the wall clock on every frame written, which is the client's hottest path and, on wasm32 or embedded targets, a call out of the module. Only one of the two fields it fed needed an instant: the dead-socket anchor, which arms once per receive-to-send transition. The other, `last_data_sent_ms`, had no reader anywhere in the core, because the watchdog deliberately anchors on the first unanswered send and never on the most recent one. Drop the field and read the clock only when the anchor actually arms. A send that continues an already-armed burst now asks for no time at all. The receive-side stamp stays exact: two decisions measure elapsed time from it, the 15 s idle-ping gate and the 20 s dead-socket check, and the only refresh trigger the core could sample it against is the keepalive tick, which is coarser than the gate it would feed. The cache reads move for the same reason: `PortableCache::get` and `remove` sampled the monotonic clock before the lookup, so every miss paid for a timestamp there was nothing to compare it against. BREAKING: `StatsSnapshot::last_data_sent_ms` and `SessionStats::last_data_sent_ms()` are gone. `frames_sent` answers "is it still sending?" and `first_send_since_recv_ms()` dates the send the watchdog cares about; an embedder that needs "when did I last write?" should stamp it at its own send call site.
|
You have reached your Codex usage limits for code reviews. You can see your limits in the Codex usage dashboard. |
|
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Repository UI (base), Organization UI (inherited) Review profile: ASSERTIVE Plan: Pro Plus Run ID: 📒 Files selected for processing (2)
📝 WalkthroughSummary by CodeRabbit
WalkthroughSession statistics now use a conditional first-send watchdog anchor instead of per-frame last-send timestamps. Clock instrumentation, deterministic keepalive timing, cache fast paths, and send-path tests validate the revised behavior. ChangesClock-aware activity metering
Estimated code review effort: 3 (Moderate) | ~25 minutes Sequence Diagram(s)sequenceDiagram
participant KeepaliveLoop
participant SessionStats
participant KeepaliveProtocol
KeepaliveLoop->>SessionStats: Read activity timestamps
KeepaliveLoop->>KeepaliveProtocol: Evaluate is_dead_socket_at with captured now
KeepaliveProtocol-->>KeepaliveLoop: Return dead-socket status
KeepaliveLoop->>KeepaliveProtocol: Compute warning duration with ms_since_at
Possibly related PRs
Suggested labels: Suggested reviewers: 🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
📦 Binary size report
.text per crate
Top movers (cargo-bloat attribution)
Baseline: |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 4
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@src/send/mod.rs`:
- Line 5604: Update the OWN_PN constant to use the repository’s fictional NANP
format, specifically a number in the required 555-01xx layout such as
12025550101.
In `@wacore/src/protocol/keepalive.rs`:
- Around line 26-30: Complete the helper documentation near ms_since by adding
the missing verb so the sentence clearly states what the dead-socket keepalive
tick evaluates against a caller-supplied now. Preserve the existing explanation
that ms_since and is_dead_socket_at use the same instant and that tests can
provide it directly.
In `@wacore/src/stats.rs`:
- Around line 121-125: Update the anchor arming logic in the surrounding stats
method to use a single atomic compare-and-update operation, so concurrent first
sends preserve the earliest successful timestamp instead of overwriting it;
retain the existing anchor == 0 or anchor <= last_recv stale-anchor recovery
behavior, and add a concurrent regression test covering competing first sends.
- Around line 12-16: The receive clock-read documentation is inaccurate for
multi-frame batches. Update wacore/src/stats.rs lines 12-16 to state that
single-frame receives use one wall-clock read, while multi-frame batches use
two—at arrival and completion; update agent_docs/observability.md lines 35-41 to
express the same observability contract. No code behavior changes are required.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Repository UI (base), Organization UI (inherited)
Review profile: ASSERTIVE
Plan: Pro Plus
Run ID: 6ab098c9-0596-4b49-8432-f4b36340c79c
📒 Files selected for processing (10)
agent_docs/observability.mdsrc/client/tests.rssrc/keepalive.rssrc/portable_cache.rssrc/send/mod.rssrc/socket/noise_socket.rssrc/test_utils.rswacore/src/protocol/keepalive.rswacore/src/stats.rswacore/src/time.rs
| use std::sync::Arc; | ||
| use wacore::time::clock_reads; | ||
|
|
||
| const OWN_PN: &str = "15551234001"; |
There was a problem hiding this comment.
📐 Maintainability & Code Quality | 🟡 Minor | ⚡ Quick win
Use the repository’s fictional NANP format.
15551234001 uses 555 as its NPA and does not use the required 555-01xx fictional layout. Use a value such as 12025550101.
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@src/send/mod.rs` at line 5604, Update the OWN_PN constant to use the
repository’s fictional NANP format, specifically a number in the required
555-01xx layout such as 12025550101.
Source: Learnings
…anchor The load-check-store let two senders that both observe an unarmed anchor overwrite each other, so the later timestamp won and pushed the dead-socket deadline out. Re-check under a CAS: the plain load still gates the clock read, so a send under an armed anchor stays free, and the arm itself now preserves the first one. Also state the multi-frame receive cost, which re-stamps on batch completion and therefore spends a second read.
|
Took three of the four:
Skipped the phone number: On the CAS, worth noting for whoever reads this later: |
There was a problem hiding this comment.
Actionable comments posted: 1
Caution
Some comments are outside the diff and can’t be posted inline due to platform limitations.
⚠️ Outside diff range comments (1)
wacore/src/stats.rs (1)
856-856: 🎯 Functional Correctness | 🟡 Minor | ⚡ Quick winMake the reset test prove that receive activity was recorded.
record_recv_batch(20, 1)does not stamplast_data_received_ms; that happens inmark_recv_activity(). Without seeding receive activity, the post-reset zero assertion passes even if reset stops clearing that field.Add
mark_recv_activity()before the send/reset sequence and assert the timestamp is non-zero before teardown.🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@wacore/src/stats.rs` at line 856, Update the reset test around first_send_since_recv_ms to call mark_recv_activity() before the send/reset sequence, then assert the recorded receive timestamp is non-zero before teardown so the reset assertion verifies that reset clears it.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@agent_docs/observability.md`:
- Around line 35-40: Update the documentation around record_frame_sent and
first_send_since_recv_ms to clarify that the timestamp is loaded on every frame,
while now_ms() is called only when a send arms or re-arms the anchor. Preserve
the existing explanation that there is no last-send timestamp.
---
Outside diff comments:
In `@wacore/src/stats.rs`:
- Line 856: Update the reset test around first_send_since_recv_ms to call
mark_recv_activity() before the send/reset sequence, then assert the recorded
receive timestamp is non-zero before teardown so the reset assertion verifies
that reset clears it.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Repository UI (base), Organization UI (inherited)
Review profile: ASSERTIVE
Plan: Pro Plus
Run ID: 01e91483-f0c4-4646-996c-32693921ebcd
📒 Files selected for processing (3)
agent_docs/observability.mdwacore/src/protocol/keepalive.rswacore/src/stats.rs
|
| Filename | Overview |
|---|---|
| wacore/src/stats.rs | Removes last_data_sent_ms field and replaces unconditional store with a CAS-gated clock read in record_frame_sent. Logic is sound: the outer load short-circuits the clock read on already-armed anchors, and the CAS preserves onOrBefore semantics. Breaking API change (StatsSnapshot::last_data_sent_ms removed) is well-justified by absence of internal readers. |
| wacore/src/time.rs | Adds clock_reads module under #[cfg(feature = "test-util")]: per-thread saturating counters for wall and monotonic reads, bumped inside now_millis() and now_nanos() respectively. Design correctly avoids the OnceLock provider-installation race by counting at the abstraction boundary rather than inside a replaceable provider. |
| wacore/src/protocol/keepalive.rs | Adds is_dead_socket_at, ms_since_at, and now_ms() taking an explicit instant, delegated to by the original functions. The keepalive tick now reads the clock once and passes it to both predicates. New boundary tests pin exact detection semantics. |
| src/portable_cache.rs | Moves entry_time() calls after the key lookup in get (both no-TTI and TTI paths) and remove, so misses pay zero monotonic reads. The same now snapshot is reused for the write-lock double-check on expiry, which is safe: a freshly re-inserted entry has inserted_at > stale_now, so is_expired returns false and the entry is not wrongly evicted. |
| src/keepalive.rs | Dead-socket branch now captures one now_ms() and passes it to both is_dead_socket_at and ms_since_at, eliminating the second clock read the old is_dead_socket / ms_since pair each made independently. |
| src/client/tests.rs | Adds wire_bookkeeping_reads_the_clock_only_where_a_value_is_used (pins CAS arming read counts) and received_stanza_handling_reads_no_clock (pins zero reads for receipt handling). Both use clock_reads::since to assert exact budgets. |
| src/send/mod.rs | Adds dm_send_stays_within_its_clock_budget (asserts wall <= 4, monotonic <= 2 per steady-state DM send) and wire_timestamp_keeps_real_time (verifies the privacy-token IQ still carries a real second despite clock-read reduction). Budget expressed as upper bounds to catch regressions without being brittle to minor changes. |
| src/test_utils.rs | create_iq_test_client now wires NoiseSocket to the client's stats via with_stats, so per-frame bookkeeping is observed by budget tests that go through this helper. |
| agent_docs/observability.md | Updates the cost-model description to reflect the removed last_data_sent_ms field, explain the new first_send_since_recv_ms anchor semantics, and document the deliberate absence of a per-frame send timestamp. |
| src/socket/noise_socket.rs | Test updated from snap.last_data_sent_ms to stats.first_send_since_recv_ms() following the removal of the sent timestamp from StatsSnapshot. |
Flowchart
%%{init: {'theme': 'neutral'}}%%
flowchart TD
A[record_frame_sent] --> B[fetch_add bytes and frames]
B --> C[load last_recv and anchor]
C --> D{anchor == 0 OR anchor <= last_recv}
D -- No: anchor is live --> E[Return, zero clock reads]
D -- Yes: unarmed or stale --> F["now = now_ms() - one wall read"]
F --> G["CAS: current == 0 OR current <= last_recv"]
G -- CAS won --> H[first_send_since_recv_ms = now]
G -- CAS lost --> I[Earlier anchor preserved, now discarded]
subgraph keepalive_tick["Keepalive tick - dead socket branch"]
K[Read first_send and last_recv from stats]
K --> L["now = now_ms() - one wall read"]
L --> M[is_dead_socket_at first_send, last_recv, now]
M -- dead --> N[reconnect_immediately]
M -- alive --> O["ms_since_at first_send, now - log elapsed, no extra read"]
end
Reviews (3): Last reviewed commit: "docs(stats): say what the anchor CAS act..." | Re-trigger Greptile
![greptile-apps[bot]](https://avatars.githubusercontent.com/in/867647?s=60&v=4){kind=small}
The comment claimed racing senders keep the earlier deadline. That only holds once an anchor is set; two senders that both observe it unarmed resolve by whichever CAS lands first, which may be the one carrying the later instant. State the real guarantee, and note that the serial sender task makes the case unreachable anyway. Also correct the observability doc: every frame loads the anchor, only the send that arms it spends a clock read.
|
Both fair, and the CAS one is a real correction on my part. Greptile is right that the comment overstated it: the CAS guarantees that once an anchor is set a later send cannot overwrite it, but two senders that both observe it unarmed resolve by whichever CAS lands first, which may well be the one holding the later instant. My commit message from the previous push said "keep the earlier deadline", which is wrong for the same reason. Comment now states the actual guarantee and notes the serial sender task makes the case unreachable in the first place. Also reworded the observability doc: the anchor is loaded on every frame, only the arming send spends the clock read. |
1 participant
Summary
A consumer reported the core asking for the time 16 times per direct message in a ping-pong benchmark, which on a platform without a cheap clock is a boundary crossing per read. This batch started as an audit of that attribution and ends with one real cut plus a decision to leave the rest exact. The cut:
SessionStats::record_frame_sentread the wall clock on every frame written, and only one of the two fields it fed actually needed an instant.Audit
I could not run the reporter's embedder, so I instrumented the core instead.
wacore::timenow counts every read that leaves the module, behind the existingtest-utilfeature. Counting at the boundary rather than inside a provider sidesteps theOnceLock: the process's firstnow_millis()fillsTIME_PROVIDERwith the default, so a suite sharing one process cannot install an instrumented provider per test. The counters are per thread, so a measurement stays exact while the rest of the suite runs in parallel.Measured on a warm client (registry, LID mapping and Signal sessions seeded) sending one direct message, counting the core's own thread:
Per-frame and per-event bookkeeping, measured directly on
SessionStats:How much this is worth depends on the traffic shape, and it is worth saying plainly. The anchor is cancelled by every receive, so in a strictly alternating request/response pattern the first send after each receive re-arms and still pays: only the extra frames of the same burst come out free, and the saving is small by construction. It scales with how many frames a send burst writes before the next receive, so offline sync, group fanout and bulk sends are where it actually pays.
Two corrections to the original attribution:
last_data_received_mshas two internal readers, not one. Besidesis_dead_socket, the keepalive loop reads it atsrc/keepalive.rs:165to decide whether to skip the ping. Both measure elapsed time, so the field cannot be sampled: the only refresh trigger the core has is the keepalive tick itself, which is 15-30 s apart and coarser than the 15 s gate it would feed. Deriving the watchdog from counters observed at tick boundaries was the other option, and it pushes worst-case detection from ~50 s to ~80 s. Rejected, and the reasoning now lives next to the field.last_data_sent_mshad zero internal readers. Nothing in the core ever called the getter. That is the read this PR removes.The cache finding held up, with a caveat:
PortableCache::getdid sample the monotonic clock before the lookup, so a miss paid for a timestamp nothing compared. But in the steady state that dominates a ping-pong the registry lookups are hits, so moving the read after the lookup measures the same 2 reads per send here. It is still the correct shape and it is now pinned by a test.Changes
SessionStatsreads the clock only when the dead-socket anchor arms, not per frame. Sends that continue an already-armed burst cost nothing.StatsSnapshot::last_data_sent_msandSessionStats::last_data_sent_ms()removed. Migration:frames_sentanswers "is it still sending?",first_send_since_recv_ms()dates the send the watchdog anchors on. An embedder that needs "when did I last write?" should stamp it at its own send call site rather than make the wire path pay for it.PortableCache::get/removeread the monotonic clock after the lookup, so a miss is free.is_dead_socket_at/ms_since_attake the instant explicitly. The keepalive tick's dead-socket branch now evaluates both against one read, and the watchdog boundary becomes testable without depending on how long a test took to run.wacore::time::clock_reads(test-util only) counts reads per thread.create_iq_test_clientwires the noise socket to the client's stats like the real one does, so per-frame bookkeeping is part of what tests observe.Guarantees
Written as tests, not prose:
wire_bookkeeping_reads_the_clock_only_where_a_value_is_usedpins 0 reads for sends under an armed anchor, 1 for the arming send, 1 per received event, 2 for a multi-frame batch.dm_send_stays_within_its_clock_budgetasserts the per-send budget and fails if it grows.received_stanza_handling_reads_no_clockpins that handling a stanza asks for no time.dead_socket_boundary_is_exactandcontinued_sends_do_not_hide_a_silent_socketprove detection against a supplied instant, including the exact deadline. The existingdead_socket_anchor_holds_across_continued_sendsandstale_pre_receive_anchor_self_heals_on_next_sendpass unchanged.expiry_boundary_is_exact_under_a_controlled_clockcovers the entry that expires exactly at the TTL and TTI deadlines;a_miss_does_not_read_the_clockpins the lazy read.wire_timestamp_keeps_real_timeproves a timestamp that reaches the server still carries the real second.No embedder has to register a new provider, change a provider signature, or keep time state of its own.
Validation
Full matrix left to CI.