Spans in loops producing strange flame charts.

[Devlyn-Nelson]

I am converting our logging helper library for work to use tracing instead of log and puffin. I am having unexpected/undesirable behavior with tracing::spans and tracing_flame::FlameLayer while using tokio::sync::mpsc::{Sender, Receiver} in a loop within a dedicated background task.

I didn't know if this is expected or not so i thought maybe someone could help me fix my problem or tell me it is an issue.

Unfortunately I can't share the code for my work, but i was able to make a reproducible example which suffers the same problem.

Program Summery

• 3 tasks: main/producer, processing, and consumer,
• Main/producer sends work to processing.
• Processing receives work, does the work, then sends result(s) to consumer, multiple results can come from 1 request.
• Consumer receives results and does stuff with it.

Expectations

Flame chart showing duration of each iteration of the processing loop.

What happens (or at least what i think is happening)

Iterations get stacked on top of each other, each iteration being within the previous iteration. This causes analytic programs to say crazy things like the processing thread was running longer than the program was running.

Code

Produces undesirable results. Replacing let _ = tx.send(a).await; with info!("{a}"); produces a flame chart that i would expect.

//! this example produces strange flame charts due to the sending and receiving in a loop.
//! to produce results closer to what i would expect: replace `let _ = tx.send(a).await;` with `info!("{a}");`,
//! which is the last line in program that is not just a single `}`
use std::time::Duration;
use tokio::sync::mpsc::{Receiver, Sender, channel};
use tracing::info;
use tracing_flame::FlameLayer;
use tracing_subscriber::{prelude::__tracing_subscriber_SubscriberExt, util::SubscriberInitExt};

#[tokio::main]
async fn main() {
    // Setup logging (we have this in a builder in our code, but this is essentially what we do for setup)
    let reg = tracing_subscriber::registry();
    let stdout_log = tracing_subscriber::fmt::layer();
    let reg = reg.with(stdout_log);
    let (flame_file_layer, _flame_guard) = match FlameLayer::with_file("test.flame") {
        Ok((flame, guard)) => {
            (Some(flame),
            Some(guard))
        }
        Err(_err) => {
            (None, None)
        }
    };
    let reg = reg.with(flame_file_layer);
    reg.init();
    // Requesting channel
    let (thing_tx, thing_rx) = channel(3);
    // Consumer channel
    let (eater_tx, eater_rx) = channel(3);
    // processing thread
    let task = tokio::task::spawn(thing(thing_rx, eater_tx));
    // consumer thread
    let _eater = tokio::task::spawn(thing_eater(eater_rx));
    // send some "requests"
    for _ in 0..10 {
        let _ = thing_tx.send(69).await;
    }
    // drop sender so processing thread exits after all requests (just for example).
    std::mem::drop(thing_tx);
    // wait for processing thread to finish. (simplified from work project)
    loop {
        tokio::time::sleep(Duration::from_secs(1)).await;
        if task.is_finished() {
            let _ = task.await;
            break;
        }
    }
}

/// Consumes results from thing thread
async fn thing_eater(mut rx: Receiver<usize>) {
    while let Some(r) = rx.recv().await {
        info!("{r}");
    }
}

/// Processes requests and sends out results (can have multiple results per request)
async fn thing(mut rx: Receiver<usize>, tx: Sender<usize>) {
    info!("thing-enter");
    while let Some(a) = rx.recv().await {
        let span = tracing::span!(logging::tracing::Level::INFO, "test_span");
        let _guard = span.enter();
        let mut i = 10;
        while i != 0 {
            // this while loop is simulating multiple results coming from 1 request, kinda.
            let span = tracing::span!(logging::tracing::Level::INFO, "test_span-inner");
            let _guard = span.enter();
            i -= 1;
            let _ = tx.send(a).await;
        }
    }
}

[dependencies]
tracing = "0.1"
tracing-appender = "0.2"
tracing-subscriber = "0.3"
tracing-flame = "0.2"
tokio = { version = "1", features = ["full"] }

[hawkw]

It looks like you are holding an Entered guard across an await point. This results in incorrect traces; the span should only be entered while it's being actively polled. See this documentation for details on what I think is the problem here.

[Devlyn-Nelson]

Thank you. This limitation is kind of a bummer considering puffins does work across awaits in a tokio environment. Is the best way to counter this by closing and opening new spans when awaits are done?

[davidbarsky]

@Devlyn-Nelson No, the preferable approach would be to make use of the #[instrument] macro or the .instrument() combinator.

[Devlyn-Nelson]

instrument works great, thanks again.