fix(blockchain): sample tick interval in handle_tick so skipped ticks don't inflate it#514
Conversation
… don't inflate it Alternative to #513. lean_tick_interval_duration_seconds measures wall-clock time between consecutive recorded ticks. It was recorded inside on_tick after the idempotency guard, so a guard-skipped tick recorded no sample and did not advance last_tick_instant. On a proposer slot the block is built during interval 4 of the previous slot, which advances the store clock to the next slot's interval 0, so the real interval-0 tick is skipped -- and the following interval-1 tick then measured across two intervals, a false ~1.6s spike even though ticks were firing on their 800ms cadence. Move the sample to handle_tick, the scheduler-level handler that runs for every tick (including guard-skipped ones), so a skipped interval no longer inflates the next sample. Unlike the proposer-path fix in #513 this needs no special-casing and also covers any other skip. Tradeoff: wall-clock-drift duplicate ticks (which the guard also swallows) are now sampled too, adding occasional sub-interval samples; acceptable for a metric meant to surface late ticks.
🤖 Kimi Code ReviewThe change correctly fixes a metrics blind spot where skipped ticks (due to the idempotency guard in Consensus & Safety: This is purely instrumentation code with no impact on consensus logic, state transitions, or cryptography. The Correctness: The logic is sound. By moving the observation to Minor observations:
Verdict: Good fix. No changes required. Automated review by Kimi (Moonshot AI) · kimi-k2.5 · custom prompt |
🤖 Codex Code ReviewNo findings. The change in crates/blockchain/src/lib.rs is observability-only: it moves Residual risk: there does not appear to be targeted test coverage for the skipped-tick metric path around the idempotency guard in crates/blockchain/src/lib.rs, so if this metric is operationally important, a focused regression test would be worthwhile. I could not run Automated review by OpenAI Codex · gpt-5.4 · custom prompt |
Greptile SummaryThis PR moves tick interval sampling to the scheduler-level tick handler.
Confidence Score: 5/5This looks safe to merge.
|
| Filename | Overview |
|---|---|
| crates/blockchain/src/lib.rs | Moves tick interval metric observation from guarded duty processing into the outer tick handler. |
Reviews (1): Last reviewed commit: "fix(blockchain): sample tick interval in..." | Re-trigger Greptile
🤖 Claude Code ReviewReview — PR 514Small, well-scoped fix that moves the Correctness
Documentation
Minor / non-blocking observations
Overall: correct, minimal, well-reasoned fix with no consensus-logic or state-transition impact (metrics-only). No blocking issues found. Automated review by Claude (Anthropic) · sonnet · custom prompt |
## Problem `lean_fork_choice_block_processing_time_seconds` is sampled by a `TimingGuard` created at the top of `on_block_core`, **before** the idempotent duplicate-block check returns early. A duplicate block does no processing, so it recorded a near-zero sample that skews the histogram low. Duplicates are common during range sync, so the effect is not negligible. This is the same class of issue as the recently fixed tick-interval metric (#514): the sample boundary didn't line up with the unit of work — there it inflated the tail, here it deflates the percentiles. ## Change - Add `TimingGuard::discard()` to cancel a measurement before the guard drops (a `disarmed` flag checked in `Drop`). - Call it on the duplicate-block early return in `on_block_core`. The block hashing (`hash_tree_root`) stays inside the timed span since it is real work; only the sample for a no-op duplicate is dropped. All other early returns (validation rejections) still record, as they represent real processing time. ## Verification `make fmt`, `make lint` (clean), full workspace build. Two new unit tests in `timing.rs` cover the guard: `records_a_sample_on_drop` and `discard_suppresses_the_sample` (both pass). `cargo test -p ethlambda-blockchain` 46 unit tests pass. Fork-choice/signature spec tests require downloaded fixtures (absent in this env).
Alternative to #513 (same bug, different approach).
Problem
lean_tick_interval_duration_secondsreported a spurious ~1.6s tail on every proposer slot. It measures wall-clock time between consecutive recorded ticks, recorded insideon_tickafter the idempotency guard. A guard-skipped tick records no sample and doesn't advancelast_tick_instant. On a proposer slot the block is built during interval 4 of the previous slot, which advances the store clock to the next slot's interval 0, so the real interval-0 tick is skipped — and the following interval-1 tick then measured across two intervals (~1.6s) even though ticks were firing on their 800ms cadence.Approach
Move the sample to
handle_tick, the scheduler-level handler that runs for every tick (including guard-skipped ones). One sample per tick regardless of whetheron_tickdrops the duty, so a skipped interval no longer inflates the next sample.Versus #513 (which records from the proposer path after the publish-alignment sleep): this needs no proposer special-casing and covers any skip uniformly. It matches how Zeam records the same metric (at the clock layer, decoupled from duty execution).
Tradeoff: wall-clock-drift duplicate ticks (which the guard also swallows) are now sampled too, adding occasional sub-interval samples. Harmless for a metric meant to surface late ticks; noted in the comment.
Verification
Confirmed on a single-node local devnet (0 gossip imports isolate the proposer path). Behavior is equivalent to #513: the skipped interval-0 tick is now sampled (sample count rises to ~5/slot), no pinned ~1.6s artifact remains, and the large samples track the real (variable) block-build duration rather than a fixed two-interval value. Total recorded time is unchanged (
_summatches #513's run).