feat: add signer capitulation latency metric, #5918

Author: fdefelici

Cargo.lock

@@ -49,6 +49,7 @@ rusqlite = { workspace = true, features = ["functions"] }
 clarity = { path = "../clarity", features = ["testing"] }
 stacks-common = { path = "../stacks-common", features = ["testing"] }
 num-traits = "0.2.18"
+chrono = "0.4.19"
 
 [dependencies.serde_json]
 version = "1.0"

stacks-signer/Cargo.toml

@@ -157,6 +157,13 @@ pub mod actions {
             .inc();
     }
 
+    /// Record the time (seconds) taken to a signer to agree with the signer set
+    pub fn record_signer_agreement_capitulation_latency(latency_s: u64) {
+        SIGNER_AGREEMENT_CAPITULATION_LATENCIES_HISTOGRAM
+            .with_label_values(&[])
+            .observe(latency_s as f64);
+    }
+
     /// Start serving monitoring metrics.
     /// This will only serve the metrics if the `monitoring_prom` feature is enabled.
     pub fn start_serving_monitoring_metrics(config: GlobalConfig) -> Result<(), String> {
@@ -238,6 +245,9 @@ pub mod actions {
     /// Increment signer agreement state conflict counter
     pub fn increment_signer_agreement_state_conflict(_conflict: SignerAgreementStateConflict) {}
 
+    /// Record the time (seconds) taken to a signer to agree with the signer set
+    pub fn record_signer_agreement_capitulation_latency(_latency_s: u64) {}
+
     /// Start serving monitoring metrics.
     /// This will only serve the metrics if the `monitoring_prom` feature is enabled.
     pub fn start_serving_monitoring_metrics(config: GlobalConfig) -> Result<(), String> {

stacks-signer/src/monitoring/mod.rs

@@ -91,6 +91,12 @@ lazy_static! {
         &["conflict"]
     ).unwrap();
 
+    pub static ref SIGNER_AGREEMENT_CAPITULATION_LATENCIES_HISTOGRAM: HistogramVec = register_histogram_vec!(histogram_opts!(
+        "stacks_signer_agreement_capitulation_latencies_histogram",
+        "Measuring the time (in seconds) for the signer to agree (capitulate) with the signer set",
+        vec![0.0, 1.0, 3.0, 5.0, 10.0, 20.0, 30.0, 60.0, 120.0]
+    ), &[]).unwrap();
+
     pub static ref SIGNER_LOCAL_STATE_MACHINE: Mutex<Option<LocalStateMachine>> = Mutex::new(None);
 }
 

stacks-signer/src/monitoring/prometheus.rs

@@ -528,7 +528,7 @@ CREATE TABLE IF NOT EXISTS signer_state_machine_updates (
     signer_addr TEXT NOT NULL,
     reward_cycle INTEGER NOT NULL,
     state_update TEXT NOT NULL,
-    received_time TEXT NOT NULL,
+    received_time INTEGER NOT NULL,
     PRIMARY KEY (signer_addr, reward_cycle)
 ) STRICT;"#;
 
@@ -1406,6 +1406,22 @@ impl SignerDb {
         }
         Ok(result)
     }
+
+    /// Retrieve the elapsed time (in seconds) between
+    /// the oldest and the newest state machine update messages
+    /// produced by the signer set
+    pub fn get_signer_state_machine_updates_latency(
+        &self,
+        reward_cycle: u64,
+    ) -> Result<u64, DBError> {
+        let query = "SELECT COALESCE( (MAX(received_time) - MIN(received_time)), 0 ) AS elapsed_time FROM signer_state_machine_updates WHERE reward_cycle = ?1";
+        let args = params![u64_to_sql(reward_cycle)?];
+        let elapsed_time_opt: Option<u64> = query_row(&self.db, query, args)?;
+        match elapsed_time_opt {
+            Some(seconds) => Ok(seconds),
+            None => Ok(0),
+        }
+    }
 }
 
 fn try_deserialize<T>(s: Option<String>) -> Result<Option<T>, DBError>
@@ -1551,6 +1567,48 @@ pub mod tests {
         assert_eq!(BlockInfo::from(block_proposal_2), block_info);
     }
 
