metric for accounts index insertion time (#18202)

runtime/src/accounts_db.rs

@@ -165,6 +165,7 @@ pub struct ErrorCounters {
 struct GenerateIndexTimings {
     pub index_time: u64,
     pub scan_time: u64,
+    pub insertion_time_us: u64,
 }
 
 impl GenerateIndexTimings {
@@ -174,6 +175,7 @@ impl GenerateIndexTimings {
             // we cannot accurately measure index insertion time because of many threads and lock contention
             ("total_us", self.index_time, i64),
             ("scan_stores_us", self.scan_time, i64),
+            ("insertion_time_us", self.insertion_time_us, i64),
         );
     }
 }
@@ -5870,8 +5872,15 @@ impl AccountsDb {
         accounts_map
     }
 
-    fn generate_index_for_slot<'a>(&self, accounts_map: GenerateIndexAccountsMap<'a>, slot: &Slot) {
+    fn generate_index_for_slot<'a>(
-        if !accounts_map.is_empty() {
+        &self,
+        accounts_map: GenerateIndexAccountsMap<'a>,
+        slot: &Slot,
+    ) -> u64 {
+        if accounts_map.is_empty() {
+            return 0;
+        }
+
         let items = accounts_map
             .iter()
             .map(|(pubkey, (_, store_id, stored_account))| {
@@ -5887,7 +5896,7 @@ impl AccountsDb {
             })
             .collect::<Vec<_>>();
 
-            let dirty_pubkeys = self
+        let (dirty_pubkeys, insert_us) = self
             .accounts_index
             .insert_new_if_missing_into_primary_index(*slot, items);
 
@@ -5908,7 +5917,7 @@ impl AccountsDb {
                 );
             }
         }
-        }
+        insert_us
     }
 
     #[allow(clippy::needless_collect)]
@@ -5923,6 +5932,7 @@ impl AccountsDb {
         let outer_slots_len = slots.len();
         let chunk_size = (outer_slots_len / 7) + 1; // approximately 400k slots in a snapshot
         let mut index_time = Measure::start("index");
+        let insertion_time_us = AtomicU64::new(0);
         let scan_time: u64 = slots
             .par_chunks(chunk_size)
             .map(|slots| {
@@ -5943,7 +5953,8 @@ impl AccountsDb {
                     scan_time.stop();
                     scan_time_sum += scan_time.as_us();
 
-                    self.generate_index_for_slot(accounts_map, slot);
+                    let insert_us = self.generate_index_for_slot(accounts_map, slot);
+                    insertion_time_us.fetch_add(insert_us, Ordering::Relaxed);
                 }
                 scan_time_sum
             })
@@ -5952,6 +5963,7 @@ impl AccountsDb {
         let timings = GenerateIndexTimings {
             scan_time,
             index_time: index_time.as_us(),
+            insertion_time_us: insertion_time_us.load(Ordering::Relaxed),
         };
         timings.report();
 

runtime/src/accounts_index.rs

@@ -1361,7 +1361,8 @@ impl<T: 'static + Clone + IsCached + ZeroLamport> AccountsIndex<T> {
         &self,
         slot: Slot,
         items: Vec<(&Pubkey, T)>,
-    ) -> Vec<Pubkey> {
+    ) -> (Vec<Pubkey>, u64) {
+        // returns (duplicate pubkey mask, insertion time us)
         let item_len = items.len();
         let potentially_new_items = items
             .into_iter()
@@ -1377,6 +1378,7 @@ impl<T: 'static + Clone + IsCached + ZeroLamport> AccountsIndex<T> {
         let mut _reclaims = SlotList::new();
         let mut duplicate_keys = Vec::with_capacity(item_len / 100); // just an estimate
         let mut w_account_maps = self.get_account_maps_write_lock();
+        let mut insert_time = Measure::start("insert_into_primary_index");
         potentially_new_items
             .into_iter()
             .for_each(|(pubkey, new_item)| {
@@ -1391,7 +1393,8 @@ impl<T: 'static + Clone + IsCached + ZeroLamport> AccountsIndex<T> {
                 }
             });
 
-        duplicate_keys
+        insert_time.stop();
+        (duplicate_keys, insert_time.as_us())
     }
 
     // Updates the given pubkey at the given slot with the new account information.