From 2eed86142927d6e416e17ee0d5f6c05ffb2fbd81 Mon Sep 17 00:00:00 2001 From: James Date: Wed, 12 Nov 2025 13:30:05 -0500 Subject: [PATCH] feat: record metrics for extraction and processing --- crates/block-processor/src/metrics.rs | 45 +++++++++++++++++++++- crates/block-processor/src/v1/processor.rs | 8 +++- 2 files changed, 51 insertions(+), 2 deletions(-) diff --git a/crates/block-processor/src/metrics.rs b/crates/block-processor/src/metrics.rs index 601af62..bb17835 100644 --- a/crates/block-processor/src/metrics.rs +++ b/crates/block-processor/src/metrics.rs @@ -14,6 +14,7 @@ //! - transact events processed //! - Transaction counts per builder block +use alloy::consensus::BlockHeader; use metrics::{Counter, Histogram, counter, describe_counter, describe_histogram, histogram}; use signet_evm::BlockResult; use signet_extract::{Extractable, Extracts, HasTxns}; @@ -56,6 +57,16 @@ const ENTER_TOKEN_PROCESSED_HELP: &str = const TRANSACT_PROCESSED: &str = "signet.block_processor.transact_events.processed"; const TRANSACT_PROCESSED_HELP: &str = "Histogram of number of transact events processed per block"; +const EXTRACTION_TIME: &str = "signet.block_processor.extraction.time"; +const EXTRACTION_TIME_HELP: &str = "Time taken to extract signet outputs from a host notification. Note: sometimes the extraction includes multiple blocks."; + +const PROCESSING_TIME: &str = "signet.block_processor.processing.time"; +const PROCESSING_TIME_HELP: &str = + "Time taken to process a single signet block from extracts, in milliseconds."; + +const BLOCK_GAS_USED: &str = "signet.block_processor.block.gas_used"; +const BLOCK_GAS_USED_HELP: &str = "Gas used per signet block processed."; + static DESCRIBE: LazyLock<()> = LazyLock::new(|| { describe_counter!(BUILDER_BLOCKS_EXTRACTED, BUILDER_BLOCKS_EXTRACTED_HELP); describe_counter!(BLOCKS_PROCESSED, BLOCKS_PROCESSED_HELP); @@ -69,6 +80,9 @@ static DESCRIBE: LazyLock<()> = LazyLock::new(|| { describe_histogram!(ENTER_PROCESSED, ENTER_PROCESSED_HELP); describe_histogram!(ENTER_TOKEN_PROCESSED, ENTER_TOKEN_PROCESSED_HELP); describe_histogram!(TRANSACT_PROCESSED, TRANSACT_PROCESSED_HELP); + describe_histogram!(EXTRACTION_TIME, EXTRACTION_TIME_HELP); + describe_histogram!(PROCESSING_TIME, PROCESSING_TIME_HELP); + describe_histogram!(BLOCK_GAS_USED, BLOCK_GAS_USED_HELP); }); fn blocks_extracted() -> Counter { @@ -170,6 +184,33 @@ fn record_transacts_processed(value: u64) { transacts_processed().record(value as f64); } +fn extraction_time() -> Histogram { + LazyLock::force(&DESCRIBE); + histogram!(EXTRACTION_TIME) +} + +pub(crate) fn record_extraction_time(started_at: &std::time::Instant) { + extraction_time().record(started_at.elapsed().as_millis() as f64); +} + +fn processing_time() -> Histogram { + LazyLock::force(&DESCRIBE); + histogram!(PROCESSING_TIME) +} + +fn record_processing_time(started_at: &std::time::Instant) { + processing_time().record(started_at.elapsed().as_millis() as f64); +} + +fn block_gas_used() -> Histogram { + LazyLock::force(&DESCRIBE); + histogram!(BLOCK_GAS_USED) +} + +fn record_block_gas_used(value: u64) { + block_gas_used().record(value as f64); +} + pub(crate) fn record_extracts(extracts: &Extracts<'_, T>) { record_enter_extracts(extracts.enters.len() as u64); record_enter_token_events(extracts.enter_tokens.len() as u64); @@ -181,9 +222,10 @@ pub(crate) fn record_extracts(extracts: &Extracts<'_, T>) { } } -pub(crate) fn record_block_result(block: &BlockResult) { +pub(crate) fn record_block_result(block: &BlockResult, started_at: &std::time::Instant) { inc_blocks_processed(); inc_transactions_processed(block.sealed_block.transactions().len() as u64); + record_processing_time(started_at); // find the index of the first magic sig transaction // That index is the count of builder block transactions @@ -212,6 +254,7 @@ pub(crate) fn record_block_result(block: &BlockResult) { }; } + record_block_gas_used(block.sealed_block().gas_used()); record_transactions_per_builder_block(txns_processed as u64); record_enters_processed(enters); record_enter_token_processed(enter_tokens); diff --git a/crates/block-processor/src/v1/processor.rs b/crates/block-processor/src/v1/processor.rs index 66ada78..9897a87 100644 --- a/crates/block-processor/src/v1/processor.rs +++ b/crates/block-processor/src/v1/processor.rs @@ -129,10 +129,14 @@ where return Ok(None); } + let start_time = std::time::Instant::now(); + let extractor = Extractor::new(self.constants.clone()); let shim = ExtractableChainShim::new(chain); let outputs = extractor.extract_signet(&shim); + metrics::record_extraction_time(&start_time); + // TODO: ENG-481 Inherit prune modes from Reth configuration. // https://linear.app/initiates/issue/ENG-481/inherit-prune-modes-from-reth-node @@ -168,6 +172,8 @@ where } metrics::record_extracts(&block_extracts); + + let start_time = std::time::Instant::now(); current = block_extracts.ru_height; let spec_id = self.spec_id(block_extracts.host_block.timestamp()); @@ -181,7 +187,7 @@ where tracing::trace!("Running EVM"); let block_result = self.run_evm(&block_extracts, spec_id).instrument(span).await?; - metrics::record_block_result(&block_result); + metrics::record_block_result(&block_result, &start_time); tracing::trace!("Committing EVM results"); let journal =