From 36019cb1e3696e3f3d75c2a2c07b1bb6c346b9fc Mon Sep 17 00:00:00 2001
From: Pankaj Garg <pankaj@solana.com>
Date: Wed, 22 May 2019 15:54:24 -0700
Subject: [PATCH] Tweaks to real PoH based on perf testing (#4396)

* Some counters for real poh perf analysis

* more metrics

* Comment on CPU affinity change, and reduce hash batch size based on TPS perf

* review comments
---
 core/src/poh_recorder.rs | 29 +++++++++++++++++++++++++++++
 core/src/poh_service.rs  |  5 ++++-
 2 files changed, 33 insertions(+), 1 deletion(-)

diff --git a/core/src/poh_recorder.rs b/core/src/poh_recorder.rs
index a2e289b734..314ec48264 100644
--- a/core/src/poh_recorder.rs
+++ b/core/src/poh_recorder.rs
@@ -20,9 +20,11 @@ use solana_runtime::bank::Bank;
 use solana_sdk::hash::Hash;
 use solana_sdk::poh_config::PohConfig;
 use solana_sdk::pubkey::Pubkey;
+use solana_sdk::timing;
 use solana_sdk::transaction::Transaction;
 use std::sync::mpsc::{channel, Receiver, Sender, SyncSender};
 use std::sync::{Arc, Mutex};
+use std::time::Instant;
 
 const MAX_LAST_LEADER_GRACE_TICKS_FACTOR: u64 = 2;
 
@@ -278,12 +280,26 @@ impl PohRecorder {
     }
 
     pub fn tick(&mut self) {
+        let now = Instant::now();
         let poh_entry = self.poh.lock().unwrap().tick();
+        inc_new_counter_warn!(
+            "poh_recorder-tick_lock_contention",
+            timing::duration_as_ms(&now.elapsed()) as usize,
+            0,
+            1000
+        );
+        let now = Instant::now();
         if let Some(poh_entry) = poh_entry {
             self.tick_height += 1;
             trace!("tick {}", self.tick_height);
 
             if self.start_leader_at_tick.is_none() {
+                inc_new_counter_warn!(
+                    "poh_recorder-tick_overhead",
+                    timing::duration_as_ms(&now.elapsed()) as usize,
+                    0,
+                    1000
+                );
                 return;
             }
 
@@ -296,6 +312,12 @@ impl PohRecorder {
             self.tick_cache.push((entry, self.tick_height));
             let _ = self.flush_cache(true);
         }
+        inc_new_counter_warn!(
+            "poh_recorder-tick_overhead",
+            timing::duration_as_ms(&now.elapsed()) as usize,
+            0,
+            1000
+        );
     }
 
     pub fn record(
@@ -318,7 +340,14 @@ impl PohRecorder {
                 return Err(Error::PohRecorderError(PohRecorderError::MaxHeightReached));
             }
 
+            let now = Instant::now();
             if let Some(poh_entry) = self.poh.lock().unwrap().record(mixin) {
+                inc_new_counter_warn!(
+                    "poh_recorder-record_lock_contention",
+                    timing::duration_as_ms(&now.elapsed()) as usize,
+                    0,
+                    1000
+                );
                 let entry = Entry {
                     num_hashes: poh_entry.num_hashes,
                     hash: poh_entry.hash,
diff --git a/core/src/poh_service.rs b/core/src/poh_service.rs
index 4d353119ac..471878fec8 100644
--- a/core/src/poh_service.rs
+++ b/core/src/poh_service.rs
@@ -18,7 +18,7 @@ pub struct PohService {
 //   contention with the PoH hashing within `tick_producer()`.
 //
 // See benches/poh.rs for some benchmarks that attempt to justify this magic number.
-pub const NUM_HASHES_PER_BATCH: u64 = 128;
+pub const NUM_HASHES_PER_BATCH: u64 = 1;
 
 impl PohService {
     pub fn new(
@@ -34,6 +34,9 @@ impl PohService {
                 if poh_config.hashes_per_tick.is_none() {
                     Self::sleepy_tick_producer(poh_recorder, &poh_config, &poh_exit_);
                 } else {
+                    // PoH service runs in a tight loop, generating hashes as fast as possible.
+                    // Let's dedicate one of the CPU cores to this thread so that it can gain
+                    // from cache performance.
                     if let Some(cores) = core_affinity::get_core_ids() {
                         core_affinity::set_for_current(cores[0]);
                     }