diff --git a/pageserver/src/metrics.rs b/pageserver/src/metrics.rs index 983a3079e4..6a5dc3e749 100644 --- a/pageserver/src/metrics.rs +++ b/pageserver/src/metrics.rs @@ -1439,27 +1439,43 @@ impl Drop for SmgrOpTimer { } impl SmgrOpFlushInProgress { - pub(crate) async fn measure(self, mut started_at: Instant, mut fut: Fut) -> O + pub(crate) async fn measure(self, started_at: Instant, mut fut: Fut) -> O where Fut: std::future::Future, { let mut fut = std::pin::pin!(fut); - // Whenever observe_guard gets called, or dropped, - // it adds the time elapsed since its last call to metrics. - // Last call is tracked in `now`. + let mut logged = false; + let mut last_counter_increment_at = started_at; let mut observe_guard = scopeguard::guard( - || { + |is_timeout| { let now = Instant::now(); - let elapsed = now - started_at; - self.global_micros - .inc_by(u64::try_from(elapsed.as_micros()).unwrap()); - self.per_timeline_micros - .inc_by(u64::try_from(elapsed.as_micros()).unwrap()); - started_at = now; + + // Increment counter + { + let elapsed_since_last_observe = now - last_counter_increment_at; + self.global_micros + .inc_by(u64::try_from(elapsed_since_last_observe.as_micros()).unwrap()); + self.per_timeline_micros + .inc_by(u64::try_from(elapsed_since_last_observe.as_micros()).unwrap()); + last_counter_increment_at = now; + } + + // Log something on every timeout, and on completion but only if we hit a timeout. + if is_timeout || logged { + logged = true; + let elapsed_total = now - started_at; + let msg = if is_timeout { + "slow flush ongoing" + } else { + "slow flush completed or cancelled" + }; + let elapsed_total_secs = format!("{:.6}", elapsed_total.as_secs_f64()); + tracing::info!(elapsed_total_secs, msg); + } }, |mut observe| { - observe(); + observe(false); }, ); @@ -1467,7 +1483,7 @@ impl SmgrOpFlushInProgress { match tokio::time::timeout(Duration::from_secs(10), &mut fut).await { Ok(v) => return v, Err(_timeout) => { - (*observe_guard)(); + (*observe_guard)(true); } } }