fix: Print StateRecords corresponding to the range of a state part …

…generated (#8798)

To help us understand why creation of certain parts is as slow as 10 second, look at the corresponding `StateRecord`s for the first and the last node of the state part.

Based on #8794

nearcore/src/metrics.rs

@@ -82,19 +82,19 @@ pub(crate) static STATE_SYNC_DUMP_EPOCH_HEIGHT: Lazy<IntGaugeVec> = Lazy::new(||
     )
     .unwrap()
 });
-pub static STATE_SYNC_APPLY_PART_DELAY: Lazy<HistogramVec> = Lazy::new(|| {
+pub static STATE_SYNC_APPLY_PART_DELAY: Lazy<near_o11y::metrics::HistogramVec> = Lazy::new(|| {
     try_create_histogram_vec(
         "near_state_sync_apply_part_delay_sec",
-        "Time needed to apply a state part",
+        "Latency of applying a state part",
         &["shard_id"],
         Some(exponential_buckets(0.001, 2.0, 20).unwrap()),
     )
     .unwrap()
 });
-pub static STATE_SYNC_OBTAIN_PART_DELAY: Lazy<HistogramVec> = Lazy::new(|| {
+pub static STATE_SYNC_OBTAIN_PART_DELAY: Lazy<near_o11y::metrics::HistogramVec> = Lazy::new(|| {
     try_create_histogram_vec(
         "near_state_sync_obtain_part_delay_sec",
-        "Time needed to obtain a part",
+        "Latency of applying a state part",
         &["shard_id"],
         Some(exponential_buckets(0.001, 2.0, 20).unwrap()),
     )

nearcore/src/runtime/mod.rs

@@ -1275,24 +1275,14 @@ impl RuntimeAdapter for NightshadeRuntime {
                     Ok(_) => true,
                     // Storage error should not happen
                     Err(err) => {
-                        tracing::error!(
-                            target: "state-parts",
-                            ?state_root,
-                            ?part_id,
-                            ?err,
-                            "State part storage error");
+                        tracing::error!(target: "state-parts", ?err, "State part storage error");
                         false
                     }
                 }
             }
             // Deserialization error means we've got the data from malicious peer
             Err(err) => {
-                tracing::error!(
-                    target: "state-parts",
-                    ?state_root,
-                    ?part_id,
-                    ?err,
-                    "State part deserialization error");
+                tracing::error!(target: "state-parts", ?err, "State part deserialization error");
                 false
             }
         }

tools/state-viewer/src/state_parts.rs

@@ -1,13 +1,15 @@
 use crate::epoch_info::iterate_and_filter;
+use borsh::BorshDeserialize;
 use near_chain::{Chain, ChainGenesis, ChainStoreAccess, DoomslugThresholdMode};
 use near_client::sync::state::StateSync;
 use near_primitives::epoch_manager::epoch_info::EpochInfo;
 use near_primitives::state_part::PartId;
+use near_primitives::state_record::StateRecord;
 use near_primitives::syncing::get_num_state_parts;
 use near_primitives::types::{EpochId, StateRoot};
 use near_primitives_core::hash::CryptoHash;
 use near_primitives_core::types::{BlockHeight, EpochHeight, ShardId};
-use near_store::Store;
+use near_store::{PartialStorage, Store, Trie};
 use nearcore::{NearConfig, NightshadeRuntime};
 use s3::serde_types::ListBucketResult;
 use std::fs::DirEntry;
@@ -341,11 +343,34 @@ fn dump_state_parts(
             .obtain_state_part(shard_id, &sync_hash, &state_root, PartId::new(part_id, num_parts))
             .unwrap();
         part_storage.write(&state_part, part_id, num_parts);
-        tracing::info!(target: "state-parts", part_id, part_length = state_part.len(), elapsed_sec = timer.elapsed().as_secs_f64(), "Wrote a state part");
+        let elapsed_sec = timer.elapsed().as_secs_f64();
+        let first_state_record = get_first_state_record(&state_root, &state_part);
+        tracing::info!(
+            target: "state-parts",
+            part_id,
+            part_length = state_part.len(),
+            elapsed_sec,
+            ?first_state_record,
+            "Wrote a state part");
     }
     tracing::info!(target: "state-parts", total_elapsed_sec = timer.elapsed().as_secs_f64(), "Wrote all requested state parts");
 }
 
+/// Returns the first `StateRecord` encountered while iterating over a sub-trie in the state part.
+fn get_first_state_record(state_root: &StateRoot, data: &[u8]) -> Option<StateRecord> {
+    let trie_nodes = BorshDeserialize::try_from_slice(data).unwrap();
+    let trie = Trie::from_recorded_storage(PartialStorage { nodes: trie_nodes }, *state_root);
+
+    for item in trie.iter().unwrap() {
+        if let Ok((key, value)) = item {
+            if let Some(sr) = StateRecord::from_raw_key_value(key, value) {
+                return Some(sr);
+            }
+        }
+    }
+    None
+}
+
 /// Reads `StateHeader` stored in the DB.
 fn read_state_header(
     epoch_selection: EpochSelection,