add execute detail timings (#15638)

Cargo.lock

@@ -4134,6 +4134,7 @@ dependencies = [
  "rand 0.7.3",
  "rand_core 0.6.2",
  "rustversion",
+ "solana-measure",
  "solana-runtime",
  "solana-sdk",
  "solana_rbpf",

core/src/banking_stage.rs

@@ -776,6 +776,11 @@ impl BankingStage {
             txs.len(),
         );
 
+        debug!(
+            "process_and_record_transactions_locked: {:?}",
+            execute_timings
+        );
+
         (Ok(num_to_commit), retryable_txs)
     }
 

ledger/src/blockstore_processor.rs

@@ -214,15 +214,19 @@ pub fn process_entries(
     transaction_status_sender: Option<TransactionStatusSender>,
     replay_vote_sender: Option<&ReplayVoteSender>,
 ) -> Result<()> {
-    process_entries_with_callback(
+    let mut timings = ExecuteTimings::default();
+    let result = process_entries_with_callback(
         bank,
         entries,
         randomize,
         None,
         transaction_status_sender,
         replay_vote_sender,
-        &mut ExecuteTimings::default(),
+        &mut timings,
-    )
+    );
+
+    debug!("process_entries: {:?}", timings);
+    result
 }
 
 fn process_entries_with_callback(
@@ -602,6 +606,8 @@ fn confirm_full_slot(
         opts.allow_dead_slots,
     )?;
 
+    debug!("confirm_full_slot: {:?}", timing.execute_timings);
+
     if !bank.is_complete() {
         Err(BlockstoreProcessorError::InvalidBlock(
             BlockError::Incomplete,

programs/bpf/Cargo.lock

@@ -2598,6 +2598,7 @@ dependencies = [
  "num-derive 0.3.0",
  "num-traits",
  "rand_core 0.6.2",
+ "solana-measure",
  "solana-runtime",
  "solana-sdk",
  "solana_rbpf",

programs/bpf_loader/Cargo.toml

@@ -16,6 +16,7 @@ log = "0.4.11"
 num-derive = "0.3"
 num-traits = "0.2"
 rand_core = "0.6.2"
+solana-measure = { path = "../../measure", version = "1.6.0" }
 solana-runtime = { path = "../../runtime", version = "1.6.0" }
 solana-sdk = { path = "../../sdk", version = "1.6.0" }
 solana_rbpf = "=0.2.5"

programs/bpf_loader/src/lib.rs

@@ -15,6 +15,7 @@ use crate::{
     syscalls::SyscallError,
 };
 use log::{log_enabled, trace, Level::Trace};
+use solana_measure::measure::Measure;
 use solana_rbpf::{
     ebpf::MM_HEAP_START,
     error::{EbpfError, UserDefinedError},
@@ -770,8 +771,12 @@ impl Executor for BpfExecutor {
         let mut keyed_accounts_iter = keyed_accounts.iter();
         let _ = next_keyed_account(&mut keyed_accounts_iter)?;
         let parameter_accounts = keyed_accounts_iter.as_slice();
+        let mut serialize_time = Measure::start("serialize");
         let mut parameter_bytes =
             serialize_parameters(loader_id, program_id, parameter_accounts, &instruction_data)?;
+        serialize_time.stop();
+        let mut create_vm_time = Measure::start("create_vm");
+        let mut execute_time;
         {
             let compute_meter = invoke_context.get_compute_meter();
             let mut vm = match create_vm(
@@ -787,7 +792,9 @@ impl Executor for BpfExecutor {
                     return Err(InstructionError::ProgramEnvironmentSetupFailure);
                 }
             };
+            create_vm_time.stop();
 
+            execute_time = Measure::start("execute");
             stable_log::program_invoke(&logger, program_id, invoke_depth);
             let mut instruction_meter = ThisInstructionMeter::new(compute_meter.clone());
             let before = compute_meter.borrow().get_remaining();
@@ -833,8 +840,17 @@ impl Executor for BpfExecutor {
                     return Err(error);
                 }
             }
+            execute_time.stop();
         }
+        let mut deserialize_time = Measure::start("deserialize");
         deserialize_parameters(loader_id, parameter_accounts, &parameter_bytes)?;
+        deserialize_time.stop();
+        invoke_context.update_timing(
+            serialize_time.as_us(),
+            create_vm_time.as_us(),
+            execute_time.as_us(),
+            deserialize_time.as_us(),
+        );
         stable_log::program_success(&logger, program_id);
         Ok(())
     }

runtime/benches/message_processor.rs

@@ -3,7 +3,7 @@
 extern crate test;
 
 use log::*;
-use solana_runtime::message_processor::PreAccount;
+use solana_runtime::message_processor::{ExecuteDetailsTimings, PreAccount};
 use solana_sdk::{account::Account, pubkey, rent::Rent};
 use test::Bencher;
 
@@ -20,13 +20,25 @@ fn bench_verify_account_changes_data(bencher: &mut Bencher) {
     );
     let post = Account::new(0, BUFSIZE, &owner);
     assert_eq!(
-        pre.verify(&owner, Some(false), &Rent::default(), &post),
+        pre.verify(
+            &owner,
+            Some(false),
+            &Rent::default(),
+            &post,
+            &mut ExecuteDetailsTimings::default()
+        ),
         Ok(())
     );
 
     // this one should be faster
     bencher.iter(|| {
-        pre.verify(&owner, Some(false), &Rent::default(), &post)
+        pre.verify(
+            &owner,
+            Some(false),
+            &Rent::default(),
+            &post,
+            &mut ExecuteDetailsTimings::default(),
+        )
         .unwrap();
     });
     let summary = bencher.bench(|_bencher| {}).unwrap();
@@ -44,7 +56,13 @@ fn bench_verify_account_changes_data(bencher: &mut Bencher) {
         false,
     );
     bencher.iter(|| {
-        pre.verify(&non_owner, Some(false), &Rent::default(), &post)
+        pre.verify(
+            &non_owner,
+            Some(false),
+            &Rent::default(),
+            &post,
+            &mut ExecuteDetailsTimings::default(),
+        )
         .unwrap();
     });
     let summary = bencher.bench(|_bencher| {}).unwrap();

runtime/src/bank.rs

@@ -15,7 +15,7 @@ use crate::{
     inline_spl_token_v2_0,
     instruction_recorder::InstructionRecorder,
     log_collector::LogCollector,
-    message_processor::{Executors, MessageProcessor},
+    message_processor::{ExecuteDetailsTimings, Executors, MessageProcessor},
     rent_collector::RentCollector,
     stakes::Stakes,
     status_cache::{SlotDelta, StatusCache},
@@ -93,11 +93,12 @@ pub const SECONDS_PER_YEAR: f64 = 365.25 * 24.0 * 60.0 * 60.0;
 
 pub const MAX_LEADER_SCHEDULE_STAKES: Epoch = 5;
 
-#[derive(Default)]
+#[derive(Default, Debug)]
 pub struct ExecuteTimings {
     pub load_us: u64,
     pub execute_us: u64,
     pub store_us: u64,
+    pub details: ExecuteDetailsTimings,
 }
 
 impl ExecuteTimings {
@@ -105,6 +106,7 @@ impl ExecuteTimings {
         self.load_us += other.load_us;
         self.execute_us += other.execute_us;
         self.store_us += other.store_us;
+        self.details.accumulate(&other.details);
     }
 }
 
@@ -2415,6 +2417,8 @@ impl Bank {
         let txs = &[transaction];
         let batch = self.prepare_simulation_batch(txs);
 
+        let mut timings = ExecuteTimings::default();
+
         let (
             _loaded_accounts,
             executed,
@@ -2431,7 +2435,7 @@ impl Bank {
             MAX_PROCESSING_AGE - MAX_TRANSACTION_FORWARDING_DELAY,
             false,
             true,
-            &mut ExecuteTimings::default(),
+            &mut timings,
         );
 
         let transaction_result = executed[0].0.clone().map(|_| ());
@@ -2439,6 +2443,8 @@ impl Bank {
             .get(0)
             .map_or(vec![], |messages| messages.to_vec());
 
+        debug!("simulate_transaction: {:?}", timings);
+
         (transaction_result, log_messages)
     }
 
@@ -2923,6 +2929,7 @@ impl Bank {
                         instruction_recorders.as_deref(),
                         self.feature_set.clone(),
                         bpf_compute_budget,
+                        &mut timings.details,
                     );
 
                     if enable_log_recording {

runtime/src/message_processor.rs

@@ -52,6 +52,31 @@ impl Executors {
     }
 }
 
+#[derive(Default, Debug)]
+pub struct ExecuteDetailsTimings {
+    pub serialize_us: u64,
+    pub create_vm_us: u64,
+    pub execute_us: u64,
+    pub deserialize_us: u64,
+    pub changed_account_count: u64,
+    pub total_account_count: u64,
+    pub total_data_size: usize,
+    pub data_size_changed: usize,
+}
+
+impl ExecuteDetailsTimings {
+    pub fn accumulate(&mut self, other: &ExecuteDetailsTimings) {
+        self.serialize_us += other.serialize_us;
+        self.create_vm_us += other.create_vm_us;
+        self.execute_us += other.execute_us;
+        self.deserialize_us += other.deserialize_us;
+        self.changed_account_count += other.changed_account_count;
+        self.total_account_count += other.total_account_count;
+        self.total_data_size += other.total_data_size;
+        self.data_size_changed += other.data_size_changed;
+    }
+}
+
 // The relevant state of an account before an Instruction executes, used
 // to verify account integrity after the Instruction completes
 #[derive(Clone, Debug, Default)]
@@ -59,6 +84,7 @@ pub struct PreAccount {
     key: Pubkey,
     is_writable: bool,
     account: RefCell<Account>,
+    changed: bool,
 }
 impl PreAccount {
     pub fn new(key: &Pubkey, account: &Account, is_writable: bool) -> Self {
@@ -66,6 +92,7 @@ impl PreAccount {
             key: *key,
             is_writable,
             account: RefCell::new(account.clone()),
+            changed: false,
         }
     }
 
@@ -75,6 +102,7 @@ impl PreAccount {
         is_writable: Option<bool>,
         rent: &Rent,
         post: &Account,
+        timings: &mut ExecuteDetailsTimings,
     ) -> Result<(), InstructionError> {
         let pre = self.account.borrow();
 
@@ -88,7 +116,8 @@ impl PreAccount {
         //   only if the account is writable and
         //   only if the account is not executable and
         //   only if the data is zero-initialized or empty
-        if pre.owner != post.owner
+        let owner_changed = pre.owner != post.owner;
+        if owner_changed
             && (!is_writable // line coverage used to get branch coverage
                 || pre.executable
                 || *program_id != pre.owner
@@ -105,7 +134,8 @@ impl PreAccount {
         }
 
         // The balance of read-only and executable accounts may not change
-        if pre.lamports != post.lamports {
+        let lamports_changed = pre.lamports != post.lamports;
+        if lamports_changed {
             if !is_writable {
                 return Err(InstructionError::ReadonlyLamportChange);
             }
@@ -116,7 +146,8 @@ impl PreAccount {
 
         // Only the system program can change the size of the data
         //  and only if the system program owns the account
-        if pre.data.len() != post.data.len()
+        let data_len_changed = pre.data.len() != post.data.len();
+        if data_len_changed
             && (!system_program::check_id(program_id) // line coverage used to get branch coverage
                 || !system_program::check_id(&pre.owner))
         {
@@ -141,7 +172,8 @@ impl PreAccount {
         }
 
         // executable is one-way (false->true) and only the account owner may set it.
-        if pre.executable != post.executable {
+        let executable_changed = pre.executable != post.executable;
+        if executable_changed {
             if !rent.is_exempt(post.lamports, post.data.len()) {
                 return Err(InstructionError::ExecutableAccountNotRentExempt);
             }
@@ -154,10 +186,24 @@ impl PreAccount {
         }
 
         // No one modifies rent_epoch (yet).
-        if pre.rent_epoch != post.rent_epoch {
+        let rent_epoch_changed = pre.rent_epoch != post.rent_epoch;
+        if rent_epoch_changed {
             return Err(InstructionError::RentEpochModified);
         }
 
+        timings.total_account_count += 1;
+        timings.total_data_size += post.data.len();
+        if owner_changed
+            || lamports_changed
+            || data_len_changed
+            || executable_changed
+            || rent_epoch_changed
+            || self.changed
+        {
+            timings.changed_account_count += 1;
+            timings.data_size_changed += post.data.len();
+        }
+
         Ok(())
     }
 
@@ -174,6 +220,8 @@ impl PreAccount {
             // Copy without allocate
             pre.data.clone_from_slice(&account.data);
         }
+
+        self.changed = true;
     }
 
     pub fn key(&self) -> Pubkey {
@@ -222,6 +270,7 @@ pub struct ThisInvokeContext<'a> {
     executors: Rc<RefCell<Executors>>,
     instruction_recorder: Option<InstructionRecorder>,
     feature_set: Arc<FeatureSet>,
+    pub timings: ExecuteDetailsTimings,
 }
 impl<'a> ThisInvokeContext<'a> {
     #[allow(clippy::too_many_arguments)]
@@ -253,6 +302,7 @@ impl<'a> ThisInvokeContext<'a> {
             executors,
             instruction_recorder,
             feature_set,
+            timings: ExecuteDetailsTimings::default(),
         }
     }
 }
@@ -293,6 +343,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> {
                 &self.rent,
                 track_writable_deescalation,
                 caller_privileges,
+                &mut self.timings,
             ),
             None => Err(InstructionError::GenericError), // Should never happen
         }
@@ -346,6 +397,18 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> {
             }
         })
     }
+    fn update_timing(
+        &mut self,
+        serialize_us: u64,
+        create_vm_us: u64,
+        execute_us: u64,
+        deserialize_us: u64,
+    ) {
+        self.timings.serialize_us += serialize_us;
+        self.timings.create_vm_us += create_vm_us;
+        self.timings.execute_us += execute_us;
+        self.timings.deserialize_us += deserialize_us;
+    }
 }
 pub struct ThisLogger {
     log_collector: Option<Rc<LogCollector>>,
@@ -836,6 +899,7 @@ impl MessageProcessor {
         executable_accounts: &[(Pubkey, RefCell<Account>)],
         accounts: &[Rc<RefCell<Account>>],
         rent: &Rent,
+        timings: &mut ExecuteDetailsTimings,
     ) -> Result<(), InstructionError> {
         // Verify all executable accounts have zero outstanding refs
         Self::verify_account_references(executable_accounts)?;
@@ -854,6 +918,7 @@ impl MessageProcessor {
                     Some(message.is_writable(account_index)),
                     rent,
                     &account,
+                    timings,
                 )?;
                 pre_sum += u128::from(pre_accounts[unique_index].lamports());
                 post_sum += u128::from(account.lamports);
@@ -879,6 +944,7 @@ impl MessageProcessor {
         rent: &Rent,
         track_writable_deescalation: bool,
         caller_privileges: Option<&[bool]>,
+        timings: &mut ExecuteDetailsTimings,
     ) -> Result<(), InstructionError> {
         // Verify the per-account instruction results
         let (mut pre_sum, mut post_sum) = (0_u128, 0_u128);
@@ -903,7 +969,7 @@ impl MessageProcessor {
                             .try_borrow_mut()
                             .map_err(|_| InstructionError::AccountBorrowOutstanding)?;
 
-                        pre_account.verify(&program_id, is_writable, &rent, &account)?;
+                        pre_account.verify(&program_id, is_writable, &rent, &account, timings)?;
                         pre_sum += u128::from(pre_account.lamports());
                         post_sum += u128::from(account.lamports);
 
@@ -944,6 +1010,7 @@ impl MessageProcessor {
         instruction_index: usize,
         feature_set: Arc<FeatureSet>,
         bpf_compute_budget: BpfComputeBudget,
+        timings: &mut ExecuteDetailsTimings,
     ) -> Result<(), InstructionError> {
         // Fixup the special instructions key if present
         // before the account pre-values are taken care of
@@ -989,7 +1056,11 @@ impl MessageProcessor {
             executable_accounts,
             accounts,
             &rent_collector.rent,
+            timings,
         )?;
+
+        timings.accumulate(&invoke_context.timings);
+
         Ok(())
     }
 
@@ -1009,6 +1080,7 @@ impl MessageProcessor {
         instruction_recorders: Option<&[InstructionRecorder]>,
         feature_set: Arc<FeatureSet>,
         bpf_compute_budget: BpfComputeBudget,
+        timings: &mut ExecuteDetailsTimings,
     ) -> Result<(), TransactionError> {
         for (instruction_index, instruction) in message.instructions.iter().enumerate() {
             let instruction_recorder = instruction_recorders
@@ -1027,6 +1099,7 @@ impl MessageProcessor {
                 instruction_index,
                 feature_set.clone(),
                 bpf_compute_budget,
+                timings,
             )
             .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?;
         }
@@ -1247,6 +1320,7 @@ mod tests {
                 Some(self.is_writable),
                 &self.rent,
                 &self.post,
+                &mut ExecuteDetailsTimings::default(),
             )
         }
     }
@@ -1646,6 +1720,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             BpfComputeBudget::new(),
+            &mut ExecuteDetailsTimings::default(),
         );
         assert_eq!(result, Ok(()));
         assert_eq!(accounts[0].borrow().lamports, 100);
@@ -1671,6 +1746,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             BpfComputeBudget::new(),
+            &mut ExecuteDetailsTimings::default(),
         );
         assert_eq!(
             result,
@@ -1700,6 +1776,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             BpfComputeBudget::new(),
+            &mut ExecuteDetailsTimings::default(),
         );
         assert_eq!(
             result,
@@ -1813,6 +1890,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             BpfComputeBudget::new(),
+            &mut ExecuteDetailsTimings::default(),
         );
         assert_eq!(
             result,
@@ -1842,6 +1920,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             BpfComputeBudget::new(),
+            &mut ExecuteDetailsTimings::default(),
         );
         assert_eq!(result, Ok(()));
 
@@ -1868,6 +1947,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             BpfComputeBudget::new(),
+            &mut ExecuteDetailsTimings::default(),
         );
         assert_eq!(result, Ok(()));
         assert_eq!(accounts[0].borrow().lamports, 80);

sdk/src/process_instruction.rs

@@ -60,6 +60,14 @@ pub trait InvokeContext {
     fn is_feature_active(&self, feature_id: &Pubkey) -> bool;
     /// Get an account from a pre-account
     fn get_account(&self, pubkey: &Pubkey) -> Option<RefCell<Account>>;
+    /// Update timing
+    fn update_timing(
+        &mut self,
+        serialize_us: u64,
+        create_vm_us: u64,
+        execute_us: u64,
+        deserialize_us: u64,
+    );
 }
 
 /// Convenience macro to log a message with an `Rc<RefCell<dyn Logger>>`
@@ -328,4 +336,12 @@ impl InvokeContext for MockInvokeContext {
     fn get_account(&self, _pubkey: &Pubkey) -> Option<RefCell<Account>> {
         None
     }
+    fn update_timing(
+        &mut self,
+        _serialize_us: u64,
+        _create_vm_us: u64,
+        _execute_us: u64,
+        _deserialize_us: u64,
+    ) {
+    }
 }