feat: add a tracing span for queries

[miikka]

This is a sketch of adding a tracing span for SQL queries. There is already a tracing event with the right information in QueryLogger - I decided to leave it as is and duplicate the row counts in the span. In theory, you would not need the event when the span is there, but in practice not everyone's logging setup will show the spans so keeping it is the safest choice.

• Partial fix for Potentially switch from log to tracing #2177.
• This has been discussed also in How do you generate OpenTelemetry traces for your queries? #2333

[syphar]

I also was starting to play around with something like this, but this breaks you try to use it because EnteredSpan is not Send.

I'm not that deep in async specifics yet, the alternative would be to try to instrument the future itself, which would be only tricky depending if you want to include both executing the query & fetching the results in the time.

[miikka]

I also was starting to play around with something like this, but this breaks you try to use it because EnteredSpan is not Send.

Hmm, how does it break? I tried to use my code and it seemed to work and produce reasonable-looking spans but admittedly it was a pretty simple setup.

[syphar]

Interesting 😄

I'll recheck with your PR

[syphar]

Yep, happens with your code too (I can't rule out I made a mistake somehow):

Error is:

error: future cannot be sent between threads safely
   --> /Users/syphar/src/sqlx/sqlx-postgres/src/connection/executor.rs:274:12
    |
274 |           Ok(try_stream! {
    |  ____________^
275 | |             loop {
276 | |                 let message = self.stream.recv().await?;
277 | |
...   |
355 | |             Ok(())
356 | |         })
    | |_________^ future created by async block is not `Send`
    |
    = help: within `{async block@/Users/syphar/src/sqlx/sqlx-core/src/ext/async_stream.rs:124:70: 136:10}`, the trait `std::marker::Send` is not implemented for `*mut ()`, which is required by `{async block@/Users/syphar/src/sqlx/sqlx-core/src/ext/async_stream.rs:124:70: 136:10}: std::marker::Send`
note: captured value is not `Send`
   --> /Users/syphar/src/sqlx/sqlx-postgres/src/connection/executor.rs:298:25
    |
298 |                         logger.increase_rows_affected(rows_affected);
    |                         ^^^^^^ has type `QueryLogger<'_>` which is not `Send`
note: required by a bound in `TryAsyncStream::<'a, T>::new`
   --> /Users/syphar/src/sqlx/sqlx-core/src/ext/async_stream.rs:28:56
    |
25  |     pub fn new<F, Fut>(f: F) -> Self
    |            --- required by a bound in this associated function
...
28  |         Fut: 'a + Future<Output = Result<(), Error>> + Send,
    |                                                        ^^^^ required by this bound in `TryAsyncStream::<'a, T>::new`
    = note: this error originates in the macro `try_stream` (in Nightly builds, run with -Z macro-backtrace for more info)

error: could not compile `sqlx-postgres` (lib) due to 1 previous error
warning: build failed, waiting for other jobs to finish...

test code is just the sqlx example:

use sqlx::postgres::PgPoolOptions;

#[tokio::main]
async fn main() -> anyhow::Result<()> {
    let pool = PgPoolOptions::new()
        .max_connections(5)
        .connect("postgres://localhost/test")
        .await?;

    let row: (i64,) = sqlx::query_as("SELECT $1")
        .bind(150_i64)
        .fetch_one(&pool)
        .await?;

    assert_eq!(row.0, 150);

    Ok(())
}

[syphar]

( using sqlx as a path dependency)

[miikka]

I see - I had only tried this with the SQLite driver which does not use TryAsyncStream, but the Postgres driver does. Tricky! I'm pretty new to Rust, so I'm not sure what are the options here. Can QueryLogger be made work, or does the instrumenting need to happen somewhere else?