investigation: add log_if_slow => shows that the io_futures are slow

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/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;