per-transaction trace log specification

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(

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<Error = ProviderError> + AsRef<P>,
     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<Arc<TrieUpdates>> = 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() {

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(),
         );
 

crates/op-rbuilder/src/monitor_tx_pool.rs

@@ -18,40 +18,46 @@ async fn transaction_event_log(
     event: FullTransactionEvent<FBPooledTransaction>,
     reverted_cache: &Cache<B256, ()>,
 ) {
+    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"
             )
         }
         FullTransactionEvent::Mined {
             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"
         ),
         FullTransactionEvent::Replaced {
             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"
             )
         }