Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: add a tracing span for queries #3176

Closed
wants to merge 1 commit into from
Closed
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
60 changes: 58 additions & 2 deletions sqlx-core/src/logger.rs
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,22 @@ macro_rules! private_tracing_dynamic_event {
}};
}

#[doc(hidden)]
#[macro_export]
macro_rules! private_tracing_dynamic_span {
(target: $target:expr, $level:expr, $($args:tt)*) => {{
use ::tracing::Level;

match $level {
Level::ERROR => ::tracing::span!(target: $target, Level::ERROR, $($args)*),
Level::WARN => ::tracing::span!(target: $target, Level::WARN, $($args)*),
Level::INFO => ::tracing::span!(target: $target, Level::INFO, $($args)*),
Level::DEBUG => ::tracing::span!(target: $target, Level::DEBUG, $($args)*),
Level::TRACE => ::tracing::span!(target: $target, Level::TRACE, $($args)*),
}
}};
}

#[doc(hidden)]
pub fn private_level_filter_to_levels(
filter: log::LevelFilter,
Expand All @@ -55,23 +71,58 @@ pub fn private_level_filter_to_levels(
}

pub use sqlformat;
use tracing::span::EnteredSpan;

pub struct QueryLogger<'q> {
sql: &'q str,
rows_returned: u64,
rows_affected: u64,
start: Instant,
settings: LogSettings,
span: Option<EnteredSpan>,
}

fn level_filter_to_level_if_enabled(level: log::LevelFilter) -> Option<tracing::Level> {
if let Some((tracing_level, log_level)) = private_level_filter_to_levels(level) {
if log::log_enabled!(target: "sqlx::query", log_level)
|| private_tracing_dynamic_enabled!(target: "sqlx::query", tracing_level)
{
return Some(tracing_level);
}
}
None
}

impl<'q> QueryLogger<'q> {
pub fn new(sql: &'q str, settings: LogSettings) -> Self {
let start = Instant::now();

let span = if let Some(tracing_level) =
level_filter_to_level_if_enabled(settings.statements_level)
{
// Ideally we would use the summary as the trace message, but `tracing` requires the message to be static
Some(
private_tracing_dynamic_span!(
target: "sqlx::query",
tracing_level,
"sqlx::query",
db.statement = sql,
rows_affected = tracing::field::Empty,
rows_returned = tracing::field::Empty,
)
.entered(),
)
} else {
None
};

Self {
sql,
rows_returned: 0,
rows_affected: 0,
start: Instant::now(),
start,
settings,
span,
}
}

Expand All @@ -83,7 +134,7 @@ impl<'q> QueryLogger<'q> {
self.rows_affected += n;
}

pub fn finish(&self) {
pub fn finish(&mut self) {
let elapsed = self.start.elapsed();

let was_slow = elapsed >= self.settings.slow_statements_duration;
Expand Down Expand Up @@ -148,6 +199,11 @@ impl<'q> QueryLogger<'q> {
elapsed_secs = elapsed.as_secs_f64(),
);
}

if let Some(span) = self.span.take().map(|span| span.exit()) {
span.record("rows_affected", self.rows_affected);
span.record("rows_returned", self.rows_returned);
}
}
}
}
Expand Down