Watching Rust Run

Published Saturday, July 27, 2024

#essay

Measuring and analyzing the behavior of our software is critical to enhancing its performance. After all, measure twice, optimize once. With Rust code that you own¹, has been made very straightforward by the Rust ecosystem. The tracing crate provides a robust API for instrumenting your Rust code for the observation of executed code paths. It's supported by a broad ecosystem consisting of subscribers that can emit trace information using hooks produced by tracing and consumers that can be used to visualize trace information.

My Usual Toolset

In this post, I'll focus on my favorite instrumentation setup for my own Rust projects: using Perfetto and stderr tracing layers.

This doesn't require many direct dependencies: only tracing, tracing-subscriber, and tracing-perfetto will be added to your Cargo.toml.

[dependencies]
tracing = "0.1.40"
tracing-subscriber = "0.3.18"
tracing-perfetto = "0.1.1"

Show Me the Stuff

Code

use tracing::{trace, warn};
use tracing_perfetto::PerfettoLayer;
use tracing_subscriber::{
    fmt::{self, format::Format},
    prelude::*,
};

#[tracing::instrument(fields(perfetto = true))]
fn pre_print() {
    trace!("About to print");
}

#[tracing::instrument(fields(perfetto = true))]
fn print() {
    trace!("Printing");
    println!("Hello, world!");
}

#[tracing::instrument(fields(perfetto = true))]
fn post_print() {
    trace!("Done printing");
}

#[tracing::instrument]
fn main() {
    let perfetto = PerfettoLayer::new(std::sync::Mutex::new(
        std::fs::File::create("test.pftrace").unwrap(),
    ))
    // See our trace!(), info!(), debug!(), warn!(), error!() events in the Perfetto timeline
    .with_debug_annotations(true)
    // See all events in the timeline regardless of markers
    .with_filter_by_marker(|_| true);

    let stderr = fmt::layer()
        .with_writer(std::io::stderr)
        .event_format(
            Format::default()
                .compact()
                .with_target(false)
                .with_source_location(true)
                // https://no-color.org/
                .with_ansi(std::env::var("NO_COLOR").unwrap_or(String::from("0")) != "1"),
        )
        .with_span_events(fmt::format::FmtSpan::ACTIVE);

    tracing_subscriber::registry()
        .with(perfetto)
        .with(stderr)
        .init();

    pre_print();
    print();
    post_print();

    trace!("Exitting");
}

Stderr Output

Why stderr? Remember that stderr is used for diagnostics, and stdout is used for application output. Notice that we can see which functions are being entered and exited and when.

2024-07-29T14:53:32.747022Z  INFO pre_print: src/main.rs:8: enter perfetto=true
2024-07-29T14:53:32.747302Z TRACE pre_print: src/main.rs:10: About to print perfetto=true
2024-07-29T14:53:32.747333Z  INFO pre_print: src/main.rs:8: exit perfetto=true
2024-07-29T14:53:32.749498Z  INFO print: src/main.rs:13: enter perfetto=true
2024-07-29T14:53:32.749542Z TRACE print: src/main.rs:15: Printing perfetto=true
Hello, world!
2024-07-29T14:53:32.749570Z  INFO print: src/main.rs:13: exit perfetto=true
2024-07-29T14:53:32.749688Z  INFO post_print: src/main.rs:19: enter perfetto=true
2024-07-29T14:53:32.749721Z TRACE post_print: src/main.rs:21: Done printing perfetto=true
2024-07-29T14:53:32.749744Z  INFO post_print: src/main.rs:19: exit perfetto=true
2024-07-29T14:53:32.749871Z TRACE src/main.rs:52: Exitting

Perfetto Visualization

Your test.pftrace file can be uploaded to ui.perfetto.dev for analysis. I prefer this view for larger scale projects, where the call stack can be extremely deep, and many tens or hundreds of events can be firing.

Caveats

A limitation of this approach is that you can only reliably instrument code that you can modify. For third party crates that don't have feature flags enabling tracing, you're out of luck. In addition, Rust's tracing solutions aren't useful across FFI boundaries. If you're working with static or shared libraries written in or for other languages, you won't have visibility beyond the software interface.

Moreover, I use this approach exclusively for local tracing. Tracing remote programs may require networked tracing solutions such as the OpenTelemetry stack.

Conclusion

This is a straightforward approach to profiling your Rust projects. It also serves as a customizable starter template for your own custom setups. You can swap the Perfetto layer with an OpenTelemetry layer, or the stderr layer with a stdout or file output layer. Ultimately, this is a nice first step for optimizing the performance of your projects. All power to you.