Delay logs (#730)

## 📝 Summary

This PR improved debuggability regarding block build timings:
- Added 5 more timestamps:
/// UnfinishedBuiltBlocksInput chose this block as the best block and
sent it downstream
    pub chosen_as_best_at: OffsetDateTime,
/// Block was sent to the bidder (SlotBidder::notify_new_built_block)
    pub sent_to_bidder: OffsetDateTime,
/// Bid received from the bidder
(UnfinishedBuiltBlocksInput::seal_command)
    pub bid_received_at: OffsetDateTime,
    /// Bid sent to the sealer thread
    pub sent_to_sealer: OffsetDateTime,
    /// Sealer picked by sealer thread
    pub picked_by_sealer_at: OffsetDateTime,
- Added new log when a block is chosen as best block.
- Added a global block id to give the blocks an easy identity.
- Changed trigger_to_bid_round_trip_time_us metric scale.

As an extra it split in a new thread the reception of a new seal command
and the presealing so we only preseal the last one.


## ✅ I have completed the following steps:

* [X] Run `make lint`
* [X] Run `make test`
* [ ] Added tests (if applicable)

Author: ZanCorDX

crates/rbuilder/src/bin/run-bundle-on-prefix.rs

@@ -11,7 +11,10 @@ use rbuilder::{
         BlockData, HistoricalDataStorage, OrdersWithTimestamp,
     },
     building::{
-        builders::block_building_helper::{BlockBuildingHelper, BlockBuildingHelperFromProvider},
+        builders::{
+            block_building_helper::{BlockBuildingHelper, BlockBuildingHelperFromProvider},
+            BuiltBlockId,
+        },
         order_priority::{FullProfitInfoGetter, OrderMaxProfitPriority},
         BlockBuildingContext, ExecutionError, MockRootHasher, NullPartialBlockExecutionTracer,
         OrderPriority, ThreadBlockBuildingContext,
@@ -158,6 +161,7 @@ impl LandedBlockInfo {
             .into();
         let order_statistics = OrderStatistics::new();
         Ok(BlockBuildingHelperFromProvider::new(
+            BuiltBlockId::ZERO,
             block_state,
             ctx,
             &mut self.local_ctx,

crates/rbuilder/src/building/builders/block_building_helper.rs

@@ -11,12 +11,12 @@ use tracing::{debug, error, trace};
 
 use crate::{
     building::{
-        estimate_payout_gas_limit, tracers::GasUsedSimulationTracer, BlockBuildingContext,
-        BlockSpace, BlockState, BuiltBlockTrace, BuiltBlockTraceError, CriticalCommitOrderError,
-        EstimatePayoutGasErr, ExecutionError, ExecutionResult, FinalizeAdjustmentState,
-        FinalizeError, FinalizeResult, FinalizeRevertStateCurrentIteration,
-        NullPartialBlockExecutionTracer, PartialBlock, PartialBlockExecutionTracer,
-        ThreadBlockBuildingContext,
+        builders::BuiltBlockId, estimate_payout_gas_limit, tracers::GasUsedSimulationTracer,
+        BlockBuildingContext, BlockSpace, BlockState, BuiltBlockTrace, BuiltBlockTraceError,
+        CriticalCommitOrderError, EstimatePayoutGasErr, ExecutionError, ExecutionResult,
+        FinalizeAdjustmentState, FinalizeError, FinalizeResult,
+        FinalizeRevertStateCurrentIteration, NullPartialBlockExecutionTracer, PartialBlock,
+        PartialBlockExecutionTracer, ThreadBlockBuildingContext,
     },
     telemetry::{self, add_block_fill_time, add_order_simulation_time},
     utils::{check_block_hash_reader_health, elapsed_ms, HistoricalBlockError},
@@ -75,6 +75,10 @@ pub trait BlockBuildingHelper: Send + Sync {
     /// BuiltBlockTrace for current state.
     fn built_block_trace(&self) -> &BuiltBlockTrace;
 
+    fn id(&self) -> BuiltBlockId {
+        self.built_block_trace().build_block_id
+    }
+
     /// BlockBuildingContext used for building.
     fn building_context(&self) -> &BlockBuildingContext;
 
@@ -97,13 +101,15 @@ pub trait BlockBuildingHelper: Send + Sync {
 pub struct BiddableUnfinishedBlock {
     pub block: Box<dyn BlockBuildingHelper>,
     pub true_block_value: U256,
+    pub chosen_as_best_at: OffsetDateTime,
 }
 
 impl Clone for BiddableUnfinishedBlock {
     fn clone(&self) -> Self {
         Self {
             block: self.block.box_clone(),
             true_block_value: self.true_block_value,
+            chosen_as_best_at: self.chosen_as_best_at,
         }
     }
 }
@@ -114,8 +120,12 @@ impl BiddableUnfinishedBlock {
         Ok(Self {
             block,
             true_block_value,
+            chosen_as_best_at: OffsetDateTime::now_utc(),
         })
     }
+    pub fn id(&self) -> BuiltBlockId {
+        self.block.id()
+    }
 
     pub fn block(&self) -> &dyn BlockBuildingHelper {
         self.block.as_ref()
@@ -189,7 +199,9 @@ pub struct FinalizeBlockResult {
 }
 
 impl BlockBuildingHelperFromProvider<NullPartialBlockExecutionTracer> {
+    #[allow(clippy::too_many_arguments)]
     pub fn new(
+        built_block_id: BuiltBlockId,
         state_provider: Arc<dyn StateProvider>,
         building_ctx: BlockBuildingContext,
         local_ctx: &mut ThreadBlockBuildingContext,
@@ -199,6 +211,7 @@ impl BlockBuildingHelperFromProvider<NullPartialBlockExecutionTracer> {
         cancel_on_fatal_error: CancellationToken,
     ) -> Result<Self, BlockBuildingHelperError> {
         BlockBuildingHelperFromProvider::new_with_execution_tracer(
+            built_block_id,
             state_provider,
             building_ctx,
             local_ctx,
@@ -222,6 +235,7 @@ impl<
     /// - Estimate payout tx cost.
     #[allow(clippy::too_many_arguments)]
     pub fn new_with_execution_tracer(
+        built_block_id: BuiltBlockId,
         state_provider: Arc<dyn StateProvider>,
         building_ctx: BlockBuildingContext,
         local_ctx: &mut ThreadBlockBuildingContext,
@@ -254,7 +268,7 @@ impl<
         partial_block.reserve_block_space(payout_tx_space);
         let payout_tx_gas = payout_tx_space.gas;
 
-        let mut built_block_trace = BuiltBlockTrace::new();
+        let mut built_block_trace = BuiltBlockTrace::new(built_block_id);
         built_block_trace.available_orders_statistics = available_orders_statistics;
         Ok(Self {
             _fee_recipient_balance_start: fee_recipient_balance_start,

crates/rbuilder/src/building/builders/mock_block_building_helper.rs

@@ -1,7 +1,7 @@
 use crate::{
     building::{
-        BlockBuildingContext, BuiltBlockTrace, CriticalCommitOrderError, ExecutionError,
-        ExecutionResult, ThreadBlockBuildingContext,
+        builders::BuiltBlockId, BlockBuildingContext, BuiltBlockTrace, CriticalCommitOrderError,
+        ExecutionError, ExecutionResult, ThreadBlockBuildingContext,
     },
     live_builder::simulation::SimulatedOrderCommand,
     provider::RootHasher,
@@ -34,7 +34,7 @@ impl MockBlockBuildingHelper {
     pub fn new(true_block_value: U256) -> Self {
         let built_block_trace = BuiltBlockTrace {
             true_bid_value: true_block_value,
-            ..Default::default()
+            ..BuiltBlockTrace::new(BuiltBlockId::ZERO)
         };
         Self {
             built_block_trace,

crates/rbuilder/src/building/builders/mod.rs

@@ -20,7 +20,14 @@ use alloy_eips::eip7594::BlobTransactionSidecarVariant;
 use alloy_primitives::{Address, Bytes};
 use rbuilder_primitives::{mev_boost::BidAdjustmentData, AccountNonce, OrderId, SimulatedOrder};
 use reth::primitives::SealedBlock;
-use std::{collections::HashMap, fmt::Debug, sync::Arc};
+use std::{
+    collections::HashMap,
+    fmt::Debug,
+    sync::{
+        atomic::{AtomicU64, Ordering},
+        Arc,
+    },
+};
 use tokio::sync::{
     broadcast,
     broadcast::error::{RecvError, TryRecvError},
@@ -44,6 +51,36 @@ pub struct Block {
     pub bid_adjustments: HashMap<Address, BidAdjustmentData>,
 }
 
+/// Id to uniquely identify every block built (unique even among different algorithms).
+#[derive(Clone, Copy, Eq, PartialEq, Debug)]
+pub struct BuiltBlockId(pub u64);
+
+impl BuiltBlockId {
+    pub const ZERO: Self = Self(0);
+}
+
+#[derive(Debug)]
+pub struct BuiltBlockIdSource {
+    next_id: AtomicU64,
+}
+
+impl BuiltBlockIdSource {
+    pub fn new() -> Self {
+        Self {
+            next_id: AtomicU64::new(0),
+        }
+    }
+    pub fn get_new_id(&self) -> BuiltBlockId {
+        BuiltBlockId(self.next_id.fetch_add(1, Ordering::Relaxed))
+    }
+}
+
+impl Default for BuiltBlockIdSource {
+    fn default() -> Self {
+        Self::new()
+    }
+}
+
 #[derive(Debug)]
 pub struct LiveBuilderInput<P> {
     pub provider: P,
@@ -53,6 +90,7 @@ pub struct LiveBuilderInput<P> {
     pub builder_name: String,
     pub cancel: CancellationToken,
     pub built_block_cache: Arc<BuiltBlockCache>,
+    pub built_block_id_source: Arc<BuiltBlockIdSource>,
 }
 
 /// Struct that helps reading new orders/cancellations
@@ -203,6 +241,7 @@ pub struct BlockBuildingAlgorithmInput<P> {
     /// A cache common to several builders so they can optimize their work looking at other builders blocks.
     pub built_block_cache: Arc<BuiltBlockCache>,
     pub cancel: CancellationToken,
+    pub built_block_id_source: Arc<BuiltBlockIdSource>,
 }
 
 /// Algorithm to build blocks

crates/rbuilder/src/building/builders/ordering_builder.rs

@@ -9,7 +9,8 @@ use crate::{
     building::{
         block_orders_from_sim_orders,
         builders::{
-            block_building_helper::BlockBuildingHelper, LiveBuilderInput, OrderIntakeConsumer,
+            block_building_helper::BlockBuildingHelper, BuiltBlockId, LiveBuilderInput,
+            OrderIntakeConsumer,
         },
         BlockBuildingContext, ExecutionError, NullPartialBlockExecutionTracer, OrderPriority,
         PartialBlockExecutionTracer, PrioritizedOrderStore, SimulatedOrderSink, Sorting,
@@ -138,7 +139,11 @@ pub fn run_ordering_builder<P, OrderPriorityType>(
         }
 
         let orders = order_intake_consumer.current_block_orders();
-        match builder.build_block(orders, input.cancel.clone()) {
+        match builder.build_block(
+            orders,
+            input.built_block_id_source.get_new_id(),
+            input.cancel.clone(),
+        ) {
             Ok(block) => {
                 if let Ok(block) = BiddableUnfinishedBlock::new(block) {
                     input.sink.new_block(block);
@@ -184,6 +189,7 @@ where
     );
     let mut block_builder = builder.build_block_with_execution_tracer(
         block_orders,
+        BuiltBlockId::ZERO,
         CancellationToken::new(),
         partial_block_execution_tracer,
     )?;
@@ -235,10 +241,12 @@ impl OrderingBuilderContext {
     pub fn build_block<OrderPriorityType: OrderPriority>(
         &mut self,
         block_orders: PrioritizedOrderStore<OrderPriorityType>,
+        built_block_id: BuiltBlockId,
         cancel_block: CancellationToken,
     ) -> eyre::Result<Box<dyn BlockBuildingHelper>> {
         self.build_block_with_execution_tracer(
             block_orders,
+            built_block_id,
             cancel_block,
             NullPartialBlockExecutionTracer {},
         )
@@ -253,6 +261,7 @@ impl OrderingBuilderContext {
     >(
         &mut self,
         mut block_orders: PrioritizedOrderStore<OrderPriorityType>,
+        built_block_id: BuiltBlockId,
         cancel_block: CancellationToken,
         partial_block_execution_tracer: PartialBlockExecutionTracerType,
     ) -> eyre::Result<Box<dyn BlockBuildingHelper>> {
@@ -267,6 +276,7 @@ impl OrderingBuilderContext {
         self.order_attempts.clear();
 
         let mut block_building_helper = BlockBuildingHelperFromProvider::new_with_execution_tracer(
+            built_block_id,
             self.state.clone(),
             self.ctx.clone(),
             &mut self.local_ctx,
@@ -468,6 +478,7 @@ where
             builder_name: self.name.clone(),
             cancel: input.cancel,
             built_block_cache: input.built_block_cache,
+            built_block_id_source: input.built_block_id_source,
         };
         run_ordering_builder::<P, OrderPriorityType>(live_input, &self.config);
     }

crates/rbuilder/src/building/builders/parallel_builder/block_building_result_assembler.rs

@@ -16,7 +16,7 @@ use crate::{
             block_building_helper::{
                 BiddableUnfinishedBlock, BlockBuildingHelper, BlockBuildingHelperFromProvider,
             },
-            handle_building_error,
+            handle_building_error, BuiltBlockIdSource,
         },
         BlockBuildingContext, ThreadBlockBuildingContext,
     },
@@ -38,6 +38,7 @@ pub struct BlockBuildingResultAssembler {
     best_results: Arc<BestResults>,
     run_id: u64,
     last_version: Option<u64>,
+    built_block_id_source: Arc<BuiltBlockIdSource>,
 }
 
 impl BlockBuildingResultAssembler {
@@ -58,6 +59,7 @@ impl BlockBuildingResultAssembler {
         cancellation_token: CancellationToken,
         builder_name: String,
         sink: Option<UnfinishedBuiltBlocksInput>,
+        built_block_id_source: Arc<BuiltBlockIdSource>,
     ) -> Self {
         Self {
             state,
@@ -70,6 +72,7 @@ impl BlockBuildingResultAssembler {
             best_results,
             run_id: 0,
             last_version: None,
+            built_block_id_source,
         }
     }
 
@@ -178,6 +181,7 @@ impl BlockBuildingResultAssembler {
         let build_start = Instant::now();
 
         let mut block_building_helper = BlockBuildingHelperFromProvider::new(
+            self.built_block_id_source.get_new_id(),
             self.state.clone(),
             self.ctx.clone(),
             &mut self.local_ctx,
@@ -251,6 +255,7 @@ impl BlockBuildingResultAssembler {
         orders_closed_at: OffsetDateTime,
     ) -> eyre::Result<Box<dyn BlockBuildingHelper>> {
         let mut block_building_helper = BlockBuildingHelperFromProvider::new(
+            self.built_block_id_source.get_new_id(),
             self.state.clone(),
             self.ctx.clone(),
             &mut self.local_ctx,

crates/rbuilder/src/building/builders/parallel_builder/mod.rs

@@ -32,7 +32,7 @@ use tracing::{error, trace};
 use crate::{
     building::builders::{
         BacktestSimulateBlockInput, Block, BlockBuildingAlgorithm, BlockBuildingAlgorithmInput,
-        LiveBuilderInput,
+        BuiltBlockIdSource, LiveBuilderInput,
     },
     provider::StateProviderFactory,
     utils::elapsed_ms,
@@ -133,6 +133,7 @@ where
             input.cancel.clone(),
             input.builder_name.clone(),
             Some(input.sink.clone()),
+            input.built_block_id_source.clone(),
         );
 
         let order_intake_consumer = OrderIntakeStore::new(input.input);
@@ -350,6 +351,7 @@ where
         CancellationToken::new(),
         String::from("backtest_builder"),
         None,
+        Arc::new(BuiltBlockIdSource::new()),
     );
     let assembler_duration = assembler_start.elapsed();
 
@@ -418,6 +420,7 @@ where
             builder_name: self.name.clone(),
             cancel: input.cancel,
             built_block_cache: input.built_block_cache,
+            built_block_id_source: input.built_block_id_source,
         };
         run_parallel_builder(live_input, &self.config);
     }