From 06e3306088c31b6a060adba46ec6307280c5db73 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1s=20Gr=C3=BCner?= <47506558+MegaRedHand@users.noreply.github.com> Date: Fri, 30 Oct 2026 11:43:31 -0300 Subject: [PATCH 1/3] perf(blockchain): run the beacon state transition while the engine verdict is in flight With an execution client, an import waited for engine_newPayload and then ran the state transition, so the two summed. The request is now built on the actor and sent from a spawned task, and the actor computes the transition meanwhile, so the import costs the larger of the two. The speculative post-state is a local value (SpeculativeTransition) until on_block_speculative accepts it. on_block's checks run unchanged and in the same order; only the transition_block call is replaced, and only when the speculation was computed for this block root and parent root and the verdict is not Invalidated. on_block derives a valid() engine for every other verdict, so the speculation is the transition it would have run. Invalidated, held blocks (no verdict, non-candidate optimistic) and a failed or panicked request task behave as before. on_block keeps its signature as a wrapper, so spec-test runners and the replay harness (no engine) are untouched. Timings: the transition that overlapped the round trip is reported under stf, and engine reports only the wait left after it, so the rows still tile the end-to-end time. A discarded speculation leaves engine covering the overlap. lean_engine_speculation_total{outcome} counts used and discarded attempts. --- crates/blockchain/src/beacon_engine.rs | 48 +++ crates/blockchain/src/import_timing.rs | 55 ++- crates/blockchain/src/lib.rs | 133 +++++-- crates/blockchain/src/metrics.rs | 27 ++ .../src/beacon/fork_choice.rs | 364 ++++++++++++++++-- docs/beacon_engine.md | 34 ++ docs/benchmarking.md | 5 + docs/metrics.md | 5 +- 8 files changed, 604 insertions(+), 67 deletions(-) diff --git a/crates/blockchain/src/beacon_engine.rs b/crates/blockchain/src/beacon_engine.rs index 38f34c39e..b3733683b 100644 --- a/crates/blockchain/src/beacon_engine.rs +++ b/crates/blockchain/src/beacon_engine.rs @@ -178,6 +178,54 @@ pub fn verdict(status: &PayloadStatusV1) -> PayloadValidity { }) } +/// [`NewPayloadRequest`] with its own copy of the payload, so it can move into +/// a spawned task. +/// +/// The chain actor sends the question from a task of its own and runs the +/// block's state transition meanwhile (see `process_block`), and a task cannot +/// borrow the block the actor goes on using. Only the payload is copied: the +/// rest of the request is already owned, and the block itself, which also +/// carries the attestations and the other operations, is never cloned. +pub struct OwnedNewPayloadRequest { + execution_payload: containers::deneb::ExecutionPayload, + versioned_hashes: Vec, + parent_beacon_block_root: Root, + execution_requests: Vec>, +} + +impl NewPayloadRequest<'_> { + /// Copies the borrowed payload so the request outlives the block. + pub fn into_owned(self) -> OwnedNewPayloadRequest { + OwnedNewPayloadRequest { + execution_payload: self.execution_payload.clone(), + versioned_hashes: self.versioned_hashes, + parent_beacon_block_root: self.parent_beacon_block_root, + execution_requests: self.execution_requests, + } + } +} + +/// [`ask`] for a request already built with [`new_payload_request`], which is +/// how the actor sends it from a task while it computes the transition. +/// +/// The answer is read exactly as [`ask`] reads it: `Err` means no answer after +/// the client's whole retry ladder, and there is no `Ok(None)` because a +/// request existing means there was something to ask. +pub async fn ask_request( + client: &EngineClient, + request: OwnedNewPayloadRequest, +) -> Result { + let status = client + .new_payload( + &request.execution_payload, + &request.versioned_hashes, + request.parent_beacon_block_root, + &request.execution_requests, + ) + .await?; + Ok(verdict(&status)) +} + /// Asks the execution client about `block`'s payload. /// /// `Ok(None)` means there was nothing to ask, which is not a failure: diff --git a/crates/blockchain/src/import_timing.rs b/crates/blockchain/src/import_timing.rs index 6625a472f..01ff46266 100644 --- a/crates/blockchain/src/import_timing.rs +++ b/crates/blockchain/src/import_timing.rs @@ -177,7 +177,9 @@ pub struct ImportTimings { pub columns_wait_end: Option, /// Beacon: the `engine_newPayload` round trip, including its retry ladder. - /// I/O wait, not work. + /// I/O wait, not work. When the state transition ran meanwhile and was + /// used, this pair starts where that transition ended and so covers only + /// the wait that remained; see [`Self::stf_spec_start`]. pub engine_start: Option, pub engine_end: Option, @@ -197,6 +199,21 @@ pub struct ImportTimings { pub stf_start: Option, pub stf_end: Option, + /// Beacon: a state transition computed while the execution client's + /// verdict was still in flight, and then used by the import. + /// + /// It runs before the `stf` pair above and overlaps the `engine_newPayload` + /// round trip, so it is neither inside `stf_start`..`stf_end` nor a + /// section of its own: the `stf` row adds it, since it is the same + /// state-transition work done earlier. Meanwhile `engine_start` is moved to + /// this pair's end, so the `engine` row reports only the wait that was left + /// once the transition finished, and the rows still sum to the end-to-end + /// time instead of counting the overlap twice. `None` whenever the import + /// ran its own transition, which is every import without an execution + /// client and every one whose speculation was discarded. + pub stf_spec_start: Option, + pub stf_spec_end: Option, + /// Beacon: the blocking hand-off of the post-state to the storage crate's /// background writer, which waits while the writer's queue is full. It /// lies inside the `stf` pair; only the report separates the two. @@ -376,6 +393,11 @@ impl ImportTimings { if let (Some(total), Some(wait)) = (stf.elapsed, writer_wait.elapsed) { stf.elapsed = Some(total.saturating_sub(wait)); } + if let (Some(total), Some(spec)) = + (stf.elapsed, span(self.stf_spec_start, self.stf_spec_end)) + { + stf.elapsed = Some(total + spec); + } vec![ Row::new("decode", self.decode_start, self.decode_end), Row::new("queue", self.queue_start, self.queue_end), @@ -897,6 +919,37 @@ mod tests { assert_eq!(row_elapsed(&timings, "writer_wait"), None); } + #[test] + fn an_overlapped_transition_is_charged_to_stf_and_not_to_engine() { + // A 100 ms round trip with a 70 ms transition running inside it, then + // 20 ms of import. Un-overlapped, that is 100 + 20 ms; overlapped, the + // engine row keeps the 30 ms that was left and stf gains the 70 ms. + let base = Instant::now(); + let mut timings = ImportTimings::default(); + (timings.stf_spec_start, timings.stf_spec_end) = pair(base, 0, 70); + (timings.engine_start, timings.engine_end) = pair(base, 70, 30); + (timings.stf_start, timings.stf_end) = pair(base, 100, 20); + + assert_eq!( + row_elapsed(&timings, "engine"), + Some(Duration::from_millis(30)) + ); + assert_eq!( + row_elapsed(&timings, "stf"), + Some(Duration::from_millis(90)) + ); + let rows: Duration = timings + .rows() + .into_iter() + .filter_map(|row| row.elapsed) + .sum(); + assert_eq!( + rows, + Duration::from_millis(120), + "the rows still tile the span" + ); + } + #[test] fn a_writer_wait_longer_than_stf_saturates_stf_to_zero() { let base = Instant::now(); diff --git a/crates/blockchain/src/lib.rs b/crates/blockchain/src/lib.rs index 251048b7a..53a6fef24 100644 --- a/crates/blockchain/src/lib.rs +++ b/crates/blockchain/src/lib.rs @@ -1796,31 +1796,81 @@ impl BlockChainServer { // `is_data_available` runs before `state_transition`, so a // block about to be held for its custody columns is never one // this node asks an execution client about. + // + // With an execution client the question is sent from a task + // of its own and this actor computes the block's state + // transition while the answer is awaited, so the two cost + // `max(engine wait, transition)` instead of their sum. The + // result stays a local value: it reaches the store only + // through `fork_choice::on_block_speculative`, after every + // check `on_block` makes and only for a verdict that agrees + // with the transition it assumed (see `SpeculativeTransition`). + // Without an engine, or without a request to send (pre-merge + // forks, gloas), nothing overlaps and the path is the old one. timings.engine_start = Some(Instant::now()); - let validity = match &self.engine { - None => fork_choice::PayloadValidity::NotRequired, - Some(client) => match beacon_engine::ask(client, &beacon_block).await { - Ok(None) => fork_choice::PayloadValidity::NotRequired, - Ok(Some(validity)) => validity, - // No answer after the whole ladder. - // `optimistic-sync.md`: a consensus engine MUST NOT - // import the block and MUST NOT apply it to the fork - // choice store. Returning `Held` leaves the block out - // of the store without marking it imported, so the - // cascade does not treat it as having produced a - // post-state. - Err(err) => { - warn!( - %slot, - block_root = %ShortRoot(&block_root.0), - %err, - "No verdict from the execution client; not importing" - ); - metrics::inc_engine_no_verdict(); - timings.engine_end = Some(Instant::now()); - return (timings, Ok(ImportOutcome::Held)); + let parent_root = beacon_block.parent_root(); + let mut speculation: Option<( + fork_choice::SpeculativeTransition, + Instant, + Instant, + )> = None; + let verdict: Result, String> = + match &self.engine { + None => Ok(None), + Some(client) => { + match beacon_engine::new_payload_request(&beacon_block) + .map(|request| request.into_owned()) + { + None => Ok(None), + Some(request) => { + let client = client.clone(); + let task = tokio::spawn(async move { + beacon_engine::ask_request(&client, request).await + }); + let spec_start = Instant::now(); + let computed = fork_choice::speculate_transition( + &self.store, + &beacon_block, + &config, + &committees, + ); + let spec_end = Instant::now(); + speculation = computed.map(|spec| (spec, spec_start, spec_end)); + // A panicked or cancelled task is no + // answer, like an exhausted retry ladder. + match task.await { + Ok(Ok(validity)) => Ok(Some(validity)), + Ok(Err(err)) => Err(err.to_string()), + Err(err) => Err(err.to_string()), + } + } + } } - }, + }; + let validity = match verdict { + Ok(None) => fork_choice::PayloadValidity::NotRequired, + Ok(Some(validity)) => validity, + // No answer after the whole ladder. + // `optimistic-sync.md`: a consensus engine MUST NOT + // import the block and MUST NOT apply it to the fork + // choice store. Returning `Held` leaves the block out + // of the store without marking it imported, so the + // cascade does not treat it as having produced a + // post-state. + Err(err) => { + warn!( + %slot, + block_root = %ShortRoot(&block_root.0), + %err, + "No verdict from the execution client; not importing" + ); + metrics::inc_engine_no_verdict(); + if speculation.is_some() { + metrics::inc_engine_speculation("discarded_held"); + } + timings.engine_end = Some(Instant::now()); + return (timings, Ok(ImportOutcome::Held)); + } }; timings.engine_end = Some(Instant::now()); @@ -1829,7 +1879,6 @@ impl BlockChainServer { // answer, is not imported at all. if matches!(validity, fork_choice::PayloadValidity::Optimistic) { let current_slot = self.wall_clock_slot(); - let parent_root = beacon_block.parent_root(); if !fork_choice::is_optimistic_candidate_block( &self.store, current_slot, @@ -1844,21 +1893,55 @@ impl BlockChainServer { block and it is not an optimistic candidate" ); metrics::inc_engine_not_optimistic_candidate(); + if speculation.is_some() { + metrics::inc_engine_speculation("discarded_held"); + } return (timings, Ok(ImportOutcome::Held)); } } + // The speculation is only worth handing on for a verdict its + // `valid()` engine agrees with. `INVALIDATED` makes `on_block` + // run the transition itself with `invalid()`, exactly as + // before. A discarded speculation leaves `engine_start` where + // it was, so the `engine` row covers the whole overlap and + // the wasted transition is not hidden from the tree. + let speculation = match speculation { + Some((spec, spec_start, spec_end)) => { + if !spec.is_for(block_root, parent_root) { + metrics::inc_engine_speculation("discarded_mismatch"); + None + } else if matches!( + validity, + fork_choice::PayloadValidity::Invalidated { .. } + ) { + metrics::inc_engine_speculation("discarded_invalidated"); + None + } else { + metrics::inc_engine_speculation("used"); + // The wait that remained once the transition was + // done; see `ImportTimings::stf_spec_start`. + timings.engine_start = Some(spec_end); + timings.stf_spec_start = Some(spec_start); + timings.stf_spec_end = Some(spec_end); + Some(spec) + } + } + None => None, + }; + // Drop any hand-off span left by an insert outside this call, // so the one taken below is this block's alone. let _ = self.store.take_state_handoff(); timings.stf_start = Some(Instant::now()); - let imported = fork_choice::on_block( + let imported = fork_choice::on_block_speculative( &mut self.store, beacon_block, &config, &evidence, &validity, &committees, + speculation, ); timings.stf_end = Some(Instant::now()); (timings.writer_wait_start, timings.writer_wait_end) = diff --git a/crates/blockchain/src/metrics.rs b/crates/blockchain/src/metrics.rs index 34c67398f..e0cd83a67 100644 --- a/crates/blockchain/src/metrics.rs +++ b/crates/blockchain/src/metrics.rs @@ -1507,6 +1507,33 @@ pub fn inc_engine_no_verdict() { LEAN_ENGINE_NO_VERDICT_TOTAL.inc(); } +/// Speculative state transitions, by what became of them. +/// +/// With an execution client, the chain actor runs a block's state transition +/// while the `engine_newPayload` round trip is in flight. `outcome` is `used` +/// (handed to `fork_choice::on_block` with a verdict that lets it stand in for +/// the transition; a block that then fails one of `on_block`'s earlier checks +/// still counts, since the work was spent either way), `discarded_invalidated` +/// (the verdict was `INVALIDATED`, so `on_block` runs its own), `discarded_held` +/// (no verdict, or a non-candidate `SYNCING`/`ACCEPTED`, so the block is not +/// imported) or `discarded_mismatch` (computed for another root or parent; +/// not expected from the actor). A high `discarded_*` share means the overlap +/// is buying nothing. +pub fn inc_engine_speculation(outcome: &str) { + static LEAN_ENGINE_SPECULATION_TOTAL: std::sync::LazyLock = + std::sync::LazyLock::new(|| { + register_int_counter_vec!( + "lean_engine_speculation_total", + "Speculative state transitions run during the engine round trip, by outcome", + &["outcome"] + ) + .unwrap() + }); + LEAN_ENGINE_SPECULATION_TOTAL + .with_label_values(&[outcome]) + .inc(); +} + /// Blocks not imported because the execution client has not validated them and /// they do not qualify for an optimistic import. /// diff --git a/crates/blockchain/state_transition/src/beacon/fork_choice.rs b/crates/blockchain/state_transition/src/beacon/fork_choice.rs index 02c959376..cd970a3d6 100644 --- a/crates/blockchain/state_transition/src/beacon/fork_choice.rs +++ b/crates/blockchain/state_transition/src/beacon/fork_choice.rs @@ -4777,6 +4777,119 @@ pub fn on_block( blob_evidence: &DataAvailability, payload_validity: &PayloadValidity, committees: &CommitteeCache, +) -> Result<()> { + on_block_speculative( + store, + signed_block, + config, + blob_evidence, + payload_validity, + committees, + None, + ) +} + +/// The state transition of one block, computed before the execution client's +/// verdict on its payload is known. +/// +/// Opaque on purpose: the only thing a holder can do with one is hand it to +/// [`on_block_speculative`], which decides whether it may stand in for the +/// transition `on_block` would otherwise run. Until then it is a local value; +/// nothing here has reached the store, and dropping it costs only the work. +/// +/// # Why it is the transition `on_block` would run +/// +/// `on_block` reads the verdict in one place, to pick the +/// [`stf::ExecutionEngine`] the transition consults: `invalid()` for +/// [`PayloadValidity::Invalidated`], `valid()` for every other verdict +/// (`NotRequired`, `Validated` and `Optimistic` alike). So a transition run +/// with `valid()` is byte for byte the one `on_block` runs for every verdict +/// except `Invalidated`, and for that one the speculation is simply not used. +/// +/// The inputs are the same too. [`transition_block`] takes the store by shared +/// reference and reads two things off it: the epoch-boundary state the +/// precompute worker cached, and, through [`cache_boundary_balances`], the +/// boundary balance cache it fills. Both are keyed by content (a checkpoint, +/// that is an epoch and a block root), so what they hold does not depend on +/// when they are consulted. Everything else is the parent's post-state, the +/// block, the config and the committee and active-balance caches, which are +/// content-keyed as well. The chain actor handles one message at a time, so +/// nothing mutates the store between this computation and `on_block`'s own. +pub struct SpeculativeTransition { + block_root: Root, + parent_root: Root, + state: BeaconState, + outcome: Result<()>, +} + +impl SpeculativeTransition { + /// Whether this was computed for the block with this root and parent root. + /// + /// [`on_block_speculative`] makes the same comparison before using one; a + /// caller asks it first only to tell a mismatch from a use when counting. + pub fn is_for(&self, block_root: Root, parent_root: Root) -> bool { + self.block_root == block_root && self.parent_root == parent_root + } +} + +/// Runs `signed_block`'s state transition against its parent's post-state with +/// the execution engine assumed valid, without touching the store. +/// +/// `None` when the parent has no post-state, the same condition under which +/// `on_block` fails with `block.parent_root in store.block_states`; the caller +/// then gets that failure from `on_block` itself. The parent state is looked up +/// exactly as `on_block` looks it up. +/// +/// None of `on_block`'s own checks run here. They run, unchanged and in the +/// same order, when the speculation is handed to [`on_block_speculative`], so a +/// block that fails one of them is rejected exactly as it is today and the +/// speculation is dropped. +pub fn speculate_transition( + store: &Store, + signed_block: &SignedBeaconBlock, + config: &Config, + committees: &CommitteeCache, +) -> Option { + let block_root = signed_block.message_hash_tree_root(); + let parent_root = signed_block.parent_root(); + let parent_state = store.get_state(&parent_root).expect("get")?; + let active_balances = store.active_balance_cache(); + let (state, outcome) = transition_block( + store, + &parent_state, + parent_root, + signed_block, + true, + config, + &stf::ExecutionEngine::valid(), + committees, + &active_balances, + ); + Some(SpeculativeTransition { + block_root, + parent_root, + state, + outcome, + }) +} + +/// [`on_block`] with an optional transition computed ahead of time. +/// +/// Every check `on_block` makes runs unchanged and in the same order. The only +/// difference is the one `transition_block` call: when `speculation` was +/// computed for this block's own root and parent root, and the verdict is not +/// `Invalidated` (the one verdict the speculation's `valid()` engine would +/// disagree with), its result stands in for that call. In every other case it +/// is dropped and the transition runs here as it always has, so the +/// invalidation path in particular is the one `on_block` has today. +pub fn on_block_speculative( + store: &mut Store, + signed_block: SignedBeaconBlock, + config: &Config, + blob_evidence: &DataAvailability, + payload_validity: &PayloadValidity, + committees: &CommitteeCache, + speculation: Option, ) -> Result<()> { let block_root = signed_block.message_hash_tree_root(); let parent_root = signed_block.parent_root(); @@ -4949,17 +5062,24 @@ pub fn on_block( // The store's own cache, so every block of this chain shares one entry per // epoch; see `ActiveBalanceCacheExt`. let active_balances = store.active_balance_cache(); - let (mut state, transition) = transition_block( - store, - &parent_state, - parent_root, - &signed_block, - true, - config, - &engine, - committees, - &active_balances, - ); + let usable = speculation.filter(|speculation| { + speculation.is_for(block_root, parent_root) + && !matches!(payload_validity, PayloadValidity::Invalidated { .. }) + }); + let (mut state, transition) = match usable { + Some(speculation) => (speculation.state, speculation.outcome), + None => transition_block( + store, + &parent_state, + parent_root, + &signed_block, + true, + config, + &engine, + committees, + &active_balances, + ), + }; // `optimistic-sync.md`: a block deemed `INVALIDATED` MUST NOT be included // in the canonical chain. That is stated here, on the verdict, rather than @@ -7111,34 +7231,13 @@ mod tests { assert!(store.is_err()); } - /// [`on_block`]'s early-return guard must read `Store::has_state`, not - /// `Store::has_block`: a block the actor is holding for missing data - /// columns is written with - /// [`Store::insert_pending_block`](ethlambda_storage::Store::insert_pending_block) - /// before it ever imports, which stores the whole signed block in one - /// `BlockHeaders` row (so `has_block` answers true) but writes no - /// `LiveChain` entry (so [`Store::block_index`](ethlambda_storage::Store::block_index), - /// a `LiveChain` scan, does not name it). Guarding on `has_block` instead - /// of `has_state` made `on_block` answer `Ok(())` for a held block - /// without importing it, so every later delivery naming it as an - /// ancestor found it "already known" and gave up without importing - /// anything either -- forever, since nothing ever gave the root a - /// post-state. + /// A store anchored one slot before a genuinely valid child block, with the + /// clock at that block's slot, and the block itself. /// - /// Delivered timely (the first block for its slot, before the - /// attestation deadline), so this also proves `on_block`'s pre-import - /// `compute_head` call (walking `Store::block_index`, for the new - /// proposer-boost dependent-root gate) tolerates a held block sitting - /// unindexed in the store: that walk never sees it, being a `LiveChain` - /// scan, so it is untouched by the held block's absent post-state. - /// - /// Builds a genuinely valid child block (correct proposer, RANDAO reveal, - /// and state root, all real BLS signatures over - /// [`test_state::secret_key_for`]'s key) rather than the zero-signature - /// [`block`] helper, since this exercises the real, signature-checking - /// [`on_block`], not a fixture harness that can skip verification. - #[test] - fn on_block_imports_a_block_already_persisted_with_no_post_state() { + /// Valid means correct proposer, RANDAO reveal and state root, all real BLS + /// signatures over [`test_state::secret_key_for`]'s key, so the real, + /// signature-checking [`on_block`] accepts it. + fn store_with_valid_child() -> (Config, Store, SignedBeaconBlock) { let config = Config::active(); let (anchor_state, anchor_block) = anchor_pair_with(1); let anchor_root = anchor_block.message_hash_tree_root(); @@ -7204,7 +7303,6 @@ mod tests { .to_bytes(), ); let signed_block = draft; - let block_root = signed_block.message_hash_tree_root(); // The store holds the child block already, exactly the shape // `hold_block_for_columns` leaves it in: one `BlockHeaders` row (so @@ -7229,6 +7327,39 @@ mod tests { config.seconds_per_slot * target_slot, )) .expect("set time"); + (config, store, signed_block) + } + + /// [`on_block`]'s early-return guard must read `Store::has_state`, not + /// `Store::has_block`: a block the actor is holding for missing data + /// columns is written with + /// [`Store::insert_pending_block`](ethlambda_storage::Store::insert_pending_block) + /// before it ever imports, which stores the whole signed block in one + /// `BlockHeaders` row (so `has_block` answers true) but writes no + /// `LiveChain` entry (so [`Store::block_index`](ethlambda_storage::Store::block_index), + /// a `LiveChain` scan, does not name it). Guarding on `has_block` instead + /// of `has_state` made `on_block` answer `Ok(())` for a held block + /// without importing it, so every later delivery naming it as an + /// ancestor found it "already known" and gave up without importing + /// anything either -- forever, since nothing ever gave the root a + /// post-state. + /// + /// Delivered timely (the first block for its slot, before the + /// attestation deadline), so this also proves `on_block`'s pre-import + /// `compute_head` call (walking `Store::block_index`, for the new + /// proposer-boost dependent-root gate) tolerates a held block sitting + /// unindexed in the store: that walk never sees it, being a `LiveChain` + /// scan, so it is untouched by the held block's absent post-state. + /// + /// Builds a genuinely valid child block (correct proposer, RANDAO reveal, + /// and state root, all real BLS signatures over + /// [`test_state::secret_key_for`]'s key) rather than the zero-signature + /// [`block`] helper, since this exercises the real, signature-checking + /// [`on_block`], not a fixture harness that can skip verification. + #[test] + fn on_block_imports_a_block_already_persisted_with_no_post_state() { + let (config, mut store, signed_block) = store_with_valid_child(); + let block_root = signed_block.message_hash_tree_root(); store .insert_pending_block(block_root, signed_block.clone()) .expect("insert"); @@ -7260,6 +7391,161 @@ mod tests { ); } + /// Imports the valid child with `validity` and `speculation` and reports + /// everything an import writes that a later reader could tell apart. + fn import_valid_child( + validity: &PayloadValidity, + speculate: impl FnOnce(&Store, &SignedBeaconBlock, &Config) -> Option, + ) -> (Result<()>, Store, Root) { + let (config, mut store, signed_block) = store_with_valid_child(); + let block_root = signed_block.message_hash_tree_root(); + let committees = CommitteeCache::default(); + let speculation = speculate(&store, &signed_block, &config); + let result = on_block_speculative( + &mut store, + signed_block, + &config, + &DataAvailability::NotRequired, + validity, + &committees, + speculation, + ); + (result, store, block_root) + } + + fn honest_speculation( + store: &Store, + block: &SignedBeaconBlock, + config: &Config, + ) -> Option { + speculate_transition(store, block, config, &CommitteeCache::default()) + } + + /// What the store holds after an import, as comparable values. + fn observed( + store: &mut Store, + block_root: Root, + config: &Config, + ) -> ( + Option, + Option<[bool; constants::NUM_BLOCK_TIMELINESS_DEADLINES]>, + Root, + Root, + Vec, + ) { + let post_state_root = store + .get_state(&block_root) + .expect("get") + .map(|state| state.hash_tree_root()); + let mut roots: Vec = store.block_index().keys().copied().collect(); + roots.sort(); + ( + post_state_root, + store.block_timeliness(&block_root), + store.proposer_boost_root(), + get_head(store, config).expect("head"), + roots, + ) + } + + #[test] + fn a_matching_speculation_leaves_the_store_as_importing_without_one() { + let config = Config::active(); + let (plain_result, mut plain, root) = + import_valid_child(&PayloadValidity::NotRequired, |_, _, _| None); + plain_result.expect("the plain import succeeds"); + for validity in [ + PayloadValidity::NotRequired, + PayloadValidity::Validated, + PayloadValidity::Optimistic, + ] { + let (result, mut speculated, speculated_root) = + import_valid_child(&validity, honest_speculation); + result.expect("the speculated import succeeds"); + assert_eq!(speculated_root, root); + assert_eq!( + observed(&mut speculated, root, &config), + observed(&mut plain, root, &config), + "{validity:?}: head, post-state root, timeliness, proposer boost and the \ + block index must be identical" + ); + } + } + + /// A speculation whose outcome is a marker nothing else produces, so the + /// result of the import says whether the speculation or a fresh transition + /// supplied it. + const POISON: &str = "poisoned speculation"; + + fn poisoned( + store: &Store, + block: &SignedBeaconBlock, + config: &Config, + ) -> Option { + let mut speculation = honest_speculation(store, block, config)?; + speculation.outcome = Err(Error::SpecAssert(POISON)); + Some(speculation) + } + + #[test] + fn a_matching_speculation_is_the_transition_on_block_uses() { + let (result, store, root) = import_valid_child(&PayloadValidity::Validated, poisoned); + assert_eq!(failed_assertion(result), Some(POISON)); + assert!( + !store.has_state(&root).unwrap(), + "a failed import writes nothing" + ); + } + + #[test] + fn a_speculation_for_another_root_or_parent_is_ignored() { + for tamper in [0u8, 1] { + let (result, store, root) = + import_valid_child(&PayloadValidity::NotRequired, |store, block, config| { + let mut speculation = poisoned(store, block, config)?; + match tamper { + 0 => speculation.block_root = Root::repeat_byte(0xee), + _ => speculation.parent_root = Root::repeat_byte(0xee), + } + Some(speculation) + }); + result.expect("the stale speculation is dropped and the real transition runs"); + assert!(store.has_state(&root).unwrap()); + } + } + + #[test] + fn an_invalidated_verdict_ignores_the_speculation_and_matches_today() { + let invalidated = PayloadValidity::Invalidated { + latest_valid_hash: None, + }; + let (without, plain_store, root) = import_valid_child(&invalidated, |_, _, _| None); + let (with_honest, honest_store, _) = import_valid_child(&invalidated, honest_speculation); + let (with_poison, poison_store, _) = import_valid_child(&invalidated, poisoned); + let without = format!("{:?}", without.expect_err("an invalidated block fails")); + assert_eq!(format!("{:?}", with_honest.expect_err("fails")), without); + assert_eq!( + format!("{:?}", with_poison.expect_err("fails")), + without, + "the speculation must not supply the transition under Invalidated" + ); + for store in [&plain_store, &honest_store, &poison_store] { + assert!(!store.has_state(&root).unwrap()); + } + } + + #[test] + fn no_speculation_without_a_parent_state() { + let (config, store, mut block) = store_with_valid_child(); + let SignedBeaconBlock::Phase0(inner) = &mut block else { + unreachable!("phase0"); + }; + inner.message.parent_root = Root::repeat_byte(0xcd); + assert!( + speculate_transition(&store, &block, &config, &CommitteeCache::default()).is_none() + ); + } + #[test] fn the_commitments_subtree_index_is_the_bodys_own_position() { // The generalized index the fixture states, minus the offset of a tree diff --git a/docs/beacon_engine.md b/docs/beacon_engine.md index 1aa13b184..d5d1502df 100644 --- a/docs/beacon_engine.md +++ b/docs/beacon_engine.md @@ -91,6 +91,40 @@ already `INVALIDATED`, which costs one merkleization on a path that should never run and buys the failure arriving where a reviewer checks this code against the specification. +### The transition runs while the answer is in flight + +With an execution client, `process_block` does not wait idle for the answer. It +builds the request on the actor (copying only the payload, never the block), +sends it from a spawned task so the HTTP exchange keeps progressing, and runs +`fork_choice::speculate_transition` on the actor meanwhile: the block's state +transition against its parent's post-state, with the engine assumed valid. The +import then costs `max(engine wait, transition)` instead of their sum. + +Why that is the transition `on_block` would run: `on_block` derives the +`ExecutionEngine` from the verdict in one place, `invalid()` for `INVALIDATED` +and `valid()` for `NOT_REQUIRED`, `VALID` and optimistic alike, and the +transition reads nothing else off the store except content-keyed caches. What +keeps it harmless: + +- The result is a local value (`SpeculativeTransition`). Nothing reaches the + store, a cache that is not content-addressed, or the network until + `on_block_speculative` accepts it, and that runs every check `on_block` makes, + unchanged and in the same order. +- It stands in for the transition only when it was computed for this block's + root and parent root and the verdict is not `INVALIDATED`. For `INVALIDATED` + it is dropped and `on_block` recomputes with `invalid()`, so the invalidation + path is the one described above, unchanged. +- A block that ends up held (no verdict, or `SYNCING`/`ACCEPTED` for a block + that is not an optimistic candidate) drops it. The attempt is counted in + `lean_engine_speculation_total{outcome}`. +- A panicked or cancelled request task is treated as no verdict, like an + exhausted retry ladder. + +The overlap shows in the import timing tree: the transition that ran during the +round trip is reported under `stf`, and `engine` reports only the wait that was +left once it finished. Without an execution client, and for forks that have no +request to send (pre-merge, gloas), nothing overlaps and the path is the old one. + ## The verdicts `optimistic-sync.md` groups the five wire statuses into three outcomes: diff --git a/docs/benchmarking.md b/docs/benchmarking.md index ae50db389..088faa3ad 100644 --- a/docs/benchmarking.md +++ b/docs/benchmarking.md @@ -277,6 +277,11 @@ is state-transition work and the two phases do not overlap. When blocks import faster than the writer persists them, the wait shows up here rather than in `stf`. +With an execution client the beacon `stf` row also includes a state +transition that ran while `engine_newPayload` was in flight, and `engine` then +reports only the wait left after it. A replay has no client, so neither applies +to its numbers. + ### What is excluded, and why Replay runs nothing that a corpus already answers for: diff --git a/docs/metrics.md b/docs/metrics.md index 1ea07953f..441abd8c5 100644 --- a/docs/metrics.md +++ b/docs/metrics.md @@ -262,6 +262,7 @@ Series appear as blocks arrive rather than being seeded, since a third of the ph | Name | Type | Usage | Sample collection event | Labels | Buckets | |------|------|-------|-------------------------|--------|---------| | `lean_block_import_phase_seconds` | Histogram | Time one section of a block's import, or of the arrival carrying it, took | Per section that ran, on each import, hold or failure | phase (see below); source=gossip,sync | 0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 0.75, 1, 1.5, 2, 3, 4, 6, 8, 12, 16, 32 | +| `lean_engine_speculation_total` | Counter | State transitions the chain actor ran while the `engine_newPayload` round trip was in flight, by what became of them | Per beacon block asked of an execution client | outcome=used,discarded_invalidated,discarded_held,discarded_mismatch | | | `lean_block_import_cascade_blocks` | Histogram | Blocks one arrival put through the import path (attempts, so a block that ends held or pended counts) | Once per arriving block message | | 1, 2, 3, 5, 8, 16, 32, 64, 128 | Per-block phases, in the order a block crosses them, plus `total` for a completed import: @@ -277,10 +278,10 @@ Per-block phases, in the order a block crosses them, plus `total` for a complete | `cascade_wait` | Between the parent's import finishing and this block being popped off the cascade queue | both | | `da_check` | The custody-column availability check itself, not the wait | beacon | | `columns_wait` | Held because custody columns had not all arrived | beacon | -| `engine` | The `engine_newPayload` round trip, including its retry ladder | beacon | +| `engine` | The `engine_newPayload` round trip, including its retry ladder. When the state transition ran meanwhile and was used, only the wait left after it finished | beacon | | `verify_struct` | Participant bounds checks and pubkey resolution | lean | | `verify_crypto` | The leanVM multi-message aggregate verification | lean | -| `stf` | The state transition. On beacon this bundles the transition and the state root, and excludes `writer_wait`, which is nested inside it | both | +| `stf` | The state transition. On beacon this bundles the transition and the state root, and excludes `writer_wait`, which is nested inside it. It includes a transition that ran during the `engine` round trip | both | | `writer_wait` | Beacon only: the importer's blocking hand-off of the post-state to the storage crate's background writer, which waits while the writer's queue is full. Subtracted from `stf`, so `stf` and `writer_wait` do not overlap | beacon | | `db_write` | The block write and handing the post-state off to the storage crate's background writer; the state's own encode/diff/commit cost is `lean_state_write_seconds` instead, not this row | lean | | `fc_head` | `update_head` | lean | From b95be16bc4880e5318f871099f4ec13921e05dc7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1s=20Gr=C3=BCner?= <47506558+MegaRedHand@users.noreply.github.com> Date: Fri, 30 Oct 2026 20:49:10 -0300 Subject: [PATCH 2/3] perf(blockchain): time the payload's execution apart from the import's engine wait The import's engine section is meant to say how long the consensus block's import waited on the execution client, but it also carried the execution client's own time whenever nothing hid it: the whole round trip for a discarded speculation, and a few microseconds of scheduling noise for every block that had nothing to ask. Its meaning is now only the wait left once the import's own state transition was done. It is a recorded zero when there was no request to send (no execution client, or a block with no payload: pre-merge or gloas) and when the answer was already in once the transition finished, so it is non-zero only when the execution client was slower than the transition, or never answered. The speculative transition is charged to stf whether the import used it or not, so the rows still sum to the end-to-end time: a held block keeps the transition it paid for, and an INVALIDATED verdict shows its transition twice. How long the execution client took is now its own histogram, lean_engine_new_payload_seconds{outcome}, observed in ask_request from the request to the answer, retry ladder included, with outcome valid, optimistic, invalidated or no_verdict. --- crates/blockchain/src/beacon_engine.rs | 28 ++++++- crates/blockchain/src/import_timing.rs | 72 +++++++++++++---- crates/blockchain/src/lib.rs | 107 ++++++++++++++----------- crates/blockchain/src/metrics.rs | 33 ++++++++ docs/beacon_engine.md | 10 ++- docs/benchmarking.md | 13 +-- docs/metrics.md | 7 +- 7 files changed, 193 insertions(+), 77 deletions(-) diff --git a/crates/blockchain/src/beacon_engine.rs b/crates/blockchain/src/beacon_engine.rs index b3733683b..14884b293 100644 --- a/crates/blockchain/src/beacon_engine.rs +++ b/crates/blockchain/src/beacon_engine.rs @@ -19,6 +19,8 @@ //! Gloas is the exception: its payload is revealed in an envelope, so its //! request ([`gloas_new_payload_request`]) needs the block and the envelope. +use std::time::Instant; + use ethlambda_engine::types::PayloadStatusValue; use ethlambda_engine::{EngineClient, EngineError, PayloadStatusV1}; use ethlambda_state_transition::beacon::containers::{self, SignedBeaconBlock}; @@ -211,19 +213,39 @@ impl NewPayloadRequest<'_> { /// The answer is read exactly as [`ask`] reads it: `Err` means no answer after /// the client's whole retry ladder, and there is no `Ok(None)` because a /// request existing means there was something to ask. +/// +/// The time from sending the request to the answer is observed as +/// `lean_engine_new_payload_seconds`, under the answer's [`outcome_label`]. pub async fn ask_request( client: &EngineClient, request: OwnedNewPayloadRequest, ) -> Result { - let status = client + let sent = Instant::now(); + let answer = client .new_payload( &request.execution_payload, &request.versioned_hashes, request.parent_beacon_block_root, &request.execution_requests, ) - .await?; - Ok(verdict(&status)) + .await + .map(|status| verdict(&status)); + crate::metrics::observe_engine_new_payload(outcome_label(&answer), sent.elapsed()); + answer +} + +/// The `outcome` an answer from [`ask_request`] is counted under. +/// +/// `not_required` is listed for completeness: a status from the execution +/// client always reads as one of the other three verdicts. +pub fn outcome_label(answer: &Result) -> &'static str { + match answer { + Ok(PayloadValidity::Validated) => "valid", + Ok(PayloadValidity::Optimistic) => "optimistic", + Ok(PayloadValidity::Invalidated { .. }) => "invalidated", + Ok(PayloadValidity::NotRequired) => "not_required", + Err(_) => "no_verdict", + } } /// Asks the execution client about `block`'s payload. diff --git a/crates/blockchain/src/import_timing.rs b/crates/blockchain/src/import_timing.rs index 01ff46266..e3b0daba8 100644 --- a/crates/blockchain/src/import_timing.rs +++ b/crates/blockchain/src/import_timing.rs @@ -176,10 +176,18 @@ pub struct ImportTimings { pub columns_wait_start: Option, pub columns_wait_end: Option, - /// Beacon: the `engine_newPayload` round trip, including its retry ladder. - /// I/O wait, not work. When the state transition ran meanwhile and was - /// used, this pair starts where that transition ended and so covers only - /// the wait that remained; see [`Self::stf_spec_start`]. + /// Beacon: how long the import sat waiting for the execution client's + /// verdict with no consensus work of its own left to do. I/O wait, not + /// work. + /// + /// The request is sent from a task of its own while the state transition + /// runs (see [`Self::stf_spec_start`]), so this pair starts where that + /// transition ended and ends when the answer arrived. Both are the same + /// instant, a recorded zero, when there was no request to send (no + /// execution client, or a block with no payload in it: pre-merge or + /// gloas) or when the answer was already in once the transition finished. + /// How long the execution client itself took is + /// `lean_engine_new_payload_seconds`, not this. pub engine_start: Option, pub engine_end: Option, @@ -200,17 +208,18 @@ pub struct ImportTimings { pub stf_end: Option, /// Beacon: a state transition computed while the execution client's - /// verdict was still in flight, and then used by the import. + /// verdict was still in flight, whether the import then used it or not. /// /// It runs before the `stf` pair above and overlaps the `engine_newPayload` /// round trip, so it is neither inside `stf_start`..`stf_end` nor a - /// section of its own: the `stf` row adds it, since it is the same - /// state-transition work done earlier. Meanwhile `engine_start` is moved to - /// this pair's end, so the `engine` row reports only the wait that was left - /// once the transition finished, and the rows still sum to the end-to-end - /// time instead of counting the overlap twice. `None` whenever the import - /// ran its own transition, which is every import without an execution - /// client and every one whose speculation was discarded. + /// section of its own: the `stf` row adds it, since it is state-transition + /// work. A discarded one is added too, so the transition an `INVALIDATED` + /// verdict makes `on_block` run again shows as the second transition it + /// is, and a held block still shows the one it paid for. The `engine` pair + /// starts at this pair's end, so the rows still sum to the end-to-end time + /// instead of counting the overlap twice. `None` whenever no request was + /// sent, which is every import without an execution client and every + /// block with no payload to ask about. pub stf_spec_start: Option, pub stf_spec_end: Option, @@ -393,10 +402,11 @@ impl ImportTimings { if let (Some(total), Some(wait)) = (stf.elapsed, writer_wait.elapsed) { stf.elapsed = Some(total.saturating_sub(wait)); } - if let (Some(total), Some(spec)) = - (stf.elapsed, span(self.stf_spec_start, self.stf_spec_end)) - { - stf.elapsed = Some(total + spec); + // Also when the import stopped before running its own transition (a + // held block), so the speculation it paid for is not lost. + if let Some(spec) = span(self.stf_spec_start, self.stf_spec_end) { + stf.elapsed = Some(stf.elapsed.unwrap_or_default() + spec); + stf.end = stf.end.or(self.stf_spec_end); } vec![ Row::new("decode", self.decode_start, self.decode_end), @@ -950,6 +960,36 @@ mod tests { ); } + #[test] + fn a_held_block_still_charges_its_speculation_to_stf() { + // No verdict: the 70 ms transition ran, then 300 ms of waiting, then + // the block was held without a transition of its own. + let base = Instant::now(); + let mut timings = ImportTimings::default(); + (timings.stf_spec_start, timings.stf_spec_end) = pair(base, 0, 70); + (timings.engine_start, timings.engine_end) = pair(base, 70, 300); + + assert_eq!( + row_elapsed(&timings, "stf"), + Some(Duration::from_millis(70)) + ); + assert_eq!( + row_elapsed(&timings, "engine"), + Some(Duration::from_millis(300)) + ); + } + + #[test] + fn an_engine_with_nothing_to_wait_for_is_a_recorded_zero() { + // No request sent, or the answer was in before the transition ended: + // the row is present and zero, so every beacon block observes it. + let base = Instant::now(); + let mut timings = ImportTimings::default(); + (timings.engine_start, timings.engine_end) = (Some(base), Some(base)); + + assert_eq!(row_elapsed(&timings, "engine"), Some(Duration::ZERO)); + } + #[test] fn a_writer_wait_longer_than_stf_saturates_stf_to_zero() { let base = Instant::now(); diff --git a/crates/blockchain/src/lib.rs b/crates/blockchain/src/lib.rs index 53a6fef24..1bfd4a064 100644 --- a/crates/blockchain/src/lib.rs +++ b/crates/blockchain/src/lib.rs @@ -1807,46 +1807,67 @@ impl BlockChainServer { // with the transition it assumed (see `SpeculativeTransition`). // Without an engine, or without a request to send (pre-merge // forks, gloas), nothing overlaps and the path is the old one. - timings.engine_start = Some(Instant::now()); + // + // The `engine` section is what the import waited once it had + // nothing left to do, so it starts as a recorded zero and only + // a request still unanswered when the transition is done + // widens it. The execution client's own time is + // `lean_engine_new_payload_seconds`, observed in + // `ask_request`. + let no_wait = Instant::now(); + (timings.engine_start, timings.engine_end) = (Some(no_wait), Some(no_wait)); let parent_root = beacon_block.parent_root(); - let mut speculation: Option<( - fork_choice::SpeculativeTransition, - Instant, - Instant, - )> = None; - let verdict: Result, String> = - match &self.engine { - None => Ok(None), - Some(client) => { - match beacon_engine::new_payload_request(&beacon_block) - .map(|request| request.into_owned()) - { - None => Ok(None), - Some(request) => { - let client = client.clone(); - let task = tokio::spawn(async move { - beacon_engine::ask_request(&client, request).await - }); - let spec_start = Instant::now(); - let computed = fork_choice::speculate_transition( - &self.store, - &beacon_block, - &config, - &committees, - ); - let spec_end = Instant::now(); - speculation = computed.map(|spec| (spec, spec_start, spec_end)); - // A panicked or cancelled task is no - // answer, like an exhausted retry ladder. - match task.await { - Ok(Ok(validity)) => Ok(Some(validity)), - Ok(Err(err)) => Err(err.to_string()), - Err(err) => Err(err.to_string()), - } + let mut speculation: Option = None; + let verdict: Result, String> = match &self + .engine + { + None => Ok(None), + Some(client) => { + match beacon_engine::new_payload_request(&beacon_block) + .map(|request| request.into_owned()) + { + None => Ok(None), + Some(request) => { + let client = client.clone(); + let task = tokio::spawn(async move { + let answer = beacon_engine::ask_request(&client, request).await; + (answer, Instant::now()) + }); + let spec_start = Instant::now(); + let computed = fork_choice::speculate_transition( + &self.store, + &beacon_block, + &config, + &committees, + ); + let spec_end = Instant::now(); + // Charged to `stf` whether or not the + // import ends up using it: it is + // state-transition work either way. + if computed.is_some() { + timings.stf_spec_start = Some(spec_start); + timings.stf_spec_end = Some(spec_end); } + speculation = computed; + // A panicked or cancelled task is no + // answer, like an exhausted retry ladder. + let (answer, answered_at) = match task.await { + Ok((answer, answered_at)) => ( + answer.map(Some).map_err(|err| err.to_string()), + answered_at, + ), + Err(err) => (Err(err.to_string()), Instant::now()), + }; + // The wait begins once the transition is + // done; an answer already in by then + // leaves it at zero. + timings.engine_start = Some(spec_end); + timings.engine_end = Some(answered_at.max(spec_end)); + answer } } - }; + } + }; let validity = match verdict { Ok(None) => fork_choice::PayloadValidity::NotRequired, Ok(Some(validity)) => validity, @@ -1868,11 +1889,9 @@ impl BlockChainServer { if speculation.is_some() { metrics::inc_engine_speculation("discarded_held"); } - timings.engine_end = Some(Instant::now()); return (timings, Ok(ImportOutcome::Held)); } }; - timings.engine_end = Some(Instant::now()); // An optimistic import is only permitted for a block that // qualifies. A block that does not, and got a NOT_VALIDATED @@ -1903,11 +1922,10 @@ impl BlockChainServer { // The speculation is only worth handing on for a verdict its // `valid()` engine agrees with. `INVALIDATED` makes `on_block` // run the transition itself with `invalid()`, exactly as - // before. A discarded speculation leaves `engine_start` where - // it was, so the `engine` row covers the whole overlap and - // the wasted transition is not hidden from the tree. + // before. A discarded speculation stays in the `stf` row, so + // the transition run twice shows as twice. let speculation = match speculation { - Some((spec, spec_start, spec_end)) => { + Some(spec) => { if !spec.is_for(block_root, parent_root) { metrics::inc_engine_speculation("discarded_mismatch"); None @@ -1919,11 +1937,6 @@ impl BlockChainServer { None } else { metrics::inc_engine_speculation("used"); - // The wait that remained once the transition was - // done; see `ImportTimings::stf_spec_start`. - timings.engine_start = Some(spec_end); - timings.stf_spec_start = Some(spec_start); - timings.stf_spec_end = Some(spec_end); Some(spec) } } diff --git a/crates/blockchain/src/metrics.rs b/crates/blockchain/src/metrics.rs index e0cd83a67..e801ee6b2 100644 --- a/crates/blockchain/src/metrics.rs +++ b/crates/blockchain/src/metrics.rs @@ -1534,6 +1534,39 @@ pub fn inc_engine_speculation(outcome: &str) { .inc(); } +/// How long the execution client took to answer `engine_newPayload` for a +/// block's payload, from sending the request to its answer, retry ladder +/// included. +/// +/// The import computes the block's state transition meanwhile, so this is not +/// what the import waited: that is `lean_block_import_phase_seconds`'s +/// `engine` phase, zero whenever the answer was in before the transition +/// finished. This is the execution client's own processing time, observed for +/// pre-gloas blocks only (a gloas payload is asked about with its envelope). +/// `outcome` is `valid`, `optimistic`, `invalidated` or `no_verdict` (no +/// answer after the whole ladder, so the time is the ladder's). +pub fn observe_engine_new_payload(outcome: &str, duration: Duration) { + static LEAN_ENGINE_NEW_PAYLOAD_SECONDS: std::sync::LazyLock = + std::sync::LazyLock::new(|| { + register_histogram_vec!( + "lean_engine_new_payload_seconds", + "Time the execution client took to answer engine_newPayload for a block, \ + retries included", + &["outcome"], + // Up to the retry ladder's worst case: three attempts at the + // per-attempt timeout plus the backoff between them. + vec![ + 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 0.75, 1.0, 1.5, 2.0, 3.0, 4.0, 6.0, + 8.0, 12.0, 16.0, 32.0, + ] + ) + .unwrap() + }); + LEAN_ENGINE_NEW_PAYLOAD_SECONDS + .with_label_values(&[outcome]) + .observe(duration.as_secs_f64()); +} + /// Blocks not imported because the execution client has not validated them and /// they do not qualify for an optimistic import. /// diff --git a/docs/beacon_engine.md b/docs/beacon_engine.md index d5d1502df..73cd135df 100644 --- a/docs/beacon_engine.md +++ b/docs/beacon_engine.md @@ -121,9 +121,13 @@ keeps it harmless: exhausted retry ladder. The overlap shows in the import timing tree: the transition that ran during the -round trip is reported under `stf`, and `engine` reports only the wait that was -left once it finished. Without an execution client, and for forks that have no -request to send (pre-merge, gloas), nothing overlaps and the path is the old one. +round trip is reported under `stf` (used or discarded), and `engine` reports only +the wait that was left once it finished, a recorded zero when the answer was +already in. Without an execution client, and for forks that have no request to +send (pre-merge, gloas), nothing overlaps, `engine` is zero, and the path is the +old one. How long the execution client itself took to answer is +`lean_engine_new_payload_seconds{outcome}`, timed around the request in +`ask_request`. ## The verdicts diff --git a/docs/benchmarking.md b/docs/benchmarking.md index 088faa3ad..0734caf1b 100644 --- a/docs/benchmarking.md +++ b/docs/benchmarking.md @@ -279,16 +279,19 @@ faster than the writer persists them, the wait shows up here rather than in With an execution client the beacon `stf` row also includes a state transition that ran while `engine_newPayload` was in flight, and `engine` then -reports only the wait left after it. A replay has no client, so neither applies -to its numbers. +reports only the wait left after it, zero when the answer was already in. The +execution client's own time is `lean_engine_new_payload_seconds`. A replay has +no client, so none of this applies to its numbers. ### What is excluded, and why Replay runs nothing that a corpus already answers for: -- **No execution client**, so `engine` reports a near-zero section with nothing - to call and `fcu` never runs. On a live follower paired with one, `engine` was - 31ms p50, about 0.5% of an import; a replay's numbers are complete without it. +- **No execution client**, so `engine` reports a zero section with nothing to + call and `fcu` never runs. On a live follower paired with one, the + `engine_newPayload` round trip was 31ms p50, about 0.5% of an import, before + the state transition was overlapped with it; a replay's numbers are complete + without it. - **An empty custody set**, so `columns_wait` never runs and no block is ever held waiting on data availability. A corpus supplies every block directly; there are no columns to wait for. diff --git a/docs/metrics.md b/docs/metrics.md index 441abd8c5..357e38770 100644 --- a/docs/metrics.md +++ b/docs/metrics.md @@ -253,7 +253,7 @@ The bookkeeping an import triggers (chain-event emission, the finality eviction On the beacon wire, `decode` for `source="gossip"` spans more than its name says. `BlockArrival::decode_start` is still the wire arrival, but `handed_off` is stamped only once the block has a gossip verdict, so the section also covers the cheap, stateless checks, the stateful check's own `spawn_blocking` task, and the verdict's trip back through the p2p actor's mailbox. There is no wait for a free validation slot to attribute here either: `try_acquire_owned` never blocks, and a message arriving with none free is reported `Ignore(Overloaded)` (and still forwarded to the chain actor) rather than queued. A rising `decode` on the beacon wire alone therefore does not mean decoding got slower; check `lean_beacon_gossip_validation_seconds` before assuming so. -`engine` and `fcu` are execution-client round trips. They are I/O waits rather than work, so a node whose import time is dominated by them is waiting on its execution client, not spending CPU. +`engine` and `fcu` are execution-client waits. They are I/O waits rather than work, so a node whose import time is dominated by them is waiting on its execution client, not spending CPU. `engine` is only the part of the `engine_newPayload` round trip the import could not hide behind its own state transition, so it is zero for most blocks; the round trip itself is `lean_engine_new_payload_seconds`. The `source` label has two values, `gossip` and `sync` (req/resp backfill). Two populations are deliberately absent. A block re-delivered to itself because its slot had not started reports under the source it first arrived on, since the hold is already visible as its `defer` section and a third label value would take the block out of the population it belongs to for every section it has left. A block this node built itself is not measured at all: it crossed no wire, so it has no `decode` and an empty `queue` taken when the import began. Both still appear in the log, which names them `deferred` and `local`. @@ -263,6 +263,7 @@ Series appear as blocks arrive rather than being seeded, since a third of the ph |------|------|-------|-------------------------|--------|---------| | `lean_block_import_phase_seconds` | Histogram | Time one section of a block's import, or of the arrival carrying it, took | Per section that ran, on each import, hold or failure | phase (see below); source=gossip,sync | 0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 0.75, 1, 1.5, 2, 3, 4, 6, 8, 12, 16, 32 | | `lean_engine_speculation_total` | Counter | State transitions the chain actor ran while the `engine_newPayload` round trip was in flight, by what became of them | Per beacon block asked of an execution client | outcome=used,discarded_invalidated,discarded_held,discarded_mismatch | | +| `lean_engine_new_payload_seconds` | Histogram | Time the execution client took to answer `engine_newPayload` for a pre-gloas block, from the request to the answer, retry ladder included. The import runs the state transition meanwhile, so this is the execution client's processing time, not what the import waited (the `engine` phase) | Per beacon block asked of an execution client | outcome=valid,optimistic,invalidated,no_verdict | 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 0.75, 1, 1.5, 2, 3, 4, 6, 8, 12, 16, 32 | | `lean_block_import_cascade_blocks` | Histogram | Blocks one arrival put through the import path (attempts, so a block that ends held or pended counts) | Once per arriving block message | | 1, 2, 3, 5, 8, 16, 32, 64, 128 | Per-block phases, in the order a block crosses them, plus `total` for a completed import: @@ -278,10 +279,10 @@ Per-block phases, in the order a block crosses them, plus `total` for a complete | `cascade_wait` | Between the parent's import finishing and this block being popped off the cascade queue | both | | `da_check` | The custody-column availability check itself, not the wait | beacon | | `columns_wait` | Held because custody columns had not all arrived | beacon | -| `engine` | The `engine_newPayload` round trip, including its retry ladder. When the state transition ran meanwhile and was used, only the wait left after it finished | beacon | +| `engine` | The wait for the `engine_newPayload` verdict left once the state transition that ran meanwhile finished. Observed as `0` for every beacon block whose answer was already in by then, and for every block with no request to send (no execution client, pre-merge, gloas). Non-zero only when the execution client was slower than the transition, or gave no answer (the rest of its retry ladder, block held) | beacon | | `verify_struct` | Participant bounds checks and pubkey resolution | lean | | `verify_crypto` | The leanVM multi-message aggregate verification | lean | -| `stf` | The state transition. On beacon this bundles the transition and the state root, and excludes `writer_wait`, which is nested inside it. It includes a transition that ran during the `engine` round trip | both | +| `stf` | The state transition. On beacon this bundles the transition and the state root, and excludes `writer_wait`, which is nested inside it. It includes the transition that ran during the `engine_newPayload` round trip, also when that one was then discarded and run again (an `INVALIDATED` verdict) or the block was held | both | | `writer_wait` | Beacon only: the importer's blocking hand-off of the post-state to the storage crate's background writer, which waits while the writer's queue is full. Subtracted from `stf`, so `stf` and `writer_wait` do not overlap | beacon | | `db_write` | The block write and handing the post-state off to the storage crate's background writer; the state's own encode/diff/commit cost is `lean_state_write_seconds` instead, not this row | lean | | `fc_head` | `update_head` | lean | From 088dfc2df293bfa00352d7f7789533a885923630 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1s=20Gr=C3=BCner?= <47506558+MegaRedHand@users.noreply.github.com> Date: Mon, 2 Nov 2026 11:12:31 -0300 Subject: [PATCH 3/3] perf(blockchain): time a gloas envelope's newPayload with the same metric lean_engine_new_payload_seconds covered only a pre-gloas block's payload, so from gloas on, when the payload is revealed in an envelope and asked about with engine_newPayloadV5, the execution client's time went unmeasured. Every newPayload request now goes through one helper, timed_new_payload, which observes the time from sending it to its answer under the verdict it reads as: the block path (ask_request, and ask) and the envelope path (ask_envelope_status, which ask_envelope also goes through) alike. An envelope refused before a request is sent, because it does not match its block, is not observed. --- crates/blockchain/src/beacon_engine.rs | 87 +++++++++++++++----------- crates/blockchain/src/lib.rs | 4 +- crates/blockchain/src/metrics.rs | 25 ++++---- docs/beacon_engine.md | 4 +- docs/metrics.md | 2 +- 5 files changed, 67 insertions(+), 55 deletions(-) diff --git a/crates/blockchain/src/beacon_engine.rs b/crates/blockchain/src/beacon_engine.rs index 14884b293..9707eb5f2 100644 --- a/crates/blockchain/src/beacon_engine.rs +++ b/crates/blockchain/src/beacon_engine.rs @@ -213,38 +213,51 @@ impl NewPayloadRequest<'_> { /// The answer is read exactly as [`ask`] reads it: `Err` means no answer after /// the client's whole retry ladder, and there is no `Ok(None)` because a /// request existing means there was something to ask. -/// -/// The time from sending the request to the answer is observed as -/// `lean_engine_new_payload_seconds`, under the answer's [`outcome_label`]. pub async fn ask_request( client: &EngineClient, request: OwnedNewPayloadRequest, ) -> Result { + let call = client.new_payload( + &request.execution_payload, + &request.versioned_hashes, + request.parent_beacon_block_root, + &request.execution_requests, + ); + let status = timed_new_payload(call).await?; + Ok(verdict(&status)) +} + +/// Awaits `call`, one `engine_newPayload*` request, and observes the time from +/// sending it to its answer as `lean_engine_new_payload_seconds`, under the +/// [`outcome_label`] of the verdict the answer reads as. +/// +/// Every request this module sends goes through here, a block's payload and an +/// envelope's alike, so the metric is the execution client's time for every +/// payload it was asked about. A request refused before it is sent (an +/// envelope that does not match its block) never reaches it. +async fn timed_new_payload( + call: impl Future>, +) -> Result { let sent = Instant::now(); - let answer = client - .new_payload( - &request.execution_payload, - &request.versioned_hashes, - request.parent_beacon_block_root, - &request.execution_requests, - ) - .await - .map(|status| verdict(&status)); - crate::metrics::observe_engine_new_payload(outcome_label(&answer), sent.elapsed()); - answer + let status = call.await; + let validity = status.as_ref().ok().map(verdict); + let outcome = outcome_label(validity.as_ref()); + crate::metrics::observe_engine_new_payload(outcome, sent.elapsed()); + status } -/// The `outcome` an answer from [`ask_request`] is counted under. +/// The `outcome` an answer is counted under: its verdict, or `no_verdict` +/// when the retry ladder ran out without one. /// /// `not_required` is listed for completeness: a status from the execution /// client always reads as one of the other three verdicts. -pub fn outcome_label(answer: &Result) -> &'static str { - match answer { - Ok(PayloadValidity::Validated) => "valid", - Ok(PayloadValidity::Optimistic) => "optimistic", - Ok(PayloadValidity::Invalidated { .. }) => "invalidated", - Ok(PayloadValidity::NotRequired) => "not_required", - Err(_) => "no_verdict", +pub fn outcome_label(verdict: Option<&PayloadValidity>) -> &'static str { + match verdict { + Some(PayloadValidity::Validated) => "valid", + Some(PayloadValidity::Optimistic) => "optimistic", + Some(PayloadValidity::Invalidated { .. }) => "invalidated", + Some(PayloadValidity::NotRequired) => "not_required", + None => "no_verdict", } } @@ -262,14 +275,13 @@ pub async fn ask( let Some(request) = new_payload_request(block) else { return Ok(None); }; - let status = client - .new_payload( - request.execution_payload, - &request.versioned_hashes, - request.parent_beacon_block_root, - &request.execution_requests, - ) - .await?; + let call = client.new_payload( + request.execution_payload, + &request.versioned_hashes, + request.parent_beacon_block_root, + &request.execution_requests, + ); + let status = timed_new_payload(call).await?; Ok(Some(verdict(&status))) } @@ -300,14 +312,13 @@ pub async fn ask_envelope_status( envelope: &containers::gloas::SignedExecutionPayloadEnvelope, ) -> Result { let request = gloas_new_payload_request(block, envelope)?; - client - .new_payload_v5( - request.execution_payload, - &request.versioned_hashes, - request.parent_beacon_block_root, - &request.execution_requests, - ) - .await + let call = client.new_payload_v5( + request.execution_payload, + &request.versioned_hashes, + request.parent_beacon_block_root, + &request.execution_requests, + ); + timed_new_payload(call).await } #[cfg(test)] diff --git a/crates/blockchain/src/lib.rs b/crates/blockchain/src/lib.rs index 1bfd4a064..446c8610d 100644 --- a/crates/blockchain/src/lib.rs +++ b/crates/blockchain/src/lib.rs @@ -1812,8 +1812,8 @@ impl BlockChainServer { // nothing left to do, so it starts as a recorded zero and only // a request still unanswered when the transition is done // widens it. The execution client's own time is - // `lean_engine_new_payload_seconds`, observed in - // `ask_request`. + // `lean_engine_new_payload_seconds`, observed around the + // request itself. let no_wait = Instant::now(); (timings.engine_start, timings.engine_end) = (Some(no_wait), Some(no_wait)); let parent_root = beacon_block.parent_root(); diff --git a/crates/blockchain/src/metrics.rs b/crates/blockchain/src/metrics.rs index e801ee6b2..c9ac2c754 100644 --- a/crates/blockchain/src/metrics.rs +++ b/crates/blockchain/src/metrics.rs @@ -1534,24 +1534,25 @@ pub fn inc_engine_speculation(outcome: &str) { .inc(); } -/// How long the execution client took to answer `engine_newPayload` for a -/// block's payload, from sending the request to its answer, retry ladder -/// included. +/// How long the execution client took to answer `engine_newPayload*` for a +/// payload, from sending the request to its answer, retry ladder included: +/// a pre-gloas block's payload, and from gloas on the payload an envelope +/// reveals. /// -/// The import computes the block's state transition meanwhile, so this is not -/// what the import waited: that is `lean_block_import_phase_seconds`'s -/// `engine` phase, zero whenever the answer was in before the transition -/// finished. This is the execution client's own processing time, observed for -/// pre-gloas blocks only (a gloas payload is asked about with its envelope). -/// `outcome` is `valid`, `optimistic`, `invalidated` or `no_verdict` (no -/// answer after the whole ladder, so the time is the ladder's). +/// For a pre-gloas block the import computes the state transition meanwhile, +/// so this is not what the import waited: that is +/// `lean_block_import_phase_seconds`'s `engine` phase, zero whenever the +/// answer was in before the transition finished. This is the execution +/// client's own processing time. `outcome` is `valid`, `optimistic`, +/// `invalidated` or `no_verdict` (no answer after the whole ladder, so the +/// time is the ladder's). pub fn observe_engine_new_payload(outcome: &str, duration: Duration) { static LEAN_ENGINE_NEW_PAYLOAD_SECONDS: std::sync::LazyLock = std::sync::LazyLock::new(|| { register_histogram_vec!( "lean_engine_new_payload_seconds", - "Time the execution client took to answer engine_newPayload for a block, \ - retries included", + "Time the execution client took to answer engine_newPayload for a block's \ + or an envelope's payload, retries included", &["outcome"], // Up to the retry ladder's worst case: three attempts at the // per-attempt timeout plus the backoff between them. diff --git a/docs/beacon_engine.md b/docs/beacon_engine.md index 73cd135df..621fd34b4 100644 --- a/docs/beacon_engine.md +++ b/docs/beacon_engine.md @@ -126,8 +126,8 @@ the wait that was left once it finished, a recorded zero when the answer was already in. Without an execution client, and for forks that have no request to send (pre-merge, gloas), nothing overlaps, `engine` is zero, and the path is the old one. How long the execution client itself took to answer is -`lean_engine_new_payload_seconds{outcome}`, timed around the request in -`ask_request`. +`lean_engine_new_payload_seconds{outcome}`, timed around every `engine_newPayload*` +request this module sends (`timed_new_payload`), a gloas envelope's included. ## The verdicts diff --git a/docs/metrics.md b/docs/metrics.md index 357e38770..cea7a6a90 100644 --- a/docs/metrics.md +++ b/docs/metrics.md @@ -263,7 +263,7 @@ Series appear as blocks arrive rather than being seeded, since a third of the ph |------|------|-------|-------------------------|--------|---------| | `lean_block_import_phase_seconds` | Histogram | Time one section of a block's import, or of the arrival carrying it, took | Per section that ran, on each import, hold or failure | phase (see below); source=gossip,sync | 0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 0.75, 1, 1.5, 2, 3, 4, 6, 8, 12, 16, 32 | | `lean_engine_speculation_total` | Counter | State transitions the chain actor ran while the `engine_newPayload` round trip was in flight, by what became of them | Per beacon block asked of an execution client | outcome=used,discarded_invalidated,discarded_held,discarded_mismatch | | -| `lean_engine_new_payload_seconds` | Histogram | Time the execution client took to answer `engine_newPayload` for a pre-gloas block, from the request to the answer, retry ladder included. The import runs the state transition meanwhile, so this is the execution client's processing time, not what the import waited (the `engine` phase) | Per beacon block asked of an execution client | outcome=valid,optimistic,invalidated,no_verdict | 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 0.75, 1, 1.5, 2, 3, 4, 6, 8, 12, 16, 32 | +| `lean_engine_new_payload_seconds` | Histogram | Time the execution client took to answer `engine_newPayload*`, from the request to the answer, retry ladder included: a pre-gloas block's payload, or from gloas on the payload an envelope reveals. For a block the import runs the state transition meanwhile, so this is the execution client's processing time, not what the import waited (the `engine` phase) | Per request sent: each pre-gloas beacon block, and each gloas envelope that passed its consensus checks | outcome=valid,optimistic,invalidated,no_verdict | 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 0.75, 1, 1.5, 2, 3, 4, 6, 8, 12, 16, 32 | | `lean_block_import_cascade_blocks` | Histogram | Blocks one arrival put through the import path (attempts, so a block that ends held or pended counts) | Once per arriving block message | | 1, 2, 3, 5, 8, 16, 32, 64, 128 | Per-block phases, in the order a block crosses them, plus `total` for a completed import: