track banking stage performance using random txn mask

core/src/banking_stage/consumer.rs

@@ -206,6 +206,26 @@ impl Consumer {
             .slot_metrics_tracker
             .increment_retryable_packets_count(retryable_transaction_indexes.len() as u64);
 
+        // Now we track the performance for the interested transactions which is not in the retryable_transaction_indexes
+        // We assume the retryable_transaction_indexes is already sorted, double check
+        for (index, packet) in packets_to_process.iter().enumerate() {
+            if packet.original_packet().meta().is_tracer_packet() {
+                if let Some(start_time) = packet.start_time() {
+                    if retryable_transaction_indexes.binary_search(&index).is_err() {
+                        let duration = Instant::now() - start_time.clone();
+
+                        debug!(
+                            "Banking stage processing took {duration:?} for transaction {:?}",
+                            packet.transaction().get_signatures().get(0)
+                        );
+                        inc_new_counter_info!(
+                            "txn-metrics-banking-stage-process-us",
+                            duration.as_micros() as usize
+                        );
+                    }
+                }
+            }
+        }
         Some(retryable_transaction_indexes)
     }
 

core/src/banking_stage/immutable_deserialized_packet.rs

@@ -15,7 +15,7 @@ use {
             VersionedTransaction,
         },
     },
-    std::{cmp::Ordering, mem::size_of, sync::Arc},
+    std::{cmp::Ordering, mem::size_of, sync::Arc, time::Instant},
     thiserror::Error,
 };
 
@@ -43,10 +43,16 @@ pub struct ImmutableDeserializedPacket {
     message_hash: Hash,
     is_simple_vote: bool,
     priority_details: TransactionPriorityDetails,
+    banking_stage_start_time: Option<Instant>,
 }
 
 impl ImmutableDeserializedPacket {
     pub fn new(packet: Packet) -> Result<Self, DeserializedPacketError> {
+        let banking_stage_start_time = if packet.meta().is_tracer_packet() {
+            Some(Instant::now())
+        } else {
+            None
+        };
         let versioned_transaction: VersionedTransaction = packet.deserialize_slice(..)?;
         let sanitized_transaction = SanitizedVersionedTransaction::try_from(versioned_transaction)?;
         let message_bytes = packet_message(&packet)?;
@@ -69,6 +75,7 @@ impl ImmutableDeserializedPacket {
             message_hash,
             is_simple_vote,
             priority_details,
+            banking_stage_start_time,
         })
     }
 
@@ -100,6 +107,10 @@ impl ImmutableDeserializedPacket {
         self.priority_details.clone()
     }
 
+    pub fn start_time(&self) -> &Option<Instant> {
+        &self.banking_stage_start_time
+    }
+
     // This function deserializes packets into transactions, computes the blake3 hash of transaction
     // messages, and verifies secp256k1 instructions.
     pub fn build_sanitized_transaction(

sdk/src/transaction/versioned/sanitized.rs

@@ -33,6 +33,10 @@ impl SanitizedVersionedTransaction {
         &self.message
     }
 
+    pub fn get_signatures(&self) -> &Vec<Signature> {
+        &self.signatures
+    }
+
     /// Consumes the SanitizedVersionedTransaction, returning the fields individually.
     pub fn destruct(self) -> (Vec<Signature>, SanitizedVersionedMessage) {
         (self.signatures, self.message)

streamer/src/nonblocking/quic.rs

@@ -726,7 +726,7 @@ fn track_streamer_fetch_packet_performance(
                 if let Some(start_time) = packet_perf_measure.remove(signature) {
                     let duration = Instant::now() - start_time;
                     debug!(
-                        "QUIC streamer fetch stage takes {duration:?} for transaction {:?}",
+                        "QUIC streamer fetch stage took {duration:?} for transaction {:?}",
                         Signature::from(signature.clone())
                     );
                     inc_new_counter_info!(