diff --git a/.gitignore b/.gitignore index 4302ff30a762a4..ad7de8ce76cffb 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 3880a9982a5e1a..fb5fbcd0b812c7 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 b9e4e0d625f4ba..7ff4b380c89909 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 50781acfd123b9..5fc0fcf4926ece 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 00000000000000..6a350c6b551ef9 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 00000000000000..275c08c245ffd6 --- /dev/null +++ b/crates/red_knot/docs/tracing.md @@ -0,0 +1,89 @@ +# 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`..`error` 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. + +## 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 00000000000000..7a9c796b5e107b --- /dev/null +++ b/crates/red_knot/src/logging.rs @@ -0,0 +1,251 @@ +//! 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 [`LogLevel::Warn`]. + Default, + + /// Enables verbose output. Emits ruff and red knot events up to the [`LogLevel::Info`] + Verbose, + + /// Enables a more verbose tracing format and emits ruff and red_knot events up to [`LogLevel::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, + }) +} + +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 1a6a555be2767a..208306416449fb 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, VerbosityLevel}; + +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(); @@ -192,11 +188,11 @@ struct MainLoop { /// The file system watcher, if running in watch mode. watcher: Option, - verbosity: Option, + verbosity: VerbosityLevel, } impl MainLoop { - fn new(verbosity: Option) -> (Self, MainLoopCancellationToken) { + fn new(verbosity: VerbosityLevel) -> (Self, MainLoopCancellationToken) { let (sender, receiver) = crossbeam_channel::bounded(10); ( @@ -254,7 +250,7 @@ impl MainLoop { if check_revision == revision { eprintln!("{}", result.join("\n")); - if self.verbosity == Some(VerbosityLevel::Trace) { + if self.verbosity.is_trace() { eprintln!("{}", countme::get_all()); } } @@ -284,7 +280,7 @@ impl MainLoop { #[allow(clippy::print_stderr, clippy::unused_self)] fn exit(self) { - if self.verbosity == Some(VerbosityLevel::Trace) { + if self.verbosity.is_trace() { eprintln!("Exit"); eprintln!("{}", countme::get_all()); } @@ -313,63 +309,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 692553bcd93e20..8b137891791fe9 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/ruff_db/src/parsed.rs b/crates/ruff_db/src/parsed.rs index 90afb1fa7ba36a..3b032fef018c4c 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);