performance degradation while using tracing_subscriber::registry with layers

[AviRaboah]

Hi guys,

In the early stages of my project, I utilized the tracing library to funnel the flow of my code into a singular file. For this purpose, I employed the tracing_subscriber::fmt while initializing the subscriber. Thankfully, during this process, I did not observe any notable impact on the performance of my code.

However, performance issues began to surface when I had to log specific events into another file. To achieve this, I employed layers for each log and used some EnvFilter for the new log file. Subsequently, I also had to alter the way I initialized the subscriber, switching from tracing_subscriber::fmt to tracing_subscriber::registry.

The changes seem to have induced a significant effect on performance. Could anyone shed light on why such a transformation would have such a substantial impact in terms of performance?

thanks,

Avi.

[davidbarsky]

Sorry for the delay. There shouldn't be a noticeable (or at the very least, large) decrease in performance in changing between tracing_subscriber::fmt and tracing_subscriber::registry as tracing_subscriber::fmt is powered by tracing_subscriber::registry. Are you using tracing-appender to log to a file, by any chance?

[AviRaboah]

hi,
yes I am using tracing_appender::rolling::hourly and then pass it to tracing_appender::non_blocking.
is it a bad practice to use a the tracing_appender in order to log to a file?

[AviRaboah]

@davidbarsky could you help what can be done in order to fix the degradation?

[davidbarsky]

@AviRaboah I'm sorry, I'm on a four-day weekend. I'd recommend trying just tracing_appender::rolling::hourly and letting me know what performance you're observing. Can you also share the code where you are setting up tracing?

[AviRaboah]

Hi, please see the code below,

pub fn init_logging() -> Vec<WorkerGuard> 
{
    
    let logs_dir = std::env::var("LOGS_DIR").unwrap_or("logs".to_string());
    let mut guards = Vec::new();

    let current_exe = std::env::current_exe().unwrap();
    let binary_name = current_exe.file_name().unwrap();

    // Define file handlers and guards
    let file_appender = tracing_appender::rolling::hourly(&logs_dir, binary_name);
    let (non_blocking_file, logfile_guard) = tracing_appender::non_blocking(file_appender);

    let file_appender_2 = tracing_appender::rolling::hourly(&logs_dir, "log_file_2.log");
    let (non_blocking_file_2, file_2_guard) = tracing_appender::non_blocking(file_appender_2);
    let (non_blocking_stdout, std_out_guard) = tracing_appender::non_blocking(std::io::stdout());

    guards.push(logfile_guard);
    guards.push(std_out_guard);
    guards.push(file_2_guard);

    // setting level
    let log_level = std::env::var("LOG_LEVEL").unwrap_or("DEBUG".to_string());
    let log_level = Level::from_str(&log_level).unwrap();

    // Construct a writer that outputs events to `stdout` *and* `rolling fild`
    let combined_writer = non_blocking_file.and(non_blocking_stdout);

    // Define layers
    let combined_layer = fmt::Layer::new().with_writer(combined_writer.with_max_level(log_level));
    let query_rules_layer = fmt::Layer::new().with_writer(non_blocking_file_2.with_max_level(log_level));

    let subscriber = tracing_subscriber::registry()
        .with(combined_layer)
        .with(query_rules_layer.with_filter(EnvFilter::new("span1")));

    tracing::subscriber::set_global_default(subscriber)
        .expect("setting default subscriber failed");

    info!("Logging initialized, level={}", log_level.as_str());
    guards
}

[AviRaboah]

@davidbarsky any idea?

[davidbarsky]

@AviRaboah (I've edited your comment to add Rust syntax highlighting.)

There are a few things that you can try. In no particular order:

• You create a non_blocking_stdout by wrapping std::io::stdout() in tracing_appender::non_blocking. Don't do that, writing to stdout is basically free.
• I'm curious if combining the filters you have (a .with_max_level(log_level), EnvFilter::new("span1") into a single filter_fn is possible for you. If there's a bug in tracing_subscriber's filtering functionality, this might help a bit.
• Since I don't have your code in question and can't benchmark it, I'm very curious as to what omitting tracing_appender::non_blocking from all callsites (e.g., not just std::io::stdout, but also, the different file_appenders) and passing the resulting file appender directly into [.with_writer] would result in. This is probably not great if you have any async code, but I'm curious of the results nonetheless.

Additionally, when you said:

for the same flow I check, something like ~500ms.

Is this 500ms per event or...? In other words, what is the unit here?