sqlx::query tracing event - avoid string parsing for subscribers

[Matthias247]

I built a custom tracing Layer which intercepts sqlx::query events in order to gather some query performance statistics across Spans.

It's great that this event exists due to #2185 and the data is super useful, so thanks for that!

However while the layer, I noticed that due to all the integer fields and the elapsed timestamp being emitted as Debug data, it causes some unnecessary parsing work on the subscriber which could potentially be avoided.

For reference: Here's the code that I use to read the submitted data back into my Layer:

#[derive(Debug, Clone, Default)]
struct SqlxQueryDataExtractor {
    summary: String,
    db_statement: String,
    rows_affected: usize,
    rows_returned: usize,
    elapsed: std::time::Duration,
}

impl field::Visit for SqlxQueryDataExtractor {
    fn record_bool(&mut self, _field: &field::Field, _value: bool) {}

    fn record_f64(&mut self, _field: &field::Field, _value: f64) {}

    fn record_i64(&mut self, _field: &field::Field, _value: i64) {}

    fn record_str(&mut self, field: &field::Field, value: &str) {
        match field.name() {
            "summary" => self.summary = value.to_string(),
            "db.statement" => self.db_statement = value.to_string(),
            _ => {}
        }
    }

    fn record_debug(&mut self, field: &field::Field, value: &dyn std::fmt::Debug) {
        match field.name() {
            "elapsed" => {
                let mut elapsed_str = format!("{:?}", value);
                if elapsed_str.ends_with("ns") {
                    elapsed_str.truncate(elapsed_str.len() - 2);
                    self.elapsed = std::time::Duration::from_nanos(
                        elapsed_str.parse::<f64>().unwrap_or_default() as u64,
                    );
                } else if elapsed_str.ends_with("µs") {
                    elapsed_str.truncate(elapsed_str.len() - "µs".len());
                    self.elapsed = std::time::Duration::from_micros(
                        elapsed_str.parse::<f64>().unwrap_or_default() as u64,
                    );
                } else if elapsed_str.ends_with("ms") {
                    elapsed_str.truncate(elapsed_str.len() - 2);
                    self.elapsed = std::time::Duration::from_millis(
                        elapsed_str.parse::<f64>().unwrap_or_default() as u64,
                    );
                } else if elapsed_str.ends_with('s') {
                    elapsed_str.truncate(elapsed_str.len() - 1);
                    self.elapsed = std::time::Duration::from_secs_f64(
                        elapsed_str.parse::<f64>().unwrap_or_default(),
                    );
                } else {
                    panic!("Unhandled time unit");
                }
            }
            "rows_affected" => {
                self.rows_affected = format!("{:?}", value).parse::<usize>().unwrap_or_default()
            }
            "rows_returned" => {
                self.rows_returned = format!("{:?}", value).parse::<usize>().unwrap_or_default()
            }
            _ => {}
        }
    }

    fn record_error(&mut self, _field: &field::Field, _value: &(dyn std::error::Error + 'static)) {}
}

impl<S> Layer<S> for SqlxQueryTracingLayer<S>
where
    S: Subscriber + for<'span> LookupSpan<'span>,
{
    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
        if event.metadata().target() != "sqlx::query" {
            return;
        }

        // intercept and parse data:
        let mut query_data = SqlxQueryDataExtractor::default();
        event.record(&mut query_data);

       println!("query_data: {:?}", query_data);
       // ... Use the event data for application purposes
    }
}

As seen, the elapsed, rows_affected and rows_returned fields are all emitted as dyn Debug - which means a consumer can only handle them by printing those fields and parsing them again. tracing unfortunately neither supports u64 nor time::Duration, so switching to those is not an Option.

A change would make the data cheaper to consume it moving towards i64 for the rows_ field and eg. something along elapsed_us which logs a plain i64 number for the elapsed time.

Changing the format for an existing field would however be a backward incompatible change. So either new fields would need to be added in addition to the existing ones or such a change could be performed with a new major version.

Since parsing a Duration in a fairly undefined string format is probably the biggest pain point right now, the biggest improvement would be to add elapsed_us in addition to elapsed. The changes to rows_ fields seem like something that could be done on the next major version change.

[abonander]

Since the logging format is not documented, I would not personally consider a change to it to be breaking. That's an implementation detail meant purely for informational and debugging purposes.

I'd be interested in discussing a stable log format, perhaps to a specific target, or another way to get this information out programmatically without having to parse log records.