Skip to content

Improve tracing in bootstrap #145261

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 18 commits into from
Aug 15, 2025
Merged

Improve tracing in bootstrap #145261

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
18 commits
Select commit Hold shift + click to select a range
e6dddcb
Store bootstrap tracing outputs to a unified directory
Kobzol Aug 10, 2025
c97b606
Store `latest` symlink to the latest tracing output directory
Kobzol Aug 10, 2025
f819729
Store Chrome step trace into the tracing directory
Kobzol Aug 10, 2025
aad5795
Use shorter command span label
Kobzol Aug 10, 2025
3a115ba
Print step timings also when the stap starts to execute
Kobzol Aug 10, 2025
c846f7c
Replace `tracing_forest` with custom span formatting
Kobzol Aug 11, 2025
1e14229
Create a span for each executed step
Kobzol Aug 11, 2025
690c781
Remove ad-hoc print of executed/cached steps in verbose mode
Kobzol Aug 11, 2025
d403934
Remove manual `#[instrument]` annotations on steps
Kobzol Aug 11, 2025
604c180
Move tracing setup to the `tracing` module
Kobzol Aug 11, 2025
c3682b2
Correctly show executed command name in Chrome trace
Kobzol Aug 11, 2025
b4a357f
Always profile commands and generate Chrome profile when tracing is e…
Kobzol Aug 11, 2025
f9a4588
Do not create a span for cached commands
Kobzol Aug 11, 2025
12828f7
Create tracing directory symlink even during dry run
Kobzol Aug 11, 2025
3e77562
Use `pretty_step_name` in `step_graph`
Kobzol Aug 11, 2025
a0306bf
Update debugging/profiling bootstrap page
Kobzol Aug 11, 2025
6f584bc
Print created location of executed commands
Kobzol Aug 11, 2025
0b8c6ad
Remove one dependency from tracing bootstrap build
Kobzol Aug 12, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
68 changes: 25 additions & 43 deletions src/bootstrap/Cargo.lock
View file
Open in desktop
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Remark: I wonder if we should suppress the e.g.

Building stage0 tool lld-wrapper (x86_64-unknown-linux-gnu)

messages that interleave the tracing output, but this is fine

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think that the interleaving is a feature, not a bug - you can then figure out where were the messages actually printed, in relation to how were the steps executed. That being said, we currently print these logs to stdout, but the tracing is printed to stderr, so the interleaving can be a bit non-deterministic.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Right. That is fine.

Original file line number Diff line number Diff line change
Expand Up @@ -11,21 +11,18 @@ dependencies = [
"memchr",
]

[[package]]
name = "ansi_term"
version = "0.12.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2"
dependencies = [
"winapi",
]

[[package]]
name = "anstyle"
version = "1.0.10"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "55cc3b69f167a1ef2e161439aa98aed94e6028e5f9a59be9a6ffb47aef1651f9"

[[package]]
name = "autocfg"
version = "1.5.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c08606f8c3cbf4ce6ec8e28fb0014a2c086708fe954eaa885384a6165172e7e8"

