From c13fb2fb46e5f982d5f68d4f82ee4ee65b49b137 Mon Sep 17 00:00:00 2001 From: Jimmy Chen Date: Thu, 28 Aug 2025 13:31:29 +1000 Subject: [PATCH] Instrument `publish_block` code path (#7945) Instrument `publish_block` code path and log dropped data columns when publishing. Example spans (running the devnet from my laptop, so the numbers aren't great) image image --- Cargo.lock | 1 + beacon_node/beacon_chain/src/beacon_chain.rs | 1 + beacon_node/http_api/Cargo.toml | 1 + beacon_node/http_api/src/publish_blocks.rs | 28 +++++++++++++++++--- beacon_node/lighthouse_tracing/src/lib.rs | 3 +++ 5 files changed, 30 insertions(+), 4 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5e89dc2a90..14f8d5cbaa 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4284,6 +4284,7 @@ dependencies = [ "health_metrics", "hex", "lighthouse_network", + "lighthouse_tracing", "lighthouse_version", "logging", "lru", diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index d5a2929301..4358e4a872 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -3059,6 +3059,7 @@ impl BeaconChain { /// Cache the data columns in the processing cache, process it, then evict it from the cache if it was /// imported or errors. + #[instrument(skip_all, level = "debug")] pub async fn process_gossip_data_columns( self: &Arc, data_columns: Vec>, diff --git a/beacon_node/http_api/Cargo.toml b/beacon_node/http_api/Cargo.toml index 781a4cfa44..2061df3762 100644 --- a/beacon_node/http_api/Cargo.toml +++ b/beacon_node/http_api/Cargo.toml @@ -20,6 +20,7 @@ futures = { workspace = true } health_metrics = { workspace = true } hex = { workspace = true } lighthouse_network = { workspace = true } +lighthouse_tracing = { workspace = true } lighthouse_version = { workspace = true } logging = { workspace = true } lru = { workspace = true } diff --git a/beacon_node/http_api/src/publish_blocks.rs b/beacon_node/http_api/src/publish_blocks.rs index 6377639ccd..f797e3f300 100644 --- a/beacon_node/http_api/src/publish_blocks.rs +++ b/beacon_node/http_api/src/publish_blocks.rs @@ -16,6 +16,7 @@ use eth2::types::{ use execution_layer::{ProvenancedPayload, SubmitBlindedBlockResponse}; use futures::TryFutureExt; use lighthouse_network::PubsubMessage; +use lighthouse_tracing::SPAN_PUBLISH_BLOCK; use network::NetworkMessage; use rand::prelude::SliceRandom; use slot_clock::SlotClock; @@ -24,7 +25,7 @@ use std::sync::Arc; use std::sync::atomic::{AtomicBool, Ordering}; use std::time::Duration; use tokio::sync::mpsc::UnboundedSender; -use tracing::{debug, error, info, warn}; +use tracing::{Span, debug, debug_span, error, info, instrument, warn}; use tree_hash::TreeHash; use types::{ AbstractExecPayload, BeaconBlockRef, BlobSidecar, BlobsList, BlockImportSource, @@ -75,6 +76,12 @@ impl ProvenancedBlock> /// Handles a request from the HTTP API for full blocks. #[allow(clippy::too_many_arguments)] +#[instrument( + name = SPAN_PUBLISH_BLOCK, + level = "info", + skip_all, + fields(?block_root, ?validation_level, provenance = tracing::field::Empty) +)] pub async fn publish_block>( block_root: Option, provenanced_block: ProvenancedBlock, @@ -96,6 +103,9 @@ pub async fn publish_block>( } else { "builder" }; + let current_span = Span::current(); + current_span.record("provenance", provenance); + let block = unverified_block.inner_block(); debug!(slot = %block.slot(), "Signed block received in HTTP API"); @@ -133,8 +143,12 @@ pub async fn publish_block>( let slot = block.message().slot(); let sender_clone = network_tx.clone(); - let build_sidecar_task_handle = - spawn_build_data_sidecar_task(chain.clone(), block.clone(), unverified_blobs)?; + let build_sidecar_task_handle = spawn_build_data_sidecar_task( + chain.clone(), + block.clone(), + unverified_blobs, + current_span.clone(), + )?; // Gossip verify the block and blobs/data columns separately. let gossip_verified_block_result = unverified_block.into_gossip_verified_block(&chain); @@ -347,6 +361,7 @@ fn spawn_build_data_sidecar_task( chain: Arc>, block: Arc>>, proofs_and_blobs: UnverifiedBlobs, + current_span: Span, ) -> Result>, Rejection> { chain .clone() @@ -356,6 +371,7 @@ fn spawn_build_data_sidecar_task( let Some((kzg_proofs, blobs)) = proofs_and_blobs else { return Ok((vec![], vec![])); }; + let _guard = debug_span!(parent: current_span, "build_data_sidecars").entered(); let peer_das_enabled = chain.spec.is_peer_das_enabled_for_epoch(block.epoch()); if !peer_das_enabled { @@ -532,7 +548,11 @@ fn publish_column_sidecars( .saturating_sub(malicious_withhold_count); // Randomize columns before dropping the last malicious_withhold_count items data_column_sidecars.shuffle(&mut **chain.rng.lock()); - data_column_sidecars.truncate(columns_to_keep); + let dropped_indices = data_column_sidecars + .drain(columns_to_keep..) + .map(|d| d.index) + .collect::>(); + debug!(indices = ?dropped_indices, "Dropping data columns from publishing"); } let pubsub_messages = data_column_sidecars .into_iter() diff --git a/beacon_node/lighthouse_tracing/src/lib.rs b/beacon_node/lighthouse_tracing/src/lib.rs index a69428d5bd..ffbad1364c 100644 --- a/beacon_node/lighthouse_tracing/src/lib.rs +++ b/beacon_node/lighthouse_tracing/src/lib.rs @@ -3,6 +3,9 @@ //! TODO: These span identifiers will be used to implement selective tracing export (to be implemented), //! where only the listed root spans and their descendants will be exported to the tracing backend. +/// Root span name for publish_block +pub const SPAN_PUBLISH_BLOCK: &str = "publish_block"; + /// Data Availability checker span identifiers pub const SPAN_PENDING_COMPONENTS: &str = "pending_components";