solana-core 1.14.13

Blockchain, Rebuilt for Scale
Documentation
use {
    solana_program_runtime::timings::ExecuteTimings,
    solana_sdk::{clock::Slot, saturating_add_assign},
    std::time::Instant,
};

#[derive(Default, Debug)]
pub struct LeaderExecuteAndCommitTimings {
    pub collect_balances_us: u64,
    pub load_execute_us: u64,
    pub freeze_lock_us: u64,
    pub record_us: u64,
    pub commit_us: u64,
    pub find_and_send_votes_us: u64,
    pub record_transactions_timings: RecordTransactionsTimings,
    pub execute_timings: ExecuteTimings,
}

impl LeaderExecuteAndCommitTimings {
    pub fn accumulate(&mut self, other: &LeaderExecuteAndCommitTimings) {
        saturating_add_assign!(self.collect_balances_us, other.collect_balances_us);
        saturating_add_assign!(self.load_execute_us, other.load_execute_us);
        saturating_add_assign!(self.freeze_lock_us, other.freeze_lock_us);
        saturating_add_assign!(self.record_us, other.record_us);
        saturating_add_assign!(self.commit_us, other.commit_us);
        saturating_add_assign!(self.find_and_send_votes_us, other.find_and_send_votes_us);
        self.record_transactions_timings
            .accumulate(&other.record_transactions_timings);
        self.execute_timings.accumulate(&other.execute_timings);
    }

    pub fn report(&self, id: u32, slot: Slot) {
        datapoint_info!(
            "banking_stage-leader_slot_execute_and_commit_timings",
            ("id", id as i64, i64),
            ("slot", slot as i64, i64),
            ("collect_balances_us", self.collect_balances_us as i64, i64),
            ("load_execute_us", self.load_execute_us as i64, i64),
            ("freeze_lock_us", self.freeze_lock_us as i64, i64),
            ("record_us", self.record_us as i64, i64),
            ("commit_us", self.commit_us as i64, i64),
            (
                "find_and_send_votes_us",
                self.find_and_send_votes_us as i64,
                i64
            ),
        );

        datapoint_info!(
            "banking_stage-leader_slot_record_timings",
            ("id", id as i64, i64),
            ("slot", slot as i64, i64),
            (
                "execution_results_to_transactions_us",
                self.record_transactions_timings
                    .execution_results_to_transactions_us as i64,
                i64
            ),
            (
                "hash_us",
                self.record_transactions_timings.hash_us as i64,
                i64
            ),
            (
                "poh_record_us",
                self.record_transactions_timings.poh_record_us as i64,
                i64
            ),
        );
    }
}

#[derive(Default, Debug)]
pub struct RecordTransactionsTimings {
    pub execution_results_to_transactions_us: u64,
    pub hash_us: u64,
    pub poh_record_us: u64,
}

impl RecordTransactionsTimings {
    pub fn accumulate(&mut self, other: &RecordTransactionsTimings) {
        saturating_add_assign!(
            self.execution_results_to_transactions_us,
            other.execution_results_to_transactions_us
        );
        saturating_add_assign!(self.hash_us, other.hash_us);
        saturating_add_assign!(self.poh_record_us, other.poh_record_us);
    }
}

// Metrics capturing wallclock time spent in various parts of BankingStage during this
// validator's leader slot
#[derive(Debug)]
pub(crate) struct LeaderSlotTimingMetrics {
    pub outer_loop_timings: OuterLoopTimings,
    pub process_buffered_packets_timings: ProcessBufferedPacketsTimings,
    pub consume_buffered_packets_timings: ConsumeBufferedPacketsTimings,
    pub process_packets_timings: ProcessPacketsTimings,
    pub execute_and_commit_timings: LeaderExecuteAndCommitTimings,
}

impl LeaderSlotTimingMetrics {
    pub(crate) fn new(bank_creation_time: &Instant) -> Self {
        Self {
            outer_loop_timings: OuterLoopTimings::new(bank_creation_time),
            process_buffered_packets_timings: ProcessBufferedPacketsTimings::default(),
            consume_buffered_packets_timings: ConsumeBufferedPacketsTimings::default(),
            process_packets_timings: ProcessPacketsTimings::default(),
            execute_and_commit_timings: LeaderExecuteAndCommitTimings::default(),
        }
    }

    pub(crate) fn report(&self, id: u32, slot: Slot) {
        self.outer_loop_timings.report(id, slot);
        self.process_buffered_packets_timings.report(id, slot);
        self.consume_buffered_packets_timings.report(id, slot);
        self.process_packets_timings.report(id, slot);
        self.execute_and_commit_timings.report(id, slot);
    }

    pub(crate) fn mark_slot_end_detected(&mut self) {
        self.outer_loop_timings.mark_slot_end_detected();
    }
}

#[derive(Debug)]
pub(crate) struct OuterLoopTimings {
    pub bank_detected_time: Instant,

