Add Metric for Proposal Latency (#3360)

* add timestamp() to BlockHeader trait

* add latency metric

* fix timestamp issue in tests

* hoist time and lock out of loop

* use helper for timestamp

Author: bfish713

crates/hotshot/example-types/src/block_types.rs

@@ -396,6 +396,10 @@ impl<
             self.payload_commitment.as_ref(),
         )
     }
+
+    fn timestamp(&self) -> u64 {
+        self.timestamp
+    }
 }
 
 impl Committable for TestBlockHeader {

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

@@ -44,6 +44,7 @@ use hotshot_types::{
     vote::{Certificate, HasViewNumber},
 };
 use hotshot_utils::anytrace::*;
+use time::OffsetDateTime;
 use tokio::time::timeout;
 use tracing::instrument;
 use vbs::version::StaticVersionType;
@@ -316,6 +317,27 @@ impl<TYPES: NodeType + Default> Default for LeafChainTraversalOutcome<TYPES> {
     }
 }
 
+async fn update_metrics<TYPES: NodeType>(
+    consensus: &OuterConsensus<TYPES>,
+    leaf_views: &[LeafInfo<TYPES>],
+) {
+    let consensus_reader = consensus.read().await;
+    let now = OffsetDateTime::now_utc().unix_timestamp() as u64;
+
+    for leaf_view in leaf_views {
+        let proposal_timestamp = leaf_view.leaf.block_header().timestamp();
+
+        let Some(proposal_to_decide_time) = now.checked_sub(proposal_timestamp) else {
+            tracing::error!("Failed to calculate proposal to decide time: {proposal_timestamp}");
+            continue;
+        };
+        consensus_reader
+            .metrics
+            .proposal_to_decide_time
+            .add_point(proposal_to_decide_time as f64);
+    }
+}
+
 /// calculate the new decided leaf chain based on the rules of HotStuff 2
 ///
 /// # Panics
@@ -426,6 +448,7 @@ pub async fn decide_from_proposal_2<TYPES: NodeType, I: NodeImplementation<TYPES
             )
             .await;
         }
+        update_metrics(&consensus, &res.leaf_views).await;
     }
 
     res

crates/hotshot/types/src/consensus.rs

@@ -394,6 +394,12 @@ pub struct ConsensusMetricsValue {
     pub number_of_empty_blocks_proposed: Box<dyn Counter>,
     /// Number of events in the hotshot event queue
     pub internal_event_queue_len: Box<dyn Gauge>,
+    /// Time from proposal creation to decide time
+    pub proposal_to_decide_time: Box<dyn Histogram>,
+    /// Time from proposal received to proposal creation
+    pub previous_proposal_to_proposal_time: Box<dyn Histogram>,
+    /// Finalized bytes per view
+    pub finalized_bytes: Box<dyn Histogram>,
 }
 
 impl ConsensusMetricsValue {
@@ -425,6 +431,11 @@ impl ConsensusMetricsValue {
                 .create_counter(String::from("number_of_empty_blocks_proposed"), None),
             internal_event_queue_len: metrics
                 .create_gauge(String::from("internal_event_queue_len"), None),
+            proposal_to_decide_time: metrics
+                .create_histogram(String::from("proposal_to_decide_time"), None),
+            previous_proposal_to_proposal_time: metrics
+                .create_histogram(String::from("previous_proposal_to_proposal_time"), None),
+            finalized_bytes: metrics.create_histogram(String::from("finalized_bytes"), None),
         }
     }
 }

crates/hotshot/types/src/traits/block_contents.rs

@@ -187,6 +187,9 @@ pub trait BlockHeader<TYPES: NodeType>:
     /// Get the block number.
     fn block_number(&self) -> u64;
 
+    /// Get the timestamp.
+    fn timestamp(&self) -> u64;
+
     /// Get the payload commitment.
     fn payload_commitment(&self) -> VidCommitment;
 

hotshot-query-service/src/availability/query_data.rs

@@ -49,7 +49,6 @@ pub type TransactionInclusionProof<Types> =
 pub type Timestamp = time::OffsetDateTime;
 
 pub trait QueryableHeader<Types: NodeType>: BlockHeader<Types> {
-    fn timestamp(&self) -> u64;
     fn namespace_size(&self, id: u32, payload_size: usize) -> u64;
 }
 

