scmstore: add some counters for flushing

Summary:
- Add global counter for indexedlog sync operations (with separate counter for threshold based automatic syncs). I want to see these for EdenFS to verify we aren't syncing more than we expect. I added global counters because this should be "good enough" and was way easier than threading a per-log counter around for the dozens of logs we use.
- Add counter for number of file/tree store flushes. I also want to see how many times we call this (which triggers indexedlog syncs).

Reviewed By: sggutier

Differential Revision: D66731804

fbshipit-source-id: 5d9d60e4a7c984dbca302cf1be85a11e3aece32a

eden/scm/lib/indexedlog/src/log.rs

@@ -46,6 +46,8 @@ use std::io::Write;
 use std::ops::RangeBounds;
 use std::path::Path;
 use std::pin::Pin;
+use std::sync::atomic::AtomicU64;
+use std::sync::atomic::Ordering;
 use std::sync::Arc;
 
 use byteorder::ByteOrder;
@@ -111,6 +113,9 @@ const ENTRY_FLAG_HAS_XXHASH32: u32 = 2;
 // 1MB index checksum. This makes checksum file within one block (4KB) for 512MB index.
 const INDEX_CHECKSUM_CHUNK_SIZE_LOGARITHM: u32 = 20;
 
+pub static SYNC_COUNT: AtomicU64 = AtomicU64::new(0);
+pub static AUTO_SYNC_COUNT: AtomicU64 = AtomicU64::new(0);
+
 /// An append-only storage with indexes and integrity checks.
 ///
 /// The [`Log`] is backed by a directory in the filesystem. The
