feat(drive-abci): per-block phase timing behind DRIVE_BLOCK_PERF - #4573
feat(drive-abci): per-block phase timing behind DRIVE_BLOCK_PERF#4573PastaPastaPasta wants to merge 3 commits into
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 41 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: Team 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 |
|
✅ Final review complete — no blockers (commit fe6a596) |
Codecov Report❌ Patch coverage is Additional details and impacted files@@ Coverage Diff @@
## v4.2-dev #4573 +/- ##
============================================
- Coverage 87.57% 86.76% -0.82%
============================================
Files 2748 2763 +15
Lines 357005 364957 +7952
============================================
+ Hits 312647 316644 +3997
- Misses 44358 48313 +3955
🚀 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.
| app.platform().create_grovedb_checkpoint(platform_version)?; | ||
| } | ||
|
|
||
| laps.lap("fb_checkpoint"); |
There was a problem hiding this comment.
🟡 Suggestion: 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.
source: ['claude']
| #[derive(Default)] | ||
| struct Totals { | ||
| blocks: u64, | ||
| /// (name, summed microseconds, samples), in first-seen order | ||
| phases: Vec<(&'static str, u64, u64)>, | ||
| } | ||
|
|
||
| impl Totals { | ||
| fn add(&mut self, name: &'static str, micros: u64) { | ||
| if let Some(entry) = self.phases.iter_mut().find(|(n, _, _)| *n == name) { | ||
| entry.1 += micros; | ||
| entry.2 += 1; | ||
| } else { | ||
| self.phases.push((name, micros, 1)); | ||
| } | ||
| } | ||
| } | ||
|
|
||
| fn totals() -> &'static Mutex<Totals> { | ||
| static TOTALS: OnceLock<Mutex<Totals>> = OnceLock::new(); | ||
| TOTALS.get_or_init(|| Mutex::new(Totals::default())) | ||
| } | ||
|
|
||
| /// Accumulates the elapsed time of successive phases of block execution. | ||
| /// | ||
| /// Timings are merged into the process-wide totals when the value is dropped. | ||
| pub struct Laps { | ||
| last: Instant, | ||
| on: bool, | ||
| buf: Vec<(&'static str, u64)>, | ||
| } | ||
|
|
||
| impl Laps { | ||
| /// Start a new lap sequence. Cheap and inert when perf logging is off. | ||
| pub fn new() -> Self { | ||
| let on = enabled(); | ||
| Laps { | ||
| last: Instant::now(), | ||
| on, | ||
| buf: if on { | ||
| Vec::with_capacity(32) | ||
| } else { | ||
| Vec::new() | ||
| }, | ||
| } | ||
| } | ||
|
|
||
| /// Record the time since the previous lap under `name`. | ||
| pub fn lap(&mut self, name: &'static str) { | ||
| if !self.on { | ||
| return; | ||
| } | ||
| let now = Instant::now(); | ||
| self.buf | ||
| .push((name, now.duration_since(self.last).as_micros() as u64)); | ||
| self.last = now; | ||
| } | ||
|
|
||
| /// True when perf logging is enabled. | ||
| pub fn on(&self) -> bool { | ||
| self.on | ||
| } | ||
| } | ||
|
|
||
| impl Default for Laps { | ||
| fn default() -> Self { | ||
| Self::new() | ||
| } | ||
| } | ||
|
|
||
| impl Drop for Laps { | ||
| fn drop(&mut self) { | ||
| if !self.on || self.buf.is_empty() { | ||
| return; | ||
| } | ||
| let mut totals = totals().lock().expect("block perf totals poisoned"); | ||
| for (name, micros) in self.buf.drain(..) { | ||
| totals.add(name, micros); | ||
| } | ||
| } | ||
| } | ||
|
|
||
| /// Record a non-timing value (e.g. a byte count) under `name`. | ||
| pub fn value(name: &'static str, v: u64) { | ||
| if !enabled() { | ||
| return; | ||
| } | ||
| totals() | ||
| .lock() | ||
| .expect("block perf totals poisoned") | ||
| .add(name, v); | ||
| } | ||
|
|
||
| /// Called once per finalized block. Emits the means and resets every | ||
| /// `DRIVE_BLOCK_PERF_EVERY` blocks. | ||
| pub fn end_block(height: u64) { | ||
| if !enabled() { | ||
| return; | ||
| } | ||
| let every = report_every(); | ||
| let report = { | ||
| let mut totals = totals().lock().expect("block perf totals poisoned"); | ||
| totals.blocks += 1; | ||
| if totals.blocks < every { | ||
| None | ||
| } else { | ||
| let blocks = totals.blocks; | ||
| let mut line = String::with_capacity(totals.phases.len() * 20); | ||
| for (name, sum, samples) in &totals.phases { | ||
| if !line.is_empty() { | ||
| line.push(' '); | ||
| } | ||
| // mean over blocks, not over samples: a phase that only runs on | ||
| // some blocks should show its share of the per-block cost | ||
| line.push_str(name); | ||
| line.push('='); | ||
| line.push_str(&(*sum / blocks).to_string()); | ||
| line.push('/'); | ||
| line.push_str(&samples.to_string()); | ||
| } | ||
| totals.phases.clear(); | ||
| totals.blocks = 0; | ||
| Some((blocks, line)) | ||
| } | ||
| }; | ||
| if let Some((blocks, line)) = report { | ||
| tracing::info!( | ||
| block_perf = "agg", | ||
| height, | ||
| blocks, | ||
| phases = line, | ||
| "block perf" | ||
| ); | ||
| } | ||
| } |
There was a problem hiding this comment.
🟡 Suggestion: 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.
source: ['claude', 'codex']
| impl Drop for Laps { | ||
| fn drop(&mut self) { | ||
| if !self.on || self.buf.is_empty() { | ||
| return; | ||
| } | ||
| let mut totals = totals().lock().expect("block perf totals poisoned"); | ||
| for (name, micros) in self.buf.drain(..) { | ||
| totals.add(name, micros); | ||
| } | ||
| } | ||
| } | ||
|
|
||
| /// Record a non-timing value (e.g. a byte count) under `name`. | ||
| pub fn value(name: &'static str, v: u64) { | ||
| if !enabled() { | ||
| return; | ||
| } | ||
| totals() | ||
| .lock() | ||
| .expect("block perf totals poisoned") | ||
| .add(name, v); | ||
| } | ||
|
|
||
| /// Called once per finalized block. Emits the means and resets every | ||
| /// `DRIVE_BLOCK_PERF_EVERY` blocks. | ||
| pub fn end_block(height: u64) { | ||
| if !enabled() { | ||
| return; | ||
| } | ||
| let every = report_every(); | ||
| let report = { | ||
| let mut totals = totals().lock().expect("block perf totals poisoned"); |
There was a problem hiding this comment.
🟡 Suggestion: 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.
source: ['claude', 'codex']
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.
2 participants
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?
A
Lapsvalue times successive phases of block execution and merges them into process-wide totals on drop.perf::end_blockreports the means everyDRIVE_BLOCK_PERF_EVERYblocks (default 500) as a single log line.Two design points worth noting:
DRIVE_BLOCK_PERF=1. The switch is aOnceLock<bool>read once; 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.
fb_proposalin the finalize handler wraps the whole offinalize_block_proposal, so it is the sum of thefbp_*phases; add up laps from one level only.Phases covered: the block-proposal path (epoch info, block-cache clear, state clone, core info, chain lock, withdrawals, DAO events, state transitions, fees, root hash, validator set) and the finalize path (proposal validation, commit signature verification, drive cache, state cache, commit, checkpoint).
Example output:
Each term is
name=mean_µs_per_block/blocks_it_ran_on.core_info,chainlockandwd_statusonly 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. The follow-up adds unit tests for the accumulation, mean-over-blocks and interval reset logic inperf.rs.Breaking Changes
None. Inert unless the environment variable is set.
Checklist:
For repository code-owners and collaborators only
🤖 Generated with Claude Code