From e81fa7137ea30b4d359cb5e8e1eefeed28869887 Mon Sep 17 00:00:00 2001
From: Christian Schwarz <christian@neon.tech>
Date: Wed, 15 Jan 2025 18:56:07 +0100
Subject: [PATCH] investigation: add log_if_slow => shows that the io_futures
 are slow

---
 pageserver/src/lib.rs                  | 42 ++++++++++++++++++++++++++
 pageserver/src/tenant/storage_layer.rs |  4 ++-
 2 files changed, 45 insertions(+), 1 deletion(-)

diff --git a/pageserver/src/lib.rs b/pageserver/src/lib.rs
index ff6af3566c..59396db4ff 100644
--- a/pageserver/src/lib.rs
+++ b/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;
diff --git a/pageserver/src/tenant/storage_layer.rs b/pageserver/src/tenant/storage_layer.rs
index ce97f5081e..fdfb44d6bf 100644
--- a/pageserver/src/tenant/storage_layer.rs
+++ b/pageserver/src/tenant/storage_layer.rs
@@ -10,6 +10,8 @@ mod layer_desc;
 mod layer_name;
 pub mod merge_iterator;
 
+use crate::LogIfSlowFutureExt;
+
 use crate::context::{AccessStatsBehavior, RequestContext};
 use bytes::Bytes;
 use futures::stream::FuturesUnordered;
@@ -418,7 +420,7 @@ impl IoConcurrency {
         match self {
             IoConcurrency::Serial => fut.await,
             IoConcurrency::FuturesUnordered { ios_tx, .. } => {
-                let mut fut = Box::pin(fut);
+                let mut fut = Box::pin(fut.log_if_slow("spawned_io", Duration::from_secs(1)));
                 // opportunistic poll to give some boost (unproven if it helps, but sounds like a good idea)
                 if let Poll::Ready(()) = futures::poll!(&mut fut) {
                     return;