feat: record validation and end-to-end response time in signer metrics

Author: hstove

stacks-signer/src/monitoring/mod.rs

@@ -16,6 +16,7 @@
 
 #[cfg(feature = "monitoring_prom")]
 use ::prometheus::HistogramTimer;
+use blockstack_lib::chainstate::nakamoto::NakamotoBlock;
 #[cfg(feature = "monitoring_prom")]
 use slog::slog_error;
 #[cfg(not(feature = "monitoring_prom"))]
@@ -123,6 +124,33 @@ pub fn new_rpc_call_timer(_full_path: &str, _origin: &str) -> NoOpTimer {
     NoOpTimer
 }
 
+/// Record the time taken to issue a block response for
+/// a given block. The block's timestamp is used to calculate the latency.
+///
+/// Call this right after broadcasting a BlockResponse
+#[allow(unused_variables)]
+pub fn record_block_response_latency(block: &NakamotoBlock) {
+    #[cfg(feature = "monitoring_prom")]
+    {
+        use clarity::util::get_epoch_time_ms;
+
+        let diff =
+            get_epoch_time_ms().saturating_sub(block.header.timestamp.saturating_mul(1000).into());
+        prometheus::SIGNER_BLOCK_RESPONSE_LATENCIES_HISTOGRAM
+            .with_label_values(&[])
+            .observe(diff as f64 / 1000.0);
+    }
+}
+
+/// Record the time taken to validate a block, as reported by the Stacks node.
+#[allow(unused_variables)]
+pub fn record_block_validation_latency(latency_ms: u64) {
+    #[cfg(feature = "monitoring_prom")]
+    prometheus::SIGNER_BLOCK_VALIDATION_LATENCIES_HISTOGRAM
+        .with_label_values(&[])
+        .observe(latency_ms as f64 / 1000.0);
+}
+
 /// Start serving monitoring metrics.
 /// This will only serve the metrics if the `monitoring_prom` feature is enabled.
 #[allow(unused_variables)]

stacks-signer/src/monitoring/prometheus.rs

@@ -62,6 +62,18 @@ lazy_static! {
         "Time (seconds) measuring round-trip RPC call latency to the Stacks node"
         // Will use DEFAULT_BUCKETS = [0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0] by default
     ), &["path"]).unwrap();
+
+    pub static ref SIGNER_BLOCK_VALIDATION_LATENCIES_HISTOGRAM: HistogramVec = register_histogram_vec!(histogram_opts!(
+        "stacks_signer_block_validation_latencies_histogram",
+        "Time (seconds) measuring block validation time reported by the Stacks node",
+        vec![0.005, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0, 20.0]
+    ), &[]).unwrap();
+
+    pub static ref SIGNER_BLOCK_RESPONSE_LATENCIES_HISTOGRAM: HistogramVec = register_histogram_vec!(histogram_opts!(
+        "stacks_signer_block_response_latencies_histogram",
+        "Time (seconds) measuring end-to-end time to respond to a block",
+        vec![0.005, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0, 20.0, 30.0, 60.0, 120.0]
+    ), &[]).unwrap();
 }
 
 pub fn gather_metrics_string() -> String {

stacks-signer/src/v0/signer.rs

@@ -466,6 +466,7 @@ impl Signer {
             {
                 Ok(_) => {
                     crate::monitoring::increment_block_responses_sent(accepted);
+                    crate::monitoring::record_block_response_latency(&block_proposal.block);
                 }
                 Err(e) => {
                     warn!("{self}: Failed to send block response to stacker-db: {e:?}",);
@@ -688,6 +689,8 @@ impl Signer {
                 .stackerdb
                 .send_message_with_retry::<SignerMessage>(block_response.into());
 
+            crate::monitoring::record_block_response_latency(&block_info.block);
+
             match res {
                 Err(e) => warn!("{self}: Failed to send block rejection to stacker-db: {e:?}"),
                 Ok(ack) if !ack.accepted => warn!(
@@ -792,6 +795,9 @@ impl Signer {
         info!("{self}: Received a block validate response: {block_validate_response:?}");
         let block_response = match block_validate_response {
             BlockValidateResponse::Ok(block_validate_ok) => {
+                crate::monitoring::record_block_validation_latency(
+                    block_validate_ok.validation_time_ms,
+                );
                 self.handle_block_validate_ok(stacks_client, block_validate_ok)
             }
             BlockValidateResponse::Reject(block_validate_reject) => {
@@ -812,6 +818,12 @@ impl Signer {
         {
             Ok(_) => {
                 crate::monitoring::increment_block_responses_sent(accepted);
+                if let Ok(Some(block_info)) = self
+                    .signer_db
+                    .block_lookup(&block_validate_response.signer_signature_hash())
+                {
+                    crate::monitoring::record_block_response_latency(&block_info.block);
+                }
             }
             Err(e) => {
                 warn!("{self}: Failed to send block rejection to stacker-db: {e:?}",);
@@ -876,6 +888,8 @@ impl Signer {
             .stackerdb
             .send_message_with_retry::<SignerMessage>(rejection.into());
 
+        crate::monitoring::record_block_response_latency(&block_info.block);
+
         match res {
             Err(e) => warn!("{self}: Failed to send block rejection to stacker-db: {e:?}"),
             Ok(ack) if !ack.accepted => warn!(

stackslib/src/net/api/postblock_proposal.rs

@@ -164,6 +164,16 @@ pub enum BlockValidateResponse {
     Reject(BlockValidateReject),
 }
 
+impl BlockValidateResponse {
+    /// Get the signer signature hash from the block validate response
+    pub fn signer_signature_hash(&self) -> Sha512Trunc256Sum {
+        match self {
+            BlockValidateResponse::Ok(ok) => ok.signer_signature_hash,
+            BlockValidateResponse::Reject(reject) => reject.signer_signature_hash,
+        }
+    }
+}
+
 impl From<Result<BlockValidateOk, BlockValidateReject>> for BlockValidateResponse {
     fn from(value: Result<BlockValidateOk, BlockValidateReject>) -> Self {
         match value {