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)
This commit is contained in:
konsti 2024-01-08 16:20:38 +01:00 committed by GitHub
parent 243392f718
commit b6338b5e4a
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 67 additions and 7 deletions

34
Cargo.lock generated
View File

@ -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"

View File

@ -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 }

View File

@ -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)