Clarify whether logging to standard output is blocking

[ufoscout]

I cannot find in the documentation a clear statement about the eventual blocking nature of logging to the standard output.
Could you please help me understand if in the following example there is blocking code in an async function?

use tracing::{Level};
use tracing_subscriber;

#[tokio::main]
async fn main() {
    let subscriber = tracing_subscriber::FmtSubscriber::builder()
        .with_max_level(Level::TRACE)
        .init();

    // IS THIS A BLOCKING CALL?
    tracing::info!("Am'I a blocking call?");

    // IS THIS A BLOCKING CALL?
    log::info!("What about me?!");
}

[hawkw]

Hi @ufoscout, thanks for the question! In both tracing and log, whether or not logging to standard out is blocking depends on the Subscriber/Logger implementation in use, so there isn't one simple answer.

In the example you posted, tracing_subscriber's FmtSubscriber does default to blocking IO. However, we use some techniques to try and reduce the time spent blocking. Primarily, this is done by formatting each line to a thread-local buffer, and then writing the line to stdout once it has been formatted, in one write call. This helps avoid issuing multiple blocking write calls as parts of the line are formatted, and keeps the critical section during which the lock on stdout is held as short as possible. This is the same strategy that env_logger uses, so if you were using env_logger, the log::info! call would have basically the exact same behavior.

Even though it makes blocking calls, the performance impact of this approach shouldn't be too significant, even in asynchronous code. Issues with blocking in async programs generally arise when a thread is blocked for a relatively long period of time,and short blocking operations are generally fine. We chose this as the default behavior because non-blocking logging would introduce additional complexity — a dedicated logging thread or async task would need to be spawned, and users would need to ensure that logs are flushed when the program exits. Non-blocking logging is theoretically superior, but the difference is probably only meaningful in particularly performance-sensitive code. And, a naive implementation where Strings are sent over tokio::sync or std::sync channels introduces other overhead in the form of allocating and deallocating both the strings themselves and the nodes in the linked lists used by channels.

Since the writer used to output formatted logs can be overridden by the user, though, it's definitely possible to supply one that's non-blocking. We don't currently provide a ready-made non-blocking writer, but adding an implementation is on my todo list. It isn't done yet mainly because I want to ensure we do it right and avoid the allocator pressure I mentioned previously.

Hope that answers your questions?

[ufoscout]

@hawkw
thanks for the clear and informative answer.
would you maybe add this information to the documentation?

[hawkw]

@ufoscout will do! And, if you like, I can ping you when the dedicated logging thread/task stuff is ready.

[ufoscout]

@hawkw
I owe you a beer! Thanks!

[hawkw]

@ufoscout I thought you might appreciate seeing that we just got a PR, #673, to add a non-blocking writer that uses a dedicated thread. Hopefully after a bit of polish, it should be ready to merge soon!

[hawkw]

Another update: thanks to @zekisherif, we've just merged #673, with an initial version of a tracing-appender crate. This crate contains a non_blocking writer that logs using a dedicated worker thread (as well as an implementation of a rolling log file). This can be used with standard out or another type implementing Write.

It still needs additional documentation & polish before it's ready to release, but if you're interested you can start trying it out now!

[rdettai]

Hi! I would like to revive this issue because I was just bitten very very hard by the blocking calls. When setting up tracing, it didn't even occur to me that there might be an issue with blocking calls. A few months later, when my logging output hit the stderr pipe buffer, my entire code just started hanging in random places (actually, not that random, my logging points 😅).

It is very important to avoid new users to fall into the same frustrating trap. I suggest a disclaimer in the tracing_subscriber::fmt docs that warns users about this and points users to tracing-appender.

But I'm not sure that would be sufficient. You usually integrate your logging at the very beginning of a project, and the blocking might kick in months later. Is there really no way to warn users when it occurs?