pageserver: trace slow requests when compact_l0

Signed-off-by: Alex Chi Z <chi@neon.tech>
Co-authored-by: Christian Schwarz <christian@neon.tech>

pageserver/src/lib.rs

@@ -375,6 +375,48 @@ async fn timed_after_cancellation<Fut: std::future::Future>(
     }
 }
 
+async fn log_if_slow<Fut: std::future::Future>(
+    name: &str,
+    warn_after: std::time::Duration,
+    fut: Fut,
+) -> <Fut as std::future::Future>::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<Fut> LogIfSlowFutureExt for Fut where Fut: std::future::Future {}
+
 #[cfg(test)]
 mod timed_tests {
     use super::timed;

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)
     }