Auto merge of #3775 - pietroalbini:more-histograms, r=Turbo87

Add more histograms

This PR adds more histograms to the metrics we collect, exposing information that could be useful when we get paged. Two metrics were added:

* `cratesio_instance_database_time_to_obtain_connection`: how long it takes to obtain a database connection
* `cratesio_instance_downloads_select_query_execution_time`: how long the `SELECT` in the download endpoint takes

A side effect of this is that `TimingRecorder` is not needed anymore: we used it to measure those two things, appending them in the logs for slow requests, but now that we have metrics there is no need to have it. If we need to measure more timings in the future we can just add more histograms. This PR thus removes `TimingRecorder` from the codebase.

r? `@jtgeibel` or `@Turbo87`
This can be reviewed commit-by-commit.

Author: bors

src/app.rs

@@ -62,6 +62,9 @@ impl App {
     pub fn new(config: config::Server, http_client: Option<Client>) -> App {
         use oauth2::{AuthUrl, ClientId, ClientSecret, TokenUrl};
 
+        let instance_metrics =
+            InstanceMetrics::new().expect("could not initialize instance metrics");
+
         let github = GitHubClient::new(http_client.clone(), config.gh_base_url.clone());
 
         let github_oauth = BasicClient::new(
@@ -116,7 +119,14 @@ impl App {
                 .connection_customizer(Box::new(primary_db_connection_config))
                 .thread_pool(thread_pool.clone());
 
-            DieselPool::new(&config.db.primary.url, primary_db_config).unwrap()
+            DieselPool::new(
+                &config.db.primary.url,
+                primary_db_config,
+                instance_metrics
+                    .database_time_to_obtain_connection
+                    .with_label_values(&["primary"]),
+            )
+            .unwrap()
         };
 
         let replica_database = if let Some(url) = config.db.replica.as_ref().map(|c| &c.url) {
@@ -135,7 +145,16 @@ impl App {
                     .connection_customizer(Box::new(replica_db_connection_config))
                     .thread_pool(thread_pool);
 
-                Some(DieselPool::new(url, replica_db_config).unwrap())
+                Some(
+                    DieselPool::new(
+                        url,
+                        replica_db_config,
+                        instance_metrics
+                            .database_time_to_obtain_connection
+                            .with_label_values(&["follower"]),
+                    )
+                    .unwrap(),
+                )
             }
         } else {
             None
@@ -150,8 +169,7 @@ impl App {
             downloads_counter: DownloadsCounter::new(),
             emails: Emails::from_environment(),
             service_metrics: ServiceMetrics::new().expect("could not initialize service metrics"),
-            instance_metrics: InstanceMetrics::new()
-                .expect("could not initialize instance metrics"),
+            instance_metrics,
             http_client,
         }
     }

src/controllers.rs

@@ -19,7 +19,6 @@ mod prelude {
 
     pub use crate::db::RequestTransaction;
     pub use crate::middleware::app::RequestApp;
-    pub use crate::middleware::log_request::TimingRecorder;
     pub use crate::util::errors::{cargo_err, AppError, AppResult, ChainError}; // TODO: Remove cargo_err from here
     pub use crate::util::{AppResponse, EndpointResult};
 
@@ -39,7 +38,6 @@ mod prelude {
         fn query_with_params(&self, params: IndexMap<String, String>) -> String;
 
         fn log_metadata<V: std::fmt::Display>(&mut self, key: &'static str, value: V);
-        fn timing_recorder(&mut self) -> TimingRecorder;
     }
 
     impl<'a> RequestUtils for dyn RequestExt + 'a {
@@ -80,17 +78,6 @@ mod prelude {
         fn log_metadata<V: std::fmt::Display>(&mut self, key: &'static str, value: V) {
             crate::middleware::log_request::add_custom_metadata(self, key, value);
         }
-
-        fn timing_recorder(&mut self) -> TimingRecorder {
-            if let Some(recorder) = self.extensions().find::<TimingRecorder>() {
-                recorder.clone()
-            } else {
-                let recorder = TimingRecorder::new();
-                self.mut_extensions()
-                    .insert::<TimingRecorder>(recorder.clone());
-                recorder
-            }
-        }
     }
 }
 

src/controllers/version/downloads.rs

@@ -14,26 +14,28 @@ use chrono::{Duration, NaiveDate, Utc};
 /// This returns a URL to the location where the crate is stored.
 pub fn download(req: &mut dyn RequestExt) -> EndpointResult {
     let app = req.app().clone();
-    let recorder = req.timing_recorder();
 
     let mut crate_name = req.params()["crate_id"].clone();
     let version = req.params()["version"].as_str();
 
     let mut log_metadata = None;
-    match recorder.record("get_conn", || req.db_conn()) {
+    match req.db_conn() {
         Ok(conn) => {
             use self::versions::dsl::*;
 
             // Returns the crate name as stored in the database, or an error if we could
             // not load the version ID from the database.
-            let (version_id, canonical_crate_name) = recorder.record("get_version", || {
-                versions
-                    .inner_join(crates::table)
-                    .select((id, crates::name))
-                    .filter(Crate::with_name(&crate_name))
-                    .filter(num.eq(version))
-                    .first::<(i32, String)>(&*conn)
-            })?;
+            let (version_id, canonical_crate_name) = app
+                .instance_metrics
+                .downloads_select_query_execution_time
+                .observe_closure_duration(|| {
+                    versions
+                        .inner_join(crates::table)
+                        .select((id, crates::name))
+                        .filter(Crate::with_name(&crate_name))
+                        .filter(num.eq(version))
+                        .first::<(i32, String)>(&*conn)
+                })?;
 
             if canonical_crate_name != crate_name {
                 app.instance_metrics

src/db.rs

@@ -2,6 +2,7 @@ use conduit::RequestExt;
 use diesel::prelude::*;
 use diesel::r2d2::{self, ConnectionManager, CustomizeConnection};
 use parking_lot::{ReentrantMutex, ReentrantMutexGuard};
+use prometheus::Histogram;
 use std::sync::Arc;
 use std::{ops::Deref, time::Duration};
 use url::Url;
@@ -10,14 +11,18 @@ use crate::middleware::app::RequestApp;
 
 #[derive(Clone)]
 pub enum DieselPool {
-    Pool(r2d2::Pool<ConnectionManager<PgConnection>>),
+    Pool {
+        pool: r2d2::Pool<ConnectionManager<PgConnection>>,
+        time_to_obtain_connection_metric: Histogram,
+    },
     Test(Arc<ReentrantMutex<PgConnection>>),
 }
 
 impl DieselPool {
     pub(crate) fn new(
         url: &str,
         config: r2d2::Builder<ConnectionManager<PgConnection>>,
+        time_to_obtain_connection_metric: Histogram,
     ) -> Result<DieselPool, PoolError> {
         let manager = ConnectionManager::new(connection_url(url));
 
@@ -32,7 +37,10 @@ impl DieselPool {
         // serving errors for the first connections until the pool is initialized) and if we can't
         // establish any connection continue booting up the application. The database pool will
         // automatically be marked as unhealthy and the rest of the application will adapt.
-        let pool = DieselPool::Pool(config.build_unchecked(manager));
+        let pool = DieselPool::Pool {
+            pool: config.build_unchecked(manager),
+            time_to_obtain_connection_metric,
+        };
         match pool.wait_until_healthy(Duration::from_secs(5)) {
             Ok(()) => {}
             Err(PoolError::UnhealthyPool) => {}
@@ -52,22 +60,25 @@ impl DieselPool {
 
     pub fn get(&self) -> Result<DieselPooledConn<'_>, PoolError> {
         match self {
-            DieselPool::Pool(pool) => {
+            DieselPool::Pool {
+                pool,
+                time_to_obtain_connection_metric,
+            } => time_to_obtain_connection_metric.observe_closure_duration(|| {
                 if let Some(conn) = pool.try_get() {
                     Ok(DieselPooledConn::Pool(conn))
                 } else if !self.is_healthy() {
                     Err(PoolError::UnhealthyPool)
                 } else {
                     Ok(DieselPooledConn::Pool(pool.get().map_err(PoolError::R2D2)?))
                 }
-            }
+            }),
             DieselPool::Test(conn) => Ok(DieselPooledConn::Test(conn.lock())),
         }
     }
 
     pub fn state(&self) -> PoolState {
         match self {
-            DieselPool::Pool(pool) => {
+            DieselPool::Pool { pool, .. } => {
                 let state = pool.state();
                 PoolState {
                     connections: state.connections,
@@ -83,7 +94,7 @@ impl DieselPool {
 
     pub fn wait_until_healthy(&self, timeout: Duration) -> Result<(), PoolError> {
         match self {
-            DieselPool::Pool(pool) => match pool.get_timeout(timeout) {
+            DieselPool::Pool { pool, .. } => match pool.get_timeout(timeout) {
                 Ok(_) => Ok(()),
                 Err(_) if !self.is_healthy() => Err(PoolError::UnhealthyPool),
                 Err(err) => Err(PoolError::R2D2(err)),

src/metrics/instance.rs

@@ -20,7 +20,7 @@
 use crate::util::errors::AppResult;
 use crate::{app::App, db::DieselPool};
 use prometheus::{
-    proto::MetricFamily, HistogramVec, IntCounter, IntCounterVec, IntGauge, IntGaugeVec,
+    proto::MetricFamily, Histogram, HistogramVec, IntCounter, IntCounterVec, IntGauge, IntGaugeVec,
 };
 
 metrics! {
@@ -29,6 +29,8 @@ metrics! {
         database_idle_conns: IntGaugeVec["pool"],
         /// Number of used database connections in the pool
         database_used_conns: IntGaugeVec["pool"],
+        /// Amount of time required to obtain a database connection
+        pub database_time_to_obtain_connection: HistogramVec["pool"],
 
         /// Number of requests processed by this instance
         pub requests_total: IntCounter,
@@ -44,6 +46,8 @@ metrics! {
         pub downloads_unconditional_redirects_total: IntCounter,
         /// Number of download requests with a non-canonical crate name.
         pub downloads_non_canonical_crate_name_total: IntCounter,
+        /// How long it takes to execute the SELECT query in the download endpoint.
+        pub downloads_select_query_execution_time: Histogram,
         /// Number of download requests that are not counted yet.
         downloads_not_counted_total: IntGauge,
     }

src/middleware/log_request.rs

@@ -8,11 +8,8 @@ use conduit::{header, Host, RequestExt, Scheme, StatusCode};
 use conduit_cookie::RequestSession;
 use sentry::Level;
 
-use std::cell::RefCell;
-use std::collections::HashMap;
 use std::fmt::{self, Display, Formatter};
-use std::rc::Rc;
-use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH};
+use std::time::{SystemTime, UNIX_EPOCH};
 
 const SLOW_REQUEST_THRESHOLD_MS: u64 = 1000;
 
@@ -94,34 +91,6 @@ pub fn add_custom_metadata<V: Display>(req: &mut dyn RequestExt, key: &'static s
     }
 }
 
-#[derive(Debug, Clone)]
-pub struct TimingRecorder {
-    sections: Rc<RefCell<HashMap<&'static str, Duration>>>,
-}
-
-impl TimingRecorder {
-    pub fn new() -> Self {
-        Self {
-            sections: Rc::new(RefCell::new(HashMap::new())),
-        }
-    }
-
-    pub fn record<R>(&self, name: &'static str, f: impl FnOnce() -> R) -> R {
-        let start = Instant::now();
-        let res = f();
-        self.sections
-            .borrow_mut()
-            .insert(name, Instant::now() - start);
-        res
-    }
-}
-
-impl Default for TimingRecorder {
-    fn default() -> Self {
-        Self::new()
-    }
-}
-
 fn report_to_sentry(req: &dyn RequestExt, res: &AfterResult, response_time: u64) {
     let (message, level) = match res {
         Err(e) => (e.to_string(), Level::Error),
@@ -255,17 +224,6 @@ impl Display for RequestLine<'_> {
 
         if self.response_time > SLOW_REQUEST_THRESHOLD_MS {
             line.add_marker("SLOW REQUEST")?;
-
-            if let Some(timings) = self.req.extensions().find::<TimingRecorder>() {
-                for (section, duration) in timings.sections.borrow().iter() {
-                    line.add_quoted_field(
-                        format!("timing_{}", section),
-                        // Debug formatting rounds the duration to the most useful unit and adds
-                        // the unit suffix. For example: 1.20s, 10.00ms, 8.35ns
-                        format!("{:.2?}", duration),
-                    )?;
-                }
-            }
         }
 
         Ok(())