diff --git a/crates/red_knot/docs/tracing.md b/crates/red_knot/docs/tracing.md index 275c08c245ffd..ac62e24172b46 100644 --- a/crates/red_knot/docs/tracing.md +++ b/crates/red_knot/docs/tracing.md @@ -47,6 +47,20 @@ 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 diff --git a/crates/red_knot/src/logging.rs b/crates/red_knot/src/logging.rs index 7a9c796b5e107..c3266b32a6afd 100644 --- a/crates/red_knot/src/logging.rs +++ b/crates/red_knot/src/logging.rs @@ -42,16 +42,16 @@ impl Verbosity { #[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 [`LogLevel::Warn`]. + /// 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 [`LogLevel::Info`] + /// Enables verbose output. Emits Ruff and Red Knot events up to the [`INFO`](tracing::Level::INFO) Verbose, - /// Enables a more verbose tracing format and emits ruff and red_knot events up to [`LogLevel::Debug`] Corresponds to `-vv` + /// 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`. + /// Enables all tracing events and uses a tree-like output format. Corresponds to `-vvv`. Trace, } @@ -145,6 +145,7 @@ pub(crate) fn setup_tracing(level: VerbosityLevel) -> anyhow::Result() -> ( Option>>, Option>>, @@ -208,7 +209,7 @@ where let formatted_level = level.to_string(); match *level { tracing::Level::TRACE => { - write!(writer, "{} ", formatted_level.purple().bold())? + write!(writer, "{} ", formatted_level.purple().bold())?; } tracing::Level::DEBUG => write!(writer, "{} ", formatted_level.blue().bold())?, tracing::Level::INFO => write!(writer, "{} ", formatted_level.green().bold())?, diff --git a/crates/red_knot/src/main.rs b/crates/red_knot/src/main.rs index 436ee52a94765..179c866481280 100644 --- a/crates/red_knot/src/main.rs +++ b/crates/red_knot/src/main.rs @@ -13,7 +13,7 @@ use ruff_db::program::{ProgramSettings, SearchPathSettings}; use ruff_db::system::{OsSystem, System, SystemPathBuf}; use target_version::TargetVersion; -use crate::logging::{setup_tracing, Verbosity, VerbosityLevel}; +use crate::logging::{setup_tracing, Verbosity}; mod logging; mod target_version; @@ -155,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)); @@ -173,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(()) @@ -187,12 +189,10 @@ struct MainLoop { /// The file system watcher, if running in watch mode. watcher: Option, - - verbosity: VerbosityLevel, } impl MainLoop { - fn new(verbosity: VerbosityLevel) -> (Self, MainLoopCancellationToken) { + fn new() -> (Self, MainLoopCancellationToken) { let (sender, receiver) = crossbeam_channel::bounded(10); ( @@ -200,13 +200,13 @@ 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(); @@ -214,26 +214,27 @@ impl MainLoop { self.watcher = Some(WorkspaceWatcher::new(watcher, db)); - let is_trace = self.verbosity.is_trace(); self.run(db); - if is_trace { - eprintln!("Exit"); - eprintln!("{}", countme::get_all()); - } - 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(); @@ -257,15 +258,15 @@ impl MainLoop { } => { if check_revision == revision { eprintln!("{}", result.join("\n")); - - if self.verbosity.is_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; } + + tracing::trace!("Counts after last check:\n{}", countme::get_all()); } MainLoopMessage::ApplyChanges(changes) => { @@ -281,6 +282,8 @@ impl MainLoop { return; } } + + tracing::debug!("Waiting for next main loop message."); } } } 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 f076e1675a38f..aecd0a8fdac1a 100644 --- a/crates/red_knot_workspace/src/site_packages.rs +++ b/crates/red_knot_workspace/src/site_packages.rs @@ -117,6 +117,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..7654df420d1a3 100644 --- a/crates/red_knot_workspace/src/workspace.rs +++ b/crates/red_knot_workspace/src/workspace.rs @@ -176,6 +176,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) { @@ -274,6 +276,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); @@ -327,6 +331,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/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 3b032fef018c4..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!("parsed_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) + } +}