Instrument attestation signing. (#8508)

We noticed attestation signing taking 2+ seconds on some of our hoodi nodes and the current traces doesn't provide enough details. This PR adds a few more spans to the `attestation_duty_cycle` code path in the VC.

Before:
<img width="842" height="154" alt="image" src="https://github.com/user-attachments/assets/cfc5c8c0-e6f2-4f56-a8e4-65001af4a005" />

After:
<img width="496" height="217" alt="image" src="https://github.com/user-attachments/assets/c91cfa88-af1b-456e-8c64-625809eb6881" />


  


Co-Authored-By: Jimmy Chen <[email protected]>

Author: jimmygchen

Cargo.lock

@@ -15,7 +15,7 @@ use std::marker::PhantomData;
 use std::path::Path;
 use std::sync::Arc;
 use task_executor::TaskExecutor;
-use tracing::{error, info, warn};
+use tracing::{error, info, instrument, warn};
 use types::{
     AbstractExecPayload, Address, AggregateAndProof, Attestation, BeaconBlock, BlindedPayload,
     ChainSpec, ContributionAndProof, Domain, Epoch, EthSpec, Fork, Graffiti, Hash256,
@@ -242,6 +242,7 @@ impl<T: SlotClock + 'static, E: EthSpec> LighthouseValidatorStore<T, E> {
 
     /// Returns a `SigningMethod` for `validator_pubkey` *only if* that validator is considered safe
     /// by doppelganger protection.
+    #[instrument(skip_all, level = "debug")]
     fn doppelganger_checked_signing_method(
         &self,
         validator_pubkey: PublicKeyBytes,
@@ -745,6 +746,7 @@ impl<T: SlotClock + 'static, E: EthSpec> ValidatorStore for LighthouseValidatorS
         }
     }
 
+    #[instrument(skip_all)]
     async fn sign_attestation(
         &self,
         validator_pubkey: PublicKeyBytes,

validator_client/lighthouse_validator_store/src/lib.rs

@@ -12,6 +12,7 @@ parking_lot = { workspace = true }
 reqwest = { workspace = true }
 serde = { workspace = true }
 task_executor = { workspace = true }
+tracing = { workspace = true }
 types = { workspace = true }
 url = { workspace = true }
 validator_metrics = { workspace = true }

validator_client/signing_method/Cargo.toml

@@ -10,6 +10,7 @@ use reqwest::{Client, header::ACCEPT};
 use std::path::PathBuf;
 use std::sync::Arc;
 use task_executor::TaskExecutor;
+use tracing::instrument;
 use types::*;
 use url::Url;
 use web3signer::{ForkInfo, MessageType, SigningRequest, SigningResponse};
@@ -131,6 +132,7 @@ impl SigningMethod {
     }
 
     /// Return the signature of `signable_message`, with respect to the `signing_context`.
+    #[instrument(skip_all, level = "debug")]
     pub async fn get_signature<E: EthSpec, Payload: AbstractExecPayload<E>>(
         &self,
         signable_message: SignableMessage<'_, E, Payload>,

validator_client/signing_method/src/lib.rs

@@ -11,6 +11,7 @@ use rusqlite::{OptionalExtension, Transaction, TransactionBehavior, params};
 use std::fs::File;
 use std::path::Path;
 use std::time::Duration;
+use tracing::instrument;
 use types::{AttestationData, BeaconBlockHeader, Epoch, Hash256, PublicKeyBytes, SignedRoot, Slot};
 
 type Pool = r2d2::Pool<SqliteConnectionManager>;
@@ -639,6 +640,7 @@ impl SlashingDatabase {
     /// to prevent concurrent checks and inserts from resulting in slashable data being inserted.
     ///
     /// This is the safe, externally-callable interface for checking attestations.
+    #[instrument(skip_all, level = "debug")]
     pub fn check_and_insert_attestation(
         &self,
         validator_pubkey: &PublicKeyBytes,

validator_client/slashing_protection/src/slashing_database.rs

@@ -8,7 +8,7 @@ use std::ops::Deref;
 use std::sync::Arc;
 use task_executor::TaskExecutor;
 use tokio::time::{Duration, Instant, sleep, sleep_until};
-use tracing::{Instrument, debug, error, info, info_span, instrument, trace, warn};
+use tracing::{Instrument, Span, debug, error, info, info_span, instrument, trace, warn};
 use tree_hash::TreeHash;
 use types::{Attestation, AttestationData, ChainSpec, CommitteeIndex, EthSpec, Slot};
 use validator_store::{Error as ValidatorStoreError, ValidatorStore};
@@ -369,79 +369,82 @@ impl<S: ValidatorStore + 'static, T: SlotClock + 'static> AttestationService<S,
 
         // Create futures to produce signed `Attestation` objects.
         let attestation_data_ref = &attestation_data;
-        let signing_futures = validator_duties.iter().map(|duty_and_proof| async move {
-            let duty = &duty_and_proof.duty;
-            let attestation_data = attestation_data_ref;
-
-            // Ensure that the attestation matches the duties.
-            if !duty.match_attestation_data::<S::E>(attestation_data, &self.chain_spec) {
-                crit!(
-                    validator = ?duty.pubkey,
-                    duty_slot = %duty.slot,
-                    attestation_slot = %attestation_data.slot,
-                    duty_index = duty.committee_index,
-                    attestation_index = attestation_data.index,
-                    "Inconsistent validator duties during signing"
-                );
-                return None;
-            }
+        let signing_futures = validator_duties.iter().map(|duty_and_proof| {
+            async move {
+                let duty = &duty_and_proof.duty;
+                let attestation_data = attestation_data_ref;
 
-            let mut attestation = match Attestation::empty_for_signing(
-                duty.committee_index,
-                duty.committee_length as usize,
-                attestation_data.slot,
-                attestation_data.beacon_block_root,
-                attestation_data.source,
-                attestation_data.target,
-                &self.chain_spec,
-            ) {
-                Ok(attestation) => attestation,
-                Err(err) => {
+                // Ensure that the attestation matches the duties.
+                if !duty.match_attestation_data::<S::E>(attestation_data, &self.chain_spec) {
                     crit!(
                         validator = ?duty.pubkey,
-                        ?duty,
-                        ?err,
-                        "Invalid validator duties during signing"
+                        duty_slot = %duty.slot,
+                        attestation_slot = %attestation_data.slot,
+                        duty_index = duty.committee_index,
+                        attestation_index = attestation_data.index,
+                        "Inconsistent validator duties during signing"
                     );
                     return None;
                 }
-            };
 
-            match self
-                .validator_store
-                .sign_attestation(
-                    duty.pubkey,
-                    duty.validator_committee_index as usize,
-                    &mut attestation,
-                    current_epoch,
-                )
-                .await
-            {
-                Ok(()) => Some((attestation, duty.validator_index)),
-                Err(ValidatorStoreError::UnknownPubkey(pubkey)) => {
-                    // A pubkey can be missing when a validator was recently
-                    // removed via the API.
-                    warn!(
-                        info = "a validator may have recently been removed from this VC",
-                        pubkey = ?pubkey,
-                        validator = ?duty.pubkey,
-                        committee_index = committee_index,
-                        slot = slot.as_u64(),
-                        "Missing pubkey for attestation"
-                    );
-                    None
-                }
-                Err(e) => {
-                    crit!(
-                        error = ?e,
-                        validator = ?duty.pubkey,
-                        committee_index,
-                        slot = slot.as_u64(),
-                        "Failed to sign attestation"
-                    );
-                    None
+                let mut attestation = match Attestation::empty_for_signing(
+                    duty.committee_index,
+                    duty.committee_length as usize,
+                    attestation_data.slot,
+                    attestation_data.beacon_block_root,
+                    attestation_data.source,
+                    attestation_data.target,
+                    &self.chain_spec,
+                ) {
+                    Ok(attestation) => attestation,
+                    Err(err) => {
+                        crit!(
+                            validator = ?duty.pubkey,
+                            ?duty,
+                            ?err,
+                            "Invalid validator duties during signing"
+                        );
+                        return None;
+                    }
+                };
+
+                match self
+                    .validator_store
+                    .sign_attestation(
+                        duty.pubkey,
+                        duty.validator_committee_index as usize,
+                        &mut attestation,
+                        current_epoch,
+                    )
+                    .await
+                {
+                    Ok(()) => Some((attestation, duty.validator_index)),
+                    Err(ValidatorStoreError::UnknownPubkey(pubkey)) => {
+                        // A pubkey can be missing when a validator was recently
+                        // removed via the API.
+                        warn!(
+                            info = "a validator may have recently been removed from this VC",
+                            pubkey = ?pubkey,
+                            validator = ?duty.pubkey,
+                            committee_index = committee_index,
+                            slot = slot.as_u64(),
+                            "Missing pubkey for attestation"
+                        );
+                        None
+                    }
+                    Err(e) => {
+                        crit!(
+                            error = ?e,
+                            validator = ?duty.pubkey,
+                            committee_index,
+                            slot = slot.as_u64(),
+                            "Failed to sign attestation"
+                        );
+                        None
+                    }
                 }
             }
+            .instrument(Span::current())
         });
 
         // Execute all the futures in parallel, collecting any successful results.