1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
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);
    }
}

#[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 checking for slot boundary and reporting leader slot metrics
    pub slot_metrics_check_slot_boundary_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,
}

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,
            slot_metrics_check_slot_boundary_us: 0,
            receive_and_buffer_packets_us: 0,
            receive_and_buffer_packets_invoked_count: 0,
        }
    }

    fn report(&self, id: u32, slot: Slot) {
        let bank_detected_to_now_us = self.bank_detected_time.elapsed().as_micros() as u64;
        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",
                bank_detected_to_now_us,
                i64
            ),
            (
                "bank_creation_to_slot_end_detected_us",
                bank_detected_to_now_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
            ),
            (
                "slot_metrics_check_slot_boundary_us",
                self.slot_metrics_check_slot_boundary_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 filtering invalid packets after leader slot has ended
    pub end_of_slot_filtering_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
            ),
            (
                "end_of_slot_filtering_us",
                self.end_of_slot_filtering_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),
        );
    }
}