Track how long background requests wait before processing

core/src/accounts_hash_verifier.rs

@@ -72,6 +72,7 @@ impl AccountsHashVerifier {
                         &accounts_package_receiver,
                     ) {
                         info!("handling accounts package: {accounts_package:?}");
+                        let enqueued_time = accounts_package.enqueued.elapsed();
 
                         let (_, measure) = measure!(Self::process_accounts_package(
                             accounts_package,
@@ -97,6 +98,7 @@ impl AccountsHashVerifier {
                                 num_re_enqueued_accounts_packages as i64,
                                 i64
                             ),
+                            ("enqueued-time-us", enqueued_time.as_micros() as i64, i64),
                             ("total-processing-time-us", measure.as_us() as i64, i64),
                         );
                     } else {
@@ -478,7 +480,7 @@ mod tests {
             sysvar::epoch_schedule::EpochSchedule,
         },
         solana_streamer::socket::SocketAddrSpace,
-        std::str::FromStr,
+        std::{str::FromStr, time::Instant},
     };
 
     fn new_test_cluster_info(contact_info: ContactInfo) -> ClusterInfo {
@@ -561,6 +563,7 @@ mod tests {
                 accounts: Arc::clone(&accounts),
                 epoch_schedule: EpochSchedule::default(),
                 rent_collector: RentCollector::default(),
+                enqueued: Instant::now(),
             };
 
             AccountsHashVerifier::process_accounts_package(

runtime/src/accounts_background_service.rs

@@ -113,6 +113,10 @@ pub struct SnapshotRequest {
     pub snapshot_root_bank: Arc<Bank>,
     pub status_cache_slot_deltas: Vec<BankSlotDelta>,
     pub request_type: SnapshotRequestType,
+
+    /// The instant this request was send to the queue.
+    /// Used to track how long requests wait before processing.
+    pub enqueued: Instant,
 }
 
 impl Debug for SnapshotRequest {
@@ -169,7 +173,12 @@ impl SnapshotRequestHandler {
                 "num-re-enqueued-requests",
                 num_re_enqueued_requests as i64,
                 i64
-            )
+            ),
+            (
+                "enqueued-time-us",
+                snapshot_request.enqueued.elapsed().as_micros() as i64,
+                i64
+            ),
         );
 
         Some(self.handle_snapshot_request(
@@ -274,6 +283,7 @@ impl SnapshotRequestHandler {
             snapshot_root_bank,
             status_cache_slot_deltas,
             request_type: _,
+            enqueued: _,
         } = snapshot_request;
 
         // we should not rely on the state of this validator until startup verification is complete
@@ -844,6 +854,7 @@ mod test {
                 snapshot_root_bank,
                 status_cache_slot_deltas: Vec::default(),
                 request_type,
+                enqueued: Instant::now(),
             };
             snapshot_request_sender.send(snapshot_request).unwrap();
         };

runtime/src/bank_forks.rs

@@ -317,6 +317,7 @@ impl BankForks {
                     snapshot_root_bank: Arc::clone(eah_bank),
                     status_cache_slot_deltas: Vec::default(),
                     request_type: SnapshotRequestType::EpochAccountsHash,
+                    enqueued: Instant::now(),
                 })
                 .expect("send epoch accounts hash request");
         }
@@ -356,6 +357,7 @@ impl BankForks {
                             snapshot_root_bank: Arc::clone(bank),
                             status_cache_slot_deltas,
                             request_type: SnapshotRequestType::Snapshot,
+                            enqueued: Instant::now(),
                         })
                     {
                         warn!(

runtime/src/snapshot_package.rs

@@ -18,6 +18,7 @@ use {
         fs,
         path::{Path, PathBuf},
         sync::{Arc, Mutex},
+        time::Instant,
     },
     tempfile::TempDir,
 };
@@ -46,6 +47,10 @@ pub struct AccountsPackage {
     pub accounts: Arc<Accounts>,
     pub epoch_schedule: EpochSchedule,
     pub rent_collector: RentCollector,
+
+    /// The instant this accounts package was send to the queue.
+    /// Used to track how long accounts packages wait before processing.
+    pub enqueued: Instant,
 }
 
 impl AccountsPackage {
@@ -116,6 +121,7 @@ impl AccountsPackage {
             accounts: bank.accounts(),
             epoch_schedule: *bank.epoch_schedule(),
             rent_collector: bank.rent_collector().clone(),
+            enqueued: Instant::now(),
         })
     }
 
@@ -139,6 +145,7 @@ impl AccountsPackage {
             accounts: Arc::new(Accounts::default_for_tests()),
             epoch_schedule: EpochSchedule::default(),
             rent_collector: RentCollector::default(),
+            enqueued: Instant::now(),
         }
     }
 }