Formatting performance

[JakubValtar]

Hi,

I noticed that formatting the message with format! before logging is much faster than letting the logger do it. I would expect the performance to be similar or the logger to be slightly faster. Is this an expected behavior?

info!("{}", s);                // 1700-2600us
info!("{}", format!("{}", s)); // 200-700us

Here is a simple test program:

[dependencies]
log = "0.4.6"
flexi_logger = "0.11.1"

use std::fmt;
use std::time::Instant;

struct Struct {
    data: [u8; 32],
}

impl fmt::Display for Struct {
    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
        write!(f, "{:?}", self.data)
    }
}

fn main() {
    let _log_handle = flexi_logger::Logger::with_str("info")
        .start()
        .unwrap();

    let mut structs = Vec::new();
    for i in 0..10 {
        structs.push(Struct { data: [i as u8; 32] });
    }

    {   // With format
        let start = Instant::now();
        for s in &structs {
            log::info!("{}", format!("{}", s));
        }
        eprintln!("with format: {:?}", start.elapsed()); // 2-7ms
    }

    {   // Plain logger
        let start = Instant::now();
        for s in &structs {
            log::info!("{}", s);
        }
        eprintln!("plain: {:?}", start.elapsed()); // 17-26ms
    }
}

The length of the message does not matter that much, it's more about how many segments the Display implementation writes. Is there maybe some buffering problem?

I can reproduce on Windows 10 with PowerShell and on Ubuntu Server.

[emabee]

Env_logger in fact uses meanwhile thread-local buffers, which might be the reason for the observed performance difference. I'll try some things out. Thanks for reporting!

[JakubValtar]

Thanks! Definitely not high priority, format! can be used as a workaround.

It seems that the performance is related to the number of values which are being printed out by write!, including nested calls when your struct has struct fields which also need to be printed out.

[emabee]

Hi Jakub, I just published version 0.13.0 which fixes this issue!