diff --git a/crates/blockchain/src/beacon_engine.rs b/crates/blockchain/src/beacon_engine.rs index 38f34c39e..9707eb5f2 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}; @@ -178,6 +180,87 @@ 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 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 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 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(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", + } +} + /// Asks the execution client about `block`'s payload. /// /// `Ok(None)` means there was nothing to ask, which is not a failure: @@ -192,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))) } @@ -230,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/import_timing.rs b/crates/blockchain/src/import_timing.rs index 6625a472f..e3b0daba8 100644 --- a/crates/blockchain/src/import_timing.rs +++ b/crates/blockchain/src/import_timing.rs @@ -176,8 +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. + /// 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, @@ -197,6 +207,22 @@ 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, 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 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, + /// 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 +402,12 @@ impl ImportTimings { if let (Some(total), Some(wait)) = (stf.elapsed, writer_wait.elapsed) { stf.elapsed = Some(total.saturating_sub(wait)); } + // 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), Row::new("queue", self.queue_start, self.queue_end), @@ -897,6 +929,67 @@ 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_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 251048b7a..446c8610d 100644 --- a/crates/blockchain/src/lib.rs +++ b/crates/blockchain/src/lib.rs @@ -1796,40 +1796,108 @@ 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. - 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)); + // + // 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. + // + // 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 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(); + 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, + // 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"); + } + 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 // 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 +1912,49 @@ 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 stays in the `stf` row, so + // the transition run twice shows as twice. + let speculation = match speculation { + Some(spec) => { + 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"); + 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..c9ac2c754 100644 --- a/crates/blockchain/src/metrics.rs +++ b/crates/blockchain/src/metrics.rs @@ -1507,6 +1507,67 @@ 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(); +} + +/// 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. +/// +/// 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'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. + 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/crates/blockchain/state_transition/src/beacon/fork_choice.rs b/crates/blockchain/state_transition/src/beacon/fork_choice.rs index ac83d85fe..4bb945798 100644 --- a/crates/blockchain/state_transition/src/beacon/fork_choice.rs +++ b/crates/blockchain/state_transition/src/beacon/fork_choice.rs @@ -4789,6 +4789,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(); @@ -4961,17 +5074,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 @@ -7123,34 +7243,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(); @@ -7216,7 +7315,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 @@ -7241,6 +7339,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"); @@ -7272,6 +7403,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..621fd34b4 100644 --- a/docs/beacon_engine.md +++ b/docs/beacon_engine.md @@ -91,6 +91,44 @@ 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` (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 every `engine_newPayload*` +request this module sends (`timed_new_payload`), a gloas envelope's included. + ## 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..0734caf1b 100644 --- a/docs/benchmarking.md +++ b/docs/benchmarking.md @@ -277,13 +277,21 @@ 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, 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 9ac92fd4f..a5b085623 100644 --- a/docs/metrics.md +++ b/docs/metrics.md @@ -260,7 +260,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`. @@ -269,6 +269,8 @@ 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_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: @@ -284,10 +286,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 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 | 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 |