From 1e5212e60dee98f0725457c16e6a54affd6f8ab1 Mon Sep 17 00:00:00 2001
From: sakridge <sakridge@gmail.com>
Date: Tue, 2 Nov 2021 10:23:35 -0700
Subject: [PATCH] Add set_root timing metrics (#21119)

---
 runtime/src/bank.rs       | 18 +++++++++++-------
 runtime/src/bank_forks.rs | 40 +++++++++++++++++++++++++++++----------
 2 files changed, 41 insertions(+), 17 deletions(-)

diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs
index 349484ee1..a358123f5 100644
--- a/runtime/src/bank.rs
+++ b/runtime/src/bank.rs
@@ -70,7 +70,7 @@ use rayon::{
     ThreadPool, ThreadPoolBuilder,
 };
 use solana_measure::measure::Measure;
-use solana_metrics::{datapoint_debug, inc_new_counter_debug, inc_new_counter_info};
+use solana_metrics::{inc_new_counter_debug, inc_new_counter_info};
 use solana_program_runtime::{ExecuteDetailsTimings, Executors, InstructionProcessor};
 #[allow(deprecated)]
 use solana_sdk::recent_blockhashes_account;
@@ -219,6 +219,11 @@ type RentCollectionCycleParams = (
     PartitionsPerCycle,
 );
 
+pub struct SquashTiming {
+    pub squash_accounts_ms: u64,
+    pub squash_cache_ms: u64,
+}
+
 type EpochCount = u64;
 
 /// Copy-on-write holder of CachedExecutors
@@ -2880,7 +2885,7 @@ impl Bank {
 
     /// squash the parent's state up into this Bank,
     ///   this Bank becomes a root
-    pub fn squash(&self) {
+    pub fn squash(&self) -> SquashTiming {
         self.freeze();
 
         //this bank and all its parents are now on the rooted path
@@ -2902,11 +2907,10 @@ impl Bank {
             .for_each(|slot| self.src.status_cache.write().unwrap().add_root(*slot));
         squash_cache_time.stop();
 
-        datapoint_debug!(
-            "tower-observed",
-            ("squash_accounts_ms", squash_accounts_time.as_ms(), i64),
-            ("squash_cache_ms", squash_cache_time.as_ms(), i64)
-        );
+        SquashTiming {
+            squash_accounts_ms: squash_accounts_time.as_ms(),
+            squash_cache_ms: squash_cache_time.as_ms(),
+        }
     }
 
     /// Return the more recent checkpoint of this bank instance.
diff --git a/runtime/src/bank_forks.rs b/runtime/src/bank_forks.rs
index 513df4538..472873b49 100644
--- a/runtime/src/bank_forks.rs
+++ b/runtime/src/bank_forks.rs
@@ -6,7 +6,7 @@ use crate::{
     snapshot_config::SnapshotConfig,
 };
 use log::*;
-use solana_metrics::inc_new_counter_info;
+use solana_measure::measure::Measure;
 use solana_sdk::{clock::Slot, hash::Hash, timing};
 use std::{
     collections::{hash_map::Entry, HashMap, HashSet},
@@ -212,15 +212,22 @@ impl BankForks {
         let mut banks = vec![root_bank];
         let parents = root_bank.parents();
         banks.extend(parents.iter());
+        let total_banks = banks.len();
+        let mut total_squash_accounts_ms = 0;
+        let mut total_squash_cache_ms = 0;
+        let mut total_snapshot_ms = 0;
         for bank in banks.iter() {
             let bank_slot = bank.slot();
             if bank.block_height() % self.accounts_hash_interval_slots == 0
                 && bank_slot > self.last_accounts_hash_slot
             {
                 self.last_accounts_hash_slot = bank_slot;
-                bank.squash();
+                let squash_timing = bank.squash();
+                total_squash_accounts_ms += squash_timing.squash_accounts_ms;
+                total_squash_cache_ms += squash_timing.squash_cache_ms;
                 is_root_bank_squashed = bank_slot == root;
 
+                let mut snapshot_time = Measure::start("squash::snapshot_time");
                 if self.snapshot_config.is_some()
                     && accounts_background_request_sender.is_snapshot_creation_enabled()
                 {
@@ -241,22 +248,35 @@ impl BankForks {
                         );
                     }
                 }
+                snapshot_time.stop();
+                total_snapshot_ms += snapshot_time.as_ms();
                 break;
             }
         }
         if !is_root_bank_squashed {
-            root_bank.squash();
+            let squash_timing = root_bank.squash();
+            total_squash_accounts_ms += squash_timing.squash_accounts_ms;
+            total_squash_cache_ms += squash_timing.squash_cache_ms;
         }
         let new_tx_count = root_bank.transaction_count();
+        let mut prune_time = Measure::start("set_root::prune");
         self.prune_non_rooted(root, highest_confirmed_root);
+        prune_time.stop();
 
-        inc_new_counter_info!(
-            "bank-forks_set_root_ms",
-            timing::duration_as_ms(&set_root_start.elapsed()) as usize
-        );
-        inc_new_counter_info!(
-            "bank-forks_set_root_tx_count",
-            (new_tx_count - root_tx_count) as usize
+        datapoint_info!(
+            "bank-forks_set_root",
+            (
+                "elapsed_ms",
+                timing::duration_as_ms(&set_root_start.elapsed()) as usize,
+                i64
+            ),
+            ("slot", root, i64),
+            ("total_banks", total_banks, i64),
+            ("total_squash_cache_ms", total_squash_cache_ms, i64),
+            ("total_squash_accounts_ms", total_squash_accounts_ms, i64),
+            ("total_snapshot_ms", total_snapshot_ms, i64),
+            ("tx_count", (new_tx_count - root_tx_count) as usize, i64),
+            ("prune_non_rooted_ms", prune_time.as_ms(), i64),
         );
     }