scmstore: instrument tree store with counters

Summary: Add basic counters for tree fetch counts and times. I didn't add anything specific for the aux data prefetching yet since that didn't fit well into the existing counters.

Reviewed By: zzl0

Differential Revision: D55372723

fbshipit-source-id: 2908327963a6fecc90a09de64aec8b180ae37b12

eden/scm/lib/revisionstore/src/scmstore/builder.rs

@@ -645,6 +645,7 @@ impl<'a> TreeStoreBuilder<'a> {
             filestore: self.filestore,
             tree_metadata_mode,
             flush_on_drop: true,
+            metrics: Default::default(),
         })
     }
 }

eden/scm/lib/revisionstore/src/scmstore/tree/metrics.rs

@@ -0,0 +1,82 @@
+/*
+ * Copyright (c) Meta Platforms, Inc. and affiliates.
+ *
+ * This software may be used and distributed according to the terms of the
+ * GNU General Public License version 2.
+ */
+
+use std::ops::AddAssign;
+use std::sync::Arc;
+
+use parking_lot::RwLock;
+#[cfg(feature = "ods")]
+use stats::prelude::*;
+
+use crate::scmstore::metrics::namespaced;
+use crate::scmstore::metrics::FetchMetrics;
+use crate::scmstore::metrics::LocalAndCacheFetchMetrics;
+
+#[derive(Clone, Debug, Default)]
+pub struct TreeStoreFetchMetrics {
+    pub(crate) indexedlog: LocalAndCacheFetchMetrics,
+    pub(crate) aux: LocalAndCacheFetchMetrics,
+    pub(crate) edenapi: FetchMetrics,
+}
+
+impl AddAssign for TreeStoreFetchMetrics {
+    fn add_assign(&mut self, rhs: Self) {
+        self.indexedlog += rhs.indexedlog;
+        self.aux += rhs.aux;
+        self.edenapi += rhs.edenapi;
+    }
+}
+
+impl TreeStoreFetchMetrics {
+    fn metrics(&self) -> impl Iterator<Item = (String, usize)> {
+        namespaced("indexedlog", self.indexedlog.metrics())
+            .chain(namespaced("aux", self.aux.metrics()))
+            .chain(namespaced("edenapi", self.edenapi.metrics()))
+    }
+
+    /// Update ODS stats.
+    /// This assumes that fbinit was called higher up the stack.
+    /// It is meant to be used when called from eden which uses the `revisionstore` with
+    /// the `ods` feature flag.
+    #[cfg(feature = "ods")]
+    pub(crate) fn update_ods(&self) -> anyhow::Result<()> {
+        for (metric, value) in self.metrics() {
+            // SAFETY: this is called from C++ and was init'd there
+            unsafe {
+                let fb = fbinit::assume_init();
+                STATS::fetch.increment_value(fb, value.try_into()?, (metric,));
+            }
+        }
+        Ok(())
+    }
+
+    #[cfg(not(feature = "ods"))]
+    pub(crate) fn update_ods(&self) -> anyhow::Result<()> {
+        Ok(())
+    }
+}
+
+#[derive(Debug, Default, Clone)]
+pub struct TreeStoreMetrics {
+    pub(crate) fetch: TreeStoreFetchMetrics,
+}
+
+impl TreeStoreMetrics {
+    pub fn new() -> Arc<RwLock<Self>> {
+        Arc::new(RwLock::new(TreeStoreMetrics::default()))
+    }
+
+    pub fn metrics(&self) -> impl Iterator<Item = (String, usize)> {
+        namespaced("scmstore.tree", namespaced("fetch", self.fetch.metrics()))
+    }
+}
+
+#[cfg(feature = "ods")]
+define_stats! {
+    prefix = "scmstore.tree";
+    fetch: dynamic_singleton_counter("fetch.{}", (specific_counter: String)),
+}

eden/scm/lib/revisionstore/src/scmstore/tree/mod.rs

@@ -8,6 +8,7 @@
 use std::borrow::Borrow;
 use std::path::PathBuf;
 use std::sync::Arc;
+use std::time::Instant;
 
 use ::types::fetch_mode::FetchMode;
 use ::types::tree::TreeItemFlag;
@@ -25,16 +26,20 @@ use edenapi_types::FileAuxData;
 use edenapi_types::TreeChildEntry;
 use minibytes::Bytes;
 use once_cell::sync::OnceCell;
+use parking_lot::RwLock;
 use storemodel::SerializationFormat;
 use tracing::field;
 
+mod metrics;
 pub mod types;
 
 use clientinfo::get_client_request_info_thread_local;
 use clientinfo::set_client_request_info_thread_local;
 use storemodel::BoxIterator;
 use storemodel::TreeEntry;
 
+use self::metrics::TreeStoreFetchMetrics;
+pub use self::metrics::TreeStoreMetrics;
 use crate::datastore::HgIdDataStore;
 use crate::datastore::RemoteDataStore;
 use crate::indexedlogdatastore::Entry;
@@ -60,6 +65,7 @@ use crate::Metadata;
 use crate::RepackLocation;
 use crate::StoreKey;
 use crate::StoreResult;
