diff --git a/pageserver/src/lib.rs b/pageserver/src/lib.rs index ff6af3566c82e..59396db4ffc00 100644 --- a/pageserver/src/lib.rs +++ b/pageserver/src/lib.rs @@ -375,6 +375,48 @@ async fn timed_after_cancellation( } } +async fn log_if_slow( + name: &str, + warn_after: std::time::Duration, + fut: Fut, +) -> ::Output { + let started = std::time::Instant::now(); + + let mut fut = std::pin::pin!(fut); + + match tokio::time::timeout(warn_after, &mut fut).await { + Ok(ret) => ret, + Err(_) => { + tracing::info!( + what = name, + elapsed_ms = started.elapsed().as_millis(), + "slow future" + ); + + let res = fut.await; + + tracing::info!( + what = name, + elapsed_ms = started.elapsed().as_millis(), + "slow future completed" + ); + + res + } + } +} + +pub(crate) trait LogIfSlowFutureExt: std::future::Future { + async fn log_if_slow(self, name: &'static str, warn_after: std::time::Duration) -> Self::Output + where + Self: Sized, + { + log_if_slow(name, warn_after, self).await + } +} + +impl LogIfSlowFutureExt for Fut where Fut: std::future::Future {} + #[cfg(test)] mod timed_tests { use super::timed; diff --git a/pageserver/src/tenant/timeline/compaction.rs b/pageserver/src/tenant/timeline/compaction.rs index 28c33813185d0..822b733aeb032 100644 --- a/pageserver/src/tenant/timeline/compaction.rs +++ b/pageserver/src/tenant/timeline/compaction.rs @@ -7,6 +7,7 @@ use std::collections::{BinaryHeap, HashMap, HashSet, VecDeque}; use std::ops::{Deref, Range}; use std::sync::Arc; +use std::time::Duration; use super::layer_manager::LayerManager; use super::{ @@ -47,6 +48,7 @@ use crate::tenant::timeline::{ImageLayerCreationOutcome, IoConcurrency}; use crate::tenant::timeline::{Layer, ResidentLayer}; use crate::tenant::{gc_block, DeltaLayer, MaybeOffloaded}; use crate::virtual_file::{MaybeFatalIo, VirtualFile}; +use crate::LogIfSlowFutureExt; use pageserver_api::config::tenant_conf_defaults::{ DEFAULT_CHECKPOINT_DISTANCE, DEFAULT_COMPACTION_THRESHOLD, }; @@ -676,6 +678,7 @@ impl Timeline { options.flags, ctx, ) + .log_if_slow("compact_legacy_repartition", Duration::from_secs(30)) .await { Ok(((dense_partitioning, sparse_partitioning), lsn)) => { @@ -717,6 +720,10 @@ impl Timeline { }, &image_ctx, ) + .log_if_slow( + "compact_legacy_create_image_layers", + Duration::from_secs(120), + ) .await?; self.upload_new_image_layers(image_layers)?; @@ -745,7 +752,9 @@ impl Timeline { // being potentially much longer. let rewrite_max = partition_count; - self.compact_shard_ancestors(rewrite_max, ctx).await?; + self.compact_shard_ancestors(rewrite_max, ctx) + .log_if_slow("compact_legacy_shard_ancestors", Duration::from_secs(300)) + .await?; } Ok(has_pending_tasks) @@ -1033,6 +1042,10 @@ impl Timeline { &ctx, ) .instrument(phase1_span) + .log_if_slow( + "compact_legacy_compact_level0_phase1", + Duration::from_secs(120), + ) .await? }; @@ -1042,6 +1055,10 @@ impl Timeline { } self.finish_compact_batch(&new_layers, &Vec::new(), &deltas_to_compact) + .log_if_slow( + "compact_legacy_finish_compact_batch", + Duration::from_secs(20), + ) .await?; Ok(fully_compacted) }