Add new_from_parent() timings (#22744)

poh/src/poh_recorder.rs

@@ -551,7 +551,7 @@ impl PohRecorder {
                 (poh_entry, target_time)
             },
             (),
-            "TickLockContention",
+            "tick_lock_contention",
         );
         self.tick_lock_contention_us += tick_lock_contention_time.as_us();
 
@@ -576,7 +576,7 @@ impl PohRecorder {
             ));
 
             let (_flush_res, flush_cache_and_tick_time) =
-                Measure::this(|_| self.flush_cache(true), (), "FlushCacheAndTick");
+                Measure::this(|_| self.flush_cache(true), (), "flush_cache_and_tick");
             self.flush_cache_tick_us += flush_cache_and_tick_time.as_us();
 
             let sleep_time = Measure::this(
@@ -590,7 +590,7 @@ impl PohRecorder {
                     }
                 },
                 (),
-                "PohSleep",
+                "poh_sleep",
             )
             .1;
             self.total_sleep_us += sleep_time.as_us();
@@ -641,12 +641,12 @@ impl PohRecorder {
         assert!(!transactions.is_empty(), "No transactions provided");
 
         let ((), report_metrics_time) =
-            Measure::this(|_| self.report_metrics(bank_slot), (), "ReportMetrics");
+            Measure::this(|_| self.report_metrics(bank_slot), (), "report_metrics");
         self.report_metrics_us += report_metrics_time.as_us();
 
         loop {
             let (flush_cache_res, flush_cache_time) =
-                Measure::this(|_| self.flush_cache(false), (), "FlushCache");
+                Measure::this(|_| self.flush_cache(false), (), "flush_cache");
             self.flush_cache_no_tick_us += flush_cache_time.as_us();
             flush_cache_res?;
 
@@ -659,11 +659,11 @@ impl PohRecorder {
             }
 
             let (mut poh_lock, poh_lock_time) =
-                Measure::this(|_| self.poh.lock().unwrap(), (), "PohLock");
+                Measure::this(|_| self.poh.lock().unwrap(), (), "poh_lock");
             self.record_lock_contention_us += poh_lock_time.as_us();
 
             let (record_mixin_res, record_mixin_time) =
-                Measure::this(|_| poh_lock.record(mixin), (), "RecordMixin");
+                Measure::this(|_| poh_lock.record(mixin), (), "record_mixin");
             self.record_us += record_mixin_time.as_us();
 
             drop(poh_lock);
@@ -680,7 +680,7 @@ impl PohRecorder {
                         self.sender.send((bank_clone, (entry, self.tick_height)))
                     },
                     (),
-                    "SendPohEntry",
+                    "send_poh_entry",
                 );
                 self.send_entry_us += send_entry_time.as_us();
                 return Ok(send_entry_res?);

poh/src/poh_service.rs

@@ -264,7 +264,7 @@ impl PohService {
                     );
                     // what do we do on failure here? Ignore for now.
                     let (_send_res, send_record_result_time) =
-                        Measure::this(|_| record.sender.send(res), (), "SendRecordResult");
+                        Measure::this(|_| record.sender.send(res), (), "send_record_result");
                     timing.total_send_record_result_us += send_record_result_time.as_us();
                     timing.num_hashes += 1; // note: may have also ticked inside record
 

runtime/src/bank.rs

@@ -1482,7 +1482,8 @@ impl Bank {
         let epoch_schedule = parent.epoch_schedule;
         let epoch = epoch_schedule.get_epoch(slot);
 
-        let rc = BankRc {
+        let (rc, bank_rc_time) = Measure::this(
+            |_| BankRc {
                 accounts: Arc::new(Accounts::new_from_parent(
                     &parent.rc.accounts,
                     slot,
@@ -1491,28 +1492,98 @@ impl Bank {
                 parent: RwLock::new(Some(parent.clone())),
                 slot,
                 bank_id_generator: parent.rc.bank_id_generator.clone(),
-        };
+            },
-        let src = StatusCacheRc {
+            (),
+            "bank_rc_creation",
+        );
+
+        let (src, status_cache_rc_time) = Measure::this(
+            |_| StatusCacheRc {
                 status_cache: parent.src.status_cache.clone(),
-        };
+            },
+            (),
+            "status_cache_rc_creation",
+        );
 
-        let fee_rate_governor =
+        let ((fee_rate_governor, fee_calculator), fee_components_time) = Measure::this(
-            FeeRateGovernor::new_derived(&parent.fee_rate_governor, parent.signature_count());
+            |_| {
+                let fee_rate_governor = FeeRateGovernor::new_derived(
+                    &parent.fee_rate_governor,
+                    parent.signature_count(),
+                );
 
-        let fee_calculator = if parent.feature_set.is_active(&disable_fee_calculator::id()) {
+                let fee_calculator = if parent.feature_set.is_active(&disable_fee_calculator::id())
+                {
                     FeeCalculator::default()
                 } else {
                     fee_rate_governor.create_fee_calculator()
                 };
+                (fee_rate_governor, fee_calculator)
+            },
+            (),
+            "fee_components_creation",
+        );
 
         let bank_id = rc.bank_id_generator.fetch_add(1, Relaxed) + 1;
+        let (blockhash_queue, blockhash_queue_time) = Measure::this(
+            |_| RwLock::new(parent.blockhash_queue.read().unwrap().clone()),
+            (),
+            "blockhash_queue_creation",
+        );
+
+        let (stakes_cache, stakes_cache_time) = Measure::this(
+            |_| StakesCache::new(parent.stakes_cache.stakes().clone()),
+            (),
+            "stakes_cache_creation",
+        );
+
+        let (epoch_stakes, epoch_stakes_time) =
+            Measure::this(|_| parent.epoch_stakes.clone(), (), "epoch_stakes_reation");
+
+        let (builtin_programs, builtin_programs_time) = Measure::this(
+            |_| parent.builtin_programs.clone(),
+            (),
+            "builtin_programs_creation",
+        );
+
+        let (rewards_pool_pubkeys, rewards_pool_pubkeys_time) = Measure::this(
+            |_| parent.rewards_pool_pubkeys.clone(),
+            (),
+            "rewards_pool_pubkeys_creation",
+        );
+
+        let (cached_executors, cached_executors_time) = Measure::this(
+            |_| {
+                let cached_executors = parent.cached_executors.read().unwrap();
+                RwLock::new(cached_executors.clone_with_epoch(epoch))
+            },
+            (),
+            "cached_executors_creation",
+        );
+
+        let (transaction_debug_keys, transaction_debug_keys_time) = Measure::this(
+            |_| parent.transaction_debug_keys.clone(),
+            (),
+            "transation_debug_keys_creation",
+        );
+
+        let (transaction_log_collector_config, transaction_log_collector_config_time) =
+            Measure::this(
+                |_| parent.transaction_log_collector_config.clone(),
+                (),
+                "transaction_log_collector_config_creation",
+            );
+
+        let (feature_set, feature_set_time) =
+            Measure::this(|_| parent.feature_set.clone(), (), "feature_set_creation");
+
         let mut new = Bank {
             rc,
             src,
             slot,
             bank_id,
             epoch,
-            blockhash_queue: RwLock::new(parent.blockhash_queue.read().unwrap().clone()),
+            blockhash_queue,
 
             // TODO: clean this up, so much special-case copying...
             hashes_per_tick: parent.hashes_per_tick,
@@ -1535,8 +1606,8 @@ impl Bank {
             transaction_entries_count: AtomicU64::new(0),
             transactions_per_entry_max: AtomicU64::new(0),
             // we will .clone_with_epoch() this soon after stake data update; so just .clone() for now
-            stakes_cache: StakesCache::new(parent.stakes_cache.stakes().clone()),
+            stakes_cache,
-            epoch_stakes: parent.epoch_stakes.clone(),
+            epoch_stakes,
             parent_hash: parent.hash(),
             parent_slot: parent.slot(),
             collector_id: *collector_id,
@@ -1546,22 +1617,19 @@ impl Bank {
             is_delta: AtomicBool::new(false),
             tick_height: AtomicU64::new(parent.tick_height.load(Relaxed)),
             signature_count: AtomicU64::new(0),
-            builtin_programs: parent.builtin_programs.clone(),
+            builtin_programs,
             compute_budget: parent.compute_budget,
             feature_builtins: parent.feature_builtins.clone(),
             hard_forks: parent.hard_forks.clone(),
             rewards: RwLock::new(vec![]),
             cluster_type: parent.cluster_type,
             lazy_rent_collection: AtomicBool::new(parent.lazy_rent_collection.load(Relaxed)),
-            rewards_pool_pubkeys: parent.rewards_pool_pubkeys.clone(),
+            rewards_pool_pubkeys,
-            cached_executors: {
+            cached_executors,
-                let cached_executors = parent.cached_executors.read().unwrap();
+            transaction_debug_keys,
-                RwLock::new(cached_executors.clone_with_epoch(epoch))
+            transaction_log_collector_config,
-            },
-            transaction_debug_keys: parent.transaction_debug_keys.clone(),
-            transaction_log_collector_config: parent.transaction_log_collector_config.clone(),
             transaction_log_collector: Arc::new(RwLock::new(TransactionLogCollector::default())),
-            feature_set: parent.feature_set.clone(),
+            feature_set,
             drop_callback: RwLock::new(OptionalDropCallback(
                 parent
                     .drop_callback
@@ -1577,43 +1645,116 @@ impl Bank {
             accounts_data_len: AtomicU64::new(parent.load_accounts_data_len()),
         };
 
+        let (_, ancestors_time) = Measure::this(
+            |_| {
                 let mut ancestors = Vec::with_capacity(1 + new.parents().len());
                 ancestors.push(new.slot());
                 new.parents().iter().for_each(|p| {
                     ancestors.push(p.slot());
                 });
                 new.ancestors = Ancestors::from(ancestors);
+            },
+            (),
+            "ancestors_creation",
+        );
 
         // Following code may touch AccountsDb, requiring proper ancestors
         let parent_epoch = parent.epoch();
+        let (_, update_epoch_time) = Measure::this(
+            |_| {
                 if parent_epoch < new.epoch() {
-            let thread_pool = ThreadPoolBuilder::new().build().unwrap();
+                    let (thread_pool, thread_pool_time) = Measure::this(
+                        |_| ThreadPoolBuilder::new().build().unwrap(),
+                        (),
+                        "thread_pool_creation",
+                    );
 
-            new.apply_feature_activations(false, false);
+                    let (_, apply_feature_activations_time) = Measure::this(
+                        |_| new.apply_feature_activations(false, false),
+                        (),
+                        "apply_feature_activation",
+                    );
 
                     // Add new entry to stakes.stake_history, set appropriate epoch and
                     // update vote accounts with warmed up stakes before saving a
                     // snapshot of stakes in epoch stakes
-            new.stakes_cache.activate_epoch(epoch, &thread_pool);
+                    let (_, activate_epoch_time) = Measure::this(
+                        |_| new.stakes_cache.activate_epoch(epoch, &thread_pool),
+                        (),
+                        "activate_epoch",
+                    );
 
                     // Save a snapshot of stakes for use in consensus and stake weighted networking
                     let leader_schedule_epoch = epoch_schedule.get_leader_schedule_epoch(slot);
-            new.update_epoch_stakes(leader_schedule_epoch);
+                    let (_, update_epoch_stakes_time) = Measure::this(
+                        |_| new.update_epoch_stakes(leader_schedule_epoch),
+                        (),
+                        "update_epoch_stakes",
+                    );
 
                     // After saving a snapshot of stakes, apply stake rewards and commission
-            new.update_rewards_with_thread_pool(parent_epoch, reward_calc_tracer, &thread_pool);
+                    let (_, update_rewards_with_thread_pool_time) = Measure::this(
+                        |_| {
+                            new.update_rewards_with_thread_pool(
+                                parent_epoch,
+                                reward_calc_tracer,
+                                &thread_pool,
+                            )
+                        },
+                        (),
+                        "update_rewards_with_thread_pool",
+                    );
+
+                    datapoint_info!(
+                        "bank-new_from_parent-new_epoch_timings",
+                        ("epoch", new.epoch(), i64),
+                        ("slot", slot, i64),
+                        ("parent_slot", parent.slot(), i64),
+                        ("thread_pool_creation_us", thread_pool_time.as_us(), i64),
+                        (
+                            "apply_feature_activations",
+                            apply_feature_activations_time.as_us(),
+                            i64
+                        ),
+                        ("activate_epoch_Us", activate_epoch_time.as_us(), i64),
+                        (
+                            "update_epoch_stakes_us",
+                            update_epoch_stakes_time.as_us(),
+                            i64
+                        ),
+                        (
+                            "update_rewards_with_thread_pool_us",
+                            update_rewards_with_thread_pool_time.as_us(),
+                            i64
+                        ),
+                    );
                 } else {
                     // Save a snapshot of stakes for use in consensus and stake weighted networking
                     let leader_schedule_epoch = epoch_schedule.get_leader_schedule_epoch(slot);
                     new.update_epoch_stakes(leader_schedule_epoch);
                 }
+            },
+            (),
+            "update_epoch",
+        );
 
         // Update sysvars before processing transactions
+        let (_, update_sysvars_time) = Measure::this(
+            |_| {
                 new.update_slot_hashes();
                 new.update_stake_history(Some(parent_epoch));
                 new.update_clock(Some(parent_epoch));
                 new.update_fees();
-        new.fill_missing_sysvar_cache_entries();
+            },
+            (),
+            "update_sysvars",
+        );
+
+        let (_, fill_sysvar_cache_time) = Measure::this(
+            |_| new.fill_missing_sysvar_cache_entries(),
+            (),
+            "fill_sysvar_cache",
+        );
 
         time.stop();
 
@@ -1621,8 +1762,36 @@ impl Bank {
             "bank-new_from_parent-heights",
             ("slot_height", slot, i64),
             ("block_height", new.block_height, i64),
-            ("parent_slot_height", parent.slot(), i64),
+            ("parent_slot", parent.slot(), i64),
-            ("time_us", time.as_us(), i64),
+            ("bank_rc_creation_us", bank_rc_time.as_us(), i64),
+            ("total_elapsed_us", time.as_us(), i64),
+            ("status_cache_rc_us", status_cache_rc_time.as_us(), i64),
+            ("fee_components_us", fee_components_time.as_us(), i64),
+            ("blockhash_queue_us", blockhash_queue_time.as_us(), i64),
+            ("stakes_cache_us", stakes_cache_time.as_us(), i64),
+            ("epoch_stakes_time_us", epoch_stakes_time.as_us(), i64),
+            ("builtin_programs_us", builtin_programs_time.as_us(), i64),
+            (
+                "rewards_pool_pubkeys_us",
+                rewards_pool_pubkeys_time.as_us(),
+                i64
+            ),
+            ("cached_executors_us", cached_executors_time.as_us(), i64),
+            (
+                "transaction_debug_keys_us",
+                transaction_debug_keys_time.as_us(),
+                i64
+            ),
+            (
+                "transaction_log_collector_config_us",
+                transaction_log_collector_config_time.as_us(),
+                i64
+            ),
+            ("feature_set_us", feature_set_time.as_us(), i64),
+            ("ancestors_us", ancestors_time.as_us(), i64),
+            ("update_epoch_us", update_epoch_time.as_us(), i64),
+            ("update_sysvars_us", update_sysvars_time.as_us(), i64),
+            ("fill_sysvar_cache_us", fill_sysvar_cache_time.as_us(), i64),
         );
 
         parent