feat(logging): Log slow acquires from connection pool

Signed-off-by: Joshua Potts <8704475+iamjpotts@users.noreply.github.com>

sqlx-core/src/pool/inner.rs

@@ -241,9 +241,10 @@ impl<DB: Database> PoolInner<DB> {
             return Err(Error::PoolClosed);
         }
 
-        let deadline = Instant::now() + self.options.acquire_timeout;
+        let acquire_started_at = Instant::now();
+        let deadline = acquire_started_at + self.options.acquire_timeout;
 
-        crate::rt::timeout(
+        let acquired = crate::rt::timeout(
             self.options.acquire_timeout,
             async {
                 loop {
@@ -272,7 +273,7 @@ impl<DB: Database> PoolInner<DB> {
                             // or if the pool was closed between `acquire_permit()` and
                             // `try_increment_size()`.
                             tracing::debug!("woke but was unable to acquire idle connection or open new one; retrying");
-                            // If so, we're likely in the current-thread runtime if it's Tokio
+                            // If so, we're likely in the current-thread runtime if it's Tokio,
                             // and so we should yield to let any spawned return_to_pool() tasks
                             // execute.
                             crate::rt::yield_now().await;
@@ -286,7 +287,21 @@ impl<DB: Database> PoolInner<DB> {
             }
         )
             .await
-            .map_err(|_| Error::PoolTimedOut)?
+            .map_err(|_| Error::PoolTimedOut)??;
+
+        let acquired_at = Instant::now();
+        let acquired_after = acquired_at - acquire_started_at;
+
+        if acquired_after >= self.options.acquire_slow_after {
+            tracing::warn!(
+                target: "sqlx::pool",
+                aquired_after_secs = acquired_after.as_secs_f64(),
+                slow_acquire_threshold_secs = self.options.acquire_slow_after.as_secs_f64(),
+                "slow connection acquire: time exceeded alert threshold"
+            )
+        }
+
+        Ok(acquired)
     }
 
     pub(super) async fn connect(

sqlx-core/src/pool/mod.rs

@@ -230,7 +230,7 @@ pub use self::maybe::MaybePoolConnection;
 /// scheme. However, in a web context, telling a client "go away, maybe try again later" results in
 /// a sub-optimal user experience.
 ///
-/// Instead with a connection pool, clients are made to wait in a fair queue for a connection to
+/// Instead, with a connection pool, clients are made to wait in a fair queue for a connection to
 /// become available; by using a single connection pool for your whole application, you can ensure
 /// that you don't exceed the connection limit of your database server while allowing response
 /// time to degrade gracefully at high load.

sqlx-core/src/pool/options.rs

@@ -74,6 +74,7 @@ pub struct PoolOptions<DB: Database> {
         >,
     >,
     pub(crate) max_connections: u32,
+    pub(crate) acquire_slow_after: Duration,
     pub(crate) acquire_timeout: Duration,
     pub(crate) min_connections: u32,
     pub(crate) max_lifetime: Option<Duration>,
@@ -94,6 +95,7 @@ impl<DB: Database> Clone for PoolOptions<DB> {
             before_acquire: self.before_acquire.clone(),
             after_release: self.after_release.clone(),
             max_connections: self.max_connections,
+            acquire_slow_after: self.acquire_slow_after,
             acquire_timeout: self.acquire_timeout,
             min_connections: self.min_connections,
             max_lifetime: self.max_lifetime,
@@ -143,6 +145,8 @@ impl<DB: Database> PoolOptions<DB> {
             // A production application will want to set a higher limit than this.
             max_connections: 10,
             min_connections: 0,
+            // Fast enough to catch problems (e.g. a full pool); slow enough to not flag typical time to add a new connection to a pool
+            acquire_slow_after: Duration::from_secs(3),
             acquire_timeout: Duration::from_secs(30),
             idle_timeout: Some(Duration::from_secs(10 * 60)),
             max_lifetime: Some(Duration::from_secs(30 * 60)),
@@ -198,6 +202,21 @@ impl<DB: Database> PoolOptions<DB> {
         self.min_connections
     }
 
+    /// Set a threshold for reporting excessive time taken to acquire a connection from
+    /// the connection pool. When the threshold is exceeded, a warning is logged.
+    ///
+    /// Defaults to a value that should not typically be exceeded by the pool enlarging
+    /// itself with an additional new connection.
+    pub fn acquire_slow_after(mut self, value: Duration) -> Self {
+        self.acquire_slow_after = value;
+        self
+    }
+
+    /// Get the threshold for reporting excessive time taken to acquire a connection.
+    pub fn get_acquire_slow_after(&self) -> Duration {
+        self.acquire_slow_after
+    }
+
     /// Set the maximum amount of time to spend waiting for a connection in [`Pool::acquire()`].
     ///
     /// Caps the total amount of time `Pool::acquire()` can spend waiting across multiple phases:
@@ -269,7 +288,7 @@ impl<DB: Database> PoolOptions<DB> {
         self
     }
 
-    /// Get's whether `test_before_acquire` is currently set.
+    /// Get whether `test_before_acquire` is currently set.
     pub fn get_test_before_acquire(&self) -> bool {
         self.test_before_acquire
     }