Auto merge of #1606 - sgrif:sg-log-connection-pool-status, r=jtgeibel

Log the state of the connection pool once per minute

On rare occasions we've had outages occur as a result of the connection
pool refusing to return any connections. Shortly before this occurs, we
start to see significant spikes in response times (likely because the
pool has begun serving only a 1 or 2 connections and there's a large
amount of contention).

Right now we have limited capability to debug this. The only
explanations that I can come up with are a bug in r2d2, or something is
happening causing our worker threads to be killed in a way that does not
run destructors, or something is causing threads to hang indefinitely.

If one of those three options above is true, we should see `connections - idle_connections`
trend towards zero over time, and diverge away from
`in_flight_requests` over time (they aren't expected to be exactly
equal, since some requests will never attempt to get a database
connection, and we can have more requests than available connections
during normal operations)

This isn't going to be enough information to definitively figure out
what's going on here, but it should hopefully give us *some* information
to help figure out where to look next

Author: bors

src/middleware/log_connection_pool_status.rs

@@ -0,0 +1,53 @@
+//! Log the current state of the database connection pool at most once per minute
+
+use super::prelude::*;
+use crate::app::App;
+
+use conduit::Request;
+use std::sync::{
+    atomic::{AtomicUsize, Ordering},
+    Arc, Mutex,
+};
+use std::time::{Duration, Instant};
+
+#[derive(Clone)]
+pub(crate) struct LogConnectionPoolStatus {
+    app: Arc<App>,
+    last_log_time: Arc<Mutex<Instant>>,
+    in_flight_requests: Arc<AtomicUsize>,
+}
+
+impl LogConnectionPoolStatus {
+    pub(crate) fn new(app: &Arc<App>) -> Self {
+        Self {
+            app: app.clone(),
+            last_log_time: Arc::new(Mutex::new(Instant::now())),
+            in_flight_requests: Arc::new(AtomicUsize::new(0)),
+        }
+    }
+}
+
+impl Middleware for LogConnectionPoolStatus {
+    fn before(&self, _: &mut dyn Request) -> Result<(), Box<dyn Error + Send>> {
+        let mut last_log_time = self.last_log_time.lock().unwrap_or_else(|e| e.into_inner());
+        let in_flight_requests = self.in_flight_requests.fetch_add(1, Ordering::SeqCst);
+        if last_log_time.elapsed() >= Duration::from_secs(60) {
+            *last_log_time = Instant::now();
+            println!(
+                "connection_pool_status=\"{:?}\" in_flight_requests={}",
+                self.app.diesel_database.state(),
+                in_flight_requests
+            );
+        }
+        Ok(())
+    }
+
+    fn after(
+        &self,
+        _: &mut dyn Request,
+        res: Result<Response, Box<dyn Error + Send>>,
+    ) -> Result<Response, Box<dyn Error + Send>> {
+        self.in_flight_requests.fetch_sub(1, Ordering::SeqCst);
+        res
+    }
+}

src/middleware/mod.rs

@@ -9,6 +9,7 @@ pub use self::current_user::CurrentUser;
 pub use self::debug::*;
 pub use self::ember_index_rewrite::EmberIndexRewrite;
 pub use self::head::Head;
+use self::log_connection_pool_status::LogConnectionPoolStatus;
 pub use self::security_headers::SecurityHeaders;
 pub use self::static_or_continue::StaticOrContinue;
 
@@ -19,6 +20,7 @@ mod debug;
 mod ember_index_rewrite;
 mod ensure_well_formed_500;
 mod head;
+mod log_connection_pool_status;
 mod log_request;
 mod require_user_agent;
 mod security_headers;
@@ -53,6 +55,10 @@ pub fn build_middleware(app: Arc<App>, endpoints: R404) -> MiddlewareBuilder {
         m.add(DebugRequest);
     }
 
+    if env::var_os("LOG_CONNECTION_POOL_STATUS").is_some() {
+        m.add(LogConnectionPoolStatus::new(&app));
+    }
+
     m.add(ConditionalGet);
 
     m.add(Cookie::new());