hotshot-query-service/src/data_source.rs

@@ -775,16 +775,17 @@ pub mod node_tests {
     };
     use hotshot_types::{
         data::{vid_commitment, VidCommitment, VidShare},
-        traits::{block_contents::EncodeBytes, node_implementation::Versions},
+        traits::{
+            block_contents::{BlockHeader, EncodeBytes},
+            node_implementation::Versions,
+        },
         vid::advz::{advz_scheme, ADVZScheme},
     };
     use jf_vid::VidScheme;
     use vbs::version::StaticVersionType;
 
     use crate::{
-        availability::{
-            BlockInfo, BlockQueryData, LeafQueryData, QueryableHeader, VidCommonQueryData,
-        },
+        availability::{BlockInfo, BlockQueryData, LeafQueryData, VidCommonQueryData},
         data_source::{
             storage::{NodeStorage, UpdateAvailabilityStorage},
             update::Transaction,
@@ -799,6 +800,10 @@ pub mod node_tests {
         Header, VidCommon,
     };
 
+    fn block_header_timestamp(header: &Header<MockTypes>) -> u64 {
+        <TestBlockHeader as BlockHeader<MockTypes>>::timestamp(header)
+    }
+
     #[tokio::test(flavor = "multi_thread")]
     pub async fn test_sync_status<D: TestableDataSource>()
     where
@@ -1232,7 +1237,9 @@ pub mod node_tests {
             let leaf = leaves.next().await.unwrap();
             let header = leaf.header().clone();
             if let Some(last_timestamp) = test_blocks.last_mut() {
-                if last_timestamp[0].timestamp() == header.timestamp() {
+                if <TestBlockHeader as BlockHeader<MockTypes>>::timestamp(&last_timestamp[0])
+                    == <TestBlockHeader as BlockHeader<MockTypes>>::timestamp(&header)
+                {
                     last_timestamp.push(header);
                 } else {
                     test_blocks.push(vec![header]);
@@ -1249,26 +1256,29 @@ pub mod node_tests {
                 let mut prev = res.prev.as_ref();
                 if let Some(prev) = prev {
                     if check_prev {
-                        assert!(prev.timestamp() < start);
+                        assert!(block_header_timestamp(prev) < start);
                     }
                 } else {
                     // `prev` can only be `None` if the first block in the window is the genesis
                     // block.
                     assert_eq!(res.from().unwrap(), 0);
                 };
                 for header in &res.window {
-                    assert!(start <= header.timestamp());
-                    assert!(header.timestamp() < end);
+                    assert!(start <= block_header_timestamp(header));
+                    assert!(block_header_timestamp(header) < end);
                     if let Some(prev) = prev {
-                        assert!(prev.timestamp() <= header.timestamp());
+                        assert!(
+                            <TestBlockHeader as BlockHeader<MockTypes>>::timestamp(prev)
+                                <= <TestBlockHeader as BlockHeader<MockTypes>>::timestamp(header)
+                        );
                     }
                     prev = Some(header);
                 }
                 if let Some(next) = &res.next {
-                    assert!(next.timestamp() >= end);
+                    assert!(<TestBlockHeader as BlockHeader<MockTypes>>::timestamp(next) >= end);
                     // If there is a `next`, there must be at least one previous block (either `prev`
                     // itself or the last block if the window is nonempty), so we can `unwrap` here.
-                    assert!(next.timestamp() >= prev.unwrap().timestamp());
+                    assert!(block_header_timestamp(next) >= block_header_timestamp(prev.unwrap()));
                 }
             };
 
@@ -1286,7 +1296,7 @@ pub mod node_tests {
         };
 
         // Case 0: happy path. All blocks are available, including prev and next.
-        let start = test_blocks[1][0].timestamp();
+        let start = <TestBlockHeader as BlockHeader<MockTypes>>::timestamp(&test_blocks[1][0]);
         let end = start + 1;
         let res = get_window(start, end).await;
         assert_eq!(res.prev.unwrap(), *test_blocks[0].last().unwrap());
@@ -1295,14 +1305,14 @@ pub mod node_tests {
 
         // Case 1: no `prev`, start of window is before genesis.
         let start = 0;
-        let end = test_blocks[0][0].timestamp() + 1;
+        let end = <TestBlockHeader as BlockHeader<MockTypes>>::timestamp(&test_blocks[0][0]) + 1;
         let res = get_window(start, end).await;
         assert_eq!(res.prev, None);
         assert_eq!(res.window, test_blocks[0]);
         assert_eq!(res.next.unwrap(), test_blocks[1][0]);
 
         // Case 2: no `next`, end of window is after the most recently sequenced block.
-        let start = test_blocks[2][0].timestamp();
+        let start = <TestBlockHeader as BlockHeader<MockTypes>>::timestamp(&test_blocks[2][0]);
         let end = i64::MAX as u64;
         let res = get_window(start, end).await;
         assert_eq!(res.prev.unwrap(), *test_blocks[1].last().unwrap());
@@ -1344,7 +1354,7 @@ pub mod node_tests {
         assert_eq!(more2.window[..more.window.len()], more.window);
 
         // Case 3: the window is empty.
-        let start = test_blocks[1][0].timestamp();
+        let start = <TestBlockHeader as BlockHeader<MockTypes>>::timestamp(&test_blocks[1][0]);
         let end = start;
         let res = get_window(start, end).await;
         assert_eq!(res.prev.unwrap(), *test_blocks[0].last().unwrap());
@@ -1366,8 +1376,8 @@ pub mod node_tests {
             .flatten()
             .collect::<Vec<_>>();
         // Make a query that would return everything, but gets limited.
-        let start = blocks[0].timestamp();
-        let end = test_blocks[2][0].timestamp();
+        let start = block_header_timestamp(&blocks[0]);
+        let end = block_header_timestamp(&test_blocks[2][0]);
         let res = ds
             .get_header_window(WindowStart::Time(start), end, 1)
             .await

hotshot-query-service/src/data_source/extension.rs

@@ -13,17 +13,20 @@
 use std::ops::{Bound, RangeBounds};
 
 use async_trait::async_trait;
-use hotshot_types::{data::VidShare, traits::node_implementation::NodeType};
+use hotshot_types::{
+    data::VidShare,
+    traits::{block_contents::BlockHeader, node_implementation::NodeType},
+};
 use jf_merkle_tree::prelude::MerkleProof;
 use tagged_base64::TaggedBase64;
 
 use super::VersionedDataSource;
 use crate::{
     availability::{
         AvailabilityDataSource, BlockId, BlockInfo, BlockQueryData, Fetch, FetchStream, LeafId,
-        LeafQueryData, PayloadMetadata, PayloadQueryData, QueryableHeader, QueryablePayload,
-        StateCertQueryData, TransactionHash, TransactionQueryData, UpdateAvailabilityData,
-        VidCommonMetadata, VidCommonQueryData,
+        LeafQueryData, PayloadMetadata, PayloadQueryData, QueryablePayload, StateCertQueryData,
+        TransactionHash, TransactionQueryData, UpdateAvailabilityData, VidCommonMetadata,
+        VidCommonQueryData,
     },
     data_source::storage::pruning::PrunedHeightDataSource,
     explorer::{self, ExplorerDataSource, ExplorerHeader, ExplorerTransaction},
@@ -441,7 +444,7 @@ where
     U: Send + Sync,
     Types: NodeType,
     Payload<Types>: QueryablePayload<Types>,
-    Header<Types>: ExplorerHeader<Types> + QueryableHeader<Types>,
+    Header<Types>: ExplorerHeader<Types> + BlockHeader<Types>,
     Transaction<Types>: ExplorerTransaction,
 {
     async fn get_block_detail(

hotshot-query-service/src/data_source/storage.rs

@@ -60,15 +60,18 @@ use std::ops::RangeBounds;
 
 use async_trait::async_trait;
 use futures::future::Future;
-use hotshot_types::{data::VidShare, traits::node_implementation::NodeType};
+use hotshot_types::{
+    data::VidShare,
+    traits::{block_contents::BlockHeader, node_implementation::NodeType},
+};
 use jf_merkle_tree::prelude::MerkleProof;
 use tagged_base64::TaggedBase64;
 
 use crate::{
     availability::{
         BlockId, BlockQueryData, LeafId, LeafQueryData, PayloadMetadata, PayloadQueryData,
-        QueryableHeader, QueryablePayload, StateCertQueryData, TransactionHash,
-        TransactionQueryData, VidCommonMetadata, VidCommonQueryData,
+        QueryablePayload, StateCertQueryData, TransactionHash, TransactionQueryData,
+        VidCommonMetadata, VidCommonQueryData,
     },
     explorer::{
         query_data::{
@@ -287,7 +290,7 @@ where
 pub trait ExplorerStorage<Types>
 where
     Types: NodeType,
-    Header<Types>: ExplorerHeader<Types> + QueryableHeader<Types>,
+    Header<Types>: ExplorerHeader<Types> + BlockHeader<Types>,
     Transaction<Types>: ExplorerTransaction,
     Payload<Types>: QueryablePayload<Types>,
 {

hotshot-query-service/src/data_source/storage/fs.rs

@@ -48,8 +48,8 @@ use crate::{
     availability::{
         data_source::{BlockId, LeafId},
         query_data::{
-            BlockHash, BlockQueryData, LeafHash, LeafQueryData, PayloadQueryData, QueryableHeader,
-            QueryablePayload, TransactionHash, TransactionQueryData, VidCommonQueryData,
+            BlockHash, BlockQueryData, LeafHash, LeafQueryData, PayloadQueryData, QueryablePayload,
+            TransactionHash, TransactionQueryData, VidCommonQueryData,
         },
         StateCertQueryData,
     },
@@ -158,7 +158,7 @@ where
 impl<Types: NodeType> FileSystemStorage<Types>
 where
     Payload<Types>: QueryablePayload<Types>,
-    Header<Types>: QueryableHeader<Types>,
+    Header<Types>: BlockHeader<Types>,
 {
     /// Create a new [FileSystemStorage] with storage at `path`.
     ///
@@ -490,7 +490,7 @@ impl<Types, T> AvailabilityStorage<Types> for Transaction<T>
 where
     Types: NodeType,
     Payload<Types>: QueryablePayload<Types>,
-    Header<Types>: QueryableHeader<Types>,
+    Header<Types>: BlockHeader<Types>,
     T: Revert + Deref<Target = FileSystemStorageInner<Types>> + Send + Sync,
 {
     async fn get_leaf(&mut self, id: LeafId<Types>) -> QueryResult<LeafQueryData<Types>> {
@@ -656,7 +656,7 @@ impl<Types: NodeType> UpdateAvailabilityStorage<Types>
     for Transaction<RwLockWriteGuard<'_, FileSystemStorageInner<Types>>>
 where
     Payload<Types>: QueryablePayload<Types>,
-    Header<Types>: QueryableHeader<Types>,
+    Header<Types>: BlockHeader<Types>,
 {
     async fn insert_leaf(&mut self, leaf: LeafQueryData<Types>) -> anyhow::Result<()> {
         self.inner
@@ -749,7 +749,7 @@ impl<Types, T> NodeStorage<Types> for Transaction<T>
 where
     Types: NodeType,
     Payload<Types>: QueryablePayload<Types>,
-    Header<Types>: QueryableHeader<Types>,
+    Header<Types>: BlockHeader<Types>,
     T: Revert + Deref<Target = FileSystemStorageInner<Types>> + Send,
 {
     async fn block_height(&mut self) -> QueryResult<usize> {

hotshot-query-service/src/data_source/storage/sql.rs

@@ -1068,7 +1068,7 @@ pub mod testing {
     use tokio::{net::TcpStream, time::timeout};
 
     use super::Config;
-    use crate::{availability::query_data::QueryableHeader, testing::sleep};
+    use crate::testing::sleep;
     #[derive(Debug)]
     pub struct TmpDb {
         #[cfg(not(feature = "embedded-db"))]
@@ -1383,7 +1383,7 @@ mod test {
 
     use super::{testing::TmpDb, *};
     use crate::{
-        availability::{LeafQueryData, QueryableHeader},
+        availability::LeafQueryData,
         data_source::storage::{pruning::PrunedHeightStorage, UpdateAvailabilityStorage},
         merklized_state::{MerklizedState, UpdateStateData},
         testing::{
@@ -1849,7 +1849,7 @@ mod test {
                     leaf.block_header().commit().to_string(),
                     payload_commitment.to_string(),
                     header_json,
-                    leaf.block_header().timestamp() as i64,
+                    <MockHeader as BlockHeader<MockTypes>>::timestamp(leaf.block_header()) as i64,
                 )],
             )
             .await