solana_timings/
lib.rs

1#[macro_use]
2extern crate eager;
3use {
4    core::fmt,
5    enum_iterator::Sequence,
6    solana_sdk::{pubkey::Pubkey, saturating_add_assign},
7    std::{
8        collections::HashMap,
9        ops::{Index, IndexMut},
10    },
11};
12
13#[derive(Default, Debug, PartialEq, Eq)]
14pub struct ProgramTiming {
15    pub accumulated_us: u64,
16    pub accumulated_units: u64,
17    pub count: u32,
18    pub errored_txs_compute_consumed: Vec<u64>,
19    // Sum of all units in `errored_txs_compute_consumed`
20    pub total_errored_units: u64,
21}
22
23impl ProgramTiming {
24    pub fn coalesce_error_timings(&mut self, current_estimated_program_cost: u64) {
25        for tx_error_compute_consumed in self.errored_txs_compute_consumed.drain(..) {
26            let compute_units_update =
27                std::cmp::max(current_estimated_program_cost, tx_error_compute_consumed);
28            saturating_add_assign!(self.accumulated_units, compute_units_update);
29            saturating_add_assign!(self.count, 1);
30        }
31    }
32
33    pub fn accumulate_program_timings(&mut self, other: &ProgramTiming) {
34        saturating_add_assign!(self.accumulated_us, other.accumulated_us);
35        saturating_add_assign!(self.accumulated_units, other.accumulated_units);
36        saturating_add_assign!(self.count, other.count);
37        // Clones the entire vector, maybe not great...
38        self.errored_txs_compute_consumed
39            .extend(other.errored_txs_compute_consumed.clone());
40        saturating_add_assign!(self.total_errored_units, other.total_errored_units);
41    }
42}
43
44/// Used as an index for `Metrics`.
45#[derive(Debug, Sequence)]
46pub enum ExecuteTimingType {
47    CheckUs,
48    ValidateFeesUs,
49    LoadUs,
50    ExecuteUs,
51    StoreUs,
52    UpdateStakesCacheUs,
53    UpdateExecutorsUs,
54    NumExecuteBatches,
55    CollectLogsUs,
56    TotalBatchesLen,
57    UpdateTransactionStatuses,
58    ProgramCacheUs,
59    CheckBlockLimitsUs,
60    FilterExecutableUs,
61}
62
63pub struct Metrics([u64; ExecuteTimingType::CARDINALITY]);
64
65impl Index<ExecuteTimingType> for Metrics {
66    type Output = u64;
67    fn index(&self, index: ExecuteTimingType) -> &Self::Output {
68        self.0.index(index as usize)
69    }
70}
71
72impl IndexMut<ExecuteTimingType> for Metrics {
73    fn index_mut(&mut self, index: ExecuteTimingType) -> &mut Self::Output {
74        self.0.index_mut(index as usize)
75    }
76}
77
78impl Default for Metrics {
79    fn default() -> Self {
80        Metrics([0; ExecuteTimingType::CARDINALITY])
81    }
82}
83
84impl core::fmt::Debug for Metrics {
85    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
86        self.0.fmt(f)
87    }
88}
89
90// The auxiliary variable that must always be provided to eager_macro_rules! must use the
91// identifier `eager_1`. Macros declared with `eager_macro_rules!` can then be used inside
92// an eager! block.
93eager_macro_rules! { $eager_1
94    #[macro_export]
95    macro_rules! report_execute_timings {
96        ($self: expr, $is_unified_scheduler_enabled: expr) => {
97            (
98                "validate_transactions_us",
99                *$self
100                    .metrics
101                    .index(ExecuteTimingType::CheckUs),
102                i64
103            ),
104            (
105                "validate_fees_us",
106                *$self
107                    .metrics
108                    .index(ExecuteTimingType::ValidateFeesUs),
109                i64
110            ),
111            (
112                "filter_executable_us",
113                *$self
114                    .metrics
115                    .index(ExecuteTimingType::FilterExecutableUs),
116                i64
117            ),
118            (
119                "program_cache_us",
120                *$self
121                    .metrics
122                    .index(ExecuteTimingType::ProgramCacheUs),
123                i64
124            ),
125            (
126                "load_us",
127                *$self
128                    .metrics
129                    .index(ExecuteTimingType::LoadUs),
130                i64
131            ),
132            (
133                "execute_us",
134                *$self
135                    .metrics
136                    .index(ExecuteTimingType::ExecuteUs),
137                i64
138            ),
139            (
140                "collect_logs_us",
141                *$self
142                    .metrics
143                    .index(ExecuteTimingType::CollectLogsUs),
144                i64
145            ),
146            (
147                "store_us",
148                *$self
149
150                    .metrics
151                    .index(ExecuteTimingType::StoreUs),
152                i64
153            ),
154            (
155                "update_stakes_cache_us",
156                *$self
157
158                    .metrics
159                    .index(ExecuteTimingType::UpdateStakesCacheUs),
160                i64
161            ),
162            (
163                "execute_accessories_update_executors_us",
164                *$self.metrics.index(ExecuteTimingType::UpdateExecutorsUs),
165                i64
166            ),
167            (
168                "total_batches_len",
169                (if $is_unified_scheduler_enabled {
170                    None
171                } else {
172                    Some(*$self
173                        .metrics
174                        .index(ExecuteTimingType::TotalBatchesLen))
175                }),
176                Option<i64>
177            ),
178            (
179                "num_execute_batches",
180                (if $is_unified_scheduler_enabled {
181                    None
182                } else {
183                    Some(*$self
184                        .metrics
185                        .index(ExecuteTimingType::NumExecuteBatches))
186                }),
187                Option<i64>
188            ),
189            (
190                "update_transaction_statuses",
191                *$self
192
193                    .metrics
194                    .index(ExecuteTimingType::UpdateTransactionStatuses),
195                i64
196            ),
197            (
198                "check_block_limits_us",
199                *$self.metrics.index(ExecuteTimingType::CheckBlockLimitsUs),
200                i64
201            ),
202            (
203                "execute_details_serialize_us",
204                $self.details.serialize_us,
205                i64
206            ),
207            (
208                "execute_details_create_vm_us",
209                $self.details.create_vm_us,
210                i64
211            ),
212            (
213                "execute_details_execute_inner_us",
214                $self.details.execute_us,
215                i64
216            ),
217            (
218                "execute_details_deserialize_us",
219                $self.details.deserialize_us,
220                i64
221            ),
222            (
223                "execute_details_get_or_create_executor_us",
224                $self.details.get_or_create_executor_us,
225                i64
226            ),
227            (
228                "execute_details_changed_account_count",
229                $self.details.changed_account_count,
230                i64
231            ),
232            (
233                "execute_details_total_account_count",
234                $self.details.total_account_count,
235                i64
236            ),
237            (
238                "execute_details_create_executor_register_syscalls_us",
239                $self
240                    .details
241                    .create_executor_register_syscalls_us,
242                i64
243            ),
244            (
245                "execute_details_create_executor_load_elf_us",
246                $self.details.create_executor_load_elf_us,
247                i64
248            ),
249            (
250                "execute_details_create_executor_verify_code_us",
251                $self.details.create_executor_verify_code_us,
252                i64
253            ),
254            (
255                "execute_details_create_executor_jit_compile_us",
256                $self.details.create_executor_jit_compile_us,
257                i64
258            ),
259            (
260                "execute_accessories_feature_set_clone_us",
261                $self
262                    .execute_accessories
263                    .feature_set_clone_us,
264                i64
265            ),
266            (
267                "execute_accessories_get_executors_us",
268                $self.execute_accessories.get_executors_us,
269                i64
270            ),
271            (
272                "execute_accessories_process_message_us",
273                $self.execute_accessories.process_message_us,
274                i64
275            ),
276            (
277                "execute_accessories_process_instructions_total_us",
278                $self
279                    .execute_accessories
280                    .process_instructions
281                    .total_us,
282                i64
283            ),
284            (
285                "execute_accessories_process_instructions_verify_caller_us",
286                $self
287                    .execute_accessories
288                    .process_instructions
289                    .verify_caller_us,
290                i64
291            ),
292            (
293                "execute_accessories_process_instructions_process_executable_chain_us",
294                $self
295                    .execute_accessories
296                    .process_instructions
297                    .process_executable_chain_us,
298                i64
299            ),
300            (
301                "execute_accessories_process_instructions_verify_callee_us",
302                $self
303                    .execute_accessories
304                    .process_instructions
305                    .verify_callee_us,
306                i64
307            ),
308        }
309    }
310}
311
312#[derive(Debug, Default)]
313pub struct ExecuteTimings {
314    pub metrics: Metrics,
315    pub details: ExecuteDetailsTimings,
316    pub execute_accessories: ExecuteAccessoryTimings,
317}
318
319impl ExecuteTimings {
320    pub fn accumulate(&mut self, other: &ExecuteTimings) {
321        for (t1, t2) in self.metrics.0.iter_mut().zip(other.metrics.0.iter()) {
322            saturating_add_assign!(*t1, *t2);
323        }
324        self.details.accumulate(&other.details);
325        self.execute_accessories
326            .accumulate(&other.execute_accessories);
327    }
328
329    pub fn saturating_add_in_place(&mut self, timing_type: ExecuteTimingType, value_to_add: u64) {
330        let idx = timing_type as usize;
331        match self.metrics.0.get_mut(idx) {
332            Some(elem) => *elem = elem.saturating_add(value_to_add),
333            None => debug_assert!(idx < ExecuteTimingType::CARDINALITY, "Index out of bounds"),
334        }
335    }
336}
337
338#[derive(Default, Debug)]
339pub struct ExecuteProcessInstructionTimings {
340    pub total_us: u64,
341    pub verify_caller_us: u64,
342    pub process_executable_chain_us: u64,
343    pub verify_callee_us: u64,
344}
345
346impl ExecuteProcessInstructionTimings {
347    pub fn accumulate(&mut self, other: &ExecuteProcessInstructionTimings) {
348        saturating_add_assign!(self.total_us, other.total_us);
349        saturating_add_assign!(self.verify_caller_us, other.verify_caller_us);
350        saturating_add_assign!(
351            self.process_executable_chain_us,
352            other.process_executable_chain_us
353        );
354        saturating_add_assign!(self.verify_callee_us, other.verify_callee_us);
355    }
356}
357
358#[derive(Default, Debug)]
359pub struct ExecuteAccessoryTimings {
360    pub feature_set_clone_us: u64,
361    pub get_executors_us: u64,
362    pub process_message_us: u64,
363    pub process_instructions: ExecuteProcessInstructionTimings,
364}
365
366impl ExecuteAccessoryTimings {
367    pub fn accumulate(&mut self, other: &ExecuteAccessoryTimings) {
368        saturating_add_assign!(self.feature_set_clone_us, other.feature_set_clone_us);
369        saturating_add_assign!(self.get_executors_us, other.get_executors_us);
370        saturating_add_assign!(self.process_message_us, other.process_message_us);
371        self.process_instructions
372            .accumulate(&other.process_instructions);
373    }
374}
375
376#[derive(Default, Debug, PartialEq, Eq)]
377pub struct ExecuteDetailsTimings {
378    pub serialize_us: u64,
379    pub create_vm_us: u64,
380    pub execute_us: u64,
381    pub deserialize_us: u64,
382    pub get_or_create_executor_us: u64,
383    pub changed_account_count: u64,
384    pub total_account_count: u64,
385    pub create_executor_register_syscalls_us: u64,
386    pub create_executor_load_elf_us: u64,
387    pub create_executor_verify_code_us: u64,
388    pub create_executor_jit_compile_us: u64,
389    pub per_program_timings: HashMap<Pubkey, ProgramTiming>,
390}
391
392impl ExecuteDetailsTimings {
393    pub fn accumulate(&mut self, other: &ExecuteDetailsTimings) {
394        saturating_add_assign!(self.serialize_us, other.serialize_us);
395        saturating_add_assign!(self.create_vm_us, other.create_vm_us);
396        saturating_add_assign!(self.execute_us, other.execute_us);
397        saturating_add_assign!(self.deserialize_us, other.deserialize_us);
398        saturating_add_assign!(
399            self.get_or_create_executor_us,
400            other.get_or_create_executor_us
401        );
402        saturating_add_assign!(self.changed_account_count, other.changed_account_count);
403        saturating_add_assign!(self.total_account_count, other.total_account_count);
404        saturating_add_assign!(
405            self.create_executor_register_syscalls_us,
406            other.create_executor_register_syscalls_us
407        );
408        saturating_add_assign!(
409            self.create_executor_load_elf_us,
410            other.create_executor_load_elf_us
411        );
412        saturating_add_assign!(
413            self.create_executor_verify_code_us,
414            other.create_executor_verify_code_us
415        );
416        saturating_add_assign!(
417            self.create_executor_jit_compile_us,
418            other.create_executor_jit_compile_us
419        );
420        for (id, other) in &other.per_program_timings {
421            let program_timing = self.per_program_timings.entry(*id).or_default();
422            program_timing.accumulate_program_timings(other);
423        }
424    }
425
426    pub fn accumulate_program(
427        &mut self,
428        program_id: &Pubkey,
429        us: u64,
430        compute_units_consumed: u64,
431        is_error: bool,
432    ) {
433        let program_timing = self.per_program_timings.entry(*program_id).or_default();
434        program_timing.accumulated_us = program_timing.accumulated_us.saturating_add(us);
435        if is_error {
436            program_timing
437                .errored_txs_compute_consumed
438                .push(compute_units_consumed);
439            program_timing.total_errored_units = program_timing
440                .total_errored_units
441                .saturating_add(compute_units_consumed);
442        } else {
443            program_timing.accumulated_units = program_timing
444                .accumulated_units
445                .saturating_add(compute_units_consumed);
446            program_timing.count = program_timing.count.saturating_add(1);
447        };
448    }
449}
450
451#[cfg(test)]
452mod tests {
453    use super::*;
454
455    fn construct_execute_timings_with_program(
456        program_id: &Pubkey,
457        us: u64,
458        compute_units_consumed: u64,
459    ) -> ExecuteDetailsTimings {
460        let mut execute_details_timings = ExecuteDetailsTimings::default();
461
462        // Accumulate an erroring transaction
463        let is_error = true;
464        execute_details_timings.accumulate_program(
465            program_id,
466            us,
467            compute_units_consumed,
468            is_error,
469        );
470
471        // Accumulate a non-erroring transaction
472        let is_error = false;
473        execute_details_timings.accumulate_program(
474            program_id,
475            us,
476            compute_units_consumed,
477            is_error,
478        );
479
480        let program_timings = execute_details_timings
481            .per_program_timings
482            .get(program_id)
483            .unwrap();
484
485        // Both error and success transactions count towards `accumulated_us`
486        assert_eq!(program_timings.accumulated_us, us.saturating_mul(2));
487        assert_eq!(program_timings.accumulated_units, compute_units_consumed);
488        assert_eq!(program_timings.count, 1,);
489        assert_eq!(
490            program_timings.errored_txs_compute_consumed,
491            vec![compute_units_consumed]
492        );
493        assert_eq!(program_timings.total_errored_units, compute_units_consumed,);
494
495        execute_details_timings
496    }
497
498    #[test]
499    fn test_execute_details_timing_acumulate_program() {
500        // Acumulate an erroring transaction
501        let program_id = Pubkey::new_unique();
502        let us = 100;
503        let compute_units_consumed = 1;
504        construct_execute_timings_with_program(&program_id, us, compute_units_consumed);
505    }
506
507    #[test]
508    fn test_execute_details_timing_acumulate() {
509        // Acumulate an erroring transaction
510        let program_id = Pubkey::new_unique();
511        let us = 100;
512        let compute_units_consumed = 1;
513        let mut execute_details_timings = ExecuteDetailsTimings::default();
514
515        // Construct another separate instance of ExecuteDetailsTimings with non default fields
516        let mut other_execute_details_timings =
517            construct_execute_timings_with_program(&program_id, us, compute_units_consumed);
518        let account_count = 1;
519        other_execute_details_timings.serialize_us = us;
520        other_execute_details_timings.create_vm_us = us;
521        other_execute_details_timings.execute_us = us;
522        other_execute_details_timings.deserialize_us = us;
523        other_execute_details_timings.changed_account_count = account_count;
524        other_execute_details_timings.total_account_count = account_count;
525
526        // Accumulate the other instance into the current instance
527        execute_details_timings.accumulate(&other_execute_details_timings);
528
529        // Check that the two instances are equal
530        assert_eq!(execute_details_timings, other_execute_details_timings);
531    }
532
533    #[test]
534    fn execute_timings_saturating_add_in_place() {
535        let mut timings = ExecuteTimings::default();
536        timings.saturating_add_in_place(ExecuteTimingType::CheckUs, 1);
537        let check_us = timings.metrics.index(ExecuteTimingType::CheckUs);
538        assert_eq!(1, *check_us);
539
540        timings.saturating_add_in_place(ExecuteTimingType::CheckUs, 2);
541        let check_us = timings.metrics.index(ExecuteTimingType::CheckUs);
542        assert_eq!(3, *check_us);
543    }
544}