Skip to content

perf(state): measure contextual verification phases #782

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
evan-forbes wants to merge 3 commits into
base: main
Choose a base branch
from
Open

perf(state): measure contextual verification phases #782

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
4a733db
perf(state): measure contextual phases
evan-forbes Aug 22, 2026
8a4519b
fix(state): make contextual phase metrics actionable
evan-forbes Aug 23, 2026
1da7d1c
fix(state): exclude proposals from contextual metrics
evan-forbes Aug 24, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
270 changes: 221 additions & 49 deletions crates/zakura-state/src/service/non_finalized_state.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@ use std::{
mem,
path::{Path, PathBuf},
sync::Arc,
time::Instant,
};

use indexmap::IndexMap;
Expand Down Expand Up @@ -38,6 +39,40 @@ mod tests;
pub(crate) use backup::write_semantically_verified_backup_block;
pub(crate) use chain::{Chain, SpendingTransactionId};

#[derive(Clone, Copy, Debug, Eq, PartialEq)]
pub(crate) enum ContextualMetrics {
Disabled,
AllBlocks,
Mined,
}

impl ContextualMetrics {
pub(crate) fn for_commit(is_mined: bool) -> Self {
if is_mined {
Self::Mined
} else {
Self::AllBlocks
}
}

pub(crate) fn record_duration(
self,
metric_name: &'static str,
mined_metric_name: &'static str,
duration: std::time::Duration,
) {
if self == Self::Disabled {
return;
}

let duration = duration.as_secs_f64();
metrics::histogram!(metric_name).record(duration);
if self == Self::Mined {
metrics::histogram!(mined_metric_name).record(duration);
}
}
}

