From b6338b5e4a9468bb39352da47b5e7573399e04aa Mon Sep 17 00:00:00 2001 From: konsti Date: Mon, 8 Jan 2024 16:20:38 +0100 Subject: [PATCH] Use tracing-durations-export to visualize parallelism bottlenecks (dev commands) (#816) Example usage: ``` # Cached TRACING_DURATIONS_FILE=target/traces/black.ndjson RUST_LOG=puffin=info cargo run --bin puffin-dev --profile profiling -- resolve black TRACING_DURATIONS_FILE=target/traces/meine_stadt_transparent.ndjson RUST_LOG=puffin=info cargo run --bin puffin-dev --profile profiling -- resolve meine_stadt_transparent TRACING_DURATIONS_FILE=target/traces/jupyter.ndjson RUST_LOG=puffin=info cargo run --bin puffin-dev --profile profiling -- resolve jupyter # No cache TRACING_DURATIONS_FILE=target/traces/black-no-cache.ndjson RUST_LOG=puffin=info cargo run --bin puffin-dev --profile profiling -- resolve --no-cache black TRACING_DURATIONS_FILE=target/traces/meine_stadt_transparent-no-cache.ndjson RUST_LOG=puffin=info cargo run --bin puffin-dev --profile profiling -- resolve --no-cache meine_stadt_transparent TRACING_DURATIONS_FILE=target/traces/jupyter-no-cache.ndjson RUST_LOG=puffin=info cargo run --bin puffin-dev --profile profiling -- resolve --no-cache jupyter ``` Uncached black output example: ![black-no-cache](https://github.com/astral-sh/puffin/assets/6826232/38497b89-7214-453b-9456-c9d9cbf7d2d5) --- Cargo.lock | 34 ++++++++++++++++++++++++++++---- crates/puffin-dev/Cargo.toml | 3 ++- crates/puffin-dev/src/main.rs | 37 +++++++++++++++++++++++++++++++++-- 3 files changed, 67 insertions(+), 7 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 875690f2a..b03506e7a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2359,6 +2359,7 @@ dependencies = [ "tokio", "toml", "tracing", + "tracing-durations-export", "tracing-subscriber", "tracing-tree", "url", @@ -2444,6 +2445,7 @@ dependencies = [ "tikv-jemallocator", "tokio", "tracing", + "tracing-durations-export", "tracing-indicatif", "tracing-subscriber", "url", @@ -3271,18 +3273,18 @@ checksum = "1c107b6f4780854c8b126e228ea8869f4d7b71260f962fefb57b996b8959ba6b" [[package]] name = "serde" -version = "1.0.194" +version = "1.0.195" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0b114498256798c94a0689e1a15fec6005dee8ac1f41de56404b67afc2a4b773" +checksum = "63261df402c67811e9ac6def069e4786148c4563f4b50fd4bf30aa370d626b02" dependencies = [ "serde_derive", ] [[package]] name = "serde_derive" -version = "1.0.194" +version = "1.0.195" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a3385e45322e8f9931410f01b3031ec534c3947d0e94c18049af4d9f9907d4e0" +checksum = "46fe8f8603d81ba86327b23a2e9cdf49e1255fb94a4c5f297f6ee0547178ea2c" dependencies = [ "proc-macro2", "quote", @@ -3446,6 +3448,12 @@ dependencies = [ "is-terminal", ] +[[package]] +name = "svg" +version = "0.14.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0d703a3635418d4e4d0e410009ddbfb65047ef9468b1d29afd3b057a5bc4c217" + [[package]] name = "syn" version = "1.0.109" @@ -3855,6 +3863,24 @@ dependencies = [ "valuable", ] +[[package]] +name = "tracing-durations-export" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1d6bb8898f56f636911130c78cc528338a2bb0426bdfb5a8fb523f98fc8da46d" +dependencies = [ + "anyhow", + "fs-err", + "itertools 0.12.0", + "once_cell", + "rustc-hash", + "serde", + "serde_json", + "svg", + "tracing", + "tracing-subscriber", +] + [[package]] name = "tracing-indicatif" version = "0.3.6" diff --git a/crates/puffin-dev/Cargo.toml b/crates/puffin-dev/Cargo.toml index f016533e0..8b3b7f2ee 100644 --- a/crates/puffin-dev/Cargo.toml +++ b/crates/puffin-dev/Cargo.toml @@ -38,7 +38,7 @@ anstream = { workspace = true } anyhow = { workspace = true } chrono = { workspace = true } clap = { workspace = true, features = ["derive"] } -fs-err = { workspace = true } +fs-err = { workspace = true, features = ["tokio"] } futures = { workspace = true } indicatif = { workspace = true } itertools = { workspace = true } @@ -48,6 +48,7 @@ rustc-hash = { workspace = true } tempfile = { workspace = true } tokio = { workspace = true } tracing = { workspace = true } +tracing-durations-export = { version = "0.1.0", features = ["plot"] } tracing-indicatif = { workspace = true } tracing-subscriber = { workspace = true } url = { workspace = true } diff --git a/crates/puffin-dev/src/main.rs b/crates/puffin-dev/src/main.rs index c32c9e052..42dad6478 100644 --- a/crates/puffin-dev/src/main.rs +++ b/crates/puffin-dev/src/main.rs @@ -1,19 +1,23 @@ #![allow(clippy::print_stdout, clippy::print_stderr)] +use std::env; use std::io::IsTerminal; +use std::path::PathBuf; use std::process::ExitCode; -use std::time::Instant; +use std::time::{Duration, Instant}; use anstream::eprintln; use anyhow::Result; use clap::Parser; -use owo_colors::OwoColorize; use tracing::debug; +use tracing_durations_export::plot::PlotConfig; +use tracing_durations_export::DurationsLayerBuilder; use tracing_indicatif::IndicatifLayer; use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::util::SubscriberInitExt; use tracing_subscriber::EnvFilter; +use owo_colors::OwoColorize; use resolve_many::ResolveManyArgs; use crate::build::{build, BuildArgs}; @@ -87,6 +91,34 @@ async fn run() -> Result<()> { #[tokio::main] async fn main() -> ExitCode { + let (duration_layer, _guard) = if let Ok(location) = env::var("TRACING_DURATIONS_FILE") { + let location = PathBuf::from(location); + if let Some(parent) = location.parent() { + fs_err::tokio::create_dir_all(&parent) + .await + .expect("Failed to create parent of TRACING_DURATIONS_FILE"); + } + let plot_config = PlotConfig { + multi_lane: true, + min_length: Some(Duration::from_secs_f32(0.002)), + remove: Some( + ["get_cached_with_callback".to_string()] + .into_iter() + .collect(), + ), + ..PlotConfig::default() + }; + let (layer, guard) = DurationsLayerBuilder::default() + .durations_file(&location) + .plot_file(location.with_extension("svg")) + .plot_config(plot_config) + .build() + .expect("Couldn't create TRACING_DURATIONS_FILE files"); + (Some(layer), Some(guard)) + } else { + (None, None) + }; + let indicatif_layer = IndicatifLayer::new(); let indicatif_compatible_writer_layer = tracing_subscriber::fmt::layer() .with_writer(indicatif_layer.get_stderr_writer()) @@ -99,6 +131,7 @@ async fn main() -> ExitCode { .unwrap() }); tracing_subscriber::registry() + .with(duration_layer) .with(filter_layer) .with(indicatif_compatible_writer_layer) .with(indicatif_layer)