Per-program id timings (#17554)

core/src/progress_map.rs

@@ -104,6 +104,27 @@ impl ReplaySlotStats {
                 i64
             ),
         );
+
+        let mut per_pubkey_timings: Vec<_> = self
+            .execute_timings
+            .details
+            .per_program_timings
+            .iter()
+            .collect();
+        per_pubkey_timings.sort_by(|a, b| b.1 .0.cmp(&a.1 .0));
+        let total: u64 = per_pubkey_timings.iter().map(|a| a.1 .0).sum();
+        for (pubkey, time) in per_pubkey_timings.iter().take(5) {
+            datapoint_info!(
+                "per_program_timings",
+                ("pubkey", pubkey.to_string(), String),
+                ("execute_us", time.0, i64)
+            );
+        }
+        datapoint_info!(
+            "per_program_timings",
+            ("pubkey", "all", String),
+            ("execute_us", total, i64)
+        );
     }
 }
 

runtime/src/message_processor.rs

@@ -4,6 +4,7 @@ use crate::{
 };
 use log::*;
 use serde::{Deserialize, Serialize};
+use solana_measure::measure::Measure;
 use solana_sdk::{
     account::{AccountSharedData, ReadableAccount, WritableAccount},
     account_utils::StateMut,
@@ -63,6 +64,7 @@ pub struct ExecuteDetailsTimings {
     pub total_account_count: u64,
     pub total_data_size: usize,
     pub data_size_changed: usize,
+    pub per_program_timings: HashMap<Pubkey, (u64, u32)>,
 }
 
 impl ExecuteDetailsTimings {
@@ -75,6 +77,11 @@ impl ExecuteDetailsTimings {
         self.total_account_count += other.total_account_count;
         self.total_data_size += other.total_data_size;
         self.data_size_changed += other.data_size_changed;
+        for (id, other) in &other.per_program_timings {
+            let time_count = self.per_program_timings.entry(*id).or_default();
+            time_count.0 += other.0;
+            time_count.1 += other.1;
+        }
     }
 }
 
@@ -1205,28 +1212,38 @@ impl MessageProcessor {
     ) -> Result<(), TransactionError> {
         let demote_sysvar_write_locks = feature_set.is_active(&demote_sysvar_write_locks::id());
         for (instruction_index, instruction) in message.instructions.iter().enumerate() {
+            let mut time = Measure::start("execute_instruction");
             let instruction_recorder = instruction_recorders
                 .as_ref()
                 .map(|recorders| recorders[instruction_index].clone());
-            self.execute_instruction(
-                message,
-                instruction,
-                &loaders[instruction_index],
-                accounts,
-                account_deps,
-                rent_collector,
-                log_collector.clone(),
-                executors.clone(),
-                instruction_recorder,
-                instruction_index,
-                feature_set.clone(),
-                bpf_compute_budget,
-                timings,
-                demote_sysvar_write_locks,
-                account_db.clone(),
-                ancestors,
-            )
-            .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?;
+            let err = self
+                .execute_instruction(
+                    message,
+                    instruction,
+                    &loaders[instruction_index],
+                    accounts,
+                    account_deps,
+                    rent_collector,
+                    log_collector.clone(),
+                    executors.clone(),
+                    instruction_recorder,
+                    instruction_index,
+                    feature_set.clone(),
+                    bpf_compute_budget,
+                    timings,
+                    demote_sysvar_write_locks,
+                    account_db.clone(),
+                    ancestors,
+                )
+                .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err));
+            time.stop();
+
+            let program_id = instruction.program_id(&message.account_keys);
+            let time_count = timings.per_program_timings.entry(*program_id).or_default();
+            time_count.0 += time.as_us();
+            time_count.1 += 1;
+
+            err?;
         }
         Ok(())
     }