    // Delay from when the bank was created to when this thread detected it
    pub bank_detected_delay_us: u64,

    // Time spent processing buffered packets
    pub process_buffered_packets_us: u64,

    // Time spent processing new incoming packets to the banking thread
    pub receive_and_buffer_packets_us: u64,

    // The number of times the function to receive and buffer new packets
    // was called
    pub receive_and_buffer_packets_invoked_count: u64,

    // Elapsed time between bank was detected and slot end was detected
    pub bank_detected_to_slot_end_detected_us: u64,
}

impl OuterLoopTimings {
    fn new(bank_creation_time: &Instant) -> Self {
        Self {
            bank_detected_time: Instant::now(),
            bank_detected_delay_us: bank_creation_time.elapsed().as_micros() as u64,
            process_buffered_packets_us: 0,
            receive_and_buffer_packets_us: 0,
            receive_and_buffer_packets_invoked_count: 0,
            bank_detected_to_slot_end_detected_us: 0,
        }
    }

    /// Call when detected slot end to capture elapsed time, which might be reported later
    fn mark_slot_end_detected(&mut self) {
        self.bank_detected_to_slot_end_detected_us =
            self.bank_detected_time.elapsed().as_micros() as u64;
    }

    fn report(&self, id: u32, slot: Slot) {
        datapoint_info!(
            "banking_stage-leader_slot_loop_timings",
            ("id", id as i64, i64),
            ("slot", slot as i64, i64),
            (
                "bank_detected_to_slot_end_detected_us",
                self.bank_detected_to_slot_end_detected_us,
                i64
            ),
            (
                "bank_creation_to_slot_end_detected_us",
                self.bank_detected_to_slot_end_detected_us + self.bank_detected_delay_us,
                i64
            ),
            ("bank_detected_delay_us", self.bank_detected_delay_us, i64),
            (
                "process_buffered_packets_us",
                self.process_buffered_packets_us,
                i64
            ),
            (
                "receive_and_buffer_packets_us",
                self.receive_and_buffer_packets_us,
                i64
            ),
            (
                "receive_and_buffer_packets_invoked_count",
                self.receive_and_buffer_packets_invoked_count,
                i64
            )
        );
    }
}

#[derive(Debug, Default)]
pub(crate) struct ProcessBufferedPacketsTimings {
    pub make_decision_us: u64,
    pub consume_buffered_packets_us: u64,
    pub forward_us: u64,
    pub forward_and_hold_us: u64,
}
impl ProcessBufferedPacketsTimings {
    fn report(&self, id: u32, slot: Slot) {
        datapoint_info!(
            "banking_stage-leader_slot_process_buffered_packets_timings",
            ("id", id as i64, i64),
            ("slot", slot as i64, i64),
            ("make_decision_us", self.make_decision_us as i64, i64),
            (
                "consume_buffered_packets_us",
                self.consume_buffered_packets_us as i64,
                i64
            ),
            ("forward_us", self.forward_us as i64, i64),
            ("forward_and_hold_us", self.forward_and_hold_us as i64, i64),
        );
    }
}

#[derive(Debug, Default)]
pub(crate) struct ConsumeBufferedPacketsTimings {
    // Time spent grabbing poh recorder lock
    pub poh_recorder_lock_us: u64,

    // Time spent processing transactions
    pub process_packets_transactions_us: u64,
}

impl ConsumeBufferedPacketsTimings {
    fn report(&self, id: u32, slot: Slot) {
        datapoint_info!(
            "banking_stage-leader_slot_consume_buffered_packets_timings",
            ("id", id as i64, i64),
            ("slot", slot as i64, i64),
            (
                "poh_recorder_lock_us",
                self.poh_recorder_lock_us as i64,
                i64
            ),
            (
                "process_packets_transactions_us",
                self.process_packets_transactions_us as i64,
                i64
            ),
        );
    }
}

#[derive(Debug, Default)]
pub(crate) struct ProcessPacketsTimings {
    // Time spent converting packets to transactions
    pub transactions_from_packets_us: u64,

    // Time spent processing transactions
    pub process_transactions_us: u64,

    // Time spent filtering retryable packets that were returned after transaction
    // processing
    pub filter_retryable_packets_us: u64,

    // Time spent running the cost model in processing transactions before executing
    // transactions
    pub cost_model_us: u64,
}

impl ProcessPacketsTimings {
    fn report(&self, id: u32, slot: Slot) {
        datapoint_info!(
            "banking_stage-leader_slot_process_packets_timings",
            ("id", id as i64, i64),
            ("slot", slot as i64, i64),
            (
                "transactions_from_packets_us",
                self.transactions_from_packets_us,
                i64
            ),
            ("process_transactions_us", self.process_transactions_us, i64),
            (
                "filter_retryable_packets_us",
                self.filter_retryable_packets_us,
                i64
            ),
            ("cost_model_us", self.cost_model_us, i64),
        );
    }
}