Add basic query logging

Prints each query performed at DEBUG level,
along with a timing of how long the query took
to execute.

Slow queries will be printed at WARN level.
Currently the slow query threshold is
hardcoded to 1 second.

Author: shssoichiro

sqlx-core/src/executor.rs

@@ -79,6 +79,10 @@ where
     /// prepare the query. Returning `Some(Default::default())` is an empty arguments object that
     /// will be prepared (and cached) before execution.
     fn into_parts(self) -> (&'q str, Option<DB::Arguments>);
+
+    /// Returns the query string, without any parameters replaced.
+    #[doc(hidden)]
+    fn query_string(&self) -> &'q str;
 }
 
 impl<'q, DB> Execute<'q, DB> for &'q str
@@ -89,6 +93,12 @@ where
     fn into_parts(self) -> (&'q str, Option<DB::Arguments>) {
         (self, None)
     }
+
+    #[inline]
+    #[doc(hidden)]
+    fn query_string(&self) -> &'q str {
+        self
+    }
 }
 
 impl<T> Executor for &'_ mut T

sqlx-core/src/lib.rs

@@ -56,6 +56,10 @@ pub mod types;
 #[macro_use]
 pub mod row;
 
+#[cfg(any(feature = "mysql", feature = "postgres", feature = "sqlite"))]
+#[macro_use]
+mod logging;
+
 #[cfg(feature = "mysql")]
 #[cfg_attr(docsrs, doc(cfg(feature = "mysql")))]
 pub mod mysql;

sqlx-core/src/logging.rs

@@ -0,0 +1,35 @@
+/// Logs the query and execution time of a statement as it runs.
+macro_rules! log_execution {
+    ( $query:expr, $block:expr ) => {{
+        // TODO: Log bound parameters
+        let query_string = $query.query_string();
+        let timer = std::time::Instant::now();
+        let result = $block;
+        let elapsed = timer.elapsed();
+        if elapsed >= std::time::Duration::from_secs(1) {
+            log::warn!(
+                "{} ..., elapsed: {:.3?}\n\n    {}\n",
+                crate::logging::parse_query_summary(query_string),
+                elapsed,
+                query_string
+            );
+        } else {
+            log::debug!(
+                "{} ..., elapsed: {:.3?}\n\n    {}\n",
+                crate::logging::parse_query_summary(query_string),
+                elapsed,
+                query_string
+            );
+        }
+        result
+    }};
+}
+
+pub(crate) fn parse_query_summary(query: &str) -> String {
+    // For now, just take the first 3 words
+    query
+        .split_whitespace()
+        .take(3)
+        .collect::<Vec<&str>>()
+        .join(" ")
+}

sqlx-core/src/mysql/executor.rs

