From ddc758439ea9651331b7d60d9c445b62cd0ed0d6 Mon Sep 17 00:00:00 2001
From: "Jeff Washington (jwash)"
 <75863576+jeffwashington@users.noreply.github.com>
Date: Fri, 19 Mar 2021 09:48:55 -0500
Subject: [PATCH] metrics for poh_recorder.record (#15998)

---
 core/src/poh_recorder.rs | 30 +++++++++++++++++++++++++++---
 1 file changed, 27 insertions(+), 3 deletions(-)

diff --git a/core/src/poh_recorder.rs b/core/src/poh_recorder.rs
index 432aabce83..c4ba5c4926 100644
--- a/core/src/poh_recorder.rs
+++ b/core/src/poh_recorder.rs
@@ -77,6 +77,10 @@ pub struct PohRecorder {
     poh_config: Arc<PohConfig>,
     ticks_per_slot: u64,
     record_lock_contention_us: u64,
+    flush_cache_no_tick_us: u64,
+    flush_cache_tick_us: u64,
+    prepare_send_us: u64,
+    send_us: u64,
     tick_lock_contention_us: u64,
     tick_overhead_us: u64,
     record_us: u64,
@@ -390,11 +394,13 @@ impl PohRecorder {
                 hash: poh_entry.hash,
                 transactions: vec![],
             };
+            self.tick_overhead_us += timing::duration_as_us(&now.elapsed());
 
+            let now = Instant::now();
             self.tick_cache.push((entry, self.tick_height));
             let _ = self.flush_cache(true);
+            self.flush_cache_tick_us += timing::duration_as_us(&now.elapsed());
         }
-        self.tick_overhead_us += timing::duration_as_us(&now.elapsed());
     }
 
     fn report_metrics(&mut self, bank_slot: Slot) {
@@ -404,6 +410,10 @@ impl PohRecorder {
                 ("slot", bank_slot, i64),
                 ("tick_lock_contention", self.tick_lock_contention_us, i64),
                 ("record_us", self.record_us, i64),
+                ("flush_cache_no_tick_us", self.flush_cache_no_tick_us, i64),
+                ("flush_cache_tick_us", self.flush_cache_tick_us, i64),
+                ("prepare_send_us", self.prepare_send_us, i64),
+                ("send_us", self.send_us, i64),
                 ("tick_overhead", self.tick_overhead_us, i64),
                 (
                     "record_lock_contention",
@@ -416,6 +426,10 @@ impl PohRecorder {
             self.record_us = 0;
             self.tick_overhead_us = 0;
             self.record_lock_contention_us = 0;
+            self.flush_cache_no_tick_us = 0;
+            self.flush_cache_tick_us = 0;
+            self.prepare_send_us = 0;
+            self.send_us = 0;
             self.last_metric = Instant::now();
         }
     }
@@ -431,7 +445,9 @@ impl PohRecorder {
         assert!(!transactions.is_empty(), "No transactions provided");
         self.report_metrics(bank_slot);
         loop {
+            let now = Instant::now();
             self.flush_cache(false)?;
+            self.flush_cache_no_tick_us += timing::duration_as_us(&now.elapsed());
 
             let working_bank = self
                 .working_bank
@@ -450,14 +466,18 @@ impl PohRecorder {
                 let res = poh_lock.record(mixin);
                 drop(poh_lock);
                 self.record_us += timing::duration_as_us(&now.elapsed());
+                let now = Instant::now();
                 if let Some(poh_entry) = res {
                     let entry = Entry {
                         num_hashes: poh_entry.num_hashes,
                         hash: poh_entry.hash,
                         transactions,
                     };
-                    self.sender
-                        .send((working_bank.bank.clone(), (entry, self.tick_height)))?;
+                    let bank_clone = working_bank.bank.clone();
+                    self.prepare_send_us += timing::duration_as_us(&now.elapsed());
+                    let now = Instant::now();
+                    self.sender.send((bank_clone, (entry, self.tick_height)))?;
+                    self.send_us += timing::duration_as_us(&now.elapsed());
                     return Ok(());
                 }
             }
@@ -506,6 +526,10 @@ impl PohRecorder {
                 ticks_per_slot,
                 poh_config: poh_config.clone(),
                 record_lock_contention_us: 0,
+                flush_cache_tick_us: 0,
+                flush_cache_no_tick_us: 0,
+                prepare_send_us: 0,
+                send_us: 0,
                 tick_lock_contention_us: 0,
                 record_us: 0,
                 tick_overhead_us: 0,