diff --git a/Cargo.lock b/Cargo.lock index 0247b111ed1..b14e0ae6ba1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -342,6 +342,7 @@ dependencies = [ "toml", "toml_edit", "tracing", + "tracing-chrome", "tracing-subscriber", "unicase", "unicode-width", @@ -3450,6 +3451,17 @@ dependencies = [ "syn 2.0.46", ] +[[package]] +name = "tracing-chrome" +version = "0.7.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "496b3cd5447f7ff527bbbf19b071ad542a000adf297d4127078b4dfdb931f41a" +dependencies = [ + "serde_json", + "tracing-core", + "tracing-subscriber", +] + [[package]] name = "tracing-core" version = "0.1.32" diff --git a/Cargo.toml b/Cargo.toml index 15e41e9ea59..277c72b80f7 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -99,6 +99,7 @@ time = { version = "0.3", features = ["parsing", "formatting", "serde"] } toml = "0.8.10" toml_edit = { version = "0.22.6", features = ["serde"] } tracing = "0.1.40" # be compatible with rustc_log: https://github.com/rust-lang/rust/blob/e51e98dde6a/compiler/rustc_log/Cargo.toml#L9 +tracing-chrome = "0.7.1" tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } unicase = "2.7.0" unicode-width = "0.1.11" @@ -198,6 +199,7 @@ time.workspace = true toml.workspace = true toml_edit.workspace = true tracing.workspace = true +tracing-chrome.workspace = true tracing-subscriber.workspace = true unicase.workspace = true unicode-width.workspace = true diff --git a/src/bin/cargo/main.rs b/src/bin/cargo/main.rs index 9845de4f7c8..a2147b4d037 100644 --- a/src/bin/cargo/main.rs +++ b/src/bin/cargo/main.rs @@ -18,7 +18,7 @@ mod commands; use crate::command_prelude::*; fn main() { - setup_logger(); + let _guard = setup_logger(); let mut gctx = match GlobalContext::default() { Ok(gctx) => gctx, @@ -41,16 +41,43 @@ fn main() { } } -fn setup_logger() { - let env = tracing_subscriber::EnvFilter::from_env("CARGO_LOG"); +fn setup_logger() -> Option { + #![allow(clippy::disallowed_methods)] + + use tracing_subscriber::prelude::*; - tracing_subscriber::fmt() + let env = tracing_subscriber::EnvFilter::from_env("CARGO_LOG"); + let fmt_layer = tracing_subscriber::fmt::layer() .with_timer(tracing_subscriber::fmt::time::Uptime::default()) .with_ansi(std::io::IsTerminal::is_terminal(&std::io::stderr())) .with_writer(std::io::stderr) - .with_env_filter(env) - .init(); + .with_filter(env); + + let (profile_layer, profile_guard) = + if env_to_bool(std::env::var_os("CARGO_LOG_PROFILE").as_deref()) { + let capture_args = + env_to_bool(std::env::var_os("CARGO_LOG_PROFILE_CAPTURE_ARGS").as_deref()); + let (layer, guard) = tracing_chrome::ChromeLayerBuilder::new() + .include_args(capture_args) + .build(); + (Some(layer), Some(guard)) + } else { + (None, None) + }; + + let registry = tracing_subscriber::registry() + .with(fmt_layer) + .with(profile_layer); + registry.init(); tracing::trace!(start = humantime::format_rfc3339(std::time::SystemTime::now()).to_string()); + profile_guard +} + +fn env_to_bool(os: Option<&OsStr>) -> bool { + match os.and_then(|os| os.to_str()) { + Some("1") | Some("true") => true, + _ => false, + } } /// Table for defining the aliases which come builtin in `Cargo`. diff --git a/src/cargo/core/compiler/build_runner/mod.rs b/src/cargo/core/compiler/build_runner/mod.rs index aa101195d93..ac99b734c8d 100644 --- a/src/cargo/core/compiler/build_runner/mod.rs +++ b/src/cargo/core/compiler/build_runner/mod.rs @@ -9,7 +9,6 @@ use crate::core::compiler::{self, artifact, Unit}; use crate::core::PackageId; use crate::util::cache_lock::CacheLockMode; use crate::util::errors::CargoResult; -use crate::util::profile; use anyhow::{bail, Context as _}; use filetime::FileTime; use itertools::Itertools; @@ -353,8 +352,6 @@ impl<'a, 'gctx> BuildRunner<'a, 'gctx> { /// place. #[tracing::instrument(skip_all)] pub fn prepare(&mut self) -> CargoResult<()> { - let _p = profile::start("preparing layout"); - self.files .as_mut() .unwrap() diff --git a/src/cargo/core/compiler/custom_build.rs b/src/cargo/core/compiler/custom_build.rs index e0f83f82f86..426d8f128c2 100644 --- a/src/cargo/core/compiler/custom_build.rs +++ b/src/cargo/core/compiler/custom_build.rs @@ -38,8 +38,8 @@ use crate::core::compiler::fingerprint::DirtyReason; use crate::core::compiler::job_queue::JobState; use crate::core::{profiles::ProfileRoot, PackageId, Target}; use crate::util::errors::CargoResult; +use crate::util::internal; use crate::util::machine_message::{self, Message}; -use crate::util::{internal, profile}; use anyhow::{bail, Context as _}; use cargo_platform::Cfg; use cargo_util::paths; @@ -196,12 +196,6 @@ impl LinkArgTarget { /// Prepares a `Work` that executes the target as a custom build script. #[tracing::instrument(skip_all)] pub fn prepare(build_runner: &mut BuildRunner<'_, '_>, unit: &Unit) -> CargoResult { - let _p = profile::start(format!( - "build script prepare: {}/{}", - unit.pkg, - unit.target.name() - )); - let metadata = build_runner.get_run_build_script_metadata(unit); if build_runner .build_script_outputs diff --git a/src/cargo/core/compiler/fingerprint/mod.rs b/src/cargo/core/compiler/fingerprint/mod.rs index 902b8072991..44d3b5f81ee 100644 --- a/src/cargo/core/compiler/fingerprint/mod.rs +++ b/src/cargo/core/compiler/fingerprint/mod.rs @@ -377,7 +377,7 @@ use crate::core::Package; use crate::util::errors::CargoResult; use crate::util::interning::InternedString; use crate::util::{self, try_canonicalize}; -use crate::util::{internal, path_args, profile, StableHasher}; +use crate::util::{internal, path_args, StableHasher}; use crate::{GlobalContext, CARGO_ENV}; use super::custom_build::BuildDeps; @@ -405,11 +405,6 @@ pub fn prepare_target( unit: &Unit, force: bool, ) -> CargoResult { - let _p = profile::start(format!( - "fingerprint: {} / {}", - unit.pkg.package_id(), - unit.target.name() - )); let bcx = build_runner.bcx; let loc = build_runner.files().fingerprint_file_path(unit, ""); diff --git a/src/cargo/core/compiler/job_queue/mod.rs b/src/cargo/core/compiler/job_queue/mod.rs index 563bcd52dc9..0ad64dc7650 100644 --- a/src/cargo/core/compiler/job_queue/mod.rs +++ b/src/cargo/core/compiler/job_queue/mod.rs @@ -144,7 +144,7 @@ use crate::util::diagnostic_server::{self, DiagnosticPrinter}; use crate::util::errors::AlreadyPrintedError; use crate::util::machine_message::{self, Message as _}; use crate::util::CargoResult; -use crate::util::{self, internal, profile}; +use crate::util::{self, internal}; use crate::util::{DependencyQueue, GlobalContext, Progress, ProgressStyle, Queue}; /// This structure is backed by the `DependencyQueue` type and manages the @@ -473,7 +473,6 @@ impl<'gctx> JobQueue<'gctx> { build_runner: &mut BuildRunner<'_, '_>, plan: &mut BuildPlan, ) -> CargoResult<()> { - let _p = profile::start("executing the job graph"); self.queue.queue_finished(); let progress = diff --git a/src/cargo/core/compiler/mod.rs b/src/cargo/core/compiler/mod.rs index 3cca4cb7f10..bed881d50db 100644 --- a/src/cargo/core/compiler/mod.rs +++ b/src/cargo/core/compiler/mod.rs @@ -93,7 +93,7 @@ use crate::core::{Feature, PackageId, Target, Verbosity}; use crate::util::errors::{CargoResult, VerboseError}; use crate::util::interning::InternedString; use crate::util::machine_message::{self, Message}; -use crate::util::{add_path_args, internal, profile}; +use crate::util::{add_path_args, internal}; use cargo_util::{paths, ProcessBuilder, ProcessError}; use cargo_util_schemas::manifest::TomlDebugInfo; use cargo_util_schemas::manifest::TomlTrimPaths; @@ -175,7 +175,6 @@ fn compile<'gctx>( // Build up the work to be done to compile this unit, enqueuing it once // we've got everything constructed. - let p = profile::start(format!("preparing: {}/{}", unit.pkg, unit.target.name())); fingerprint::prepare_init(build_runner, unit)?; let job = if unit.mode.is_run_custom_build() { @@ -216,7 +215,6 @@ fn compile<'gctx>( job }; jobs.enqueue(build_runner, unit, job)?; - drop(p); // Be sure to compile all dependencies of this target as well. let deps = Vec::from(build_runner.unit_deps(unit)); // Create vec due to mutable borrow. diff --git a/src/cargo/core/global_cache_tracker.rs b/src/cargo/core/global_cache_tracker.rs index bc6198a8362..8ab34f12e58 100644 --- a/src/cargo/core/global_cache_tracker.rs +++ b/src/cargo/core/global_cache_tracker.rs @@ -552,7 +552,6 @@ impl GlobalCacheTracker { clean_ctx: &mut CleanContext<'_>, gc_opts: &GcOpts, ) -> CargoResult<()> { - let _p = crate::util::profile::start("cleaning global cache files"); let gctx = clean_ctx.gctx; let base = BasePaths { index: gctx.registry_index_path().into_path_unlocked(), @@ -706,7 +705,6 @@ impl GlobalCacheTracker { sync_size: bool, delete_paths: &mut Vec, ) -> CargoResult<()> { - let _p = crate::util::profile::start("global cache db sync"); debug!(target: "gc", "starting db sync"); // For registry_index and git_db, add anything that is missing in the db. Self::update_parent_for_missing_from_db(conn, now, REGISTRY_INDEX_TABLE, &base.index)?; @@ -804,9 +802,6 @@ impl GlobalCacheTracker { parent_table_name: &str, base_path: &Path, ) -> CargoResult<()> { - let _p = crate::util::profile::start(format!( - "update parent db for missing from db {parent_table_name}" - )); trace!(target: "gc", "checking for untracked parent to add to {parent_table_name}"); let names = Self::names_from(base_path)?; @@ -833,7 +828,6 @@ impl GlobalCacheTracker { table_name: &str, base_path: &Path, ) -> CargoResult<()> { - let _p = crate::util::profile::start(format!("update db for removed {table_name}")); trace!(target: "gc", "checking for db entries to remove from {table_name}"); let mut select_stmt = conn.prepare_cached(&format!( "SELECT {table_name}.rowid, {parent_table_name}.name, {table_name}.name @@ -863,9 +857,6 @@ impl GlobalCacheTracker { child_base_paths: &[&Path], delete_paths: &mut Vec, ) -> CargoResult<()> { - let _p = crate::util::profile::start(format!( - "update db parent for removed from disk {parent_table_name}" - )); trace!(target: "gc", "checking for db entries to remove from {parent_table_name}"); let mut select_stmt = conn.prepare_cached(&format!("SELECT rowid, name FROM {parent_table_name}"))?; @@ -899,7 +890,6 @@ impl GlobalCacheTracker { now: Timestamp, base_path: &Path, ) -> CargoResult<()> { - let _p = crate::util::profile::start("populate untracked crate"); trace!(target: "gc", "populating untracked crate files"); let mut insert_stmt = conn.prepare_cached( "INSERT INTO registry_crate (registry_id, name, size, timestamp) @@ -939,7 +929,6 @@ impl GlobalCacheTracker { base_path: &Path, populate_size: bool, ) -> CargoResult<()> { - let _p = crate::util::profile::start(format!("populate untracked {table_name}")); trace!(target: "gc", "populating untracked files for {table_name}"); // Gather names (and make sure they are in the database). let id_names = Self::names_from(&base_path)?; @@ -1003,7 +992,6 @@ impl GlobalCacheTracker { table_name: &str, base_path: &Path, ) -> CargoResult<()> { - let _p = crate::util::profile::start(format!("update NULL sizes {table_name}")); trace!(target: "gc", "updating NULL size information in {table_name}"); let mut null_stmt = conn.prepare_cached(&format!( "SELECT {table_name}.rowid, {table_name}.name, {parent_table_name}.name @@ -1570,7 +1558,6 @@ impl DeferredGlobalLastUse { /// This will also clear the state of `self`. #[tracing::instrument(skip_all)] pub fn save(&mut self, tracker: &mut GlobalCacheTracker) -> CargoResult<()> { - let _p = crate::util::profile::start("saving last-use data"); trace!(target: "gc", "saving last-use data"); if self.is_empty() { return Ok(()); diff --git a/src/cargo/core/resolver/features.rs b/src/cargo/core/resolver/features.rs index 85b0a112a8e..b86b96a5dab 100644 --- a/src/cargo/core/resolver/features.rs +++ b/src/cargo/core/resolver/features.rs @@ -455,8 +455,6 @@ impl<'a, 'gctx> FeatureResolver<'a, 'gctx> { requested_targets: &[CompileKind], opts: FeatureOpts, ) -> CargoResult { - use crate::util::profile; - let _p = profile::start("resolve features"); let track_for_host = opts.decouple_host_deps || opts.ignore_inactive_targets; let mut r = FeatureResolver { ws, diff --git a/src/cargo/core/resolver/mod.rs b/src/cargo/core/resolver/mod.rs index 2c3ee3afb50..20072331354 100644 --- a/src/cargo/core/resolver/mod.rs +++ b/src/cargo/core/resolver/mod.rs @@ -70,7 +70,6 @@ use crate::core::{Dependency, PackageId, Registry, Summary}; use crate::util::context::GlobalContext; use crate::util::errors::CargoResult; use crate::util::network::PollExt; -use crate::util::profile; use self::context::ResolverContext; use self::dep_cache::RegistryQueryer; @@ -131,7 +130,6 @@ pub fn resolve( resolve_version: ResolveVersion, gctx: Option<&GlobalContext>, ) -> CargoResult { - let _p = profile::start("resolving"); let first_version = match gctx { Some(config) if config.cli_unstable().direct_minimal_versions => { Some(VersionOrdering::MinimumVersionsFirst) diff --git a/src/cargo/ops/cargo_compile/mod.rs b/src/cargo/ops/cargo_compile/mod.rs index e8b3c53f683..4aaf4878712 100644 --- a/src/cargo/ops/cargo_compile/mod.rs +++ b/src/cargo/ops/cargo_compile/mod.rs @@ -54,7 +54,7 @@ use crate::ops; use crate::ops::resolve::WorkspaceResolve; use crate::util::context::GlobalContext; use crate::util::interning::InternedString; -use crate::util::{profile, CargoResult, StableHasher}; +use crate::util::{CargoResult, StableHasher}; mod compile_filter; pub use compile_filter::{CompileFilter, FilterRule, LibRule}; @@ -155,7 +155,6 @@ pub fn compile_ws<'a>( return Compilation::new(&bcx); } crate::core::gc::auto_gc(bcx.gctx); - let _p = profile::start("compiling"); let build_runner = BuildRunner::new(&bcx)?; build_runner.compile(exec) } diff --git a/src/cargo/ops/resolve.rs b/src/cargo/ops/resolve.rs index 98d1ba0dfca..f9e036b2e05 100644 --- a/src/cargo/ops/resolve.rs +++ b/src/cargo/ops/resolve.rs @@ -71,7 +71,7 @@ use crate::ops; use crate::sources::PathSource; use crate::util::cache_lock::CacheLockMode; use crate::util::errors::CargoResult; -use crate::util::{profile, CanonicalUrl}; +use crate::util::CanonicalUrl; use anyhow::Context as _; use std::collections::{HashMap, HashSet}; use tracing::{debug, trace}; @@ -147,8 +147,6 @@ pub fn resolve_ws_with_opts<'gctx>( // Second, resolve with precisely what we're doing. Filter out // transitive dependencies if necessary, specify features, handle // overrides, etc. - let _p = profile::start("resolving with overrides..."); - add_overrides(&mut registry, ws)?; for (replace_spec, dep) in ws.root_replace() { diff --git a/src/cargo/util/mod.rs b/src/cargo/util/mod.rs index 09e38190708..cacc88fcb28 100644 --- a/src/cargo/util/mod.rs +++ b/src/cargo/util/mod.rs @@ -54,7 +54,6 @@ pub mod job; mod lockserver; pub mod machine_message; pub mod network; -pub mod profile; mod progress; mod queue; pub mod restricted_names; diff --git a/src/cargo/util/profile.rs b/src/cargo/util/profile.rs deleted file mode 100644 index ede8db1913b..00000000000 --- a/src/cargo/util/profile.rs +++ /dev/null @@ -1,92 +0,0 @@ -//! An internal performance profiler for Cargo itself. -//! -//! > **Note**: This might not be the module you are looking for. -//! > For information about how Cargo handles compiler flags with profiles, -//! > please see the module [`cargo::core::profiles`](crate::core::profiles). - -use std::cell::RefCell; -use std::env; -use std::fmt; -use std::io::{stdout, StdoutLock, Write}; -use std::iter::repeat; -use std::mem; -use std::time; - -thread_local!(static PROFILE_STACK: RefCell> = RefCell::new(Vec::new())); -thread_local!(static MESSAGES: RefCell> = RefCell::new(Vec::new())); - -type Message = (usize, u64, String); - -pub struct Profiler { - desc: String, -} - -fn enabled_level() -> Option { - // ALLOWED: for profiling Cargo itself, not intended to be used beyond Cargo contributors. - #[allow(clippy::disallowed_methods)] - env::var("CARGO_PROFILE").ok().and_then(|s| s.parse().ok()) -} - -pub fn start(desc: T) -> Profiler { - if enabled_level().is_none() { - return Profiler { - desc: String::new(), - }; - } - - PROFILE_STACK.with(|stack| stack.borrow_mut().push(time::Instant::now())); - - Profiler { - desc: desc.to_string(), - } -} - -impl Drop for Profiler { - fn drop(&mut self) { - let Some(enabled) = enabled_level() else { - return; - }; - - let (start, stack_len) = PROFILE_STACK.with(|stack| { - let mut stack = stack.borrow_mut(); - let start = stack.pop().unwrap(); - (start, stack.len()) - }); - let duration = start.elapsed(); - let duration_ms = duration.as_secs() * 1000 + u64::from(duration.subsec_millis()); - - let msg = (stack_len, duration_ms, mem::take(&mut self.desc)); - MESSAGES.with(|msgs| msgs.borrow_mut().push(msg)); - - if stack_len == 0 { - fn print(lvl: usize, msgs: &[Message], enabled: usize, stdout: &mut StdoutLock<'_>) { - if lvl > enabled { - return; - } - let mut last = 0; - for (i, &(l, time, ref msg)) in msgs.iter().enumerate() { - if l != lvl { - continue; - } - writeln!( - stdout, - "{} {:6}ms - {}", - repeat(" ").take(lvl + 1).collect::(), - time, - msg - ) - .expect("printing profiling info to stdout"); - - print(lvl + 1, &msgs[last..i], enabled, stdout); - last = i; - } - } - let stdout = stdout(); - MESSAGES.with(|msgs| { - let mut msgs = msgs.borrow_mut(); - print(0, &msgs, enabled, &mut stdout.lock()); - msgs.clear(); - }); - } - } -} diff --git a/src/cargo/util/rustc.rs b/src/cargo/util/rustc.rs index 4d4c328a0b3..3e0df24fe1a 100644 --- a/src/cargo/util/rustc.rs +++ b/src/cargo/util/rustc.rs @@ -10,7 +10,7 @@ use serde::{Deserialize, Serialize}; use tracing::{debug, info, warn}; use crate::util::interning::InternedString; -use crate::util::{profile, CargoResult, GlobalContext, StableHasher}; +use crate::util::{CargoResult, GlobalContext, StableHasher}; /// Information on the `rustc` executable #[derive(Debug)] @@ -48,8 +48,6 @@ impl Rustc { cache_location: Option, gctx: &GlobalContext, ) -> CargoResult { - let _p = profile::start("Rustc::new"); - let mut cache = Cache::load( wrapper.as_deref(), workspace_wrapper.as_deref(), diff --git a/src/doc/contrib/src/tests/profiling.md b/src/doc/contrib/src/tests/profiling.md index 1cc980ca3e3..f8410291b13 100644 --- a/src/doc/contrib/src/tests/profiling.md +++ b/src/doc/contrib/src/tests/profiling.md @@ -2,15 +2,24 @@ ## Internal profiler -Cargo has a basic, hierarchical profiler built-in. The environment variable -`CARGO_PROFILE` can be set to an integer which specifies how deep in the -profile stack to print results for. +Cargo leverages [tracing](https://crates.io/crates/tracing) +as a basic, hierarchical built-in profiler. -```sh -# Output first three levels of profiling info -CARGO_PROFILE=3 cargo generate-lockfile +Environment variables: +- `CARGO_LOG_PROFILE=`: log tracing events to a file in the current working directory +- `CARGO_LOG_PROFILE_CAPTURE_ARGS=`: include arguments in the events + +At process exit, your trace will be in a file like `trace-1668480819035032.json`. +Open that file with [ui.perfetto.dev](https://ui.perfetto.dev) (or chrome://tracing) to browse your trace. + +Example: +```console +$ # Output first three levels of profiling info +$ CARGO_LOG_PROFILE=true cargo generate-lockfile ``` +**Note:** This is intended for the development of cargo and there are no compatibility guarantees on this functionality. + ## Benchmarking ### Benchsuite