@@ -321,6 +326,7 @@ impl Log {
 
             if let Some(threshold) = self.open_options.auto_sync_threshold {
                 if self.mem_buf.len() as u64 >= threshold {
+                    AUTO_SYNC_COUNT.fetch_add(1, Ordering::Relaxed);
                     self.sync()
                         .context("sync triggered by auto_sync_threshold")?;
                 }
@@ -455,6 +461,8 @@ impl Log {
     ///
     /// For in-memory-only Logs, this function does nothing, and returns 0.
     pub fn sync(&mut self) -> crate::Result<u64> {
+        SYNC_COUNT.fetch_add(1, Ordering::Relaxed);
+
         let result: crate::Result<_> = (|| {
             let span = debug_span!("Log::sync", dirty_bytes = self.mem_buf.len());
             if let Some(dir) = &self.dir.as_opt_path() {

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

@@ -452,6 +452,7 @@ impl FileStore {
     }
 
     #[allow(unused_must_use)]
+    #[tracing::instrument(level = "debug", skip(self))]
     pub fn flush(&self) -> Result<()> {
         let mut result = Ok(());
         let mut handle_error = |error| {
@@ -483,6 +484,7 @@ impl FileStore {
         for (k, v) in metrics.metrics() {
             hg_metrics::increment_counter(k, v as u64);
         }
+        hg_metrics::increment_counter("scmstore.file.flush", 1);
         if let Err(err) = metrics.fetch.update_ods() {
             tracing::error!("Error updating ods fetch metrics: {}", err);
         }

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

@@ -55,14 +55,31 @@ impl FileStoreFetchMetrics {
     /// the `ods` feature flag.
     #[cfg(feature = "ods")]
     pub(crate) fn update_ods(&self) -> anyhow::Result<()> {
+        use std::sync::atomic::Ordering;
+
+        use indexedlog::log::AUTO_SYNC_COUNT;
+        use indexedlog::log::SYNC_COUNT;
+
         // Just give up if fbinit hasn't been called (e.g. in tests or from sl).
         if !fbinit::was_performed() {
             return Ok(());
         }
+
         let fb = fbinit::expect_init();
+
         for (metric, value) in self.metrics() {
             STATS::fetch.increment_value(fb, value.try_into()?, (metric,));
         }
+
+        // Assume we are called from flush()
+        STATS::flush.increment_value(fb, 1);
+
+        // These aren't technically filestore specific, but we don't have a convenient generic ODS logging spot.
+        STATS::indexedlog_sync
+            .increment_value(fb, SYNC_COUNT.swap(0, Ordering::Relaxed).try_into()?);
+        STATS::indexedlog_auto_sync
+            .increment_value(fb, AUTO_SYNC_COUNT.swap(0, Ordering::Relaxed).try_into()?);
+
         Ok(())
     }
     #[cfg(not(feature = "ods"))]
@@ -184,6 +201,9 @@ impl FileStoreMetrics {
 
 #[cfg(feature = "ods")]
 define_stats! {
-    prefix = "scmstore.file";
-    fetch: dynamic_singleton_counter("fetch.{}", (specific_counter: String)),
+    prefix = "scmstore";
+    fetch: dynamic_singleton_counter("file.fetch.{}", (specific_counter: String)),
+    flush: singleton_counter("file"),
+    indexedlog_sync: singleton_counter("indexedlog.sync"),
+    indexedlog_auto_sync: singleton_counter("indexedlog.auto_sync"),
 }

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

@@ -445,6 +445,7 @@ impl TreeStore {
     }
 
     #[allow(unused_must_use)]
+    #[tracing::instrument(level = "debug", skip(self))]
     pub fn flush(&self) -> Result<()> {
         let mut result = Ok(());
         let mut handle_error = |error| {
@@ -476,7 +477,7 @@ impl TreeStore {
         for (k, v) in metrics.metrics() {
             hg_metrics::increment_counter(k, v as u64);
         }
-
+        hg_metrics::increment_counter("scmstore.tree.flush", 1);
         if let Err(err) = metrics.fetch.update_ods() {
             tracing::error!(?err, "error updating tree ods counters");
         }

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

@@ -59,6 +59,10 @@ impl TreeStoreFetchMetrics {
         for (metric, value) in self.metrics() {
             STATS::fetch.increment_value(fb, value.try_into()?, (metric,));
         }
+
+        // Assume we are called from flush()
+        STATS::flush.increment_value(fb, 1);
+
         Ok(())
     }
 
@@ -87,4 +91,5 @@ impl TreeStoreMetrics {
 define_stats! {
     prefix = "scmstore.tree";
     fetch: dynamic_singleton_counter("fetch.{}", (specific_counter: String)),
+    flush: singleton_counter(),
 }

eden/scm/tests/test-fb-ext-remotefilelog-local.t

@@ -72,23 +72,7 @@
   $ clearcache
   $ echo xxxx > x
   $ echo yyyy > y
-  $ LOG=eagerepo::api=trace,revisionstore::scmstore=trace hg commit --debug -m x --config devel.print-metrics=scmstore.file.fetch.edenapi
-  DEBUG revisionstore::scmstore::tree: fetch_mode=FetchMode(REMOTE | LOCAL) attrs=TreeAttributes { content: true, parents: false, aux_data: false } fetch_children_metadata=false fetch_tree_aux_data=false fetch_local=true fetch_remote=true keys_len=1
-   INFO fetch_edenapi: revisionstore::scmstore::tree::fetch: enter
-  DEBUG fetch_edenapi: revisionstore::scmstore::tree::fetch: attempt to fetch 1 keys from edenapi (Some("eager:$TESTTMP/master"))
-  DEBUG fetch_edenapi: eagerepo::api: trees 960fd206ec076c5e0cd62ea972739158a2ea625c Some(TreeAttributes { manifest_blob: true, parents: true, child_metadata: false, augmented_trees: false })
-  TRACE fetch_edenapi: eagerepo::api:  found: 960fd206ec076c5e0cd62ea972739158a2ea625c, 169 bytes
-   INFO fetch_edenapi{downloaded=0 uploaded=0 requests=0 time=0 latency=0 download_speed="NaN"}: revisionstore::scmstore::tree::fetch: exit
-  committing files:
-  x
-  DEBUG eagerepo::api: history 1406e74118627694268417491f018a4a883152f0
-  TRACE eagerepo::api:  found: 1406e74118627694268417491f018a4a883152f0, 42 bytes
-  y
-  DEBUG eagerepo::api: history 076f5e2225b3ff0400b98c92aa6cdf403ee24cca
-  TRACE eagerepo::api:  found: 076f5e2225b3ff0400b98c92aa6cdf403ee24cca, 42 bytes
-  committing manifest
-  committing changelog
-  committed c9f680bc139617fbc46abc1a1103f36b380bbed0
+  $ hg commit -m x --config devel.print-metrics=scmstore.file.fetch
 
 # restore state for future tests
 

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

@@ -42,6 +42,7 @@ Prefetch (and also check we get counters):
   scmstore.file.fetch.indexedlog.local.requests: 1
   scmstore.file.fetch.indexedlog.local.singles: 1
   scmstore.file.fetch.indexedlog.local.time: * (glob) (?)
+  scmstore.file.flush: * (glob)
   scmstore.tree.fetch.edenapi.keys: 1
   scmstore.tree.fetch.edenapi.requests: 1
   scmstore.tree.fetch.edenapi.singles: 1
@@ -56,6 +57,7 @@ Prefetch (and also check we get counters):
   scmstore.tree.fetch.indexedlog.local.requests: 1
   scmstore.tree.fetch.indexedlog.local.singles: 1
   scmstore.tree.fetch.indexedlog.local.time: * (glob) (?)
+  scmstore.tree.flush: * (glob)
 
 Now we do have aux data locally:
   $ hg debugscmstore -r $A A --fetch-mode=LOCAL --mode=file