SVM: fix executor metrics accumulation in program loader (#3695)

runtime/src/bank.rs

@@ -7365,7 +7365,14 @@ impl Bank {
         let environments = self
             .transaction_processor
             .get_environments_for_epoch(effective_epoch)?;
-        load_program_with_pubkey(self, &environments, pubkey, self.slot(), reload)
+        load_program_with_pubkey(
+            self,
+            &environments,
+            pubkey,
+            self.slot(),
+            &mut ExecuteTimings::default(), // Called by ledger-tool, metrics not accumulated.
+            reload,
+        )
     }
 
     pub fn withdraw(&self, pubkey: &Pubkey, lamports: u64) -> Result<()> {

svm/src/program_loader.rs

@@ -15,7 +15,7 @@ use {
         pubkey::Pubkey,
         transaction::{self, TransactionError},
     },
-    solana_timings::ExecuteDetailsTimings,
+    solana_timings::ExecuteTimings,
     solana_type_overrides::sync::Arc,
 };
 
@@ -124,6 +124,7 @@ pub fn load_program_with_pubkey<CB: TransactionProcessingCallback>(
     environments: &ProgramRuntimeEnvironments,
     pubkey: &Pubkey,
     slot: Slot,
+    execute_timings: &mut ExecuteTimings,
     reload: bool,
 ) -> Option<Arc<ProgramCacheEntry>> {
     let mut load_program_metrics = LoadProgramMetrics {
@@ -206,8 +207,7 @@ pub fn load_program_with_pubkey<CB: TransactionProcessingCallback>(
         )
     });
 
-    let mut timings = ExecuteDetailsTimings::default();
-    load_program_metrics.submit_datapoint(&mut timings);
+    load_program_metrics.submit_datapoint(&mut execute_timings.details);
     loaded_program.update_access_slot(slot);
     Some(Arc::new(loaded_program))
 }
@@ -524,6 +524,7 @@ mod tests {
             &batch_processor.get_environments_for_epoch(50).unwrap(),
             &key,
             500,
+            &mut ExecuteTimings::default(),
             false,
         );
         assert!(result.is_none());
@@ -546,6 +547,7 @@ mod tests {
             &batch_processor.get_environments_for_epoch(20).unwrap(),
             &key,
             0, // Slot 0
+            &mut ExecuteTimings::default(),
             false,
         );
 
