Skip to content
This repository has been archived by the owner on Apr 6, 2023. It is now read-only.

feat: instrument cache hit and misses #208

Merged
merged 6 commits into from
Nov 9, 2021
Merged
Show file tree
Hide file tree
Changes from 4 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
18 changes: 18 additions & 0 deletions docs/data.md
Original file line number Diff line number Diff line change
Expand Up @@ -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 counter representing the number of entries in the
first level of hashing in the in-memory deduped hashmap.

- `cache.memory.storage_len` - A counter 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.
Expand All @@ -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.
32 changes: 29 additions & 3 deletions merino-cache/src/memory.rs
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,7 @@

use anyhow::anyhow;
use async_trait::async_trait;
use cadence::{Histogrammed, StatsdClient};
use cadence::{Counted, CountedExt, Histogrammed, StatsdClient};
use deduped_dashmap::{ControlFlow, DedupedMap};
use lazy_static::lazy_static;
use merino_settings::providers::MemoryCacheConfig;
Expand Down Expand Up @@ -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 {
Expand All @@ -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);
}
});
}
Expand All @@ -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();
Expand Down Expand Up @@ -174,6 +176,13 @@ impl Suggester {
?removed_storage,
"finished removing expired entries from cache"
);

metrics_client
.count("cache.memory.storage_len", items.len_storage() as i64)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I missed this the first time, but this needs to be metrics_client.gauge, not .count. That's because count is equivalent to incr, but with a larger step. (more specifically, incr is count with n = 1). With count we'd end up with a graph of the integral of the cache size overtime, which definitely isn't what we want.

.ok();
metrics_client
.count("cache.memory.pointers_len", items.len_pointers() as i64)
.ok();
}
}

Expand Down Expand Up @@ -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),
Expand All @@ -215,6 +225,7 @@ impl SuggestionProvider for Suggester {
}
None => {
tracing::debug!("cache miss");
self.metrics_client.incr("cache.memory.miss").ok();
}
}

Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -299,12 +311,26 @@ 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();
assert!(collected_data.contains(&"merino-test.cache.memory.storage_len:1|c".to_string()));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

needs updating per the gauge type

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, right. thanks.

assert!(collected_data.contains(&"merino-test.cache.memory.pointers_len:1|c".to_string()));
}

#[test]
Expand Down
4 changes: 3 additions & 1 deletion merino-cache/src/redis/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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::{
Expand Down Expand Up @@ -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...");
Expand All @@ -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));
Expand Down