diff --git a/sqlx-core/src/executor.rs b/sqlx-core/src/executor.rs index 0379bcf83..37dfe22f7 100644 --- a/sqlx-core/src/executor.rs +++ b/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); + + /// 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) { (self, None) } + + #[inline] + #[doc(hidden)] + fn query_string(&self) -> &'q str { + self + } } impl Executor for &'_ mut T diff --git a/sqlx-core/src/lib.rs b/sqlx-core/src/lib.rs index 024a1f91c..d692eec93 100644 --- a/sqlx-core/src/lib.rs +++ b/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; diff --git a/sqlx-core/src/logging.rs b/sqlx-core/src/logging.rs new file mode 100644 index 000000000..a817ddb86 --- /dev/null +++ b/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::>() + .join(" ") +} diff --git a/sqlx-core/src/mysql/executor.rs b/sqlx-core/src/mysql/executor.rs index 469c366cd..024e6ea73 100644 --- a/sqlx-core/src/mysql/executor.rs +++ b/sqlx-core/src/mysql/executor.rs @@ -182,11 +182,13 @@ 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 + }) }) } @@ -194,7 +196,7 @@ impl Executor for super::MySqlConnection { 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) }) } } diff --git a/sqlx-core/src/postgres/executor.rs b/sqlx-core/src/postgres/executor.rs index d5b834f4b..e0e11af3c 100644 --- a/sqlx-core/src/postgres/executor.rs +++ b/sqlx-core/src/postgres/executor.rs @@ -488,11 +488,13 @@ 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 + }) }) } @@ -500,7 +502,7 @@ impl Executor for super::PgConnection { 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) }) } } diff --git a/sqlx-core/src/query.rs b/sqlx-core/src/query.rs index 141da710f..6ca51b19d 100644 --- a/sqlx-core/src/query.rs +++ b/sqlx-core/src/query.rs @@ -51,6 +51,11 @@ where fn into_parts(self) -> (&'q str, Option) { (self.query, Some(self.arguments)) } + + #[doc(hidden)] + fn query_string(&self) -> &'q str { + self.query + } } impl<'q, DB> Query<'q, DB> diff --git a/sqlx-core/src/query_as.rs b/sqlx-core/src/query_as.rs index 3aed1d5cc..3f1888908 100644 --- a/sqlx-core/src/query_as.rs +++ b/sqlx-core/src/query_as.rs @@ -44,6 +44,12 @@ where fn into_parts(self) -> (&'q str, Option<::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 diff --git a/sqlx-core/src/sqlite/executor.rs b/sqlx-core/src/sqlite/executor.rs index faef0e72b..3ba7b5f47 100644 --- a/sqlx-core/src/sqlite/executor.rs +++ b/sqlx-core/src/sqlite/executor.rs @@ -91,27 +91,29 @@ 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 + } + + if query.is_empty() { + break; + } } - while let Step::Row = statement.step().await? { - // We only care about the rows modified; ignore - } - - if query.is_empty() { - break; - } - } - - Ok(self.changes()) + Ok(self.changes()) + }) }) } @@ -119,7 +121,7 @@ impl Executor for SqliteConnection { 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) }) } }