@@ -182,19 +182,21 @@ impl Executor for super::MySqlConnection {
     where
         E: Execute<'q, Self::Database>,
     {
-        Box::pin(async move {
-            let (query, arguments) = query.into_parts();
+        log_execution!(query, {
+            Box::pin(async move {
+                let (query, arguments) = query.into_parts();
 
-            self.run(query, arguments).await?;
-            self.affected_rows().await
+                self.run(query, arguments).await?;
+                self.affected_rows().await
+            })
         })
     }
 
     fn fetch<'q, E>(&mut self, query: E) -> MySqlCursor<'_, 'q>
     where
         E: Execute<'q, Self::Database>,
     {
-        MySqlCursor::from_connection(self, query)
+        log_execution!(query, { MySqlCursor::from_connection(self, query) })
     }
 
     #[doc(hidden)]
@@ -216,6 +218,6 @@ impl<'c> RefExecutor<'c> for &'c mut super::MySqlConnection {
     where
         E: Execute<'q, Self::Database>,
     {
-        MySqlCursor::from_connection(self, query)
+        log_execution!(query, { MySqlCursor::from_connection(self, query) })
     }
 }

sqlx-core/src/postgres/executor.rs

@@ -488,19 +488,21 @@ impl Executor for super::PgConnection {
     where
         E: Execute<'q, Self::Database>,
     {
-        Box::pin(async move {
-            let (query, arguments) = query.into_parts();
+        log_execution!(query, {
+            Box::pin(async move {
+                let (query, arguments) = query.into_parts();
 
-            self.run(query, arguments).await?;
-            self.affected_rows().await
+                self.run(query, arguments).await?;
+                self.affected_rows().await
+            })
         })
     }
 
     fn fetch<'q, E>(&mut self, query: E) -> PgCursor<'_, 'q>
     where
         E: Execute<'q, Self::Database>,
     {
-        PgCursor::from_connection(self, query)
+        log_execution!(query, { PgCursor::from_connection(self, query) })
     }
 
     #[doc(hidden)]
@@ -522,6 +524,6 @@ impl<'c> RefExecutor<'c> for &'c mut super::PgConnection {
     where
         E: Execute<'q, Self::Database>,
     {
-        PgCursor::from_connection(self, query)
+        log_execution!(query, { PgCursor::from_connection(self, query) })
     }
 }

sqlx-core/src/query.rs

@@ -51,6 +51,11 @@ where
     fn into_parts(self) -> (&'q str, Option<DB::Arguments>) {
         (self.query, Some(self.arguments))
     }
+
+    #[doc(hidden)]
+    fn query_string(&self) -> &'q str {
+        self.query
+    }
 }
 
 impl<'q, DB> Query<'q, DB>

sqlx-core/src/query_as.rs

@@ -44,6 +44,12 @@ where
     fn into_parts(self) -> (&'q str, Option<<DB as Database>::Arguments>) {
         (self.query, Some(self.arguments))
     }
+
+    #[inline]
+    #[doc(hidden)]
+    fn query_string(&self) -> &'q str {
+        self.query
+    }
 }
 
 /// Construct a raw SQL query that is mapped to a concrete type

sqlx-core/src/sqlite/executor.rs

@@ -91,35 +91,37 @@ impl Executor for SqliteConnection {
     where
         E: Execute<'q, Self::Database>,
     {
-        let (mut query, mut arguments) = query.into_parts();
+        log_execution!(query, {
+            let (mut query, mut arguments) = query.into_parts();
 
-        Box::pin(async move {
-            loop {
-                let key = self.prepare(&mut query, arguments.is_some())?;
-                let statement = self.statement_mut(key);
+            Box::pin(async move {
+                loop {
+                    let key = self.prepare(&mut query, arguments.is_some())?;
+                    let statement = self.statement_mut(key);
 
-                if let Some(arguments) = &mut arguments {
-                    statement.bind(arguments)?;
-                }
+                    if let Some(arguments) = &mut arguments {
+                        statement.bind(arguments)?;
+                    }
 
-                while let Step::Row = statement.step().await? {
-                    // We only care about the rows modified; ignore
-                }
+                    while let Step::Row = statement.step().await? {
+                        // We only care about the rows modified; ignore
+                    }
 
-                if query.is_empty() {
-                    break;
+                    if query.is_empty() {
+                        break;
+                    }
                 }
-            }
 
-            Ok(self.changes())
+                Ok(self.changes())
+            })
         })
     }
 
     fn fetch<'q, E>(&mut self, query: E) -> SqliteCursor<'_, 'q>
     where
         E: Execute<'q, Self::Database>,
     {
-        SqliteCursor::from_connection(self, query)
+        log_execution!(query, { SqliteCursor::from_connection(self, query) })
     }
 
     #[doc(hidden)]
@@ -186,6 +188,6 @@ impl<'e> RefExecutor<'e> for &'e mut SqliteConnection {
     where
         E: Execute<'q, Self::Database>,
     {
-        SqliteCursor::from_connection(self, query)
+        log_execution!(query, { SqliteCursor::from_connection(self, query) })
     }
 }