+    fn system_time_from_ymd_hms_optional(
+        year: u32,
+        month: u32,
+        day: u32,
+        hour: u32,
+        minute: u32,
+        second: u32,
+    ) -> Option<SystemTime> {
+        use std::time::{Duration, UNIX_EPOCH};
+
+        use chrono::NaiveDate;
+        // Make sure year is safe to cast
+        if year > i32::MAX as u32 {
+            return None;
+        }
+        // Cast year to i32 safely
+        let year_i32 = year as i32;
+        let naive =
+            NaiveDate::from_ymd_opt(year_i32, month, day)?.and_hms_opt(hour, minute, second)?;
+
+        let timestamp = naive.timestamp();
+        if timestamp < 0 {
+            return None;
+        }
+
+        // Convert to SystemTime
+        let duration = timestamp as u64;
+        Some(UNIX_EPOCH + Duration::from_secs(duration))
+    }
+
+    fn system_time_from_ymd_hms(
+        year: u32,
+        month: u32,
+        day: u32,
+        hour: u32,
+        minute: u32,
+        second: u32,
+    ) -> SystemTime {
+        system_time_from_ymd_hms_optional(year, month, day, hour, minute, second)
+            .expect("Invalid system time")
+    }
+
     #[test]
     fn test_basic_signer_db() {
         let db_path = tmp_db_path();
@@ -2500,4 +2558,92 @@ pub mod tests {
         assert_eq!(updates.get(&address_2), None);
         assert_eq!(updates.get(&address_3), Some(&update_3));
     }
+
+    #[test]
+    fn retrieve_latency_for_signer_state_machine_updates() {
+        let db_path = tmp_db_path();
+        let mut db = SignerDb::new(db_path).expect("Failed to create signer db");
+        let reward_cycle_1 = 1;
+        let address_1 = StacksAddress::p2pkh(false, &StacksPublicKey::new());
+        let update_1 = StateMachineUpdate::new(
+            0,
+            3,
+            StateMachineUpdateContent::V0 {
+                burn_block: ConsensusHash([0x55; 20]),
+                burn_block_height: 100,
+                current_miner: StateMachineUpdateMinerState::ActiveMiner {
+                    current_miner_pkh: Hash160([0xab; 20]),
+                    tenure_id: ConsensusHash([0x44; 20]),
+                    parent_tenure_id: ConsensusHash([0x22; 20]),
+                    parent_tenure_last_block: StacksBlockId([0x33; 32]),
+                    parent_tenure_last_block_height: 1,
+                },
+            },
+        )
+        .unwrap();
+        let time_1 = system_time_from_ymd_hms(2025, 04, 17, 12, 30, 00);
+
+        let address_2 = StacksAddress::p2pkh(false, &StacksPublicKey::new());
+        let update_2 = StateMachineUpdate::new(
+            0,
+            4,
+            StateMachineUpdateContent::V0 {
+                burn_block: ConsensusHash([0x55; 20]),
+                burn_block_height: 100,
+                current_miner: StateMachineUpdateMinerState::NoValidMiner,
+            },
+        )
+        .unwrap();
+        let time_2 = system_time_from_ymd_hms(2025, 04, 17, 12, 30, 01);
+
+        let address_3 = StacksAddress::p2pkh(false, &StacksPublicKey::new());
+        let update_3 = StateMachineUpdate::new(
+            0,
+            2,
+            StateMachineUpdateContent::V0 {
+                burn_block: ConsensusHash([0x66; 20]),
+                burn_block_height: 101,
+                current_miner: StateMachineUpdateMinerState::NoValidMiner,
+            },
+        )
+        .unwrap();
+        let time_3 = system_time_from_ymd_hms(2025, 04, 17, 12, 30, 10);
+
+        assert_eq!(
+            0,
+            db.get_signer_state_machine_updates_latency(reward_cycle_1)
+                .unwrap(),
+            "latency on empty database should be 0 seconds for reward_cycle {reward_cycle_1}"
+        );
+
+        db.insert_state_machine_update(reward_cycle_1, &address_1, &update_1, &time_1)
+            .expect("Unable to insert block into db");
+
+        assert_eq!(
+            0,
+            db.get_signer_state_machine_updates_latency(reward_cycle_1)
+                .unwrap(),
+            "latency between same update should be 0 seconds"
+        );
+
+        db.insert_state_machine_update(reward_cycle_1, &address_2, &update_2, &time_2)
+            .expect("Unable to insert block into db");
+
+        assert_eq!(
+            1,
+            db.get_signer_state_machine_updates_latency(reward_cycle_1)
+                .unwrap(),
+            "latency between updates should be 1 second"
+        );
+
+        db.insert_state_machine_update(reward_cycle_1, &address_3, &update_3, &time_3)
+            .expect("Unable to insert block into db");
+
+        assert_eq!(
+            10,
+            db.get_signer_state_machine_updates_latency(reward_cycle_1)
+                .unwrap(),
+            "latency between updates should be 10 second"
+        );
+    }
 }

