Tracing std::io::err performance

[dmolokanov]

Question

Version

tracing v0.1.15

Platform

Linux 5.4.0-40-generic #44-Ubuntu SMP Tue Jun 23 00:01:04 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

Crates

Description

During a performance investigation, I noticed that env_logger almost twice faster than tracing. When running following code:

fn main() {
    let mut histogram = Vec::new();

    #[cfg(feature = "_env_logger")]
    init_logger();

    #[cfg(feature = "_tracing")]
    init_tracing();

    for _ in 0..10 {
        histogram.push(run());
    }

    println!("{:?}", histogram);
}

#[cfg(feature = "_env_logger")]
use log::*;

#[cfg(feature = "_env_logger")]
fn init_logger() {
    env_logger::builder()
        .filter(None, log::LevelFilter::Debug)
        .init();
}

#[cfg(feature = "_tracing")]
use tracing::*;

#[cfg(feature = "_tracing")]
pub fn init_tracing() {
    let subscriber = tracing_subscriber::fmt::Subscriber::builder()
        .with_max_level(tracing::Level::DEBUG)
        .with_writer(std::io::stderr)
        .finish();
    let _ = tracing::subscriber::set_global_default(subscriber);
}

pub fn run() -> std::time::Duration {
    let now = std::time::Instant::now();
    foo();
    now.elapsed()
}

fn foo() {
    info!("start");
    let mut sum: usize = 0;
    for i in 1..10000 {
        sum += i * i;
        info!("{}", sum);
    }
    info!("end");
}

I get these results

> cargo run --features="_env_logger" 2> env_logger.log
[92.721706ms, 79.050765ms, 79.023794ms, 78.711705ms, 78.609609ms, 78.786813ms, 79.318841ms, 79.037189ms, 79.048981ms, 79.082023ms]

> cargo run --features="_tracing" 2> tracing.log   
[212.847395ms, 217.956667ms, 221.897184ms, 222.149296ms, 211.947051ms, 201.19702ms, 201.460157ms, 207.29997ms, 221.83216ms, 221.585358ms]

Do you have any guidance to improve performance? Maybe some configuration/flag that can help?

[KodrAus]

Hey @dmolokanov 👋

Are you calling cargo run with --release?

If you still see similar differences with --release it could be that std::io::stderr isn't buffered, but env_logger does buffer writes to the output stream.

To rule that out you can try replace your std::io::stderr writer with a dummy Write that just discards its input. If it is buffering then you can try wrapping your std::io::stderr in a BufWriter (don't forget to call flush!)

[hawkw]

There should also be some performance improvements for filtering coming up in the next tracing/tracing-core release.

[dmolokanov]

@KodrAus --release flag helped indeed, thanks! but env_logger still a bit faster.

> cargo run --release --features="_env_logger" 2> logger.log    
[21.794854ms, 20.786304ms, 20.755551ms, 20.710926ms, 20.604818ms, 20.568095ms, 20.485771ms, 20.522497ms, 20.612611ms, 20.576678ms]

> cargo run --release --features="_tracing" 2> tracing.log   
[30.624495ms, 30.037613ms, 29.903471ms, 29.682317ms, 29.544971ms, 29.452051ms, 29.516603ms, 29.393053ms, 29.233241ms, 29.429358ms]

@hawkw Do you have any (rough?) estimates when performance improvements will land?

[hawkw]

@hawkw Do you have any (rough?) estimates when performance improvements will land?

Hopefully today or tomorrow --- the branch is #853.

Although, after taking a closer look at your benchmark code, it looks like these changes probably won't effect this specific case, since there are no events below the DEBUG level that are being filtered out in your code.

I took a quick look at env_logger's implementation, and they don't use BufWriter either --- they use a similar implementation to ours, where the actual formatted output is written to a thread-local buffer that's reused for each write. Compare env_logger:
https://github.com/env-logger-rs/env_logger/blob/b8c3754a1de50ac720657d2f328ea98148e1d80d/src/lib.rs#L868-L924
and tracing_subscriber::fmt:

tracing/tracing-subscriber/src/fmt/fmt_layer.rs

Lines 686 to 711 in aa5c523

	thread_local! {
	static BUF: RefCell<String> = RefCell::new(String::new());
	}
	BUF.with(|buf| {
	let borrow = buf.try_borrow_mut();
	let mut a;
	let mut b;
	let mut buf = match borrow {
	Ok(buf) => {
	a = buf;
	&mut *a
	}
	_ => {
	b = String::new();
	&mut b
	}
	};
	let ctx = self.make_ctx(ctx);
	if self.fmt_event.format_event(&ctx, &mut buf, event).is_ok() {
	let mut writer = self.make_writer.make_writer();
	let _ = io::Write::write_all(&mut writer, buf.as_bytes());
	}
	buf.clear();

My guess is that the performance difference in this case is either due to tracing_subscriber's formatting code being more complex (we could probably optimize this a bit; there are a lot of function calls and they may not all be inlined?), or because tracing requires an additional thread-local storage hit to check if there is a scoped dispatcher. A potentially worthwhile optimization is having a flag indicating whether scoped thread local dispatchers are in use, and skipping the TLS hit if it's unset...