diff --git a/.gitignore b/.gitignore index 4302ff30a762a..ad7de8ce76cff 100644 --- a/.gitignore +++ b/.gitignore @@ -21,6 +21,14 @@ flamegraph.svg # `CARGO_TARGET_DIR=target-llvm-lines RUSTFLAGS="-Csymbol-mangling-version=v0" cargo llvm-lines -p ruff --lib` /target* +# samply profiles +profile.json + +# tracing-flame traces +tracing.folded +tracing-flamechart.svg +tracing-flamegraph.svg + ### # Rust.gitignore ### diff --git a/Cargo.lock b/Cargo.lock index 3880a9982a5e1..fb5fbcd0b812c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1482,11 +1482,11 @@ dependencies = [ [[package]] name = "nu-ansi-term" -version = "0.50.0" +version = "0.50.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "dd2800e1520bdc966782168a627aa5d1ad92e33b984bf7c7615d31280c83ff14" +checksum = "d4a28e057d01f97e61255210fcff094d74ed0466038633e95017f5beb68e4399" dependencies = [ - "windows-sys 0.48.0", + "windows-sys 0.52.0", ] [[package]] @@ -1860,7 +1860,9 @@ name = "red_knot" version = "0.0.0" dependencies = [ "anyhow", + "chrono", "clap", + "colored", "countme", "crossbeam", "ctrlc", @@ -1873,6 +1875,7 @@ dependencies = [ "salsa", "tempfile", "tracing", + "tracing-flame", "tracing-subscriber", "tracing-tree", ] @@ -3225,6 +3228,17 @@ dependencies = [ "valuable", ] +[[package]] +name = "tracing-flame" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0bae117ee14789185e129aaee5d93750abe67fdc5a9a62650452bfe4e122a3a9" +dependencies = [ + "lazy_static", + "tracing", + "tracing-subscriber", +] + [[package]] name = "tracing-indicatif" version = "0.3.6" @@ -3272,7 +3286,7 @@ version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f459ca79f1b0d5f71c54ddfde6debfc59c8b6eeb46808ae492077f739dc7b49c" dependencies = [ - "nu-ansi-term 0.50.0", + "nu-ansi-term 0.50.1", "tracing-core", "tracing-log", "tracing-subscriber", diff --git a/Cargo.toml b/Cargo.toml index b9e4e0d625f4b..7ff4b380c8990 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -132,8 +132,9 @@ thiserror = { version = "1.0.58" } tikv-jemallocator = { version = "0.6.0" } toml = { version = "0.8.11" } tracing = { version = "0.1.40" } +tracing-flame = { version = "0.2.0" } tracing-indicatif = { version = "0.3.6" } -tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } +tracing-subscriber = { version = "0.3.18", default-features = false, features = ["env-filter", "fmt"] } tracing-tree = { version = "0.4.0" } typed-arena = { version = "2.0.2" } unic-ucd-category = { version = "0.9" } diff --git a/crates/red_knot/Cargo.toml b/crates/red_knot/Cargo.toml index 50781acfd123b..5fc0fcf4926ec 100644 --- a/crates/red_knot/Cargo.toml +++ b/crates/red_knot/Cargo.toml @@ -19,20 +19,22 @@ red_knot_server = { workspace = true } ruff_db = { workspace = true, features = ["os", "cache"] } anyhow = { workspace = true } +chrono = { workspace = true } clap = { workspace = true, features = ["wrap_help"] } +colored = { workspace = true } countme = { workspace = true, features = ["enable"] } crossbeam = { workspace = true } ctrlc = { version = "3.4.4" } rayon = { workspace = true } salsa = { workspace = true } -tracing = { workspace = true } -tracing-subscriber = { workspace = true } +tracing = { workspace = true, features = ["release_max_level_debug"] } +tracing-subscriber = { workspace = true, features = ["env-filter", "fmt"] } +tracing-flame = { workspace = true } tracing-tree = { workspace = true } [dev-dependencies] filetime = { workspace = true } tempfile = { workspace = true } - [lints] workspace = true diff --git a/crates/red_knot/docs/tracing-flamegraph.png b/crates/red_knot/docs/tracing-flamegraph.png new file mode 100644 index 0000000000000..6a350c6b551ef Binary files /dev/null and b/crates/red_knot/docs/tracing-flamegraph.png differ diff --git a/crates/red_knot/docs/tracing.md b/crates/red_knot/docs/tracing.md new file mode 100644 index 0000000000000..98b4665e28a30 --- /dev/null +++ b/crates/red_knot/docs/tracing.md @@ -0,0 +1,103 @@ +# Tracing + +Traces are a useful tool to narrow down the location of a bug or, at least, to understand why the compiler is doing a particular thing. +Note, tracing messages with severity `debug` or greater are user-facing. They should be phrased accordingly. +Tracing spans are only shown when using `-vvv`. + +## Verbosity levels + +The CLI supports different verbosity levels. + +- default: Only show errors and warnings. +- `-v` activates `info!`: Show generally useful information such as paths of configuration files, detected platform, etc., but it's not a lot of messages, it's something you'll activate in CI by default. cargo build e.g. shows you which packages are fresh. +- `-vv` activates `debug!` and timestamps: This should be enough information to get to the bottom of bug reports. When you're processing many packages or files, you'll get pages and pages of output, but each line is link to a specific action or state change. +- `-vvv` activates `trace!` (only in debug builds) and shows tracing-spans: At this level, you're logging everything. Most of this is wasted, it's really slow, we dump e.g. the entire resolution graph. Only useful to developers, and you almost certainly want to use `RED_KNOT_LOG` to filter it down to the area your investigating. + +## `RED_KNOT_LOG` + +By default, the CLI shows messages from the `ruff` and `red_knot` crates. Tracing messages from other crates are not shown. +The `RED_KNOT_LOG` environment variable allows you to customize which messages are shown by specifying one +or more [filter directives](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html#directives). + +### Examples + +#### Show all debug messages + +Shows debug messages from all crates. + +```bash +RED_KNOT_LOG=debug +``` + +#### Show salsa query execution messages + +Show the salsa `execute: my_query` messages in addition to all red knot messages. + +```bash +RED_KNOT_LOG=ruff=trace,red_knot=trace,salsa=info +``` + +#### Show typing traces + +Only show traces for the `red_knot_python_semantic::types` module. + +```bash +RED_KNOT_LOG="red_knot_python_semantic::types" +``` + +Note: Ensure that you use `-vvv` to see tracing spans. + +#### Show messages for a single file + +Shows all messages that are inside of a span for a specific file. + +```bash +RED_KNOT_LOG=red_knot[{file=/home/micha/astral/test/x.py}]=trace +``` + +**Note**: Tracing still shows all spans because tracing can't know at the time of entering the span +whether one if its children has the file `x.py`. + +**Note**: Salsa currently logs the entire memoized values. In our case, the source text and parsed AST. +This very quickly leads to extremely long outputs. + +## Tracing and Salsa + +Be mindful about using `tracing` in Salsa queries, especially when using `warn` or `error` because it isn't guaranteed +that the query will execute after restoring from a persistent cache. In which case the user won't see the message. + +For example, don't use `tracing` to show the user a message when generating a lint violation failed +because the message would only be shown when linting the file the first time, but not on subsequent analysis +runs or when restoring from a persistent cache. This can be confusing for users because they +don't understand why a specific lint violation isn't raised. Instead, change your +query to return the failure as part of the query's result or use a Salsa accumulator. + +## Release builds + +`trace!` events are removed in release builds. + +## Profiling + +Red Knot generates a folded stack trace to the current directory named `tracing.folded` when setting the environment variable `RED_KNOT_LOG_PROFILE` to `1` or `true`. + +```bash +RED_KNOT_LOG_PROFILE=1 red_knot -- --current-directory=../test -vvv +``` + +You can convert the textual representation into a visual one using `inferno`. + +```shell +cargo install inferno +``` + +```shell +# flamegraph +cat tracing.folded | inferno-flamegraph > tracing-flamegraph.svg + +# flamechart +cat tracing.folded | inferno-flamegraph --flamechart > tracing-flamechart.svg +``` + +![Example flamegraph](./tracing-flamegraph.png) + +See [`tracing-flame`](https://crates.io/crates/tracing-flame) for more details. diff --git a/crates/red_knot/src/logging.rs b/crates/red_knot/src/logging.rs new file mode 100644 index 0000000000000..8ceff9472e220 --- /dev/null +++ b/crates/red_knot/src/logging.rs @@ -0,0 +1,254 @@ +//! Sets up logging for Red Knot + +use anyhow::Context; +use colored::Colorize; +use std::fmt; +use std::fs::File; +use std::io::BufWriter; +use tracing::log::LevelFilter; +use tracing::{Event, Subscriber}; +use tracing_subscriber::fmt::format::Writer; +use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields}; +use tracing_subscriber::registry::LookupSpan; +use tracing_subscriber::EnvFilter; + +/// Logging flags to `#[command(flatten)]` into your CLI +#[derive(clap::Args, Debug, Clone, Default)] +#[command(about = None, long_about = None)] +pub(crate) struct Verbosity { + #[arg( + long, + short = 'v', + help = "Use verbose output (or `-vv` and `-vvv` for more verbose output)", + action = clap::ArgAction::Count, + global = true, + )] + verbose: u8, +} + +impl Verbosity { + /// Returns the verbosity level based on the number of `-v` flags. + /// + /// Returns `None` if the user did not specify any verbosity flags. + pub(crate) fn level(&self) -> VerbosityLevel { + match self.verbose { + 0 => VerbosityLevel::Default, + 1 => VerbosityLevel::Verbose, + 2 => VerbosityLevel::ExtraVerbose, + _ => VerbosityLevel::Trace, + } + } +} + +#[derive(Debug, Copy, Clone, Eq, PartialEq, Ord, PartialOrd)] +pub(crate) enum VerbosityLevel { + /// Default output level. Only shows Ruff and Red Knot events up to the [`WARN`](tracing::Level::WARN). + Default, + + /// Enables verbose output. Emits Ruff and Red Knot events up to the [`INFO`](tracing::Level::INFO). + /// Corresponds to `-v`. + Verbose, + + /// Enables a more verbose tracing format and emits Ruff and Red Knot events up to [`DEBUG`](tracing::Level::DEBUG). + /// Corresponds to `-vv` + ExtraVerbose, + + /// Enables all tracing events and uses a tree-like output format. Corresponds to `-vvv`. + Trace, +} + +impl VerbosityLevel { + const fn level_filter(self) -> LevelFilter { + match self { + VerbosityLevel::Default => LevelFilter::Warn, + VerbosityLevel::Verbose => LevelFilter::Info, + VerbosityLevel::ExtraVerbose => LevelFilter::Debug, + VerbosityLevel::Trace => LevelFilter::Trace, + } + } + + pub(crate) const fn is_trace(self) -> bool { + matches!(self, VerbosityLevel::Trace) + } + + pub(crate) const fn is_extra_verbose(self) -> bool { + matches!(self, VerbosityLevel::ExtraVerbose) + } +} + +pub(crate) fn setup_tracing(level: VerbosityLevel) -> anyhow::Result { + use tracing_subscriber::prelude::*; + + // The `RED_KNOT_LOG` environment variable overrides the default log level. + let filter = if let Ok(log_env_variable) = std::env::var("RED_KNOT_LOG") { + EnvFilter::builder() + .parse(log_env_variable) + .context("Failed to parse directives specified in RED_KNOT_LOG environment variable.")? + } else { + match level { + VerbosityLevel::Default => { + // Show warning traces + EnvFilter::default().add_directive(tracing::level_filters::LevelFilter::WARN.into()) + } + level => { + let level_filter = level.level_filter(); + + // Show info|debug|trace events, but allow `RED_KNOT_LOG` to override + let filter = EnvFilter::default().add_directive( + format!("red_knot={level_filter}") + .parse() + .expect("Hardcoded directive to be valid"), + ); + + filter.add_directive( + format!("ruff={level_filter}") + .parse() + .expect("Hardcoded directive to be valid"), + ) + } + } + }; + + let (profiling_layer, guard) = setup_profile(); + + let registry = tracing_subscriber::registry() + .with(filter) + .with(profiling_layer); + + if level.is_trace() { + let subscriber = registry.with( + tracing_tree::HierarchicalLayer::default() + .with_indent_lines(true) + .with_indent_amount(2) + .with_bracketed_fields(true) + .with_thread_ids(true) + .with_targets(true) + .with_writer(std::io::stderr) + .with_timer(tracing_tree::time::Uptime::default()), + ); + + subscriber.init(); + } else { + let subscriber = registry.with( + tracing_subscriber::fmt::layer() + .event_format(RedKnotFormat { + display_level: true, + display_timestamp: level.is_extra_verbose(), + show_spans: false, + }) + .with_writer(std::io::stderr), + ); + + subscriber.init(); + } + + Ok(TracingGuard { + _flame_guard: guard, + }) +} + +#[allow(clippy::type_complexity)] +fn setup_profile() -> ( + Option>>, + Option>>, +) +where + S: Subscriber + for<'span> LookupSpan<'span>, +{ + if let Ok("1" | "true") = std::env::var("RED_KNOT_LOG_PROFILE").as_deref() { + let (layer, guard) = tracing_flame::FlameLayer::with_file("tracing.folded") + .expect("Flame layer to be created"); + (Some(layer), Some(guard)) + } else { + (None, None) + } +} + +pub(crate) struct TracingGuard { + _flame_guard: Option>>, +} + +struct RedKnotFormat { + display_timestamp: bool, + display_level: bool, + show_spans: bool, +} + +/// See +impl FormatEvent for RedKnotFormat +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result { + let meta = event.metadata(); + let ansi = writer.has_ansi_escapes(); + + if self.display_timestamp { + let timestamp = chrono::Local::now() + .format("%Y-%m-%d %H:%M:%S.%f") + .to_string(); + if ansi { + write!(writer, "{} ", timestamp.dimmed())?; + } else { + write!( + writer, + "{} ", + chrono::Local::now().format("%Y-%m-%d %H:%M:%S.%f") + )?; + } + } + + if self.display_level { + let level = meta.level(); + // Same colors as tracing + if ansi { + let formatted_level = level.to_string(); + match *level { + tracing::Level::TRACE => { + write!(writer, "{} ", formatted_level.purple().bold())?; + } + tracing::Level::DEBUG => write!(writer, "{} ", formatted_level.blue().bold())?, + tracing::Level::INFO => write!(writer, "{} ", formatted_level.green().bold())?, + tracing::Level::WARN => write!(writer, "{} ", formatted_level.yellow().bold())?, + tracing::Level::ERROR => write!(writer, "{} ", level.to_string().red().bold())?, + } + } else { + write!(writer, "{level} ")?; + } + } + + if self.show_spans { + let span = event.parent(); + let mut seen = false; + + let span = span + .and_then(|id| ctx.span(id)) + .or_else(|| ctx.lookup_current()); + + let scope = span.into_iter().flat_map(|span| span.scope().from_root()); + + for span in scope { + seen = true; + if ansi { + write!(writer, "{}:", span.metadata().name().bold())?; + } else { + write!(writer, "{}:", span.metadata().name())?; + } + } + + if seen { + writer.write_char(' ')?; + } + } + + ctx.field_format().format_fields(writer.by_ref(), event)?; + + writeln!(writer) + } +} diff --git a/crates/red_knot/src/main.rs b/crates/red_knot/src/main.rs index 1a6a555be2767..179c866481280 100644 --- a/crates/red_knot/src/main.rs +++ b/crates/red_knot/src/main.rs @@ -4,12 +4,6 @@ use std::sync::Mutex; use clap::Parser; use crossbeam::channel as crossbeam_channel; use red_knot_workspace::site_packages::site_packages_dirs_of_venv; -use tracing::subscriber::Interest; -use tracing::{Level, Metadata}; -use tracing_subscriber::filter::LevelFilter; -use tracing_subscriber::layer::{Context, Filter, SubscriberExt}; -use tracing_subscriber::{Layer, Registry}; -use tracing_tree::time::Uptime; use red_knot_workspace::db::RootDatabase; use red_knot_workspace::watch; @@ -18,8 +12,10 @@ use red_knot_workspace::workspace::WorkspaceMetadata; use ruff_db::program::{ProgramSettings, SearchPathSettings}; use ruff_db::system::{OsSystem, System, SystemPathBuf}; use target_version::TargetVersion; -use verbosity::{Verbosity, VerbosityLevel}; +use crate::logging::{setup_tracing, Verbosity}; + +mod logging; mod target_version; mod verbosity; @@ -106,7 +102,7 @@ pub fn main() -> anyhow::Result<()> { } = Args::parse_from(std::env::args().collect::>()); let verbosity = verbosity.level(); - countme::enable(verbosity == Some(VerbosityLevel::Trace)); + countme::enable(verbosity.is_trace()); if matches!(command, Some(Command::Server)) { let four = NonZeroUsize::new(4).unwrap(); @@ -119,7 +115,7 @@ pub fn main() -> anyhow::Result<()> { return red_knot_server::Server::new(worker_threads)?.run(); } - setup_tracing(verbosity); + let _guard = setup_tracing(verbosity)?; let cwd = if let Some(cwd) = current_directory { let canonicalized = cwd.as_utf8_path().canonicalize_utf8().unwrap(); @@ -159,7 +155,7 @@ pub fn main() -> anyhow::Result<()> { // cache and load the cache if it exists. let mut db = RootDatabase::new(workspace_metadata, program_settings, system); - let (main_loop, main_loop_cancellation_token) = MainLoop::new(verbosity); + let (main_loop, main_loop_cancellation_token) = MainLoop::new(); // Listen to Ctrl+C and abort the watch mode. let main_loop_cancellation_token = Mutex::new(Some(main_loop_cancellation_token)); @@ -177,6 +173,8 @@ pub fn main() -> anyhow::Result<()> { main_loop.run(&mut db); }; + tracing::trace!("Counts for entire CLI run :\n{}", countme::get_all()); + std::mem::forget(db); Ok(()) @@ -191,12 +189,10 @@ struct MainLoop { /// The file system watcher, if running in watch mode. watcher: Option, - - verbosity: Option, } impl MainLoop { - fn new(verbosity: Option) -> (Self, MainLoopCancellationToken) { + fn new() -> (Self, MainLoopCancellationToken) { let (sender, receiver) = crossbeam_channel::bounded(10); ( @@ -204,32 +200,41 @@ impl MainLoop { sender: sender.clone(), receiver, watcher: None, - verbosity, }, MainLoopCancellationToken { sender }, ) } fn watch(mut self, db: &mut RootDatabase) -> anyhow::Result<()> { + tracing::debug!("Starting watch mode"); let sender = self.sender.clone(); let watcher = watch::directory_watcher(move |event| { sender.send(MainLoopMessage::ApplyChanges(event)).unwrap(); })?; self.watcher = Some(WorkspaceWatcher::new(watcher, db)); + self.run(db); + Ok(()) } - #[allow(clippy::print_stderr)] fn run(mut self, db: &mut RootDatabase) { - // Schedule the first check. self.sender.send(MainLoopMessage::CheckWorkspace).unwrap(); + + self.main_loop(db); + + tracing::debug!("Exiting main loop"); + } + + #[allow(clippy::print_stderr)] + fn main_loop(&mut self, db: &mut RootDatabase) { + // Schedule the first check. + tracing::debug!("Starting main loop"); + let mut revision = 0usize; while let Ok(message) = self.receiver.recv() { - tracing::trace!("Main Loop: Tick"); - match message { MainLoopMessage::CheckWorkspace => { let db = db.snapshot(); @@ -253,15 +258,15 @@ impl MainLoop { } => { if check_revision == revision { eprintln!("{}", result.join("\n")); - - if self.verbosity == Some(VerbosityLevel::Trace) { - eprintln!("{}", countme::get_all()); - } + } else { + tracing::debug!("Discarding check result for outdated revision: current: {revision}, result revision: {check_revision}"); } if self.watcher.is_none() { - return self.exit(); + return; } + + tracing::trace!("Counts after last check:\n{}", countme::get_all()); } MainLoopMessage::ApplyChanges(changes) => { @@ -274,19 +279,11 @@ impl MainLoop { self.sender.send(MainLoopMessage::CheckWorkspace).unwrap(); } MainLoopMessage::Exit => { - return self.exit(); + return; } } - } - self.exit(); - } - - #[allow(clippy::print_stderr, clippy::unused_self)] - fn exit(self) { - if self.verbosity == Some(VerbosityLevel::Trace) { - eprintln!("Exit"); - eprintln!("{}", countme::get_all()); + tracing::debug!("Waiting for next main loop message."); } } } @@ -313,63 +310,3 @@ enum MainLoopMessage { ApplyChanges(Vec), Exit, } - -fn setup_tracing(verbosity: Option) { - let trace_level = match verbosity { - None => Level::WARN, - Some(VerbosityLevel::Info) => Level::INFO, - Some(VerbosityLevel::Debug) => Level::DEBUG, - Some(VerbosityLevel::Trace) => Level::TRACE, - }; - - let subscriber = Registry::default().with( - tracing_tree::HierarchicalLayer::default() - .with_indent_lines(true) - .with_indent_amount(2) - .with_bracketed_fields(true) - .with_thread_ids(true) - .with_targets(true) - .with_writer(|| Box::new(std::io::stderr())) - .with_timer(Uptime::default()) - .with_filter(LoggingFilter { trace_level }), - ); - - tracing::subscriber::set_global_default(subscriber).unwrap(); -} - -struct LoggingFilter { - trace_level: Level, -} - -impl LoggingFilter { - fn is_enabled(&self, meta: &Metadata<'_>) -> bool { - let filter = if meta.target().starts_with("red_knot") || meta.target().starts_with("ruff") { - self.trace_level - } else if meta.target().starts_with("salsa") && self.trace_level <= Level::INFO { - // Salsa emits very verbose query traces with level info. Let's not show these to the user. - Level::WARN - } else { - Level::INFO - }; - - meta.level() <= &filter - } -} - -impl Filter for LoggingFilter { - fn enabled(&self, meta: &Metadata<'_>, _cx: &Context<'_, S>) -> bool { - self.is_enabled(meta) - } - - fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { - if self.is_enabled(meta) { - Interest::always() - } else { - Interest::never() - } - } - - fn max_level_hint(&self) -> Option { - Some(LevelFilter::from_level(self.trace_level)) - } -} diff --git a/crates/red_knot/src/verbosity.rs b/crates/red_knot/src/verbosity.rs index 692553bcd93e2..8b137891791fe 100644 --- a/crates/red_knot/src/verbosity.rs +++ b/crates/red_knot/src/verbosity.rs @@ -1,34 +1 @@ -#[derive(Debug, Copy, Clone, Eq, PartialEq, Ord, PartialOrd)] -pub(crate) enum VerbosityLevel { - Info, - Debug, - Trace, -} -/// Logging flags to `#[command(flatten)]` into your CLI -#[derive(clap::Args, Debug, Clone, Default)] -#[command(about = None, long_about = None)] -pub(crate) struct Verbosity { - #[arg( - long, - short = 'v', - help = "Use verbose output (or `-vv` and `-vvv` for more verbose output)", - action = clap::ArgAction::Count, - global = true, - )] - verbose: u8, -} - -impl Verbosity { - /// Returns the verbosity level based on the number of `-v` flags. - /// - /// Returns `None` if the user did not specify any verbosity flags. - pub(crate) fn level(&self) -> Option { - match self.verbose { - 0 => None, - 1 => Some(VerbosityLevel::Info), - 2 => Some(VerbosityLevel::Debug), - _ => Some(VerbosityLevel::Trace), - } - } -} diff --git a/crates/red_knot_module_resolver/src/resolver.rs b/crates/red_knot_module_resolver/src/resolver.rs index 14a7c826db2b9..5833da5c5a472 100644 --- a/crates/red_knot_module_resolver/src/resolver.rs +++ b/crates/red_knot_module_resolver/src/resolver.rs @@ -32,10 +32,18 @@ pub(crate) fn resolve_module_query<'db>( let name = module_name.name(db); let _span = tracing::trace_span!("resolve_module", %name).entered(); - let (search_path, module_file, kind) = resolve_name(db, name)?; + let Some((search_path, module_file, kind)) = resolve_name(db, name) else { + tracing::debug!("Module '{name}' not found in the search paths."); + return None; + }; let module = Module::new(name.clone(), kind, search_path, module_file); + tracing::debug!( + "Resolved module '{name}' to '{path}'.", + path = module_file.path(db) + ); + Some(module) } diff --git a/crates/red_knot_python_semantic/src/semantic_index.rs b/crates/red_knot_python_semantic/src/semantic_index.rs index 45d24a599db35..54d0ba3b33a4b 100644 --- a/crates/red_knot_python_semantic/src/semantic_index.rs +++ b/crates/red_knot_python_semantic/src/semantic_index.rs @@ -34,7 +34,7 @@ type SymbolMap = hashbrown::HashMap; /// Prefer using [`symbol_table`] when working with symbols from a single scope. #[salsa::tracked(return_ref, no_eq)] pub(crate) fn semantic_index(db: &dyn Db, file: File) -> SemanticIndex<'_> { - let _span = tracing::trace_span!("semantic_index", file=?file.path(db)).entered(); + let _span = tracing::trace_span!("semantic_index", file = %file.path(db)).entered(); let parsed = parsed_module(db.upcast(), file); @@ -50,7 +50,7 @@ pub(crate) fn semantic_index(db: &dyn Db, file: File) -> SemanticIndex<'_> { pub(crate) fn symbol_table<'db>(db: &'db dyn Db, scope: ScopeId<'db>) -> Arc { let file = scope.file(db); let _span = - tracing::trace_span!("symbol_table", scope=?scope.as_id(), file=?file.path(db)).entered(); + tracing::trace_span!("symbol_table", scope=?scope.as_id(), file=%file.path(db)).entered(); let index = semantic_index(db, file); index.symbol_table(scope.file_scope_id(db)) @@ -65,7 +65,7 @@ pub(crate) fn symbol_table<'db>(db: &'db dyn Db, scope: ScopeId<'db>) -> Arc(db: &'db dyn Db, scope: ScopeId<'db>) -> Arc> { let file = scope.file(db); let _span = - tracing::trace_span!("use_def_map", scope=?scope.as_id(), file=?file.path(db)).entered(); + tracing::trace_span!("use_def_map", scope=?scope.as_id(), file=%file.path(db)).entered(); let index = semantic_index(db, file); index.use_def_map(scope.file_scope_id(db)) @@ -74,7 +74,7 @@ pub(crate) fn use_def_map<'db>(db: &'db dyn Db, scope: ScopeId<'db>) -> Arc ScopeId<'_> { - let _span = tracing::trace_span!("global_scope", file=?file.path(db)).entered(); + let _span = tracing::trace_span!("global_scope", file = %file.path(db)).entered(); FileScopeId::global().to_scope_id(db, file) } diff --git a/crates/red_knot_python_semantic/src/types/infer.rs b/crates/red_knot_python_semantic/src/types/infer.rs index 769a000655a6c..a0853200c23c8 100644 --- a/crates/red_knot_python_semantic/src/types/infer.rs +++ b/crates/red_knot_python_semantic/src/types/infer.rs @@ -50,7 +50,7 @@ use crate::Db; pub(crate) fn infer_scope_types<'db>(db: &'db dyn Db, scope: ScopeId<'db>) -> TypeInference<'db> { let file = scope.file(db); let _span = - tracing::trace_span!("infer_scope_types", scope=?scope.as_id(), file=?file.path(db)) + tracing::trace_span!("infer_scope_types", scope=?scope.as_id(), file=%file.path(db)) .entered(); // Using the index here is fine because the code below depends on the AST anyway. @@ -83,7 +83,7 @@ pub(crate) fn infer_definition_types<'db>( let _span = tracing::trace_span!( "infer_definition_types", definition = ?definition.as_id(), - file = ?file.path(db) + file = %file.path(db) ) .entered(); @@ -104,7 +104,7 @@ pub(crate) fn infer_expression_types<'db>( ) -> TypeInference<'db> { let file = expression.file(db); let _span = - tracing::trace_span!("infer_expression_types", expression=?expression.as_id(), file=?file.path(db)) + tracing::trace_span!("infer_expression_types", expression=?expression.as_id(), file=%file.path(db)) .entered(); let index = semantic_index(db, file); diff --git a/crates/red_knot_workspace/src/lint.rs b/crates/red_knot_workspace/src/lint.rs index 812f2c0612886..c2b57440d1cc3 100644 --- a/crates/red_knot_workspace/src/lint.rs +++ b/crates/red_knot_workspace/src/lint.rs @@ -2,7 +2,7 @@ use std::cell::RefCell; use std::ops::Deref; use std::time::Duration; -use tracing::trace_span; +use tracing::debug_span; use red_knot_module_resolver::ModuleName; use red_knot_python_semantic::types::Type; @@ -76,7 +76,7 @@ fn lint_lines(source: &str, diagnostics: &mut Vec) { #[allow(unreachable_pub)] #[salsa::tracked(return_ref)] pub fn lint_semantic(db: &dyn Db, file_id: File) -> Diagnostics { - let _span = trace_span!("lint_semantic", file=?file_id.path(db)).entered(); + let _span = debug_span!("lint_semantic", file=%file_id.path(db)).entered(); let source = source_text(db.upcast(), file_id); let parsed = parsed_module(db.upcast(), file_id); diff --git a/crates/red_knot_workspace/src/site_packages.rs b/crates/red_knot_workspace/src/site_packages.rs index 0e6585825b1ba..c5d26f20edc9d 100644 --- a/crates/red_knot_workspace/src/site_packages.rs +++ b/crates/red_knot_workspace/src/site_packages.rs @@ -94,6 +94,10 @@ fn site_packages_dir_from_sys_prefix( let site_packages_candidate = path.join("site-packages"); if system.is_directory(&site_packages_candidate) { + tracing::debug!( + "Resoled site-packages directory: {}", + site_packages_candidate + ); return Ok(site_packages_candidate); } } diff --git a/crates/red_knot_workspace/src/watch/watcher.rs b/crates/red_knot_workspace/src/watch/watcher.rs index 61205530a0544..ff3e01009799b 100644 --- a/crates/red_knot_workspace/src/watch/watcher.rs +++ b/crates/red_knot_workspace/src/watch/watcher.rs @@ -109,6 +109,8 @@ struct WatcherInner { impl Watcher { /// Sets up file watching for `path`. pub fn watch(&mut self, path: &SystemPath) -> notify::Result<()> { + tracing::debug!("Watching path: {path}."); + self.inner_mut() .watcher .watch(path.as_std_path(), RecursiveMode::Recursive) @@ -116,6 +118,8 @@ impl Watcher { /// Stops file watching for `path`. pub fn unwatch(&mut self, path: &SystemPath) -> notify::Result<()> { + tracing::debug!("Unwatching path: {path}."); + self.inner_mut().watcher.unwatch(path.as_std_path()) } @@ -125,6 +129,7 @@ impl Watcher { /// /// The call blocks until the watcher has stopped. pub fn stop(mut self) { + tracing::debug!("Stop file watcher"); self.set_stop(); } @@ -173,8 +178,8 @@ struct Debouncer { } impl Debouncer { - #[tracing::instrument(level = "trace", skip(self))] fn add_result(&mut self, result: notify::Result) { + tracing::trace!("Handling file watcher event: {result:?}."); match result { Ok(event) => self.add_event(event), Err(error) => self.add_error(error), diff --git a/crates/red_knot_workspace/src/workspace.rs b/crates/red_knot_workspace/src/workspace.rs index 584eae83dae16..f70f535c4a53e 100644 --- a/crates/red_knot_workspace/src/workspace.rs +++ b/crates/red_knot_workspace/src/workspace.rs @@ -120,8 +120,8 @@ impl Workspace { self.package_tree(db).values().copied() } - #[tracing::instrument(skip_all)] pub fn reload(self, db: &mut dyn Db, metadata: WorkspaceMetadata) { + tracing::debug!("Reloading workspace"); assert_eq!(self.root(db), metadata.root()); let mut old_packages = self.package_tree(db).clone(); @@ -145,7 +145,6 @@ impl Workspace { .to(new_packages); } - #[tracing::instrument(level = "debug", skip_all)] pub fn update_package(self, db: &mut dyn Db, metadata: PackageMetadata) -> anyhow::Result<()> { let path = metadata.root().to_path_buf(); @@ -176,6 +175,8 @@ impl Workspace { /// Checks all open files in the workspace and its dependencies. #[tracing::instrument(level = "debug", skip_all)] pub fn check(self, db: &dyn Db) -> Vec { + tracing::debug!("Checking workspace"); + let mut result = Vec::new(); if let Some(open_files) = self.open_files(db) { @@ -194,16 +195,18 @@ impl Workspace { /// Opens a file in the workspace. /// /// This changes the behavior of `check` to only check the open files rather than all files in the workspace. - #[tracing::instrument(level = "debug", skip(self, db))] pub fn open_file(self, db: &mut dyn Db, file: File) { + tracing::debug!("Opening file {}", file.path(db)); + let mut open_files = self.take_open_files(db); open_files.insert(file); self.set_open_files(db, open_files); } /// Closes a file in the workspace. - #[tracing::instrument(level = "debug", skip(self, db))] pub fn close_file(self, db: &mut dyn Db, file: File) -> bool { + tracing::debug!("Closing file {}", file.path(db)); + let mut open_files = self.take_open_files(db); let removed = open_files.remove(&file); @@ -224,6 +227,8 @@ impl Workspace { /// This changes the behavior of `check` to only check the open files rather than all files in the workspace. #[tracing::instrument(level = "debug", skip(self, db))] pub fn set_open_files(self, db: &mut dyn Db, open_files: FxHashSet) { + tracing::debug!("Set open workspace files (count: {})", open_files.len()); + self.set_open_fileset(db).to(Some(Arc::new(open_files))); } @@ -231,6 +236,8 @@ impl Workspace { /// /// This changes the behavior of `check` to check all files in the workspace instead of just the open files. pub fn take_open_files(self, db: &mut dyn Db) -> FxHashSet { + tracing::debug!("Take open workspace files"); + // Salsa will cancel any pending queries and remove its own reference to `open_files` // so that the reference counter to `open_files` now drops to 1. let open_files = self.set_open_fileset(db).to(None); @@ -256,6 +263,12 @@ impl Package { #[tracing::instrument(level = "debug", skip(db))] pub fn remove_file(self, db: &mut dyn Db, file: File) { + tracing::debug!( + "Remove file {} from package {}", + file.path(db), + self.name(db) + ); + let Some(mut index) = PackageFiles::indexed_mut(db, self) else { return; }; @@ -263,8 +276,9 @@ impl Package { index.remove(file); } - #[tracing::instrument(level = "debug", skip(db))] pub fn add_file(self, db: &mut dyn Db, file: File) { + tracing::debug!("Add file {} to package {}", file.path(db), self.name(db)); + let Some(mut index) = PackageFiles::indexed_mut(db, self) else { return; }; @@ -274,6 +288,8 @@ impl Package { #[tracing::instrument(level = "debug", skip(db))] pub(crate) fn check(self, db: &dyn Db) -> Vec { + tracing::debug!("Checking package {}", self.root(db)); + let mut result = Vec::new(); for file in &self.files(db).read() { let diagnostics = check_file(db, file); @@ -286,10 +302,12 @@ impl Package { /// Returns the files belonging to this package. #[salsa::tracked] pub fn files(self, db: &dyn Db) -> IndexedFiles { + let _entered = tracing::debug_span!("files").entered(); let files = self.file_set(db); let indexed = match files.get() { Index::Lazy(vacant) => { + tracing::debug!("Indexing files for package {}", self.name(db)); let files = discover_package_files(db, self.root(db)); vacant.set(files) } @@ -317,8 +335,9 @@ impl Package { } } - #[tracing::instrument(level = "debug", skip(db))] pub fn reload_files(self, db: &mut dyn Db) { + tracing::debug!("Reload files for package {}", self.name(db)); + if !self.file_set(db).is_lazy() { // Force a re-index of the files in the next revision. self.set_file_set(db).to(PackageFiles::lazy()); @@ -327,6 +346,10 @@ impl Package { } pub(super) fn check_file(db: &dyn Db, file: File) -> Diagnostics { + let path = file.path(db); + let _span = tracing::debug_span!("check_file", file=%path).entered(); + tracing::debug!("Checking file {path}"); + let mut diagnostics = Vec::new(); diagnostics.extend_from_slice(lint_syntax(db, file)); diagnostics.extend_from_slice(lint_semantic(db, file)); diff --git a/crates/ruff_db/src/files.rs b/crates/ruff_db/src/files.rs index 74940fc463f05..cf17740afcdb5 100644 --- a/crates/ruff_db/src/files.rs +++ b/crates/ruff_db/src/files.rs @@ -77,7 +77,6 @@ impl Files { /// /// The operation always succeeds even if the path doesn't exist on disk, isn't accessible or if the path points to a directory. /// In these cases, a file with status [`FileStatus::NotFound`] is returned. - #[tracing::instrument(level = "trace", skip(self, db))] fn system(&self, db: &dyn Db, path: &SystemPath) -> File { let absolute = SystemPath::absolute(path, db.system().current_directory()); @@ -86,6 +85,8 @@ impl Files { .system_by_path .entry(absolute.clone()) .or_insert_with(|| { + tracing::trace!("Adding file {path}"); + let metadata = db.system().path_metadata(path); let durability = self .root(db, path) @@ -118,7 +119,6 @@ impl Files { /// Looks up a vendored file by its path. Returns `Some` if a vendored file for the given path /// exists and `None` otherwise. - #[tracing::instrument(level = "trace", skip(self, db))] fn vendored(&self, db: &dyn Db, path: &VendoredPath) -> Result { let file = match self.inner.vendored_by_path.entry(path.to_path_buf()) { Entry::Occupied(entry) => *entry.get(), @@ -131,6 +131,7 @@ impl Files { Err(_) => return Err(FileError::NotFound), }; + tracing::trace!("Adding vendored file {}", path); let file = File::builder(FilePath::Vendored(path.to_path_buf())) .permissions(Some(0o444)) .revision(metadata.revision()) @@ -151,13 +152,14 @@ impl Files { /// For a non-existing file, creates a new salsa [`File`] ingredient and stores it for future lookups. /// /// The operations fails if the system failed to provide a metadata for the path. - #[tracing::instrument(level = "trace", skip(self, db), ret)] pub fn add_virtual_file(&self, db: &dyn Db, path: &SystemVirtualPath) -> Option { let file = match self.inner.system_virtual_by_path.entry(path.to_path_buf()) { Entry::Occupied(entry) => *entry.get(), Entry::Vacant(entry) => { let metadata = db.system().virtual_path_metadata(path).ok()?; + tracing::trace!("Adding virtual file {}", path); + let file = File::builder(FilePath::SystemVirtual(path.to_path_buf())) .revision(metadata.revision()) .permissions(metadata.permissions()) @@ -207,9 +209,9 @@ impl Files { /// Refreshing the state of every file under `path` is expensive. It requires iterating over all known files /// and making system calls to get the latest status of each file in `path`. /// That's why [`File::sync_path`] and [`File::sync_path`] is preferred if it is known that the path is a file. - #[tracing::instrument(level = "debug", skip(db))] pub fn sync_recursively(db: &mut dyn Db, path: &SystemPath) { let path = SystemPath::absolute(path, db.system().current_directory()); + tracing::debug!("Syncing all files in {path}"); let inner = Arc::clone(&db.files().inner); for entry in inner.system_by_path.iter_mut() { @@ -237,8 +239,8 @@ impl Files { /// # Performance /// Refreshing the state of every file is expensive. It requires iterating over all known files and /// issuing a system call to get the latest status of each file. - #[tracing::instrument(level = "debug", skip(db))] pub fn sync_all(db: &mut dyn Db) { + tracing::debug!("Syncing all files"); let inner = Arc::clone(&db.files().inner); for entry in inner.system_by_path.iter_mut() { File::sync_system_path(db, entry.key(), Some(*entry.value())); @@ -350,7 +352,6 @@ impl File { } /// Refreshes the file metadata by querying the file system if needed. - #[tracing::instrument(level = "debug", skip(db))] pub fn sync_path(db: &mut dyn Db, path: &SystemPath) { let absolute = SystemPath::absolute(path, db.system().current_directory()); Files::touch_root(db, &absolute); @@ -358,7 +359,6 @@ impl File { } /// Syncs the [`File`]'s state with the state of the file on the system. - #[tracing::instrument(level = "debug", skip(db))] pub fn sync(self, db: &mut dyn Db) { let path = self.path(db).clone(); @@ -413,16 +413,19 @@ impl File { let durability = durability.unwrap_or_default(); if file.status(db) != status { + tracing::debug!("Updating the status of {}", file.path(db),); file.set_status(db).with_durability(durability).to(status); } if file.revision(db) != revision { + tracing::debug!("Updating the revision of {}", file.path(db)); file.set_revision(db) .with_durability(durability) .to(revision); } if file.permissions(db) != permission { + tracing::debug!("Updating the permissions of {}", file.path(db),); file.set_permissions(db) .with_durability(durability) .to(permission); diff --git a/crates/ruff_db/src/files/path.rs b/crates/ruff_db/src/files/path.rs index 816eaf461a3db..fddac0fa226fc 100644 --- a/crates/ruff_db/src/files/path.rs +++ b/crates/ruff_db/src/files/path.rs @@ -2,6 +2,7 @@ use crate::files::{system_path_to_file, vendored_path_to_file, File}; use crate::system::{SystemPath, SystemPathBuf, SystemVirtualPath, SystemVirtualPathBuf}; use crate::vendored::{VendoredPath, VendoredPathBuf}; use crate::Db; +use std::fmt::{Display, Formatter}; /// Path to a file. /// @@ -209,3 +210,13 @@ impl PartialEq for VendoredPathBuf { other == self } } + +impl Display for FilePath { + fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { + match self { + FilePath::System(path) => std::fmt::Display::fmt(path, f), + FilePath::SystemVirtual(path) => std::fmt::Display::fmt(path, f), + FilePath::Vendored(path) => std::fmt::Display::fmt(path, f), + } + } +} diff --git a/crates/ruff_db/src/parsed.rs b/crates/ruff_db/src/parsed.rs index 90afb1fa7ba36..610372b59c57f 100644 --- a/crates/ruff_db/src/parsed.rs +++ b/crates/ruff_db/src/parsed.rs @@ -22,7 +22,7 @@ use crate::Db; /// for determining if a query result is unchanged. #[salsa::tracked(return_ref, no_eq)] pub fn parsed_module(db: &dyn Db, file: File) -> ParsedModule { - let _span = tracing::trace_span!("parse_module", file = ?file.path(db)).entered(); + let _span = tracing::trace_span!("parsed_module", file = %file.path(db)).entered(); let source = source_text(db, file); let path = file.path(db); diff --git a/crates/ruff_db/src/source.rs b/crates/ruff_db/src/source.rs index 3bebac8e5778d..92b54500db25b 100644 --- a/crates/ruff_db/src/source.rs +++ b/crates/ruff_db/src/source.rs @@ -14,7 +14,7 @@ use crate::Db; #[salsa::tracked] pub fn source_text(db: &dyn Db, file: File) -> SourceText { let path = file.path(db); - let _span = tracing::trace_span!("source_text", file=?path).entered(); + let _span = tracing::trace_span!("source_text", file = %path).entered(); let is_notebook = match path { FilePath::System(system) => system.extension().is_some_and(|extension| { diff --git a/crates/ruff_db/src/vendored/path.rs b/crates/ruff_db/src/vendored/path.rs index 7144ae5a3df37..a8cb07a672363 100644 --- a/crates/ruff_db/src/vendored/path.rs +++ b/crates/ruff_db/src/vendored/path.rs @@ -1,4 +1,5 @@ use std::borrow::Borrow; +use std::fmt::Formatter; use std::ops::Deref; use std::path; @@ -197,3 +198,15 @@ impl TryFrom for VendoredPathBuf { Ok(VendoredPathBuf(camino::Utf8PathBuf::try_from(value)?)) } } + +impl std::fmt::Display for VendoredPath { + fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { + write!(f, "vendored://{}", &self.0) + } +} + +impl std::fmt::Display for VendoredPathBuf { + fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { + std::fmt::Display::fmt(self.as_path(), f) + } +}