stacks-signer/src/signerdb.rs

@@ -619,6 +619,7 @@ impl Signer {
             &mut self.signer_db,
             &mut self.global_state_evaluator,
             self.stacks_address,
+            self.reward_cycle,
         );
     }
 

stacks-signer/src/v0/signer.rs

@@ -773,6 +773,7 @@ impl LocalStateMachine {
         signerdb: &mut SignerDb,
         eval: &mut GlobalStateEvaluator,
         local_address: StacksAddress,
+        reward_cycle: u64,
     ) {
         // Before we ever access eval...we should make sure to include our own local state machine update message in the evaluation
         let local_update: Result<StateMachineUpdateMessage, _> = (&*self).try_into();
@@ -833,26 +834,8 @@ impl LocalStateMachine {
             crate::monitoring::actions::increment_signer_agreement_state_change_reason(
                 crate::monitoring::SignerAgreementStateChangeReason::MinerViewUpdate,
             );
-            #[cfg(feature = "monitoring_prom")]
-            match (&current_miner, &new_miner) {
-                (
-                    StateMachineUpdateMinerState::ActiveMiner {
-                        parent_tenure_id: current_parent_tenure,
-                        ..
-                    },
-                    StateMachineUpdateMinerState::ActiveMiner {
-                        parent_tenure_id: new_parent_tenure,
-                        ..
-                    },
-                ) => {
-                    if current_parent_tenure != new_parent_tenure {
-                        crate::monitoring::actions::increment_signer_agreement_state_change_reason(
-                            crate::monitoring::SignerAgreementStateChangeReason::MinerParentTenureUpdate,
-                        );
-                    }
-                }
-                _ => {}
-            }
+            Self::monitor_miner_parent_tenure_update(&current_miner, &new_miner);
+            Self::monitor_capitulation_latency(signerdb, reward_cycle);
 
             *self = Self::Initialized(SignerStateMachine {
                 burn_block,
@@ -862,4 +845,47 @@ impl LocalStateMachine {
             });
         }
     }
+
+    #[allow(unused_variables)]
+    fn monitor_miner_parent_tenure_update(
+        current_miner: &StateMachineUpdateMinerState,
+        new_miner: &StateMachineUpdateMinerState,
+    ) {
+        #[cfg(feature = "monitoring_prom")]
+        match (&current_miner, &new_miner) {
+            (
+                StateMachineUpdateMinerState::ActiveMiner {
+                    parent_tenure_id: current_parent_tenure,
+                    ..
+                },
+                StateMachineUpdateMinerState::ActiveMiner {
+                    parent_tenure_id: new_parent_tenure,
+                    ..
+                },
+            ) => {
+                if current_parent_tenure != new_parent_tenure {
+                    crate::monitoring::actions::increment_signer_agreement_state_change_reason(
+                        crate::monitoring::SignerAgreementStateChangeReason::MinerParentTenureUpdate,
+                    );
+                }
+            }
+            _ => {}
+        }
+    }
+
+    #[allow(unused_variables)]
+    fn monitor_capitulation_latency(signer_db: &SignerDb, reward_cycle: u64) {
+        #[cfg(feature = "monitoring_prom")]
+        {
+            let latency_result = signer_db.get_signer_state_machine_updates_latency(reward_cycle);
+            match latency_result {
+                Ok(seconds) => {
+                    crate::monitoring::actions::record_signer_agreement_capitulation_latency(
+                        seconds,
+                    )
+                }
+                Err(e) => warn!("Failed to retrieve state updates latency in signerdb: {e}"),
+            }
+        }
+    }
 }