better log messages for elapsed time warns

[RoloEdits]

Is your feature request related to a problem? Please describe.

When the elapsed time for a query goes over some amount, there is a log for a warn. The message then only contained the query itself and again in another field a truncated version of the query.

Describe the solution you'd like

A clear "query took too long" in one of those fields would help convey what might seem like a random warn. The time was already a problem, but was known, and time was spent trying to figure out if there was another issue at play.

Describe alternatives you've considered

As its the library itself that has the logging, there is nothing I can do as long query times are not an error that can be matched on.

Additional context

version 0.7.1
postgres 15

Looks like this is the line where the logic for the log happens:

sqlx/sqlx-core/src/logger.rs

Lines 86 to 93 in 7e7dded

	pub fn finish(&self) {
	let elapsed = self.start.elapsed();
	let lvl = if elapsed >= self.settings.slow_statements_duration {
	self.settings.slow_statements_level
	} else {
	self.settings.statements_level
	};

[Matthias247]

Why would it be a random WARN if you configure slow_statements_level to WARN and statements_level to e.g. DEBUG? In this case the only condition for seeing a WARN is a slow query.

[RoloEdits]

I have already configured the log level for sqlx to be debug through the LevelFilter enum. I have not done any other kind config with the log levels other than what seems to be the only way to interface with it when creating the pool. And by this view, I would say that is random.

[Matthias247]

You need to set the different log levels on sqlx. Along

let database_connect_options: sqlx::postgres::PgConnectOptions = database_url
    .parse::<sqlx::postgres::PgConnectOptions>()?
    .log_statements("DEBUG".parse().unwrap())
    .log_slow_statements("WARN".parse().unwrap());

let database_connection = sqlx::pool::PoolOptions::new()
    .connect_with(database_connect_options)
    .await?;

[RoloEdits]

I see. Thanks. Though I still think the messages can be improved, so I think the issue still stands.

[arifd]

I agree. It may be intuitive to you @Matthias247 because you know the slow_statement is the only kind of event that is logged at WARN level or so, but every time I see it I always have to think twice about what it is WARNing me for.

[ppershing]

We were also surprised to suddenly see new warnings and didn't know what changed (did we update the library? Something else in our debug/warn setup?). Having the log prefixed with "Slow query:" or something like that would help us to diagnose the root cause way faster.