diff --git a/crates/op-rbuilder/src/builder/context.rs b/crates/op-rbuilder/src/builder/context.rs index 1119b050..fd20a591 100644 --- a/crates/op-rbuilder/src/builder/context.rs +++ b/crates/op-rbuilder/src/builder/context.rs @@ -452,6 +452,19 @@ impl OpPayloadBuilderCtx { let tx_hash = tx.tx_hash(); let tx_uncompressed_size = tx.encode_2718_len() as u64; + if std::env::var("ENABLE_TX_TRACKING_DEBUG_LOGS") + .map(|v| v.eq_ignore_ascii_case("true")) + .unwrap_or(false) + { + debug!( + target: "tx_trace", + tx_hash = ?tx_hash, + block_number = self.block_number(), + flashblock_index, + stage = "builder_popped" + ); + } + // exclude reverting transaction if: // - the transaction comes from a bundle (is_some) and the hash **is not** in reverted hashes // Note that we need to use the Option to signal whether the transaction comes from a bundle, @@ -563,6 +576,21 @@ impl OpPayloadBuilderCtx { // reverted or not, as this is a check against maliciously searchers // sending txs that are expensive to compute but always revert. let gas_used = result.gas_used(); + if std::env::var("ENABLE_TX_TRACKING_DEBUG_LOGS") + .map(|v| v.eq_ignore_ascii_case("true")) + .unwrap_or(false) + { + debug!( + target: "tx_trace", + tx_hash = ?tx_hash, + block_number = self.block_number(), + flashblock_index, + gas_used, + success = result.is_success(), + evm_duration_us = tx_simulation_start_time.elapsed().as_micros() as u64, + stage = "evm_executed" + ); + } if self .address_gas_limiter .consume_gas(tx.signer(), gas_used) @@ -637,6 +665,20 @@ impl OpPayloadBuilderCtx { info.executed_senders.push(tx.signer()); info.executed_transactions.push(tx.into_inner()); + if std::env::var("ENABLE_TX_TRACKING_DEBUG_LOGS") + .map(|v| v.eq_ignore_ascii_case("true")) + .unwrap_or(false) + { + debug!( + target: "tx_trace", + tx_hash = ?target_hash, + block_number = self.block_number(), + flashblock_index, + cumulative_gas = info.cumulative_gas_used, + stage = "builder_committed" + ); + } + let can_backrun = self.backrun_ctx.args.backruns_enabled && tx_succeeded && !self.backrun_ctx.args.is_limit_reached( diff --git a/crates/op-rbuilder/src/builder/payload.rs b/crates/op-rbuilder/src/builder/payload.rs index 26e8b27b..e5179ae3 100644 --- a/crates/op-rbuilder/src/builder/payload.rs +++ b/crates/op-rbuilder/src/builder/payload.rs @@ -498,6 +498,20 @@ where .ws_pub .publish(&fb_payload) .map_err(PayloadBuilderError::other)?; + if std::env::var("ENABLE_TX_TRACKING_DEBUG_LOGS") + .map(|v| v.eq_ignore_ascii_case("true")) + .unwrap_or(false) + { + debug!( + target: "tx_trace", + payload_id = %ctx.payload_id(), + block_number = ctx.block_number(), + flashblock_index = fb_payload.index, + byte_size = flashblock_byte_size, + total_txs = info.executed_transactions.len(), + stage = "fb_published" + ); + } ctx.metrics .flashblock_byte_size_histogram .record(flashblock_byte_size as f64); @@ -874,6 +888,20 @@ where .ws_pub .publish(&fb_payload) .wrap_err("failed to publish flashblock via websocket")?; + if std::env::var("ENABLE_TX_TRACKING_DEBUG_LOGS") + .map(|v| v.eq_ignore_ascii_case("true")) + .unwrap_or(false) + { + debug!( + target: "tx_trace", + payload_id = %ctx.payload_id(), + block_number = ctx.block_number(), + flashblock_index, + byte_size = flashblock_byte_size, + total_txs = info.executed_transactions.len(), + stage = "fb_published" + ); + } self.built_fb_payload_tx .try_send(new_payload.clone()) .wrap_err("failed to send built payload to handler")?; @@ -1040,6 +1068,9 @@ where DB: Database + AsRef

, P: StateRootProvider + HashedPostStateProvider + StorageRootProvider, { + let enable_tx_trace_logs = std::env::var("ENABLE_TX_TRACKING_DEBUG_LOGS") + .map(|v| v.eq_ignore_ascii_case("true")) + .unwrap_or(false); // We use it to preserve state, so we run merge_transitions on transition state at most once let untouched_transition_state = state.transition_state.clone(); let state_merge_start_time = Instant::now(); @@ -1052,6 +1083,15 @@ where .state_transition_merge_gauge .set(state_transition_merge_time); + if enable_tx_trace_logs { + debug!( + target: "tx_trace", + block_number = ctx.block_number(), + duration_us = state_transition_merge_time.as_micros() as u64, + stage = "state_merge" + ); + } + let block_number = ctx.block_number(); let expected = ctx.parent().number + 1; if block_number != expected { @@ -1079,6 +1119,11 @@ where let mut hashed_state = HashedPostState::default(); let mut trie_updates_to_cache: Option> = None; + let flashblock_index_for_trace = fb_state + .as_deref() + .map(|s| s.flashblock_index()) + .unwrap_or(0); + if calculate_state_root { let state_provider = state.database.as_ref(); @@ -1151,6 +1196,19 @@ where duration_ms = state_root_calculation_time.as_millis(), "State root calculation completed" ); + + if enable_tx_trace_logs { + debug!( + target: "tx_trace", + block_number = ctx.block_number(), + flashblock_index = flashblock_index_for_trace, + duration_ms = state_root_calculation_time.as_millis() as u64, + incremental = fb_state.as_deref().and_then(|s| s.prev_trie_updates.as_ref()).is_some(), + cumulative_gas = info.cumulative_gas_used, + num_txs = info.executed_transactions.len(), + stage = "state_root_computed" + ); + } } let mut requests_hash = None; @@ -1255,7 +1313,9 @@ where "Executed block created" ); + let seal_start = Instant::now(); let sealed_block = Arc::new(block.seal_slow()); + let seal_duration = seal_start.elapsed(); debug!( target: "payload_builder", id = %ctx.payload_id(), @@ -1265,6 +1325,20 @@ where let block_hash = sealed_block.hash(); + if enable_tx_trace_logs { + debug!( + target: "tx_trace", + block_number = ctx.block_number(), + flashblock_index = flashblock_index_for_trace, + block_hash = ?block_hash, + seal_duration_us = seal_duration.as_micros() as u64, + build_block_total_time_since_state_root_start_us = state_root_start_time.elapsed().as_micros() as u64, + cumulative_gas = info.cumulative_gas_used, + num_txs = info.executed_transactions.len(), + stage = "block_sealed" + ); + } + // pick the new transactions from the info field and update the last flashblock index let (new_transactions, new_receipts) = if let Some(fb_state) = fb_state { if let Some(updates) = trie_updates_to_cache.take() { diff --git a/crates/op-rbuilder/src/builder/wspub.rs b/crates/op-rbuilder/src/builder/wspub.rs index eb120edc..fd6374fd 100644 --- a/crates/op-rbuilder/src/builder/wspub.rs +++ b/crates/op-rbuilder/src/builder/wspub.rs @@ -80,6 +80,7 @@ impl WebSocketPublisher { message = "Sending flashblock to rollup-boost", id = %payload.payload_id, index = payload.index, + block_number = payload.metadata.block_number, base = payload.base.is_some(), ); diff --git a/crates/op-rbuilder/src/monitor_tx_pool.rs b/crates/op-rbuilder/src/monitor_tx_pool.rs index 8500aef0..e87a18cd 100644 --- a/crates/op-rbuilder/src/monitor_tx_pool.rs +++ b/crates/op-rbuilder/src/monitor_tx_pool.rs @@ -18,20 +18,26 @@ async fn transaction_event_log( event: FullTransactionEvent, reverted_cache: &Cache, ) { + if !std::env::var("ENABLE_TX_TRACKING_DEBUG_LOGS") + .map(|v| v.eq_ignore_ascii_case("true")) + .unwrap_or(false) + { + return; + } match event { FullTransactionEvent::Pending(hash) => { debug!( - target = "monitoring", - tx_hash = hash.to_string(), - kind = "pending", + target: "tx_trace", + tx_hash = %hash, + stage = "pool_pending", "Transaction event received" ) } FullTransactionEvent::Queued(hash, _) => { debug!( - target = "monitoring", - tx_hash = hash.to_string(), - kind = "queued", + target: "tx_trace", + tx_hash = %hash, + stage = "pool_queued", "Transaction event received" ) } @@ -39,9 +45,9 @@ async fn transaction_event_log( tx_hash, block_hash, } => debug!( - target = "monitoring", + target = "tx_trace", tx_hash = tx_hash.to_string(), - kind = "mined", + stage = "mined_in_block", block_hash = block_hash.to_string(), "Transaction event received" ), @@ -49,9 +55,9 @@ async fn transaction_event_log( transaction, replaced_by, } => debug!( - target = "monitoring", + target = "tx_trace", tx_hash = transaction.hash().to_string(), - kind = "replaced", + stage = "replaced", replaced_by = replaced_by.to_string(), "Transaction event received" ), @@ -61,17 +67,17 @@ async fn transaction_event_log( reverted_cache.insert(hash, ()).await; debug!( - target = "monitoring", + target = "tx_trace", tx_hash = hash.to_string(), - kind = "discarded", + stage = "discarded", "Transaction event received" ) } FullTransactionEvent::Invalid(hash) => { debug!( - target = "monitoring", + target = "tx_trace", tx_hash = hash.to_string(), - kind = "invalid", + stage = "marked_invalid", "Transaction event received" ) }