feat: instrument cache hit and misses (#208)

Co-authored-by: Michael Cooper <mythmon@gmail.com>

docs/data.md

@@ -111,6 +111,18 @@ the level and type of the log is listed.
   - `cache-status` - If the response was pulled from the cache or regenerated.
     `"hit"`, `"miss"`, `"error"`, or `"none"`.
 
+- `cache.memory.hit` - A counter that is incremented every time the in-memory
+  cache is queried and a cached suggestion is found.
+
+- `cache.memory.miss` - A counter that is incremented every time the in-memory
+  cache is queried and a cached suggestion is not found.
+
+- `cache.memory.pointers-len` - A gauge representing the number of entries in
+  the first level of hashing in the in-memory deduped hashmap.
+
+- `cache.memory.storage-len` - A gauge representing the number of entries in the
+  second level of hashing in the in-memory deduped hashmap.
+
 - `cache.redis.duration-us` - A histogram that records the amount of time, in
   microseconds, that the Redis cache took to provide a suggestion. Includes the
   time it takes to fallback to the inner provider for cache misses and errors.
@@ -119,3 +131,9 @@ the level and type of the log is listed.
 
   - `cache-status` - If the response was pulled from the cache or regenerated.
     `"hit"`, `"miss"`, `"error"`, or `"none"`.
+
+- `cache.redis.hit` - A counter that is incremented every time the redis cache
+  is queried and a cached suggestion is found.
+
+- `cache.redis.miss` - A counter that is incremented every time the redis cache
+  is queried and a cached suggestion is not found.

merino-cache/src/memory.rs

@@ -7,7 +7,7 @@
 
 use anyhow::anyhow;
 use async_trait::async_trait;
-use cadence::{Histogrammed, StatsdClient};
+use cadence::{CountedExt, Gauged, Histogrammed, StatsdClient};
 use deduped_dashmap::{ControlFlow, DedupedMap};
 use lazy_static::lazy_static;
 use merino_settings::providers::MemoryCacheConfig;
@@ -108,6 +108,7 @@ impl Suggester {
         let items = Arc::new(DedupedMap::new());
 
         {
+            let metrics = metrics_client.clone();
             let task_items = items.clone();
             let task_interval = config.cleanup_interval;
             tokio::spawn(async move {
@@ -118,7 +119,7 @@ impl Suggester {
                 timer.tick().await;
                 loop {
                     timer.tick().await;
-                    Self::remove_expired_entries(&task_items);
+                    Self::remove_expired_entries(&task_items, &metrics);
                 }
             });
         }
@@ -138,6 +139,7 @@ impl Suggester {
     #[tracing::instrument(level = "debug", skip(items))]
     fn remove_expired_entries<K: Eq + Hash + Debug>(
         items: &Arc<DedupedMap<K, Instant, Vec<Suggestion>>>,
+        metrics_client: &StatsdClient,
     ) {
         let start = Instant::now();
         let count_before_storage = items.len_storage();
@@ -174,6 +176,13 @@ impl Suggester {
             ?removed_storage,
             "finished removing expired entries from cache"
         );
+
+        metrics_client
+            .gauge("cache.memory.storage-len", items.len_storage() as u64)
+            .ok();
+        metrics_client
+            .gauge("cache.memory.pointers-len", items.len_pointers() as u64)
+            .ok();
     }
 }
 
@@ -207,6 +216,7 @@ impl SuggestionProvider for Suggester {
                 }
                 Some((expiration, suggestions)) => {
                     tracing::debug!("cache hit");
+                    self.metrics_client.incr("cache.memory.hit").ok();
                     rv = Some(SuggestionResponse {
                         cache_status: CacheStatus::Hit,
                         cache_ttl: Some(expiration - now),
@@ -215,6 +225,7 @@ impl SuggestionProvider for Suggester {
                 }
                 None => {
                     tracing::debug!("cache miss");
+                    self.metrics_client.incr("cache.memory.miss").ok();
                 }
             }
 
@@ -271,6 +282,7 @@ impl SuggestionProvider for Suggester {
 #[cfg(test)]
 mod tests {
     use super::{Suggester, LOCK_TABLE};
+    use cadence::{SpyMetricSink, StatsdClient};
     use deduped_dashmap::DedupedMap;
     use fake::{Fake, Faker};
     use merino_suggest::Suggestion;
@@ -299,12 +311,27 @@ mod tests {
         assert!(cache.contains_key(&"current".to_owned()));
         assert!(cache.contains_key(&"expired".to_owned()));
 
-        Suggester::remove_expired_entries(&cache);
+        // Provide an inspectable metrics sink to validate the collected data.
+        let (rx, sink) = SpyMetricSink::new();
+        let metrics_client = StatsdClient::from_sink("merino-test", sink);
+
+        Suggester::remove_expired_entries(&cache, &metrics_client);
 
         assert_eq!(cache.len_storage(), 1);
         assert_eq!(cache.len_pointers(), 1);
         assert!(cache.contains_key(&"current".to_owned()));
         assert!(!cache.contains_key(&"expired".to_owned()));
+
+        // Verify the reported metric.
+        assert_eq!(rx.len(), 2);
+        let collected_data: Vec<String> = rx
+            .iter()
+            .take(2)
+            .map(|x| String::from_utf8(x).unwrap())
+            .collect();
+        dbg!(&collected_data);
+        assert!(collected_data.contains(&"merino-test.cache.memory.storage-len:1|g".to_string()));
+        assert!(collected_data.contains(&"merino-test.cache.memory.pointers-len:1|g".to_string()));
     }
 
     #[test]

merino-cache/src/redis/mod.rs

@@ -10,7 +10,7 @@ use std::{
 use crate::redis::domain::RedisSuggestions;
 use anyhow::Context;
 use async_trait::async_trait;
-use cadence::{Histogrammed, StatsdClient};
+use cadence::{CountedExt, Histogrammed, StatsdClient};
 use fix_hidden_lifetime_bug::fix_hidden_lifetime_bug;
 use merino_settings::{providers::RedisCacheConfig, Settings};
 use merino_suggest::{
@@ -380,6 +380,7 @@ impl SuggestionProvider for Suggester {
 
         let rv = if let CacheCheckResult::Hit(suggestions) = cache_result {
             tracing::debug!(%key, "cache hit");
+            self.metrics_client.incr("cache.redis.hit").ok();
             suggestions
         } else if rlock.is_locked(&key).await? {
             tracing::debug!(%key, "cache updating...");
@@ -396,6 +397,7 @@ impl SuggestionProvider for Suggester {
 
             if let CacheCheckResult::Miss = cache_result {
                 tracing::debug!(%key, "cache miss");
+                self.metrics_client.incr("cache.redis.miss").ok();
                 response.with_cache_status(CacheStatus::Miss)
             } else {
                 debug_assert!(matches!(cache_result, CacheCheckResult::ErrorAsMiss));