@@ -580,6 +582,7 @@ mod tests {
             &batch_processor.get_environments_for_epoch(20).unwrap(),
             &key,
             200,
+            &mut ExecuteTimings::default(),
             false,
         );
         let loaded_program = ProgramCacheEntry::new_tombstone(
@@ -607,6 +610,7 @@ mod tests {
             &batch_processor.get_environments_for_epoch(20).unwrap(),
             &key,
             200,
+            &mut ExecuteTimings::default(),
             false,
         );
 
@@ -660,6 +664,7 @@ mod tests {
             &batch_processor.get_environments_for_epoch(0).unwrap(),
             &key1,
             0,
+            &mut ExecuteTimings::default(),
             false,
         );
         let loaded_program = ProgramCacheEntry::new_tombstone(
@@ -697,6 +702,7 @@ mod tests {
             &batch_processor.get_environments_for_epoch(20).unwrap(),
             &key1,
             200,
+            &mut ExecuteTimings::default(),
             false,
         );
 
@@ -746,6 +752,7 @@ mod tests {
             &batch_processor.get_environments_for_epoch(0).unwrap(),
             &key,
             0,
+            &mut ExecuteTimings::default(),
             false,
         );
         let loaded_program = ProgramCacheEntry::new_tombstone(
@@ -779,6 +786,7 @@ mod tests {
             &batch_processor.get_environments_for_epoch(20).unwrap(),
             &key,
             200,
+            &mut ExecuteTimings::default(),
             false,
         );
 
@@ -829,6 +837,7 @@ mod tests {
                     .unwrap(),
                 &key,
                 200,
+                &mut ExecuteTimings::default(),
                 false,
             )
             .unwrap();

svm/src/transaction_processor.rs

@@ -368,6 +368,7 @@ impl<FG: ForkGraph> TransactionBatchProcessor<FG> {
             let program_cache_for_tx_batch = self.replenish_program_cache(
                 callbacks,
                 &program_accounts_map,
+                &mut execute_timings,
                 config.check_program_modification_slot,
                 config.limit_to_load_programs,
             );
@@ -731,6 +732,7 @@ impl<FG: ForkGraph> TransactionBatchProcessor<FG> {
         &self,
         callback: &CB,
         program_accounts_map: &HashMap<Pubkey, (&Pubkey, u64)>,
+        execute_timings: &mut ExecuteTimings,
         check_program_modification_slot: bool,
         limit_to_load_programs: bool,
     ) -> ProgramCacheForTxBatch {
@@ -778,6 +780,7 @@ impl<FG: ForkGraph> TransactionBatchProcessor<FG> {
                         &program_cache.get_environments_for_epoch(self.epoch),
                         &key,
                         self.slot,
+                        execute_timings,
                         false,
                     )
                     .expect("called load_program_with_pubkey() with nonexistent account");
@@ -850,6 +853,7 @@ impl<FG: ForkGraph> TransactionBatchProcessor<FG> {
                     &environments_for_epoch,
                     &key,
                     self.slot,
+                    &mut ExecuteTimings::default(),
                     false,
                 ) {
                     recompiled.tx_usage_counter.fetch_add(
@@ -1575,7 +1579,13 @@ mod tests {
         let mut account_maps: HashMap<Pubkey, (&Pubkey, u64)> = HashMap::new();
         account_maps.insert(key, (&owner, 4));
 
-        batch_processor.replenish_program_cache(&mock_bank, &account_maps, false, true);
+        batch_processor.replenish_program_cache(
+            &mock_bank,
+            &account_maps,
+            &mut ExecuteTimings::default(),
+            false,
+            true,
+        );
     }
 
     #[test]
@@ -1603,6 +1613,7 @@ mod tests {
             let result = batch_processor.replenish_program_cache(
                 &mock_bank,
                 &account_maps,
+                &mut ExecuteTimings::default(),
                 false,
                 limit_to_load_programs,
             );

svm/tests/concurrent_tests.rs

@@ -30,6 +30,7 @@ use {
             TransactionProcessingEnvironment,
         },
     },
+    solana_timings::ExecuteTimings,
     std::collections::HashMap,
 };
 
@@ -67,7 +68,13 @@ fn program_cache_execution(threads: usize) {
             let maps = account_maps.clone();
             let programs = programs.clone();
             thread::spawn(move || {
-                let result = processor.replenish_program_cache(&local_bank, &maps, false, true);
+                let result = processor.replenish_program_cache(
+                    &local_bank,
+                    &maps,
+                    &mut ExecuteTimings::default(),
+                    false,
+                    true,
+                );
                 for key in &programs {
                     let cache_entry = result.find(key);
                     assert!(matches!(

svm/tests/conformance.rs

@@ -424,6 +424,7 @@ fn execute_fixture_as_instr(
         &batch_processor.get_environments_for_epoch(2).unwrap(),
         &program_id,
         42,
+        &mut ExecuteTimings::default(),
         false,
     )
     .unwrap();

svm/tests/integration_test.rs

@@ -2449,3 +2449,40 @@ fn svm_inspect_account() {
         num_actual_inspected_accounts,
     );
 }
+
+// Tests for proper accumulation of metrics across loaded programs in a batch.
+#[test]
+fn svm_metrics_accumulation() {
+    for test_entry in program_medley() {
+        let env = SvmTestEnvironment::create(test_entry);
+
+        let (transactions, check_results) = env.test_entry.prepare_transactions();
+
+        let result = env.batch_processor.load_and_execute_sanitized_transactions(
+            &env.mock_bank,
+            &transactions,
+            check_results,
+            &env.processing_environment,
+            &env.processing_config,
+        );
+
+        assert_ne!(
+            result
+                .execute_timings
+                .details
+                .create_executor_jit_compile_us,
+            0
+        );
+        assert_ne!(
+            result.execute_timings.details.create_executor_load_elf_us,
+            0
+        );
+        assert_ne!(
+            result
+                .execute_timings
+                .details
+                .create_executor_verify_code_us,
+            0
+        );
+    }
+}