[[package]]
name = "bitflags"
version = "2.6.0"
Expand All @@ -47,6 +44,7 @@ version = "0.0.0"
dependencies = [
"build_helper",
"cc",
"chrono",
"clap",
"clap_complete",
"cmake",
Expand All @@ -71,7 +69,6 @@ dependencies = [
"toml",
"tracing",
"tracing-chrome",
"tracing-forest",
"tracing-subscriber",
"walkdir",
"windows",
Expand Down Expand Up @@ -112,6 +109,15 @@ version = "1.0.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"

[[package]]
name = "chrono"
version = "0.4.41"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c469d952047f47f91b68d1cba3f10d63c11d73e4636f24f08daf0278abf01c4d"
dependencies = [
"num-traits",
]

[[package]]
name = "clap"
version = "4.5.20"
Expand Down Expand Up @@ -458,6 +464,15 @@ dependencies = [
"winapi",
]

[[package]]
name = "num-traits"
version = "0.2.19"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "071dfc062690e90b734c0b2273ce72ad0ffa95f0c74596bc250dcfd960262841"
dependencies = [
"autocfg",
]

[[package]]
name = "objc2-core-foundation"
version = "0.3.1"
Expand Down Expand Up @@ -775,26 +790,6 @@ dependencies = [
"winapi-util",
]

[[package]]
name = "thiserror"
version = "1.0.69"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "b6aaf5339b578ea85b50e080feb250a3e8ae8cfcdff9a461c9ec2904bc923f52"
dependencies = [
"thiserror-impl",
]

[[package]]
name = "thiserror-impl"
version = "1.0.69"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "4fee6c4efc90059e10f81e6d42c60a18f76588c3d74cb83a0b242a2b6c7504c1"
dependencies = [
"proc-macro2",
"quote",
"syn",
]

[[package]]
name = "thread_local"
version = "1.1.8"
Expand Down Expand Up @@ -857,19 +852,6 @@ dependencies = [
"valuable",
]

[[package]]
name = "tracing-forest"
version = "0.1.6"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ee40835db14ddd1e3ba414292272eddde9dad04d3d4b65509656414d1c42592f"
dependencies = [
"ansi_term",
"smallvec",
"thiserror",
"tracing",
"tracing-subscriber",
]

[[package]]
name = "tracing-log"
version = "0.2.0"
Expand Down
5 changes: 3 additions & 2 deletions src/bootstrap/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,7 @@ default-run = "bootstrap"

[features]
build-metrics = ["sysinfo"]
tracing = ["dep:tracing", "dep:tracing-chrome", "dep:tracing-subscriber", "dep:tracing-forest"]
tracing = ["dep:tracing", "dep:tracing-chrome", "dep:tracing-subscriber", "dep:chrono", "dep:tempfile"]

[lib]
path = "src/lib.rs"
Expand Down Expand Up @@ -61,10 +61,11 @@ xz2 = "0.1"
sysinfo = { version = "0.36.0", default-features = false, optional = true, features = ["system"] }

# Dependencies needed by the `tracing` feature
chrono = { version = "0.4", default-features = false, optional = true, features = ["now", "std"] }
tracing = { version = "0.1", optional = true, features = ["attributes"] }
tracing-chrome = { version = "0.7", optional = true }
tracing-subscriber = { version = "0.3", optional = true, features = ["env-filter", "fmt", "registry", "std"] }
tracing-forest = { version = "0.1.6", optional = true, default-features = false, features = ["smallvec", "ansi", "env-filter"] }
tempfile = { version = "3.15.0", optional = true }

[target.'cfg(windows)'.dependencies.junction]
version = "1.0.0"
Expand Down
86 changes: 40 additions & 46 deletions src/bootstrap/src/bin/main.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@

use std::fs::{self, OpenOptions};
use std::io::{self, BufRead, BufReader, IsTerminal, Write};
use std::path::Path;
use std::str::FromStr;
use std::time::Instant;
use std::{env, process};
Expand All @@ -15,19 +16,16 @@ use bootstrap::{
Build, CONFIG_CHANGE_HISTORY, ChangeId, Config, Flags, Subcommand, debug,
find_recent_config_change_ids, human_readable_changes, t,
};
#[cfg(feature = "tracing")]
use tracing::instrument;

fn is_bootstrap_profiling_enabled() -> bool {
env::var("BOOTSTRAP_PROFILE").is_ok_and(|v| v == "1")
fn is_tracing_enabled() -> bool {
cfg!(feature = "tracing")
}

#[cfg_attr(feature = "tracing", instrument(level = "trace", name = "main"))]
fn main() {
#[cfg(feature = "tracing")]
let _guard = setup_tracing();
let guard = bootstrap::setup_tracing("BOOTSTRAP_TRACING");

let start_time = Instant::now();
let _start_time = Instant::now();

let args = env::args().skip(1).collect::<Vec<_>>();

Expand Down Expand Up @@ -102,6 +100,35 @@ fn main() {
let dump_bootstrap_shims = config.dump_bootstrap_shims;
let out_dir = config.out.clone();

let tracing_enabled = is_tracing_enabled();

// Prepare a directory for tracing output
// Also store a symlink named "latest" to point to the latest tracing directory.
let tracing_dir = out_dir.join("bootstrap-trace").join(std::process::id().to_string());
let latest_trace_dir = tracing_dir.parent().unwrap().join("latest");
if tracing_enabled {
let _ = std::fs::remove_dir_all(&tracing_dir);
std::fs::create_dir_all(&tracing_dir).unwrap();

#[cfg(windows)]
let _ = std::fs::remove_dir(&latest_trace_dir);
#[cfg(not(windows))]
let _ = std::fs::remove_file(&latest_trace_dir);

#[cfg(not(windows))]
fn symlink_dir_inner(original: &Path, link: &Path) -> io::Result<()> {
use std::os::unix::fs;
fs::symlink(original, link)
}

#[cfg(windows)]
fn symlink_dir_inner(target: &Path, junction: &Path) -> io::Result<()> {
junction::create(target, junction)
}

t!(symlink_dir_inner(&tracing_dir, &latest_trace_dir));
}

debug!("creating new build based on config");
let mut build = Build::new(config);
build.build();
Expand Down Expand Up @@ -156,12 +183,13 @@ fn main() {
}
}

if is_bootstrap_profiling_enabled() {
build.report_summary(start_time);
}

#[cfg(feature = "tracing")]
build.report_step_graph();
{
build.report_summary(&tracing_dir.join("command-stats.txt"), _start_time);
build.report_step_graph(&tracing_dir);
guard.copy_to_dir(&tracing_dir);
eprintln!("Tracing/profiling output has been written to {}", latest_trace_dir.display());
}
}

fn check_version(config: &Config) -> Option<String> {
Expand Down Expand Up @@ -219,37 +247,3 @@ fn check_version(config: &Config) -> Option<String> {

Some(msg)
}

// # Note on `tracing` usage in bootstrap
//
// Due to the conditional compilation via the `tracing` cargo feature, this means that `tracing`
// usages in bootstrap need to be also gated behind the `tracing` feature:
//
// - `tracing` macros with log levels (`trace!`, `debug!`, `warn!`, `info`, `error`) should not be
// used *directly*. You should use the wrapped `tracing` macros which gate the actual invocations
// behind `feature = "tracing"`.
// - `tracing`'s `#[instrument(..)]` macro will need to be gated like `#![cfg_attr(feature =
// "tracing", instrument(..))]`.
#[cfg(feature = "tracing")]
fn setup_tracing() -> impl Drop {
use tracing_forest::ForestLayer;
use tracing_subscriber::EnvFilter;
use tracing_subscriber::layer::SubscriberExt;

let filter = EnvFilter::from_env("BOOTSTRAP_TRACING");

let mut chrome_layer = tracing_chrome::ChromeLayerBuilder::new().include_args(true);

// Writes the Chrome profile to trace-<unix-timestamp>.json if enabled
if !is_bootstrap_profiling_enabled() {
chrome_layer = chrome_layer.writer(io::sink());
}

let (chrome_layer, _guard) = chrome_layer.build();

let registry =
tracing_subscriber::registry().with(filter).with(ForestLayer::default()).with(chrome_layer);

tracing::subscriber::set_global_default(registry).unwrap();
_guard
}
Loading
Loading