+use crate::StoreType;
 
 #[derive(Clone, Debug)]
 pub enum TreeMetadataMode {
@@ -98,6 +104,8 @@ pub struct TreeStore {
     pub tree_metadata_mode: TreeMetadataMode,
 
     pub flush_on_drop: bool,
+
+    pub(crate) metrics: Arc<RwLock<TreeStoreMetrics>>,
 }
 
 impl Drop for TreeStore {
@@ -153,31 +161,42 @@ impl TreeStore {
             keys_len
         );
 
+        let store_metrics = self.metrics.clone();
+
         let process_func = move || -> Result<()> {
+            let mut metrics = TreeStoreFetchMetrics::default();
+
             if fetch_local {
-                if let Some(ref indexedlog_cache) = indexedlog_cache {
-                    let pending: Vec<_> = common
-                        .pending(TreeAttributes::CONTENT, false)
-                        .map(|(key, _attrs)| key.clone())
-                        .collect();
-                    for key in pending.into_iter() {
-                        if let Some(entry) = indexedlog_cache.get_entry(key)? {
-                            tracing::trace!("{:?} found in cache", &entry.key());
-                            common.found(entry.key().clone(), LazyTree::IndexedLog(entry).into());
+                for (log, store_type) in [
+                    (&indexedlog_cache, StoreType::Shared),
+                    (&indexedlog_local, StoreType::Local),
+                ] {
+                    if let Some(log) = log {
+                        let start_time = Instant::now();
+
+                        let pending: Vec<_> = common
+                            .pending(TreeAttributes::CONTENT, false)
+                            .map(|(key, _attrs)| key.clone())
+                            .collect();
+
+                        let store_metrics = metrics.indexedlog.store(store_type);
+                        let fetch_count = pending.len();
+
+                        store_metrics.fetch(fetch_count);
+
+                        let mut found_count: usize = 0;
+                        for key in pending.into_iter() {
+                            if let Some(entry) = log.get_entry(key)? {
+                                tracing::trace!("{:?} found in {:?}", &entry.key(), store_type);
+                                common
+                                    .found(entry.key().clone(), LazyTree::IndexedLog(entry).into());
+                                found_count += 1;
+                            }
                         }
-                    }
-                }
 
-                if let Some(ref indexedlog_local) = indexedlog_local {
-                    let pending: Vec<_> = common
-                        .pending(TreeAttributes::CONTENT, false)
-                        .map(|(key, _attrs)| key.clone())
-                        .collect();
-                    for key in pending.into_iter() {
-                        if let Some(entry) = indexedlog_local.get_entry(key)? {
-                            tracing::trace!("{:?} found in local", &entry.key());
-                            common.found(entry.key().clone(), LazyTree::IndexedLog(entry).into());
-                        }
+                        store_metrics.hit(found_count);
+                        store_metrics.miss(fetch_count - found_count);
+                        let _ = store_metrics.time_from_duration(start_time.elapsed());
                     }
                 }
             }
@@ -189,6 +208,10 @@ impl TreeStore {
                         .map(|(key, _attrs)| key.clone())
                         .collect();
                     if !pending.is_empty() {
+                        let start_time = Instant::now();
+
+                        metrics.edenapi.fetch(pending.len());
+
                         let span = tracing::info_span!(
                             "fetch_edenapi",
                             downloaded = field::Empty,
@@ -237,6 +260,7 @@ impl TreeStore {
                             common.found(key, entry.into());
                         }
                         util::record_edenapi_stats(&span, &response.stats);
+                        let _ = metrics.edenapi.time_from_duration(start_time.elapsed());
                     }
                 } else {
                     tracing::debug!("no EdenApi associated with TreeStore");
@@ -289,6 +313,13 @@ impl TreeStore {
 
             // TODO(meyer): Report incomplete / not found, handle errors better instead of just always failing the batch, etc
             common.results(FetchErrors::new());
+
+            if let Err(err) = metrics.update_ods() {
+                tracing::error!(?err, "error udpating tree ods counters");
+            }
+
+            store_metrics.write().fetch += metrics;
+
             Ok(())
         };
         let process_func_errors = move || {
@@ -332,6 +363,7 @@ impl TreeStore {
             filestore: None,
             flush_on_drop: true,
             tree_metadata_mode: TreeMetadataMode::Never,
+            metrics: Default::default(),
         }
     }
 
@@ -351,6 +383,12 @@ impl TreeStore {
             indexedlog_cache.flush_log().map_err(&mut handle_error);
         }
 
+        let mut metrics = self.metrics.write();
+        for (k, v) in metrics.metrics() {
+            hg_metrics::increment_counter(k, v);
+        }
+        *metrics = Default::default();
+
         result
     }
 
@@ -386,6 +424,7 @@ impl LegacyStore for TreeStore {
             filestore: None,
             flush_on_drop: true,
             tree_metadata_mode: TreeMetadataMode::Never,
+            metrics: self.metrics.clone(),
         })
     }
 

eden/scm/tests/test-remotefilelog-prefetch.t

@@ -41,6 +41,18 @@ Prefetch (and also check we get counters):
   scmstore.file.fetch.indexedlog.local.misses: 1
   scmstore.file.fetch.indexedlog.local.requests: 1
   scmstore.file.fetch.indexedlog.local.time: * (glob) (?)
+  scmstore.tree.fetch.edenapi.keys: 1
+  scmstore.tree.fetch.edenapi.requests: 1
+  scmstore.tree.fetch.edenapi.time: * (glob) (?)
+  scmstore.tree.fetch.indexedlog.cache.hits: 2
+  scmstore.tree.fetch.indexedlog.cache.keys: 3
+  scmstore.tree.fetch.indexedlog.cache.misses: 1
+  scmstore.tree.fetch.indexedlog.cache.requests: 4
+  scmstore.tree.fetch.indexedlog.cache.time: * (glob) (?)
+  scmstore.tree.fetch.indexedlog.local.keys: 1
+  scmstore.tree.fetch.indexedlog.local.misses: 1
+  scmstore.tree.fetch.indexedlog.local.requests: 4
+  scmstore.tree.fetch.indexedlog.local.time: * (glob) (?)
 
 Now we do have aux data locally:
   $ hg debugscmstore -r $A A --fetch-mode=local_only --mode=file