Track cache lookup time

This commit is contained in:
Yuchen Wu 2024-05-15 17:33:12 -07:00 committed by Edward Wang
parent 026f483712
commit ac25f03e62
2 changed files with 14 additions and 3 deletions

2
.bleep
View file

@ -1 +1 @@
b0438fe62f4b4004646ca3621a0c0215c6385f6f
ce62ef5259bbe34107ad85f6f5557cda0d53764f

View file

@ -21,7 +21,7 @@ use key::{CacheHashKey, HashBinary};
use lock::WritePermit;
use pingora_error::Result;
use pingora_http::ResponseHeader;
use std::time::{Duration, SystemTime};
use std::time::{Duration, Instant, SystemTime};
use trace::CacheTraceCTX;
pub mod cache_control;
@ -222,6 +222,8 @@ struct HttpCacheInner {
pub lock: Option<Locked>, // TODO: these 3 fields should come in 1 sub struct
pub cache_lock: Option<&'static CacheLock>,
pub lock_duration: Option<Duration>,
/// time spent in cache lookup and reading the header
pub lookup_duration: Option<Duration>,
pub traces: trace::CacheTraceCTX,
}
@ -369,6 +371,7 @@ impl HttpCache {
lock: None,
cache_lock,
lock_duration: None,
lookup_duration: None,
traces: CacheTraceCTX::new(),
}));
}
@ -896,7 +899,15 @@ impl HttpCache {
let inner = self.inner_mut();
let mut span = inner.traces.child("lookup");
let key = inner.key.as_ref().unwrap(); // safe, this phase should have cache key
let now = Instant::now();
let result = inner.storage.lookup(key, &span.handle()).await?;
let lookup_duration = now.elapsed();
// one request may have multiple lookups
inner.lookup_duration = Some(
inner
.lookup_duration
.map_or(lookup_duration, |d| d + lookup_duration),
);
let result = result.and_then(|(meta, header)| {
if let Some(ts) = inner.valid_after {
if meta.created() < ts {
@ -1015,7 +1026,7 @@ impl HttpCache {
let _span = inner.traces.child("cache_lock");
let lock = inner.lock.take(); // remove the lock from self
if let Some(Locked::Read(r)) = lock {
let now = std::time::Instant::now();
let now = Instant::now();
r.wait().await;
let lock_duration = now.elapsed();
// it's possible for a request to be locked more than once