/// The state of the chains in memory, including queued blocks.
///
/// Clones of the non-finalized state contain independent copies of the chains.
Expand Down Expand Up @@ -350,20 +385,41 @@ impl NonFinalizedState {
/// Commit block to the non-finalized state, on top of:
/// - an existing chain's tip, or
/// - a newly forked chain.
#[tracing::instrument(level = "debug", skip(self, finalized_state, prepared))]
pub fn commit_block(
&mut self,
prepared: SemanticallyVerifiedBlock,
finalized_state: &ZakuraDb,
) -> Result<(), ValidateContextError> {
self.commit_block_with_metrics(prepared, finalized_state, ContextualMetrics::Disabled)
}

#[tracing::instrument(
name = "commit_block",
level = "debug",
skip(self, finalized_state, prepared)
)]
pub(crate) fn commit_block_with_metrics(
&mut self,
prepared: SemanticallyVerifiedBlock,
finalized_state: &ZakuraDb,
contextual_metrics: ContextualMetrics,
) -> Result<(), ValidateContextError> {
let parent_hash = prepared.block.header.previous_block_hash;
let (height, hash) = (prepared.height, prepared.hash);

let parent_chain = self.parent_chain(parent_hash)?;
let parent_chain_start = Instant::now();
let parent_chain = self.parent_chain(parent_hash);
contextual_metrics.record_duration(
"state.contextual.parent_chain.duration_seconds",
"state.contextual.mined.parent_chain.duration_seconds",
parent_chain_start.elapsed(),
);
let parent_chain = parent_chain?;

// If the block is invalid, return the error,
// and drop the cloned parent Arc, or newly created chain fork.
let modified_chain = self.validate_and_commit(parent_chain, prepared, finalized_state)?;
let modified_chain =
self.validate_and_commit(parent_chain, prepared, finalized_state, contextual_metrics)?;

// If the block is valid:
// - add the new chain fork or updated chain to the set of recent chains
Expand Down Expand Up @@ -516,36 +572,66 @@ impl NonFinalizedState {

/// Commit block to the non-finalized state as a new chain where its parent
/// is the finalized tip.
#[tracing::instrument(level = "debug", skip(self, finalized_state, prepared))]
#[allow(clippy::unwrap_in_result)]
pub fn commit_new_chain(
&mut self,
prepared: SemanticallyVerifiedBlock,
finalized_state: &ZakuraDb,
) -> Result<(), ValidateContextError> {
let finalized_tip_height = finalized_state.finalized_tip_height();

// TODO: fix tests that don't initialize the finalized state
#[cfg(not(test))]
let finalized_tip_height = finalized_tip_height.expect("finalized state contains blocks");
#[cfg(test)]
let finalized_tip_height = finalized_tip_height.unwrap_or(zakura_chain::block::Height(0));

let chain = Chain::new(
&self.network,
finalized_tip_height,
finalized_state.sprout_tree_for_tip()?,
finalized_state.sapling_tree_for_tip(),
finalized_state.orchard_tree_for_tip(),
finalized_state.ironwood_tree_for_tip(),
finalized_state.history_tree(),
finalized_state.finalized_value_pool(),
self.commit_new_chain_with_metrics(prepared, finalized_state, ContextualMetrics::Disabled)
}

#[tracing::instrument(
name = "commit_new_chain",
level = "debug",
skip(self, finalized_state, prepared)
)]
#[allow(clippy::unwrap_in_result)]
pub(crate) fn commit_new_chain_with_metrics(
&mut self,
prepared: SemanticallyVerifiedBlock,
finalized_state: &ZakuraDb,
contextual_metrics: ContextualMetrics,
) -> Result<(), ValidateContextError> {
let chain_new_start = Instant::now();
let chain: Result<Chain, ValidateContextError> = (|| {
let finalized_tip_height = finalized_state.finalized_tip_height();

// TODO: fix tests that don't initialize the finalized state
#[cfg(not(test))]
let finalized_tip_height =
finalized_tip_height.expect("finalized state contains blocks");
#[cfg(test)]
let finalized_tip_height =
finalized_tip_height.unwrap_or(zakura_chain::block::Height(0));

Ok(Chain::new(
&self.network,
finalized_tip_height,
finalized_state.sprout_tree_for_tip()?,
finalized_state.sapling_tree_for_tip(),
finalized_state.orchard_tree_for_tip(),
finalized_state.ironwood_tree_for_tip(),
finalized_state.history_tree(),
finalized_state.finalized_value_pool(),
))
})();
contextual_metrics.record_duration(
"state.contextual.chain_new.duration_seconds",
"state.contextual.mined.chain_new.duration_seconds",
chain_new_start.elapsed(),
);
let chain = chain?;

let (height, hash) = (prepared.height, prepared.hash);

// If the block is invalid, return the error, and drop the newly created chain fork
let chain = self.validate_and_commit(Arc::new(chain), prepared, finalized_state)?;
let chain = self.validate_and_commit(
Arc::new(chain),
prepared,
finalized_state,
contextual_metrics,
)?;

// If the block is valid, add the new chain fork to the set of recent chains.
self.insert(chain);
Expand All @@ -565,6 +651,7 @@ impl NonFinalizedState {
new_chain: Arc<Chain>,
prepared: SemanticallyVerifiedBlock,
finalized_state: &ZakuraDb,
contextual_metrics: ContextualMetrics,
) -> Result<Arc<Chain>, ValidateContextError> {
if self
.invalidated_blocks
Expand All @@ -579,28 +666,58 @@ impl NonFinalizedState {
// Reads from disk
//
// TODO: if these disk reads show up in profiles, run them in parallel, using std::thread::spawn()
let unspent_utxo_snapshot_start = Instant::now();

@ValarDragon ValarDragon Sep 11, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

im worried about Instant::now() being called repeatedly being an atomic slowdown for small operations. (IIRC its around 30ns)

Its probably fine here though

let unspent_utxos = new_chain.unspent_utxos();
contextual_metrics.record_duration(
"state.contextual.unspent_utxo_snapshot.duration_seconds",
"state.contextual.mined.unspent_utxo_snapshot.duration_seconds",
unspent_utxo_snapshot_start.elapsed(),
);

let transparent_spend_start = Instant::now();
let spent_utxos = check::utxo::transparent_spend(
&prepared,
&new_chain.unspent_utxos(),
&unspent_utxos,
&new_chain.spent_utxos,
finalized_state,
)?;
);
contextual_metrics.record_duration(
"state.contextual.transparent_spend.duration_seconds",
"state.contextual.mined.transparent_spend.duration_seconds",
transparent_spend_start.elapsed(),
);
let spent_utxos = spent_utxos?;

@czarcas7ic czarcas7ic Sep 4, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The copied unspent outputs now stay in memory for the rest of validation, so we use more memory than before. We could free that copy as soon as the spending checks finish, like the old code did.


// Reads from disk
check::anchors::block_sapling_orchard_ironwood_anchors_refer_to_final_treestates(
finalized_state,
&new_chain,
&prepared,
)?;
let shielded_anchor_start = Instant::now();
let shielded_anchors =
check::anchors::block_sapling_orchard_ironwood_anchors_refer_to_final_treestates(
finalized_state,
&new_chain,
&prepared,
);
contextual_metrics.record_duration(
"state.contextual.shielded_anchors.duration_seconds",
"state.contextual.mined.shielded_anchors.duration_seconds",
shielded_anchor_start.elapsed(),
);
shielded_anchors?;

// Reads from disk
let sprout_anchor_fetch_start = Instant::now();
let sprout_final_treestates = check::anchors::block_fetch_sprout_final_treestates(
finalized_state,
&new_chain,
&prepared,
);
contextual_metrics.record_duration(
"state.contextual.sprout_anchor_fetch.duration_seconds",
"state.contextual.mined.sprout_anchor_fetch.duration_seconds",
sprout_anchor_fetch_start.elapsed(),
);

// Quick check that doesn't read from disk
let contextual_block_start = Instant::now();
let height = prepared.height;
let block_hash = prepared.hash;
let transaction_count = prepared.block.transactions.len();
Expand All @@ -614,9 +731,27 @@ impl NonFinalizedState {
transaction_count,
spent_utxo_count,
},
)?;

Self::validate_and_update_parallel(new_chain, contextual, sprout_final_treestates)
);
contextual_metrics.record_duration(
"state.contextual.block_construction.duration_seconds",
"state.contextual.mined.block_construction.duration_seconds",
contextual_block_start.elapsed(),
);
let contextual = contextual?;

let parallel_update_start = Instant::now();
let result = Self::validate_and_update_parallel(
new_chain,
contextual,
sprout_final_treestates,
contextual_metrics,
);
contextual_metrics.record_duration(
"state.contextual.parallel_update.duration_seconds",
"state.contextual.mined.parallel_update.duration_seconds",
parallel_update_start.elapsed(),
);
result
}

