Add Summary stats per epoch (#3612)

* add summary stats per epoch

* add timeout count

Author: bfish713

crates/hotshot/task-impls/src/stats.rs

@@ -1,4 +1,7 @@
-use std::{collections::BTreeMap, sync::Arc};
+use std::{
+    collections::{BTreeMap, BTreeSet},
+    sync::Arc,
+};
 
 use async_broadcast::{Receiver, Sender};
 use async_trait::async_trait;
@@ -7,7 +10,11 @@ use hotshot_task::task::TaskState;
 use hotshot_types::{
     consensus::OuterConsensus,
     epoch_membership::EpochMembershipCoordinator,
-    traits::node_implementation::{ConsensusTime, NodeType},
+    traits::{
+        block_contents::BlockHeader,
+        node_implementation::{ConsensusTime, NodeType},
+        BlockPayload,
+    },
     vote::HasViewNumber,
 };
 use hotshot_utils::{
@@ -38,6 +45,7 @@ pub struct LeaderViewStats<TYPES: NodeType> {
 pub struct ReplicaViewStats<TYPES: NodeType> {
     pub view: TYPES::View,
     pub view_change: Option<i128>,
+    pub proposal_timestamp: Option<i128>,
     pub proposal_recv: Option<i128>,
     pub vote_send: Option<i128>,
     pub timeout_vote_send: Option<i128>,
@@ -74,6 +82,7 @@ impl<TYPES: NodeType> ReplicaViewStats<TYPES> {
         Self {
             view,
             view_change: None,
+            proposal_timestamp: None,
             proposal_recv: None,
             vote_send: None,
             timeout_vote_send: None,
@@ -97,6 +106,10 @@ pub struct StatsTaskState<TYPES: NodeType> {
     membership_coordinator: EpochMembershipCoordinator<TYPES>,
     leader_stats: BTreeMap<TYPES::View, LeaderViewStats<TYPES>>,
     replica_stats: BTreeMap<TYPES::View, ReplicaViewStats<TYPES>>,
+    latencies_by_view: BTreeMap<TYPES::View, i128>,
+    sizes_by_view: BTreeMap<TYPES::View, i128>,
+    epoch_start_times: BTreeMap<TYPES::Epoch, i128>,
+    timeouts: BTreeSet<TYPES::View>,
 }
 
 impl<TYPES: NodeType> StatsTaskState<TYPES> {
@@ -115,6 +128,10 @@ impl<TYPES: NodeType> StatsTaskState<TYPES> {
             membership_coordinator,
             leader_stats: BTreeMap::new(),
             replica_stats: BTreeMap::new(),
+            latencies_by_view: BTreeMap::new(),
+            sizes_by_view: BTreeMap::new(),
+            epoch_start_times: BTreeMap::new(),
+            timeouts: BTreeSet::new(),
         }
     }
     fn leader_entry(&mut self, view: TYPES::View) -> &mut LeaderViewStats<TYPES> {
@@ -130,6 +147,9 @@ impl<TYPES: NodeType> StatsTaskState<TYPES> {
     fn garbage_collect(&mut self, view: TYPES::View) {
         self.leader_stats = self.leader_stats.split_off(&view);
         self.replica_stats = self.replica_stats.split_off(&view);
+        self.latencies_by_view = self.latencies_by_view.split_off(&view);
+        self.sizes_by_view = self.sizes_by_view.split_off(&view);
+        self.timeouts = BTreeSet::new();
     }
 
     fn dump_stats(&self) -> Result<()> {
@@ -163,6 +183,29 @@ impl<TYPES: NodeType> StatsTaskState<TYPES> {
         );
         Ok(())
     }
+
+    fn log_basic_stats(&self, now: i128, epoch: &TYPES::Epoch) {
+        let num_views = self.latencies_by_view.len();
+        let total_latency = self.latencies_by_view.values().sum::<i128>();
+        let average_latency = total_latency / num_views as i128;
+        tracing::warn!("Average latency: {}ms", average_latency);
+        tracing::warn!(
+            "Number of timeouts in epoch: {}, is {}",
+            epoch,
+            self.timeouts.len()
+        );
+        let total_size = self.sizes_by_view.values().sum::<i128>();
+        if total_size == 0 {
+            // Either no TXNs or we are not in the DA committee and don't know block sizes
+            return;
+        }
+        if let Some(epoch_start_time) = self.epoch_start_times.get(epoch) {
+            let elapsed_time = now - epoch_start_time;
+            // multiply by 1000 to convert to seconds
+            let throughput = (total_size / elapsed_time) * 1000;
+            tracing::warn!("Throughput: {} bytes/s", throughput);
+        }
+    }
 }
 
 #[async_trait]
@@ -240,6 +283,9 @@ impl<TYPES: NodeType> TaskState for StatsTaskState<TYPES> {
             HotShotEvent::QuorumProposalValidated(proposal, _) => {
                 self.replica_entry(proposal.data.view_number())
                     .proposal_validated = Some(now);
+                self.replica_entry(proposal.data.view_number())
+                    .proposal_timestamp =
+                    Some(proposal.data.block_header().timestamp_millis() as i128);
             },
             HotShotEvent::DaProposalSend(proposal, _) => {
                 self.leader_entry(proposal.data.view_number())
@@ -288,6 +334,7 @@ impl<TYPES: NodeType> TaskState for StatsTaskState<TYPES> {
                 if self.view < *view {
                     self.view = *view;
                 }
+                let prev_epoch = self.epoch;
                 let mut new_epoch = false;
                 if self.epoch < *epoch {
                     self.epoch = *epoch;
@@ -298,6 +345,9 @@ impl<TYPES: NodeType> TaskState for StatsTaskState<TYPES> {
                 }
 
                 if new_epoch {
+                    if let Some(prev_epoch) = prev_epoch {
+                        self.log_basic_stats(now, &prev_epoch);
+                    }
                     let _ = self.dump_stats();
                     self.garbage_collect(*view - 1);
                 }
@@ -312,8 +362,9 @@ impl<TYPES: NodeType> TaskState for StatsTaskState<TYPES> {
                     self.leader_entry(*view).builder_start = Some(now);
                 }
             },
-            HotShotEvent::Timeout(..) => {
-                self.replica_entry(self.view).timeout_triggered = Some(now);
+            HotShotEvent::Timeout(view, _) => {
+                self.replica_entry(*view).timeout_triggered = Some(now);
+                self.timeouts.insert(*view);
             },
             HotShotEvent::TransactionsRecv(_txns) => {
                 // TODO: Track transactions by time
@@ -334,6 +385,23 @@ impl<TYPES: NodeType> TaskState for StatsTaskState<TYPES> {
                 self.replica_entry(proposal.data.view_number())
                     .proposal_prelim_validated = Some(now);
             },
+            HotShotEvent::LeavesDecided(leaves) => {
+                for leaf in leaves {
+                    if leaf.view_number() == TYPES::View::genesis() {
+                        continue;
+                    }
+                    let view = leaf.view_number();
+                    let timestamp = leaf.block_header().timestamp_millis() as i128;
+                    let now_millis = now / 1_000_000;
+                    let latency = now_millis - timestamp;
+                    tracing::debug!("View {} Latency: {}ms", view, latency);
+                    self.latencies_by_view.insert(view, latency);
+                    self.sizes_by_view.insert(
+                        view,
+                        leaf.block_payload().map(|p| p.txn_bytes()).unwrap_or(0) as i128,
+                    );
+                }
+            },
             _ => {},
         }
         Ok(())

crates/hotshot/types/src/data/ns_table.rs

@@ -22,7 +22,7 @@ pub fn parse_ns_table(payload_byte_len: usize, bytes: &[u8]) -> Vec<Range<usize>
     if bytes.len() < NUM_NSS_BYTE_LEN
         || !(bytes.len() - NUM_NSS_BYTE_LEN).is_multiple_of(NS_OFFSET_BYTE_LEN + NS_ID_BYTE_LEN)
     {
-        tracing::warn!(
+        tracing::info!(
             "Failed to parse the metadata as namespace table. Use a single namespace table \
              instead."
         );
@@ -34,7 +34,7 @@ pub fn parse_ns_table(payload_byte_len: usize, bytes: &[u8]) -> Vec<Range<usize>
             / NS_ID_BYTE_LEN.saturating_add(NS_OFFSET_BYTE_LEN)
         || (num_entries == 0 && payload_byte_len != 0)
     {
-        tracing::warn!(
+        tracing::info!(
             "Failed to parse the metadata as namespace table. Use a single namespace table \
              instead."
         );
@@ -53,7 +53,7 @@ pub fn parse_ns_table(payload_byte_len: usize, bytes: &[u8]) -> Vec<Range<usize>
                 .unwrap(),
         ) as usize;
         if r < l || r > payload_byte_len {
-            tracing::warn!(
+            tracing::info!(
                 "Failed to parse the metadata as namespace table. Use a single namespace table \
                  instead."
             );
@@ -63,7 +63,7 @@ pub fn parse_ns_table(payload_byte_len: usize, bytes: &[u8]) -> Vec<Range<usize>
         l = r;
     }
     if l != payload_byte_len {
-        tracing::warn!(
+        tracing::info!(
             "Failed to parse the metadata as namespace table. Use a single namespace table \
              instead."
         );