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 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 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#[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
90eager_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 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 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 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 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 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 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 execute_details_timings.accumulate(&other_execute_details_timings);
528
529 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}