Repository navigation
feat(drive-abci): debug-only per-block phase timing - #4573
Conversation
Times each phase of ProcessProposal and FinalizeBlock and reports the means every DRIVE_BLOCK_PERF_EVERY blocks (default 500). Off unless DRIVE_BLOCK_PERF=1, and accumulated in memory rather than logged per block, so the measurement does not pay for a log line inside the spans it measures. This is what located the two per-block costs that scale with chain history: an unbounded withdrawal-document query and GroveDB checkpoint creation during replay.
|
Warning Review limit reachedNext included review available in 10 minutes. View limit detailsLimit details: You’ve used the included review currently available. You've used all free OSS reviews for now. Wait for the free limit to reset to keep reviewing this public repository. Review configuration: ⚙️ Run configurationConfiguration used: Path: .coderabbit.yaml Review profile: CHILL Plan: Advanced Run ID: 📒 Files selected for processing (6)
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 |
|
⚡ Priority review — 9th in line, starts as soon as a slot frees (commit e39d1a5) |
Codecov Report❌ Patch coverage is Additional details and impacted files@@ Coverage Diff @@
## v4.2-dev #4573 +/- ##
============================================
+ Coverage 78.79% 82.23% +3.44%
============================================
Files 2845 2845
Lines 406819 402104 -4715
============================================
+ Hits 320549 330680 +10131
+ Misses 86270 71424 -14846
🚀 New features to boost your workflow:
|
thepastaclaw
left a comment
thepastaclaw
left a comment
There was a problem hiding this comment.
Final validation — GLM Flash + Sol
The opt-in timing instrumentation is consensus-inert and appropriately keeps logging outside measured spans, but several accounting details reduce the trustworthiness of its output: conditional phases report misleading sample counts, and protocol-change work remains unattributed. The aggregation lifecycle also lacks focused tests, and best-effort telemetry should not be able to panic block processing after mutex poisoning.
Source: reviewer 1: glm-5.3-flash (agent: phase1-reviewer, role: general); reviewer 2: glm-5.3-flash (agent: phase1-reviewer, role: security-auditor); reviewer 3: glm-5.3-flash (agent: phase1-reviewer, role: rust-quality); reviewer 4: gpt-5.6-sol (agent: phase2-reviewer, role: general); reviewer 5: gpt-5.6-sol (agent: phase2-reviewer, role: security-auditor); reviewer 6: gpt-5.6-sol (agent: phase2-reviewer, role: rust-quality); final verifier: gpt-5.6-sol (agent: sol-verifier, role: final-verifier)
Review provenance
- Phase 1 reviewers (GLM Flash):
glm-5.3-flash— general (completed); agentphase1-reviewer,glm-5.3-flash— security-auditor (completed); agentphase1-reviewer,glm-5.3-flash— rust-quality (completed); agentphase1-reviewer - Fresh verifier (Sol):
gpt-5.6-sol— final-verifier; agentsol-verifier - Phase 2 reviewers (Sol):
gpt-5.6-sol— general (completed); agentphase2-reviewer,gpt-5.6-sol— security-auditor (completed); agentphase2-reviewer,gpt-5.6-sol— rust-quality (completed); agentphase2-reviewer
🟡 4 suggestion(s)
1 additional finding(s) omitted (not in diff).
🤖 Prompt for all review comments with AI agents
These findings are from an automated code review. Verify each finding against the current code and only fix it if needed.
In `packages/rs-drive-abci/src/abci/handler/finalize_block.rs`:
- [SUGGESTION] packages/rs-drive-abci/src/abci/handler/finalize_block.rs:108-113: Conditional phases report one sample even when skipped
`fb_checkpoint` is sampled on every finalized block even though checkpoint creation only runs when `checkpoint_needed` is true. A window with one checkpoint and 499 ordinary blocks therefore reports `/500`, not `/1`, so the sample count cannot provide the advertised fire rate. The same issue affects `chainlock`, `wd_status`, and `fbp_wd_broadcast`, whose lap calls also sit outside their conditional branches. Add a timer operation that always advances the boundary but records a sample only when the corresponding work executed, and use it consistently for conditional phases.
In `packages/rs-drive-abci/src/execution/engine/run_block_proposal/mod.rs`:
- [SUGGESTION] packages/rs-drive-abci/src/execution/engine/run_block_proposal/mod.rs:86-149: Protocol-change migrations are omitted from the phase totals
After recording `state_clone`, this function resolves the block platform version and may execute `perform_events_on_first_block_of_protocol_change`, then enters the versioned implementation without another outer lap. `Laps::drop` only merges recorded entries and does not record the elapsed tail, while the inner `Laps` starts after the migration. Protocol-activation work can therefore be substantial yet entirely absent from a replay report. Record this segment after the protocol-change event, preferably only when the migration executes so its sample count also reflects the actual fire rate.
In `packages/rs-drive-abci/src/perf.rs`:
- [SUGGESTION] packages/rs-drive-abci/src/perf.rs:26-160: No unit tests cover the new aggregation and reporting logic
The module has no focused coverage for `Totals::add`, first-seen phase ordering, sum/sample accumulation, mean-over-block arithmetic, or clearing both phases and the block counter at an interval boundary. These calculations directly determine the performance measurements and can regress while still producing plausible output. The process-global `OnceLock` configuration makes environment-based tests order-dependent, but `Totals` can be tested directly and report formatting/reset can be extracted into a pure helper for deterministic unit tests.
- [SUGGESTION] packages/rs-drive-abci/src/perf.rs:96-127: Poisoned perf mutex can abort block processing
All three mutex acquisitions call `expect("block perf totals poisoned")`, including the acquisition in `Drop for Laps`. If the mutex is ever poisoned, this diagnostics-only feature will panic during block processing; if the drop occurs during unwinding, the second panic aborts the process. The `expect` message also does not document an invariant proving poisoning impossible. Since these counters are best-effort telemetry and the inner value remains usable, recover consistently with `PoisonError::into_inner` at every lock site.
PastaPastaPasta
left a comment
PastaPastaPasta
left a comment
There was a problem hiding this comment.
Review
Verdict: merge after changes. Inert unless the environment variable is set, so the risk is low; the changes are CI hygiene and two small correctness points in the instrument itself.
1. Correctness
The timing logic is right: Instant deltas accumulated in memory, merged into process totals on drop, reported as a mean over blocks. Two issues:
- Sample counts do not mean fire rate for conditional phases.
fb_checkpoint,chainlock,wd_statusandfbp_wd_broadcastcalllapoutside theirif, so they record a near-zero sample on every block. The description says the sample count "is how the fire rate of a phase becomes visible"; for these four it is not. Add alap_if(condition, name)that always advances the boundary and records only when the work ran. expecton a poisoned mutex insideDrop. If a block panics while the totals lock is held, the nextLapsdrop during unwinding panics again and aborts the process. This is telemetry; recover withunwrap_or_else(PoisonError::into_inner)at all three lock sites.
Also: fb_proposal wraps the whole of finalize_block_proposal, so it overlaps the fbp_* phases. That is fine as a nested total, but the module doc should say so, or a reader will add them up.
2. Clarity
The description explains the design choices well (accumulate instead of log per block, mean over blocks). The example output lists sps_serialize, which no lap in this PR produces; it came from a branch that also instrumented store_platform_state. Please make the example match the code.
3. Codebase standards
- CI is red on the title:
benchis not an allowed type in.github/workflows/pr.yml. This is instrumentation, sofeat(drive-abci): ...fits. Squash merges use the PR title, so the commit type follows. - The codebase configures operators through
PlatformConfig(envy), not rawstd::env::varinside modules. For a diagnostic switch that must stay zero-cost and zero-touch I think theOnceLockread is defensible, but it is a deviation and the module doc should say why. Laps::on()andperf::value()have no callers. Remove them; whoever needs them can add them back with a use.- No unit tests, which is why
codecov/patchfails.Totals::addand the report formatting are pure and easy to test once the formatting is pulled out ofend_block.
4. Importance and alternatives
This found #4569 and #4570, so it has paid for itself. The idiomatic alternative in this codebase is Prometheus histograms via crate::metrics, which would give per-phase distributions to any scraper. For a replay benchmark a single periodic log line is easier to read, and the two are not exclusive. I would merge this and consider histograms later.
5. Existing bot findings
All three thepastaclaw comments (conditional sample counts, poisoned mutex, tests) are valid and addressed above.
I will push: title to feat, lap_if, poison recovery, removal of dead API, tests, and a corrected example in the description.
🤖 Posted autonomously by Claude on behalf of pasta.
PastaPastaPasta
changed the title
fb_checkpoint, chainlock, wd_status and fbp_wd_broadcast recorded a near-zero sample on every block, so their sample counts said nothing about how often the work ran. A lap_if records a sample only when it did. Recover a poisoned totals lock instead of panicking in Drop, remove the unused on() and value(), pull the report formatting into Totals so it can be unit tested, and note the env-var switch and the nested fb_proposal lap in the module doc.
…rified The verification inside the chainlock block runs only for a lock this node did not propose itself, so the sample condition needs known_from_us as well. Also note the zero-interval behaviour of end_block and cover lap_if's skipped path.
|
Pushed 19f82f4 and 9826308 on top of the original commit, and retitled the PR to
Ready for human review. 🤖 Posted autonomously by Claude on behalf of pasta. |
PastaPastaPasta
added
the
ready for final review
PastaPastaPasta
changed the title
thepastaclaw
left a comment
thepastaclaw
left a comment
There was a problem hiding this comment.
Final validation — Phase 2 only (queue backlog)
Verified all three supplied findings against head 2e7fb4d and retained them as suggestions: two conditional phases overcount executions, and the skipped-lap test does not enforce boundary advancement. The instrumentation is consistently debug-gated, and no blocking issue was confirmed. Validation used source and diff inspection plus git diff --check; reviewer-reported test runs were not independently rerun.
Source: reviewer 1: gpt-6-astra (agent: phase2-reviewer, role: general); reviewer 2: gpt-6-astra (agent: phase2-reviewer, role: rust-quality); reviewer 3: gpt-6-astra (agent: phase2-reviewer, role: security-auditor); final verifier: gpt-6-astra (agent: astra-verifier, role: final-verifier)
Review provenance
- Triage:
criticalbygpt-6-astra(effort low) — Although compiled out of standard release builds, the instrumentation runs directly inside consensus-sensitive proposal execution and finalization paths, including signature verification, withdrawals, and storage commits, so timing, synchronization, or failure side effects warrant heightened review. - Phase 1 reviewers: not run (skipped for throughput: 36 PRs queued, above the 10 limit)
- Fresh verifier:
gpt-6-astra— final-verifier; agentastra-verifier - Phase 2 reviewers:
gpt-6-astra— general (completed, effort xhigh); agentphase2-reviewer,gpt-6-astra— rust-quality (completed, effort xhigh); agentphase2-reviewer,gpt-6-astra— security-auditor (completed, effort xhigh); agentphase2-reviewer
🟡 3 suggestion(s)
🤖 Prompt for all review comments with AI agents
These findings are from an automated code review. Verify each finding against the current code and only fix it if needed.
In `packages/rs-drive-abci/src/execution/engine/run_block_proposal/v0/mod.rs`:
- [SUGGESTION] packages/rs-drive-abci/src/execution/engine/run_block_proposal/v0/mod.rs:269-270: Exclude no-op core-info updates from the sample count
`update_core_info` dispatches to `update_core_info_v0`, which returns immediately when `block_platform_state.last_committed_core_height()` equals the proposed Core height and `is_init_chain` is false. This call passes false, but the unconditional lap records a sample even on those skipped updates. Consequently, a 500-block replay window with 331 Core-height advances reports `core_info=.../500` instead of the documented `/331`, obscuring the update's execution frequency. Capture the height-change condition before calling `update_core_info` and pass it to `lap_if`, so skipped updates advance the timing boundary without recording a sample.
In `packages/rs-drive-abci/src/execution/engine/finalize_block_proposal/v0/mod.rs`:
- [SUGGESTION] packages/rs-drive-abci/src/execution/engine/finalize_block_proposal/v0/mod.rs:204: Do not sample commit verification when testing disables it
With `testing-config` enabled, `PlatformTestConfig::default_minimal_verifications()` sets `block_commit_signature_verification` to false, so the verification branch above does not execute. This unconditional lap still records a sample for every finalized block, making the timing report indicate that commit-signature verification ran even when the simulation disabled it. Use the existing `verify_commit_signature` condition with `lap_if` to preserve the boundary without counting skipped verification.
In `packages/rs-drive-abci/src/perf.rs`:
- [SUGGESTION] packages/rs-drive-abci/src/perf.rs:232-235: Make the skipped-lap test reject an unchanged boundary
`before` is the old boundary, and `assert!(laps.last >= before)` permits that boundary to remain unchanged. If `lap_if` were changed to update `self.last` only when `ran` is true, both this assertion and the remaining buffer assertions would still pass, although the next recorded phase would incorrectly include the skipped interval. Set the old boundary deliberately in the past and compare against an instant captured immediately before the call, so the test rejects that regression without sleeps.
| { | ||
| let _timer = crate::metrics::abci_request_duration("finalize_block"); | ||
| #[cfg(debug_assertions)] | ||
| let mut laps = crate::perf::Laps::new(); |
There was a problem hiding this comment.
why you not using tracing spans? as a side effect it would make logging more descriptive.
There was a problem hiding this comment.
I considered spans and kept the stopwatch, for three reasons:
- Aggregation. A span gives you its own duration when it closes; turning that into a per-phase mean over 500 blocks needs a custom
Layerthat keys on span name and accumulates, which is the same amount of code asperf.rsbut harder to keep zero-cost. - Where the cost lands. The out-of-the-box way to get span timings is the fmt layer with
FmtSpan::CLOSE, which formats a log line per span per block inside the very region being measured. That is what the first version of this PR did with events and it visibly inflated the phases under investigation, which is why it moved to accumulated means. - Shape. These phases are consecutive marks between statements in one function, not nested scopes. Wrapping each of ~25 statements in
let _span = span!(...).entered(); ...; drop(_span)would make the block execution code much harder to read than one#[cfg(debug_assertions)]line after each call.
The descriptive-logging side effect is real but I think it is a separate change: adding tracing::instrument to the phase functions would benefit release logs, which this debug-only instrumentation deliberately stays out of. Happy to do that as a follow-up if you want it.
…-timing # Conflicts: # packages/rs-drive-abci/src/abci/handler/finalize_block.rs # packages/rs-drive-abci/src/execution/engine/run_block_proposal/mod.rs
Address review on the phase timing instrumentation: - `Laps` becomes `PhaseTimer`, constructed with a scope (the function it lives in); every phase is reported as `scope.phase`, so the `run_block_proposal`, `finalize_block_proposal` and `finalize_block` phases are prefixed consistently. - Phases are named after the call they time (`process_raw_state_transitions`, `update_core_info`, ...) instead of abbreviations like `val_app_ver` or `wd_status`. - Phases that timed nothing but struct construction or plain comparisons (`fb_commit_check`, `fbp_basic_checks`, `fbp_block_info`, `fbp_ext_block_info`, `fbp_should_checkpoint`, `exec_ctx`) are dropped. - `upgrade_protocol_version_on_epoch_change`, `update_core_info` and `verify_commit_signature` record a sample only on the blocks the work ran, like the other conditional phases. - The post-commit work the base branch added since the PR forked gets its own phases: `promote_data_contract_cache` and `flush_pending_prefix_drops`. - The skipped-phase test now rejects a boundary that does not move. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
|
Merged
The tracing-spans thread is left open with my reasoning; the rest are resolved. PR description updated to match.
🤖 Generated with Claude Code |
Issue being fixed or feature implemented
There was no way to see where a block's time goes inside drive-abci.
ProcessProposallogged oneelapsed_time_ms— truncated to whole milliseconds — andFinalizeBlocklogged nothing at all, so more than half the per-block cost was unattributed.That gap hid two costs that scale with chain history and together accounted for most of a mainnet sync:
Neither is visible without per-phase numbers. Both were found with this.
What was done?
In debug builds, a
PhaseTimertimes the successive phases of one function during block execution and merges them into process-wide totals on drop. Each timer has a scope (the function it lives in) and each phase is named after the call it times, so a report term likerun_block_proposal.process_raw_state_transitionsgreps straight to the code.perf::end_blockreports the means everyDRIVE_BLOCK_PERF_EVERYblocks (default 500) as a single log line.Two design points worth noting:
perfmodule and every timing call site are guarded by#[cfg(debug_assertions)]. Release builds contain no phase timers, environment reads, totals mutex, or report logging from this feature, even whenDRIVE_BLOCK_PERF=1is set. In builds with debug assertions enabled, that environment switch still defaults to off and is read once throughOnceLock<bool>; when off,Laps::newallocates nothing and everylapreturns immediately.The mean is over blocks rather than over samples, so a phase that only runs on some blocks shows its share of the per-block cost rather than its cost when it fires. Sample counts are reported alongside, which is how the fire rate of a phase becomes visible. Phases whose work is conditional (
upgrade_protocol_version_on_epoch_change,verify_chain_lock,update_core_info,update_broadcasted_withdrawal_statuses,verify_commit_signature,append_signatures_and_broadcast_withdrawal_transactions,create_grovedb_checkpoint) record a sample only on the blocks the work ran, usingend_phase_if. Only real work is timed: struct construction, field assignments and plain comparisons between two calls are not given a phase of their own.finalize_block.finalize_block_proposalin the finalize handler wraps the whole offinalize_block_proposal, so it is the sum of thefinalize_block_proposal.*phases; add up phases from one level only.Phases covered: the block-proposal path (epoch info, drive cache preparation, platform state clone, protocol upgrade, chain lock, core info, proposed app version, withdrawals, DAO events, state transitions, address balances, shielded anchors, fees, credit history, root hash, validator set) and the finalize path (block id hash, vote extensions, commit signature, withdrawal broadcast, drive cache, state cache, commit, data-contract cache promotion, prefix-drop flush, checkpoint).
Example output:
Each term is
scope.phase=mean_µs_per_block/blocks_it_ran_on.update_core_info,verify_chain_lockandupdate_broadcasted_withdrawal_statusesonly run on blocks that advance the core height, which is why their sample counts are below 500; phases that run on every block show/500.How Has This Been Tested?
Used throughout a full mainnet replay, genesis to 424,981, and for every A/B measurement behind #4569, #4570, #4571 and #4572.
cargo test -p drive-abci --lib— 2,770 passed. Unit tests inperf.rscover the accumulation (first-seen order, scopes kept apart), mean-over-blocks, interval reset, the skipped-phase boundary and the empty report.Release-exclusion validation:
cargo build -p drive-abci --release --lockedpassed.cargo test -p drive-abci --lib --locked -- perf::passed: 5 tests.DRIVE_BLOCK_PERFstrings, phase/report markers, ordrive_abci::perfsymbols; the debug test executable retains the instrumentation as a positive control.drive_abci::perf::Lapsagainst the release library fails because the module is configured out.cargo clippy -p drive-abci --lib --locked -- -D warnings, formatting, andgit diff --checkpassed.Breaking Changes
None for standard release builds: all phase-timing instrumentation is excluded at compile time. Debug builds require
DRIVE_BLOCK_PERF=1to enable it.Checklist:
For repository code-owners and collaborators only
🤖 Generated with Claude Code