/// Validate `contextual` and update `new_chain`, doing CPU-intensive work in parallel batches.
Expand All @@ -626,6 +761,7 @@ impl NonFinalizedState {
new_chain: Arc<Chain>,
contextual: ContextuallyVerifiedBlock,
sprout_final_treestates: HashMap<sprout::tree::Root, Arc<sprout::tree::NoteCommitmentTree>>,
contextual_metrics: ContextualMetrics,
) -> Result<Arc<Chain>, ValidateContextError> {
let mut block_commitment_result = None;
let mut sprout_anchor_result = None;
Expand All @@ -642,22 +778,25 @@ impl NonFinalizedState {

rayon::in_place_scope_fifo(|scope| {
scope.spawn_fifo(|_scope| {
block_commitment_result = Some(check::block_commitment_is_valid_for_chain_history(
let start = Instant::now();
let result = check::block_commitment_is_valid_for_chain_history(
block,
&network,
&history_tree,
None,
));
);
block_commitment_result = Some((result, start.elapsed()));
});

scope.spawn_fifo(|_scope| {
sprout_anchor_result =
Some(check::anchors::block_sprout_anchors_refer_to_treestates(
sprout_final_treestates,
block2,
transaction_hashes,
height,
));
let start = Instant::now();
let result = check::anchors::block_sprout_anchors_refer_to_treestates(
sprout_final_treestates,
block2,
transaction_hashes,
height,
);
sprout_anchor_result = Some((result, start.elapsed()));
});

// We're pretty sure the new block is valid,
Expand All @@ -666,19 +805,52 @@ impl NonFinalizedState {
// Pushing a block onto a Chain can launch additional parallel batches.
// TODO: should we pass _scope into Chain::push()?
scope.spawn_fifo(|_scope| {
// TODO: Replace with Arc::unwrap_or_clone() when it stabilises:
// https://github.com/rust-lang/rust/issues/93610
let new_chain = Arc::try_unwrap(new_chain)
.unwrap_or_else(|shared_chain| (*shared_chain).clone());
chain_push_result = Some(new_chain.push(contextual).map(Arc::new));
let chain_clone_start = Instant::now();
let new_chain = Arc::unwrap_or_clone(new_chain);
let chain_clone_duration = chain_clone_start.elapsed();

let chain_push_start = Instant::now();
let result = new_chain.push(contextual).map(Arc::new);
chain_push_result =
Some((result, chain_clone_duration, chain_push_start.elapsed()));
});
});

// Don't return the updated Chain unless all the parallel results were Ok
block_commitment_result.expect("scope has finished")?;
sprout_anchor_result.expect("scope has finished")?;
let (block_commitment_result, block_commitment_duration) =
block_commitment_result.expect("scope has finished");
let (sprout_anchor_result, sprout_anchor_duration) =
sprout_anchor_result.expect("scope has finished");
let (chain_push_result, chain_clone_duration, chain_push_duration) =
chain_push_result.expect("scope has finished");

// These task durations overlap. Only `parallel_update` measures their
// combined critical-path wall time.
contextual_metrics.record_duration(
"state.contextual.parallel_task.block_commitment.duration_seconds",
"state.contextual.mined.parallel_task.block_commitment.duration_seconds",
block_commitment_duration,
);
contextual_metrics.record_duration(
"state.contextual.parallel_task.sprout_anchor_check.duration_seconds",
"state.contextual.mined.parallel_task.sprout_anchor_check.duration_seconds",
sprout_anchor_duration,
);
contextual_metrics.record_duration(
"state.contextual.parallel_task.chain_clone.duration_seconds",
"state.contextual.mined.parallel_task.chain_clone.duration_seconds",
chain_clone_duration,
);
contextual_metrics.record_duration(
"state.contextual.parallel_task.chain_push.duration_seconds",
"state.contextual.mined.parallel_task.chain_push.duration_seconds",
chain_push_duration,
);

block_commitment_result?;
sprout_anchor_result?;

chain_push_result.expect("scope has finished")
chain_push_result
}

/// Returns the length of the non-finalized portion of the current best chain
Expand Down
Loading
Loading