Unnamed repository; edit this file 'description' to name the repository.
Auto merge of #16394 - davidbarsky:david/add-more-tracing-spans, r=Veykril
internal: add some `tracing` to {Request, Notification}Dispatch
Some of the tracing config would need to be changed in order to benefit more from this (especially `.with_span_events(FmtSpan::CLOSE)`), which provides span events like the following:
```
2024-01-18T02:41:06.675779Z INFO request{method="textDocument/codeLens" request_id=RequestId(I32(17))}: rust_analyzer::dispatch: close time.busy=61.8µs time.idle=5.29µs
```
I dunno if y'all need `LoggerFormatter` in here, but if you don't, I'd be happy to yeet it out of rust-analyzer. In any case, this provided a pretty decent amount of information in the logs, and I can expand this as needed or we can land this PR and expand later.
96 files changed, 658 insertions, 825 deletions
diff --git a/Cargo.lock b/Cargo.lock index ca1fc63570..dfaf5c23f1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -19,11 +19,11 @@ checksum = "f26201604c87b1e01bd3d98f8d5d9a8fcbb815e8cedb41ffccbeb4bf593a35fe" [[package]] name = "always-assert" -version = "0.1.3" +version = "0.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4436e0292ab1bb631b42973c61205e704475fe8126af845c8d923c0996328127" +checksum = "a1078fa1ce1e34b1872d8611ad921196d76bdd7027e949fbe31231abde201892" dependencies = [ - "log", + "tracing", ] [[package]] @@ -78,6 +78,7 @@ dependencies = [ "span", "stdx", "syntax", + "tracing", "triomphe", "vfs", ] @@ -497,6 +498,7 @@ dependencies = [ "span", "stdx", "syntax", + "tracing", "triomphe", "tt", ] @@ -671,6 +673,7 @@ dependencies = [ "test-fixture", "test-utils", "text-edit", + "tracing", ] [[package]] @@ -691,6 +694,7 @@ dependencies = [ "test-fixture", "test-utils", "text-edit", + "tracing", ] [[package]] @@ -748,6 +752,7 @@ dependencies = [ "test-fixture", "test-utils", "text-edit", + "tracing", ] [[package]] @@ -1343,6 +1348,7 @@ dependencies = [ "once_cell", "perf-event", "tikv-jemalloc-ctl", + "tracing", "winapi", ] @@ -1582,7 +1588,6 @@ dependencies = [ "tikv-jemallocator", "toolchain", "tracing", - "tracing-log", "tracing-subscriber", "tracing-tree", "triomphe", @@ -1596,26 +1601,26 @@ dependencies = [ [[package]] name = "rust-analyzer-salsa" -version = "0.17.0-pre.5" +version = "0.17.0-pre.6" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ca9d387a9801f4fb9b366789ad1bfc08448cafc49cf148d907cfcd88ab665d7f" +checksum = "719825638c59fd26a55412a24561c7c5bcf54364c88b9a7a04ba08a6eafaba8d" dependencies = [ "indexmap", "lock_api", - "log", "oorandom", "parking_lot", "rust-analyzer-salsa-macros", "rustc-hash", "smallvec", + "tracing", "triomphe", ] [[package]] name = "rust-analyzer-salsa-macros" -version = "0.17.0-pre.5" +version = "0.17.0-pre.6" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a2035f385d7fae31e9b086f40b272ee1d79c484472f31c9a10348a406e841eaf" +checksum = "4d96498e9684848c6676c399032ebc37c52da95ecbefa83d71ccc53b9f8a4a8e" dependencies = [ "heck", "proc-macro2", @@ -1864,6 +1869,7 @@ dependencies = [ "stdx", "test-utils", "text-edit", + "tracing", "triomphe", "ungrammar", ] @@ -1891,6 +1897,7 @@ dependencies = [ "rustc-hash", "stdx", "text-size", + "tracing", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index 56db5a28c0..d5f9740c6d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -113,7 +113,7 @@ itertools = "0.12.0" libc = "0.2.150" nohash-hasher = "0.2.0" rayon = "1.8.0" -rust-analyzer-salsa = "0.17.0-pre.5" +rust-analyzer-salsa = "0.17.0-pre.6" rustc-hash = "1.1.0" semver = "1.0.14" serde = { version = "1.0.192", features = ["derive"] } @@ -128,9 +128,9 @@ text-size = "1.1.1" tracing = "0.1.40" tracing-tree = "0.3.0" tracing-subscriber = { version = "0.3.18", default-features = false, features = [ - "registry", - "fmt", - "tracing-log", + "registry", + "fmt", + "tracing-log", ] } triomphe = { version = "0.1.10", default-features = false, features = ["std"] } xshell = "0.2.5" diff --git a/crates/base-db/Cargo.toml b/crates/base-db/Cargo.toml index 1aa43175f9..485ba78846 100644 --- a/crates/base-db/Cargo.toml +++ b/crates/base-db/Cargo.toml @@ -17,6 +17,7 @@ rust-analyzer-salsa.workspace = true rustc-hash.workspace = true triomphe.workspace = true semver.workspace = true +tracing.workspace = true # local deps cfg.workspace = true @@ -27,4 +28,4 @@ vfs.workspace = true span.workspace = true [lints] -workspace = true
\ No newline at end of file +workspace = true diff --git a/crates/base-db/src/change.rs b/crates/base-db/src/change.rs index 4332e572e2..003ffb24d9 100644 --- a/crates/base-db/src/change.rs +++ b/crates/base-db/src/change.rs @@ -51,7 +51,7 @@ impl FileChange { } pub fn apply(self, db: &mut dyn SourceDatabaseExt) { - let _p = profile::span("RootDatabase::apply_change"); + let _p = tracing::span!(tracing::Level::INFO, "RootDatabase::apply_change").entered(); if let Some(roots) = self.roots { for (idx, root) in roots.into_iter().enumerate() { let root_id = SourceRootId(idx as u32); diff --git a/crates/base-db/src/input.rs b/crates/base-db/src/input.rs index 852f36ea71..51e6fdb951 100644 --- a/crates/base-db/src/input.rs +++ b/crates/base-db/src/input.rs @@ -494,7 +494,7 @@ impl CrateGraph { from: CrateId, dep: Dependency, ) -> Result<(), CyclicDependenciesError> { - let _p = profile::span("add_dep"); + let _p = tracing::span!(tracing::Level::INFO, "add_dep").entered(); self.check_cycle_after_dependency(from, dep.crate_id)?; diff --git a/crates/base-db/src/lib.rs b/crates/base-db/src/lib.rs index 90da7efd4a..d7fc9d4c95 100644 --- a/crates/base-db/src/lib.rs +++ b/crates/base-db/src/lib.rs @@ -65,7 +65,7 @@ pub trait SourceDatabase: FileLoader + std::fmt::Debug { } fn parse(db: &dyn SourceDatabase, file_id: FileId) -> Parse<ast::SourceFile> { - let _p = profile::span("parse_query").detail(|| format!("{file_id:?}")); + let _p = tracing::span!(tracing::Level::INFO, "parse_query", ?file_id).entered(); let text = db.file_text(file_id); SourceFile::parse(&text) } @@ -116,7 +116,7 @@ impl<T: SourceDatabaseExt> FileLoader for FileLoaderDelegate<&'_ T> { } fn relevant_crates(&self, file_id: FileId) -> Arc<[CrateId]> { - let _p = profile::span("relevant_crates"); + let _p = tracing::span!(tracing::Level::INFO, "relevant_crates").entered(); let source_root = self.0.file_source_root(file_id); self.0.source_root_crates(source_root) } diff --git a/crates/hir-def/src/attr.rs b/crates/hir-def/src/attr.rs index a8e081705e..bee6f0083b 100644 --- a/crates/hir-def/src/attr.rs +++ b/crates/hir-def/src/attr.rs @@ -75,7 +75,7 @@ impl Attrs { db: &dyn DefDatabase, v: VariantId, ) -> Arc<ArenaMap<LocalFieldId, Attrs>> { - let _p = profile::span("fields_attrs_query"); + let _p = tracing::span!(tracing::Level::INFO, "fields_attrs_query").entered(); // FIXME: There should be some proper form of mapping between item tree field ids and hir field ids let mut res = ArenaMap::default(); @@ -322,7 +322,7 @@ impl AttrsWithOwner { } pub(crate) fn attrs_query(db: &dyn DefDatabase, def: AttrDefId) -> Attrs { - let _p = profile::span("attrs_query"); + let _p = tracing::span!(tracing::Level::INFO, "attrs_query").entered(); // FIXME: this should use `Trace` to avoid duplication in `source_map` below let raw_attrs = match def { AttrDefId::ModuleId(module) => { diff --git a/crates/hir-def/src/body.rs b/crates/hir-def/src/body.rs index e4308c6b7f..ce8a9eab14 100644 --- a/crates/hir-def/src/body.rs +++ b/crates/hir-def/src/body.rs @@ -122,7 +122,7 @@ impl Body { db: &dyn DefDatabase, def: DefWithBodyId, ) -> (Arc<Body>, Arc<BodySourceMap>) { - let _p = profile::span("body_with_source_map_query"); + let _p = tracing::span!(tracing::Level::INFO, "body_with_source_map_query").entered(); let mut params = None; let mut is_async_fn = false; diff --git a/crates/hir-def/src/data.rs b/crates/hir-def/src/data.rs index ca02b5d68e..73fbad5e67 100644 --- a/crates/hir-def/src/data.rs +++ b/crates/hir-def/src/data.rs @@ -340,7 +340,7 @@ impl ImplData { db: &dyn DefDatabase, id: ImplId, ) -> (Arc<ImplData>, DefDiagnostics) { - let _p = profile::span("impl_data_with_diagnostics_query"); + let _p = tracing::span!(tracing::Level::INFO, "impl_data_with_diagnostics_query").entered(); let ItemLoc { container: module_id, id: tree_id } = id.lookup(db); let item_tree = tree_id.item_tree(db); diff --git a/crates/hir-def/src/db.rs b/crates/hir-def/src/db.rs index 97845f0f2b..68f57600ec 100644 --- a/crates/hir-def/src/db.rs +++ b/crates/hir-def/src/db.rs @@ -254,7 +254,7 @@ fn include_macro_invoc(db: &dyn DefDatabase, krate: CrateId) -> Vec<(MacroCallId } fn crate_def_map_wait(db: &dyn DefDatabase, krate: CrateId) -> Arc<DefMap> { - let _p = profile::span("crate_def_map:wait"); + let _p = tracing::span!(tracing::Level::INFO, "crate_def_map:wait").entered(); db.crate_def_map_query(krate) } diff --git a/crates/hir-def/src/find_path.rs b/crates/hir-def/src/find_path.rs index efda8abf4b..515a2cc824 100644 --- a/crates/hir-def/src/find_path.rs +++ b/crates/hir-def/src/find_path.rs @@ -26,7 +26,7 @@ pub fn find_path( prefer_no_std: bool, prefer_prelude: bool, ) -> Option<ModPath> { - let _p = profile::span("find_path"); + let _p = tracing::span!(tracing::Level::INFO, "find_path").entered(); find_path_inner(FindPathCtx { db, prefixed: None, prefer_no_std, prefer_prelude }, item, from) } @@ -38,7 +38,7 @@ pub fn find_path_prefixed( prefer_no_std: bool, prefer_prelude: bool, ) -> Option<ModPath> { - let _p = profile::span("find_path_prefixed"); + let _p = tracing::span!(tracing::Level::INFO, "find_path_prefixed").entered(); find_path_inner( FindPathCtx { db, prefixed: Some(prefix_kind), prefer_no_std, prefer_prelude }, item, @@ -497,7 +497,7 @@ fn find_local_import_locations( item: ItemInNs, from: ModuleId, ) -> Vec<(ModuleId, Name)> { - let _p = profile::span("find_local_import_locations"); + let _p = tracing::span!(tracing::Level::INFO, "find_local_import_locations").entered(); // `from` can import anything below `from` with visibility of at least `from`, and anything // above `from` with any visibility. That means we do not need to descend into private siblings diff --git a/crates/hir-def/src/generics.rs b/crates/hir-def/src/generics.rs index 7daae821f8..349d327aaa 100644 --- a/crates/hir-def/src/generics.rs +++ b/crates/hir-def/src/generics.rs @@ -373,7 +373,7 @@ impl GenericParams { db: &dyn DefDatabase, def: GenericDefId, ) -> Interned<GenericParams> { - let _p = profile::span("generic_params_query"); + let _p = tracing::span!(tracing::Level::INFO, "generic_params_query").entered(); let krate = def.module(db).krate; let cfg_options = db.crate_graph(); diff --git a/crates/hir-def/src/import_map.rs b/crates/hir-def/src/import_map.rs index 15c127f156..66d9cf54da 100644 --- a/crates/hir-def/src/import_map.rs +++ b/crates/hir-def/src/import_map.rs @@ -75,7 +75,7 @@ impl ImportMap { } pub(crate) fn import_map_query(db: &dyn DefDatabase, krate: CrateId) -> Arc<Self> { - let _p = profile::span("import_map_query"); + let _p = tracing::span!(tracing::Level::INFO, "import_map_query").entered(); let map = Self::collect_import_map(db, krate); @@ -126,7 +126,7 @@ impl ImportMap { } fn collect_import_map(db: &dyn DefDatabase, krate: CrateId) -> ImportMapIndex { - let _p = profile::span("collect_import_map"); + let _p = tracing::span!(tracing::Level::INFO, "collect_import_map").entered(); let def_map = db.crate_def_map(krate); let mut map = FxIndexMap::default(); @@ -216,7 +216,7 @@ impl ImportMap { is_type_in_ns: bool, trait_import_info: &ImportInfo, ) { - let _p = profile::span("collect_trait_assoc_items"); + let _p = tracing::span!(tracing::Level::INFO, "collect_trait_assoc_items").entered(); for &(ref assoc_item_name, item) in &db.trait_data(tr).items { let module_def_id = match item { AssocItemId::FunctionId(f) => ModuleDefId::from(f), @@ -398,7 +398,7 @@ pub fn search_dependencies( krate: CrateId, ref query: Query, ) -> FxHashSet<ItemInNs> { - let _p = profile::span("search_dependencies").detail(|| format!("{query:?}")); + let _p = tracing::span!(tracing::Level::INFO, "search_dependencies", ?query).entered(); let graph = db.crate_graph(); diff --git a/crates/hir-def/src/item_tree.rs b/crates/hir-def/src/item_tree.rs index c37cf52155..299ad33c34 100644 --- a/crates/hir-def/src/item_tree.rs +++ b/crates/hir-def/src/item_tree.rs @@ -109,7 +109,8 @@ pub struct ItemTree { impl ItemTree { pub(crate) fn file_item_tree_query(db: &dyn DefDatabase, file_id: HirFileId) -> Arc<ItemTree> { - let _p = profile::span("file_item_tree_query").detail(|| format!("{file_id:?}")); + let _p = tracing::span!(tracing::Level::INFO, "file_item_tree_query", ?file_id).entered(); + let syntax = db.parse_or_expand(file_id); let ctx = lower::Ctx::new(db, file_id); diff --git a/crates/hir-def/src/lang_item.rs b/crates/hir-def/src/lang_item.rs index 60c8baf424..7d98f6cfe8 100644 --- a/crates/hir-def/src/lang_item.rs +++ b/crates/hir-def/src/lang_item.rs @@ -91,7 +91,7 @@ impl LangItems { db: &dyn DefDatabase, krate: CrateId, ) -> Option<Arc<LangItems>> { - let _p = profile::span("crate_lang_items_query"); + let _p = tracing::span!(tracing::Level::INFO, "crate_lang_items_query").entered(); let mut lang_items = LangItems::default(); @@ -163,7 +163,7 @@ impl LangItems { start_crate: CrateId, item: LangItem, ) -> Option<LangItemTarget> { - let _p = profile::span("lang_item_query"); + let _p = tracing::span!(tracing::Level::INFO, "lang_item_query").entered(); if let Some(target) = db.crate_lang_items(start_crate).and_then(|it| it.items.get(&item).copied()) { @@ -183,7 +183,7 @@ impl LangItems { ) where T: Into<AttrDefId> + Copy, { - let _p = profile::span("collect_lang_item"); + let _p = tracing::span!(tracing::Level::INFO, "collect_lang_item").entered(); if let Some(lang_item) = lang_attr(db, item.into()) { self.items.entry(lang_item).or_insert_with(|| constructor(item)); } @@ -199,7 +199,7 @@ pub(crate) fn notable_traits_in_deps( db: &dyn DefDatabase, krate: CrateId, ) -> Arc<[Arc<[TraitId]>]> { - let _p = profile::span("notable_traits_in_deps").detail(|| format!("{krate:?}")); + let _p = tracing::span!(tracing::Level::INFO, "notable_traits_in_deps", ?krate).entered(); let crate_graph = db.crate_graph(); Arc::from_iter( @@ -208,7 +208,7 @@ pub(crate) fn notable_traits_in_deps( } pub(crate) fn crate_notable_traits(db: &dyn DefDatabase, krate: CrateId) -> Option<Arc<[TraitId]>> { - let _p = profile::span("crate_notable_traits").detail(|| format!("{krate:?}")); + let _p = tracing::span!(tracing::Level::INFO, "crate_notable_traits", ?krate).entered(); let mut traits = Vec::new(); diff --git a/crates/hir-def/src/nameres.rs b/crates/hir-def/src/nameres.rs index 2295df16fd..1fa975789e 100644 --- a/crates/hir-def/src/nameres.rs +++ b/crates/hir-def/src/nameres.rs @@ -306,9 +306,10 @@ impl DefMap { pub const ROOT: LocalModuleId = LocalModuleId::from_raw(la_arena::RawIdx::from_u32(0)); pub(crate) fn crate_def_map_query(db: &dyn DefDatabase, krate: CrateId) -> Arc<DefMap> { - let _p = profile::span("crate_def_map_query").detail(|| { - db.crate_graph()[krate].display_name.as_deref().unwrap_or_default().to_string() - }); + let crate_graph = db.crate_graph(); + let krate_name = crate_graph[krate].display_name.as_deref().unwrap_or_default(); + + let _p = tracing::span!(tracing::Level::INFO, "crate_def_map_query", ?krate_name).entered(); let crate_graph = db.crate_graph(); diff --git a/crates/hir-def/src/nameres/collector.rs b/crates/hir-def/src/nameres/collector.rs index 248d3213d5..bdef9c8a93 100644 --- a/crates/hir-def/src/nameres/collector.rs +++ b/crates/hir-def/src/nameres/collector.rs @@ -273,7 +273,7 @@ struct DefCollector<'a> { impl DefCollector<'_> { fn seed_with_top_level(&mut self) { - let _p = profile::span("seed_with_top_level"); + let _p = tracing::span!(tracing::Level::INFO, "seed_with_top_level").entered(); let file_id = self.db.crate_graph()[self.def_map.krate].root_file_id; let item_tree = self.db.file_item_tree(file_id.into()); @@ -401,7 +401,7 @@ impl DefCollector<'_> { } fn resolution_loop(&mut self) { - let _p = profile::span("DefCollector::resolution_loop"); + let _p = tracing::span!(tracing::Level::INFO, "DefCollector::resolution_loop").entered(); // main name resolution fixed-point loop. let mut i = 0; @@ -410,7 +410,7 @@ impl DefCollector<'_> { self.db.unwind_if_cancelled(); { - let _p = profile::span("resolve_imports loop"); + let _p = tracing::span!(tracing::Level::INFO, "resolve_imports loop").entered(); 'resolve_imports: loop { if self.resolve_imports() == ReachedFixedPoint::Yes { @@ -436,7 +436,7 @@ impl DefCollector<'_> { } fn collect(&mut self) { - let _p = profile::span("DefCollector::collect"); + let _p = tracing::span!(tracing::Level::INFO, "DefCollector::collect").entered(); self.resolution_loop(); @@ -792,8 +792,8 @@ impl DefCollector<'_> { } fn resolve_import(&self, module_id: LocalModuleId, import: &Import) -> PartialResolvedImport { - let _p = profile::span("resolve_import") - .detail(|| format!("{}", import.path.display(self.db.upcast()))); + let _p = tracing::span!(tracing::Level::INFO, "resolve_import", import_path = %import.path.display(self.db.upcast())) + .entered(); tracing::debug!("resolving import: {:?} ({:?})", import, self.def_map.data.edition); match import.source { ImportSource::ExternCrate { .. } => { @@ -856,7 +856,7 @@ impl DefCollector<'_> { } fn record_resolved_import(&mut self, directive: &ImportDirective) { - let _p = profile::span("record_resolved_import"); + let _p = tracing::span!(tracing::Level::INFO, "record_resolved_import").entered(); let module_id = directive.module_id; let import = &directive.import; @@ -1430,7 +1430,7 @@ impl DefCollector<'_> { fn finish(mut self) -> DefMap { // Emit diagnostics for all remaining unexpanded macros. - let _p = profile::span("DefCollector::finish"); + let _p = tracing::span!(tracing::Level::INFO, "DefCollector::finish").entered(); for directive in &self.unresolved_macros { match &directive.kind { diff --git a/crates/hir-def/src/per_ns.rs b/crates/hir-def/src/per_ns.rs index 14890364d0..6a62ef6970 100644 --- a/crates/hir-def/src/per_ns.rs +++ b/crates/hir-def/src/per_ns.rs @@ -92,7 +92,7 @@ impl PerNs { } pub fn filter_visibility(self, mut f: impl FnMut(Visibility) -> bool) -> PerNs { - let _p = profile::span("PerNs::filter_visibility"); + let _p = tracing::span!(tracing::Level::INFO, "PerNs::filter_visibility").entered(); PerNs { types: self.types.filter(|&(_, v, _)| f(v)), values: self.values.filter(|&(_, v, _)| f(v)), @@ -125,7 +125,7 @@ impl PerNs { } pub fn iter_items(self) -> impl Iterator<Item = (ItemInNs, Option<ImportOrExternCrate>)> { - let _p = profile::span("PerNs::iter_items"); + let _p = tracing::span!(tracing::Level::INFO, "PerNs::iter_items").entered(); self.types .map(|it| (ItemInNs::Types(it.0), it.2)) .into_iter() diff --git a/crates/hir-expand/src/db.rs b/crates/hir-expand/src/db.rs index 8c43017971..19dda651d7 100644 --- a/crates/hir-expand/src/db.rs +++ b/crates/hir-expand/src/db.rs @@ -280,7 +280,7 @@ fn parse_macro_expansion( db: &dyn ExpandDatabase, macro_file: MacroFileId, ) -> ExpandResult<(Parse<SyntaxNode>, Arc<ExpansionSpanMap>)> { - let _p = profile::span("parse_macro_expansion"); + let _p = tracing::span!(tracing::Level::INFO, "parse_macro_expansion").entered(); let loc = db.lookup_intern_macro_call(macro_file.macro_call_id); let expand_to = loc.expand_to(); let mbe::ValueResult { value: tt, err } = macro_expand(db, macro_file.macro_call_id, loc); @@ -501,7 +501,7 @@ fn macro_expand( macro_call_id: MacroCallId, loc: MacroCallLoc, ) -> ExpandResult<CowArc<tt::Subtree>> { - let _p = profile::span("macro_expand"); + let _p = tracing::span!(tracing::Level::INFO, "macro_expand").entered(); let ExpandResult { value: tt, mut err } = match loc.def.kind { MacroDefKind::ProcMacro(..) => return db.expand_proc_macro(macro_call_id).map(CowArc::Arc), diff --git a/crates/hir-ty/src/autoderef.rs b/crates/hir-ty/src/autoderef.rs index 4625a3b01a..991fd2f91d 100644 --- a/crates/hir-ty/src/autoderef.rs +++ b/crates/hir-ty/src/autoderef.rs @@ -142,7 +142,7 @@ pub(crate) fn deref_by_trait( table @ &mut InferenceTable { db, .. }: &mut InferenceTable<'_>, ty: Ty, ) -> Option<Ty> { - let _p = profile::span("deref_by_trait"); + let _p = tracing::span!(tracing::Level::INFO, "deref_by_trait").entered(); if table.resolve_ty_shallow(&ty).inference_var(Interner).is_some() { // don't try to deref unknown variables return None; diff --git a/crates/hir-ty/src/chalk_db.rs b/crates/hir-ty/src/chalk_db.rs index 4d509f20d0..7e460f9f86 100644 --- a/crates/hir-ty/src/chalk_db.rs +++ b/crates/hir-ty/src/chalk_db.rs @@ -689,7 +689,7 @@ pub(crate) fn impl_datum_query( krate: CrateId, impl_id: ImplId, ) -> Arc<ImplDatum> { - let _p = profile::span("impl_datum"); + let _p = tracing::span!(tracing::Level::INFO, "impl_datum").entered(); debug!("impl_datum {:?}", impl_id); let impl_: hir_def::ImplId = from_chalk(db, impl_id); impl_def_datum(db, krate, impl_id, impl_) diff --git a/crates/hir-ty/src/db.rs b/crates/hir-ty/src/db.rs index 89fe8c2b82..21679150b3 100644 --- a/crates/hir-ty/src/db.rs +++ b/crates/hir-ty/src/db.rs @@ -281,7 +281,7 @@ pub trait HirDatabase: DefDatabase + Upcast<dyn DefDatabase> { } fn infer_wait(db: &dyn HirDatabase, def: DefWithBodyId) -> Arc<InferenceResult> { - let _p = profile::span("infer:wait").detail(|| match def { + let detail = match def { DefWithBodyId::FunctionId(it) => db.function_data(it).name.display(db.upcast()).to_string(), DefWithBodyId::StaticId(it) => { db.static_data(it).name.clone().display(db.upcast()).to_string() @@ -297,7 +297,8 @@ fn infer_wait(db: &dyn HirDatabase, def: DefWithBodyId) -> Arc<InferenceResult> db.enum_variant_data(it).name.display(db.upcast()).to_string() } DefWithBodyId::InTypeConstId(it) => format!("in type const {it:?}"), - }); + }; + let _p = tracing::span!(tracing::Level::INFO, "infer:wait", ?detail).entered(); db.infer_query(def) } @@ -307,7 +308,7 @@ fn trait_solve_wait( block: Option<BlockId>, goal: crate::Canonical<crate::InEnvironment<crate::Goal>>, ) -> Option<crate::Solution> { - let _p = profile::span("trait_solve::wait"); + let _p = tracing::span!(tracing::Level::INFO, "trait_solve::wait").entered(); db.trait_solve_query(krate, block, goal) } diff --git a/crates/hir-ty/src/diagnostics/decl_check.rs b/crates/hir-ty/src/diagnostics/decl_check.rs index a37dba4805..78f2005e67 100644 --- a/crates/hir-ty/src/diagnostics/decl_check.rs +++ b/crates/hir-ty/src/diagnostics/decl_check.rs @@ -45,7 +45,7 @@ mod allow { } pub fn incorrect_case(db: &dyn HirDatabase, owner: ModuleDefId) -> Vec<IncorrectCase> { - let _p = profile::span("validate_module_item"); + let _p = tracing::span!(tracing::Level::INFO, "validate_module_item").entered(); let mut validator = DeclValidator::new(db); validator.validate_item(owner); validator.sink diff --git a/crates/hir-ty/src/diagnostics/expr.rs b/crates/hir-ty/src/diagnostics/expr.rs index 530608292e..eda8f2371c 100644 --- a/crates/hir-ty/src/diagnostics/expr.rs +++ b/crates/hir-ty/src/diagnostics/expr.rs @@ -48,7 +48,8 @@ pub enum BodyValidationDiagnostic { impl BodyValidationDiagnostic { pub fn collect(db: &dyn HirDatabase, owner: DefWithBodyId) -> Vec<BodyValidationDiagnostic> { - let _p = profile::span("BodyValidationDiagnostic::collect"); + let _p = + tracing::span!(tracing::Level::INFO, "BodyValidationDiagnostic::collect").entered(); let infer = db.infer(owner); let mut validator = ExprValidator::new(owner, infer); validator.validate_body(db); diff --git a/crates/hir-ty/src/infer.rs b/crates/hir-ty/src/infer.rs index 0d89269b32..71c3f89716 100644 --- a/crates/hir-ty/src/infer.rs +++ b/crates/hir-ty/src/infer.rs @@ -75,7 +75,7 @@ pub(crate) use closure::{CaptureKind, CapturedItem, CapturedItemWithoutTy}; /// The entry point of type inference. pub(crate) fn infer_query(db: &dyn HirDatabase, def: DefWithBodyId) -> Arc<InferenceResult> { - let _p = profile::span("infer_query"); + let _p = tracing::span!(tracing::Level::INFO, "infer_query").entered(); let resolver = def.resolver(db.upcast()); let body = db.body(def); let mut ctx = InferenceContext::new(db, def, &body, resolver); diff --git a/crates/hir-ty/src/infer/unify.rs b/crates/hir-ty/src/infer/unify.rs index 9c41540077..61c8233950 100644 --- a/crates/hir-ty/src/infer/unify.rs +++ b/crates/hir-ty/src/infer/unify.rs @@ -509,7 +509,8 @@ impl<'a> InferenceTable<'a> { } pub(crate) fn resolve_obligations_as_possible(&mut self) { - let _span = profile::span("resolve_obligations_as_possible"); + let _span = + tracing::span!(tracing::Level::INFO, "resolve_obligations_as_possible").entered(); let mut changed = true; let mut obligations = mem::take(&mut self.resolve_obligations_buffer); while mem::take(&mut changed) { diff --git a/crates/hir-ty/src/method_resolution.rs b/crates/hir-ty/src/method_resolution.rs index f8ce3008f1..1c068bf684 100644 --- a/crates/hir-ty/src/method_resolution.rs +++ b/crates/hir-ty/src/method_resolution.rs @@ -143,7 +143,8 @@ pub struct TraitImpls { impl TraitImpls { pub(crate) fn trait_impls_in_crate_query(db: &dyn HirDatabase, krate: CrateId) -> Arc<Self> { - let _p = profile::span("trait_impls_in_crate_query").detail(|| format!("{krate:?}")); + let _p = + tracing::span!(tracing::Level::INFO, "trait_impls_in_crate_query", ?krate).entered(); let mut impls = FxHashMap::default(); Self::collect_def_map(db, &mut impls, &db.crate_def_map(krate)); @@ -155,7 +156,7 @@ impl TraitImpls { db: &dyn HirDatabase, block: BlockId, ) -> Option<Arc<Self>> { - let _p = profile::span("trait_impls_in_block_query"); + let _p = tracing::span!(tracing::Level::INFO, "trait_impls_in_block_query").entered(); let mut impls = FxHashMap::default(); Self::collect_def_map(db, &mut impls, &db.block_def_map(block)); @@ -171,7 +172,8 @@ impl TraitImpls { db: &dyn HirDatabase, krate: CrateId, ) -> Arc<[Arc<Self>]> { - let _p = profile::span("trait_impls_in_deps_query").detail(|| format!("{krate:?}")); + let _p = + tracing::span!(tracing::Level::INFO, "trait_impls_in_deps_query", ?krate).entered(); let crate_graph = db.crate_graph(); Arc::from_iter( @@ -272,7 +274,8 @@ pub struct InherentImpls { impl InherentImpls { pub(crate) fn inherent_impls_in_crate_query(db: &dyn HirDatabase, krate: CrateId) -> Arc<Self> { - let _p = profile::span("inherent_impls_in_crate_query").detail(|| format!("{krate:?}")); + let _p = + tracing::span!(tracing::Level::INFO, "inherent_impls_in_crate_query", ?krate).entered(); let mut impls = Self { map: FxHashMap::default(), invalid_impls: Vec::default() }; let crate_def_map = db.crate_def_map(krate); @@ -286,7 +289,7 @@ impl InherentImpls { db: &dyn HirDatabase, block: BlockId, ) -> Option<Arc<Self>> { - let _p = profile::span("inherent_impls_in_block_query"); + let _p = tracing::span!(tracing::Level::INFO, "inherent_impls_in_block_query").entered(); let mut impls = Self { map: FxHashMap::default(), invalid_impls: Vec::default() }; let block_def_map = db.block_def_map(block); @@ -359,7 +362,7 @@ pub(crate) fn incoherent_inherent_impl_crates( krate: CrateId, fp: TyFingerprint, ) -> SmallVec<[CrateId; 2]> { - let _p = profile::span("inherent_impl_crates_query"); + let _p = tracing::span!(tracing::Level::INFO, "inherent_impl_crates_query").entered(); let mut res = SmallVec::new(); let crate_graph = db.crate_graph(); diff --git a/crates/hir-ty/src/mir/borrowck.rs b/crates/hir-ty/src/mir/borrowck.rs index 2dd5fa78d0..ea4e60cad3 100644 --- a/crates/hir-ty/src/mir/borrowck.rs +++ b/crates/hir-ty/src/mir/borrowck.rs @@ -71,7 +71,7 @@ pub fn borrowck_query( db: &dyn HirDatabase, def: DefWithBodyId, ) -> Result<Arc<[BorrowckResult]>, MirLowerError> { - let _p = profile::span("borrowck_query"); + let _p = tracing::span!(tracing::Level::INFO, "borrowck_query").entered(); let mut res = vec![]; all_mir_bodies(db, def, |body| { res.push(BorrowckResult { diff --git a/crates/hir-ty/src/mir/lower.rs b/crates/hir-ty/src/mir/lower.rs index f51853107f..74bac8cbf1 100644 --- a/crates/hir-ty/src/mir/lower.rs +++ b/crates/hir-ty/src/mir/lower.rs @@ -2068,7 +2068,7 @@ pub fn mir_body_for_closure_query( } pub fn mir_body_query(db: &dyn HirDatabase, def: DefWithBodyId) -> Result<Arc<MirBody>> { - let _p = profile::span("mir_body_query").detail(|| match def { + let detail = match def { DefWithBodyId::FunctionId(it) => db.function_data(it).name.display(db.upcast()).to_string(), DefWithBodyId::StaticId(it) => db.static_data(it).name.display(db.upcast()).to_string(), DefWithBodyId::ConstId(it) => db @@ -2082,7 +2082,8 @@ pub fn mir_body_query(db: &dyn HirDatabase, def: DefWithBodyId) -> Result<Arc<Mi db.enum_variant_data(it).name.display(db.upcast()).to_string() } DefWithBodyId::InTypeConstId(it) => format!("in type const {it:?}"), - }); + }; + let _p = tracing::span!(tracing::Level::INFO, "mir_body_query", ?detail).entered(); let body = db.body(def); let infer = db.infer(def); let mut result = lower_to_mir(db, def, &body, &infer, body.body_expr)?; diff --git a/crates/hir-ty/src/traits.rs b/crates/hir-ty/src/traits.rs index b6bc76bc98..3a1a4e63ea 100644 --- a/crates/hir-ty/src/traits.rs +++ b/crates/hir-ty/src/traits.rs @@ -100,13 +100,14 @@ pub(crate) fn trait_solve_query( block: Option<BlockId>, goal: Canonical<InEnvironment<Goal>>, ) -> Option<Solution> { - let _p = profile::span("trait_solve_query").detail(|| match &goal.value.goal.data(Interner) { + let detail = match &goal.value.goal.data(Interner) { GoalData::DomainGoal(DomainGoal::Holds(WhereClause::Implemented(it))) => { db.trait_data(it.hir_trait_id()).name.display(db.upcast()).to_string() } GoalData::DomainGoal(DomainGoal::Holds(WhereClause::AliasEq(_))) => "alias_eq".to_string(), _ => "??".to_string(), - }); + }; + let _p = tracing::span!(tracing::Level::INFO, "trait_solve_query", ?detail).entered(); tracing::info!("trait_solve_query({:?})", goal.value.goal); if let GoalData::DomainGoal(DomainGoal::Holds(WhereClause::AliasEq(AliasEq { diff --git a/crates/hir/Cargo.toml b/crates/hir/Cargo.toml index 668a14cd55..7fea837287 100644 --- a/crates/hir/Cargo.toml +++ b/crates/hir/Cargo.toml @@ -17,6 +17,7 @@ either.workspace = true arrayvec.workspace = true itertools.workspace = true smallvec.workspace = true +tracing.workspace = true triomphe.workspace = true once_cell = "1.17.1" diff --git a/crates/hir/src/lib.rs b/crates/hir/src/lib.rs index eafba8a88b..28decd4ce7 100644 --- a/crates/hir/src/lib.rs +++ b/crates/hir/src/lib.rs @@ -235,7 +235,7 @@ impl Crate { db: &dyn DefDatabase, query: import_map::Query, ) -> impl Iterator<Item = Either<ModuleDef, Macro>> { - let _p = profile::span("query_external_importables"); + let _p = tracing::span!(tracing::Level::INFO, "query_external_importables"); import_map::search_dependencies(db, self.into(), query).into_iter().map(|item| { match ItemInNs::from(item) { ItemInNs::Types(mod_id) | ItemInNs::Values(mod_id) => Either::Left(mod_id), @@ -539,13 +539,8 @@ impl Module { /// Fills `acc` with the module's diagnostics. pub fn diagnostics(self, db: &dyn HirDatabase, acc: &mut Vec<AnyDiagnostic>) { - let _p = profile::span("Module::diagnostics").detail(|| { - format!( - "{:?}", - self.name(db) - .map_or("<unknown>".into(), |name| name.display(db.upcast()).to_string()) - ) - }); + let name = self.name(db); + let _p = tracing::span!(tracing::Level::INFO, "Module::diagnostics", ?name); let def_map = self.id.def_map(db.upcast()); for diag in def_map.diagnostics() { if diag.in_module != self.id.local_id { @@ -4057,7 +4052,7 @@ impl Type { name: Option<&Name>, mut callback: impl FnMut(Function) -> Option<T>, ) -> Option<T> { - let _p = profile::span("iterate_method_candidates"); + let _p = tracing::span!(tracing::Level::INFO, "iterate_method_candidates"); let mut slot = None; self.iterate_method_candidates_dyn( @@ -4136,7 +4131,7 @@ impl Type { name: Option<&Name>, mut callback: impl FnMut(AssocItem) -> Option<T>, ) -> Option<T> { - let _p = profile::span("iterate_path_candidates"); + let _p = tracing::span!(tracing::Level::INFO, "iterate_path_candidates"); let mut slot = None; self.iterate_path_candidates_dyn( db, @@ -4202,7 +4197,7 @@ impl Type { &'a self, db: &'a dyn HirDatabase, ) -> impl Iterator<Item = Trait> + 'a { - let _p = profile::span("applicable_inherent_traits"); + let _p = tracing::span!(tracing::Level::INFO, "applicable_inherent_traits"); self.autoderef_(db) .filter_map(|ty| ty.dyn_trait()) .flat_map(move |dyn_trait_id| hir_ty::all_super_traits(db.upcast(), dyn_trait_id)) @@ -4210,7 +4205,7 @@ impl Type { } pub fn env_traits<'a>(&'a self, db: &'a dyn HirDatabase) -> impl Iterator<Item = Trait> + 'a { - let _p = profile::span("env_traits"); + let _p = tracing::span!(tracing::Level::INFO, "env_traits"); self.autoderef_(db) .filter(|ty| matches!(ty.kind(Interner), TyKind::Placeholder(_))) .flat_map(|ty| { diff --git a/crates/hir/src/semantics.rs b/crates/hir/src/semantics.rs index 46f3997620..7dc84a0353 100644 --- a/crates/hir/src/semantics.rs +++ b/crates/hir/src/semantics.rs @@ -671,10 +671,8 @@ impl<'db> SemanticsImpl<'db> { mut token: SyntaxToken, f: &mut dyn FnMut(InFile<SyntaxToken>) -> ControlFlow<()>, ) { - let _p = profile::span("descend_into_macros"); - + let _p = tracing::span!(tracing::Level::INFO, "descend_into_macros"); let mut include_macro_file_id_and_span = None; - let sa = match token.parent().and_then(|parent| self.analyze_no_infer(&parent)) { Some(it) => it, None => { @@ -1303,7 +1301,7 @@ impl<'db> SemanticsImpl<'db> { offset: Option<TextSize>, infer_body: bool, ) -> Option<SourceAnalyzer> { - let _p = profile::span("Semantics::analyze_impl"); + let _p = tracing::span!(tracing::Level::INFO, "Semantics::analyze_impl"); let node = self.find_file(node); let container = self.with_ctx(|ctx| ctx.find_container(node))?; diff --git a/crates/hir/src/semantics/source_to_def.rs b/crates/hir/src/semantics/source_to_def.rs index f60b3749b0..14dbe69240 100644 --- a/crates/hir/src/semantics/source_to_def.rs +++ b/crates/hir/src/semantics/source_to_def.rs @@ -117,7 +117,7 @@ pub(super) struct SourceToDefCtx<'a, 'b> { impl SourceToDefCtx<'_, '_> { pub(super) fn file_to_def(&self, file: FileId) -> SmallVec<[ModuleId; 1]> { - let _p = profile::span("SourceBinder::to_module_def"); + let _p = tracing::span!(tracing::Level::INFO, "SourceBinder::to_module_def"); let mut mods = SmallVec::new(); for &crate_id in self.db.relevant_crates(file).iter() { // FIXME: inner items @@ -132,7 +132,7 @@ impl SourceToDefCtx<'_, '_> { } pub(super) fn module_to_def(&self, src: InFile<ast::Module>) -> Option<ModuleId> { - let _p = profile::span("module_to_def"); + let _p = tracing::span!(tracing::Level::INFO, "module_to_def"); let parent_declaration = src .syntax() .ancestors_with_macros_skip_attr_item(self.db.upcast()) @@ -153,7 +153,7 @@ impl SourceToDefCtx<'_, '_> { } pub(super) fn source_file_to_def(&self, src: InFile<ast::SourceFile>) -> Option<ModuleId> { - let _p = profile::span("source_file_to_def"); + let _p = tracing::span!(tracing::Level::INFO, "source_file_to_def"); let file_id = src.file_id.original_file(self.db.upcast()); self.file_to_def(file_id).first().copied() } diff --git a/crates/ide-assists/Cargo.toml b/crates/ide-assists/Cargo.toml index 4d4bac5fb9..98961a18de 100644 --- a/crates/ide-assists/Cargo.toml +++ b/crates/ide-assists/Cargo.toml @@ -17,6 +17,7 @@ cov-mark = "2.0.0-pre.1" itertools.workspace = true either.workspace = true smallvec.workspace = true +tracing.workspace = true # local deps stdx.workspace = true @@ -38,4 +39,4 @@ sourcegen.workspace = true in-rust-tree = [] [lints] -workspace = true
\ No newline at end of file +workspace = true diff --git a/crates/ide-assists/src/handlers/add_missing_impl_members.rs b/crates/ide-assists/src/handlers/add_missing_impl_members.rs index 410c623109..a0f4f8eb84 100644 --- a/crates/ide-assists/src/handlers/add_missing_impl_members.rs +++ b/crates/ide-assists/src/handlers/add_missing_impl_members.rs @@ -105,7 +105,7 @@ fn add_missing_impl_members_inner( assist_id: &'static str, label: &'static str, ) -> Option<()> { - let _p = profile::span("add_missing_impl_members_inner"); + let _p = tracing::span!(tracing::Level::INFO, "add_missing_impl_members_inner"); let impl_def = ctx.find_node_at_offset::<ast::Impl>()?; let impl_ = ctx.sema.to_def(&impl_def)?; diff --git a/crates/ide-completion/Cargo.toml b/crates/ide-completion/Cargo.toml index 7fbcf3d19e..f2a11276ba 100644 --- a/crates/ide-completion/Cargo.toml +++ b/crates/ide-completion/Cargo.toml @@ -14,6 +14,7 @@ doctest = false [dependencies] cov-mark = "2.0.0-pre.1" itertools.workspace = true +tracing.workspace = true once_cell = "1.17.0" smallvec.workspace = true @@ -38,4 +39,4 @@ test-utils.workspace = true test-fixture.workspace = true [lints] -workspace = true
\ No newline at end of file +workspace = true diff --git a/crates/ide-completion/src/completions/expr.rs b/crates/ide-completion/src/completions/expr.rs index d3c817d4b4..1433216d61 100644 --- a/crates/ide-completion/src/completions/expr.rs +++ b/crates/ide-completion/src/completions/expr.rs @@ -15,7 +15,7 @@ pub(crate) fn complete_expr_path( path_ctx @ PathCompletionCtx { qualified, .. }: &PathCompletionCtx, expr_ctx: &ExprCtx, ) { - let _p = profile::span("complete_expr_path"); + let _p = tracing::span!(tracing::Level::INFO, "complete_expr_path").entered(); if !ctx.qualifier_ctx.none() { return; } diff --git a/crates/ide-completion/src/completions/flyimport.rs b/crates/ide-completion/src/completions/flyimport.rs index e330430d6b..0e04ad35d3 100644 --- a/crates/ide-completion/src/completions/flyimport.rs +++ b/crates/ide-completion/src/completions/flyimport.rs @@ -207,7 +207,8 @@ fn import_on_the_fly( position: SyntaxNode, potential_import_name: String, ) -> Option<()> { - let _p = profile::span("import_on_the_fly").detail(|| potential_import_name.clone()); + let _p = + tracing::span!(tracing::Level::INFO, "import_on_the_fly", ?potential_import_name).entered(); ImportScope::find_insert_use_container(&position, &ctx.sema)?; @@ -293,7 +294,8 @@ fn import_on_the_fly_pat_( position: SyntaxNode, potential_import_name: String, ) -> Option<()> { - let _p = profile::span("import_on_the_fly_pat").detail(|| potential_import_name.clone()); + let _p = tracing::span!(tracing::Level::INFO, "import_on_the_fly_pat", ?potential_import_name) + .entered(); ImportScope::find_insert_use_container(&position, &ctx.sema)?; @@ -343,7 +345,9 @@ fn import_on_the_fly_method( position: SyntaxNode, potential_import_name: String, ) -> Option<()> { - let _p = profile::span("import_on_the_fly_method").detail(|| potential_import_name.clone()); + let _p = + tracing::span!(tracing::Level::INFO, "import_on_the_fly_method", ?potential_import_name) + .entered(); ImportScope::find_insert_use_container(&position, &ctx.sema)?; diff --git a/crates/ide-completion/src/completions/item_list.rs b/crates/ide-completion/src/completions/item_list.rs index 4de15ab759..addd9dac1a 100644 --- a/crates/ide-completion/src/completions/item_list.rs +++ b/crates/ide-completion/src/completions/item_list.rs @@ -28,7 +28,7 @@ pub(crate) fn complete_item_list( path_ctx @ PathCompletionCtx { qualified, .. }: &PathCompletionCtx, kind: &ItemListKind, ) { - let _p = profile::span("complete_item_list"); + let _p = tracing::span!(tracing::Level::INFO, "complete_item_list").entered(); if path_ctx.is_trivial_path() { add_keywords(acc, ctx, Some(kind)); } diff --git a/crates/ide-completion/src/completions/mod_.rs b/crates/ide-completion/src/completions/mod_.rs index 5d138eea46..ecf5b29e2c 100644 --- a/crates/ide-completion/src/completions/mod_.rs +++ b/crates/ide-completion/src/completions/mod_.rs @@ -21,7 +21,7 @@ pub(crate) fn complete_mod( return None; } - let _p = profile::span("completion::complete_mod"); + let _p = tracing::span!(tracing::Level::INFO, "completion::complete_mod").entered(); let mut current_module = ctx.module; // For `mod $0`, `ctx.module` is its parent, but for `mod f$0`, it's `mod f` itself, but we're diff --git a/crates/ide-completion/src/completions/type.rs b/crates/ide-completion/src/completions/type.rs index a30fd13b1d..e6a4335c3f 100644 --- a/crates/ide-completion/src/completions/type.rs +++ b/crates/ide-completion/src/completions/type.rs @@ -15,7 +15,7 @@ pub(crate) fn complete_type_path( path_ctx @ PathCompletionCtx { qualified, .. }: &PathCompletionCtx, location: &TypeLocation, ) { - let _p = profile::span("complete_type_path"); + let _p = tracing::span!(tracing::Level::INFO, "complete_type_path").entered(); let scope_def_applicable = |def| { use hir::{GenericParam::*, ModuleDef::*}; diff --git a/crates/ide-completion/src/context.rs b/crates/ide-completion/src/context.rs index 575f524209..2c0370c58f 100644 --- a/crates/ide-completion/src/context.rs +++ b/crates/ide-completion/src/context.rs @@ -568,7 +568,8 @@ impl CompletionContext<'_> { /// A version of [`SemanticsScope::process_all_names`] that filters out `#[doc(hidden)]` items and /// passes all doc-aliases along, to funnel it into [`Completions::add_path_resolution`]. pub(crate) fn process_all_names(&self, f: &mut dyn FnMut(Name, ScopeDef, Vec<SmolStr>)) { - let _p = profile::span("CompletionContext::process_all_names"); + let _p = + tracing::span!(tracing::Level::INFO, "CompletionContext::process_all_names").entered(); self.scope.process_all_names(&mut |name, def| { if self.is_scope_def_hidden(def) { return; @@ -579,7 +580,8 @@ impl CompletionContext<'_> { } pub(crate) fn process_all_names_raw(&self, f: &mut dyn FnMut(Name, ScopeDef)) { - let _p = profile::span("CompletionContext::process_all_names_raw"); + let _p = tracing::span!(tracing::Level::INFO, "CompletionContext::process_all_names_raw") + .entered(); self.scope.process_all_names(f); } @@ -637,7 +639,7 @@ impl<'a> CompletionContext<'a> { position @ FilePosition { file_id, offset }: FilePosition, config: &'a CompletionConfig, ) -> Option<(CompletionContext<'a>, CompletionAnalysis)> { - let _p = profile::span("CompletionContext::new"); + let _p = tracing::span!(tracing::Level::INFO, "CompletionContext::new").entered(); let sema = Semantics::new(db); let original_file = sema.parse(file_id); diff --git a/crates/ide-completion/src/context/analysis.rs b/crates/ide-completion/src/context/analysis.rs index 8a4ac00de9..65ecaf6bac 100644 --- a/crates/ide-completion/src/context/analysis.rs +++ b/crates/ide-completion/src/context/analysis.rs @@ -72,7 +72,7 @@ fn expand( mut fake_ident_token: SyntaxToken, relative_offset: TextSize, ) -> ExpansionResult { - let _p = profile::span("CompletionContext::expand"); + let _p = tracing::span!(tracing::Level::INFO, "CompletionContext::expand").entered(); let mut derive_ctx = None; 'expansion: loop { @@ -211,7 +211,7 @@ fn analyze( original_token: &SyntaxToken, self_token: &SyntaxToken, ) -> Option<(CompletionAnalysis, (Option<Type>, Option<ast::NameOrNameRef>), QualifierCtx)> { - let _p = profile::span("CompletionContext::analyze"); + let _p = tracing::span!(tracing::Level::INFO, "CompletionContext::analyze").entered(); let ExpansionResult { original_file, speculative_file, offset, fake_ident_token, derive_ctx } = expansion_result; diff --git a/crates/ide-completion/src/item.rs b/crates/ide-completion/src/item.rs index 864b993f71..bcf169f465 100644 --- a/crates/ide-completion/src/item.rs +++ b/crates/ide-completion/src/item.rs @@ -433,7 +433,7 @@ impl Builder { } pub(crate) fn build(self, db: &RootDatabase) -> CompletionItem { - let _p = profile::span("item::Builder::build"); + let _p = tracing::span!(tracing::Level::INFO, "item::Builder::build").entered(); let label = self.label; let mut label_detail = None; diff --git a/crates/ide-completion/src/lib.rs b/crates/ide-completion/src/lib.rs index d26b6f431b..733523d369 100644 --- a/crates/ide-completion/src/lib.rs +++ b/crates/ide-completion/src/lib.rs @@ -236,7 +236,7 @@ pub fn resolve_completion_edits( FilePosition { file_id, offset }: FilePosition, imports: impl IntoIterator<Item = (String, String)>, ) -> Option<Vec<TextEdit>> { - let _p = profile::span("resolve_completion_edits"); + let _p = tracing::span!(tracing::Level::INFO, "resolve_completion_edits").entered(); let sema = hir::Semantics::new(db); let original_file = sema.parse(file_id); diff --git a/crates/ide-completion/src/render.rs b/crates/ide-completion/src/render.rs index ad26280ae7..4d49d2f498 100644 --- a/crates/ide-completion/src/render.rs +++ b/crates/ide-completion/src/render.rs @@ -292,7 +292,7 @@ fn render_resolution_pat( import_to_add: Option<LocatedImport>, resolution: ScopeDef, ) -> Builder { - let _p = profile::span("render_resolution"); + let _p = tracing::span!(tracing::Level::INFO, "render_resolution").entered(); use hir::ModuleDef::*; if let ScopeDef::ModuleDef(Macro(mac)) = resolution { @@ -310,7 +310,7 @@ fn render_resolution_path( import_to_add: Option<LocatedImport>, resolution: ScopeDef, ) -> Builder { - let _p = profile::span("render_resolution"); + let _p = tracing::span!(tracing::Level::INFO, "render_resolution").entered(); use hir::ModuleDef::*; match resolution { @@ -418,7 +418,7 @@ fn render_resolution_simple_( import_to_add: Option<LocatedImport>, resolution: ScopeDef, ) -> Builder { - let _p = profile::span("render_resolution"); + let _p = tracing::span!(tracing::Level::INFO, "render_resolution").entered(); let db = ctx.db(); let ctx = ctx.import_to_add(import_to_add); diff --git a/crates/ide-completion/src/render/const_.rs b/crates/ide-completion/src/render/const_.rs index 3c73983c39..a2bfac994f 100644 --- a/crates/ide-completion/src/render/const_.rs +++ b/crates/ide-completion/src/render/const_.rs @@ -6,7 +6,7 @@ use ide_db::SymbolKind; use crate::{item::CompletionItem, render::RenderContext}; pub(crate) fn render_const(ctx: RenderContext<'_>, const_: hir::Const) -> Option<CompletionItem> { - let _p = profile::span("render_const"); + let _p = tracing::span!(tracing::Level::INFO, "render_const").entered(); render(ctx, const_) } diff --git a/crates/ide-completion/src/render/function.rs b/crates/ide-completion/src/render/function.rs index 0f2608d132..4ae7ea861c 100644 --- a/crates/ide-completion/src/render/function.rs +++ b/crates/ide-completion/src/render/function.rs @@ -25,7 +25,7 @@ pub(crate) fn render_fn( local_name: Option<hir::Name>, func: hir::Function, ) -> Builder { - let _p = profile::span("render_fn"); + let _p = tracing::span!(tracing::Level::INFO, "render_fn").entered(); render(ctx, local_name, func, FuncKind::Function(path_ctx)) } @@ -36,7 +36,7 @@ pub(crate) fn render_method( local_name: Option<hir::Name>, func: hir::Function, ) -> Builder { - let _p = profile::span("render_method"); + let _p = tracing::span!(tracing::Level::INFO, "render_method").entered(); render(ctx, local_name, func, FuncKind::Method(dot_access, receiver)) } diff --git a/crates/ide-completion/src/render/literal.rs b/crates/ide-completion/src/render/literal.rs index f2d67df01d..f52a5f7625 100644 --- a/crates/ide-completion/src/render/literal.rs +++ b/crates/ide-completion/src/render/literal.rs @@ -27,7 +27,7 @@ pub(crate) fn render_variant_lit( variant: hir::Variant, path: Option<hir::ModPath>, ) -> Option<Builder> { - let _p = profile::span("render_enum_variant"); + let _p = tracing::span!(tracing::Level::INFO, "render_enum_variant").entered(); let db = ctx.db(); let name = local_name.unwrap_or_else(|| variant.name(db)); @@ -41,7 +41,7 @@ pub(crate) fn render_struct_literal( path: Option<hir::ModPath>, local_name: Option<hir::Name>, ) -> Option<Builder> { - let _p = profile::span("render_struct_literal"); + let _p = tracing::span!(tracing::Level::INFO, "render_struct_literal").entered(); let db = ctx.db(); let name = local_name.unwrap_or_else(|| strukt.name(db)); diff --git a/crates/ide-completion/src/render/macro_.rs b/crates/ide-completion/src/render/macro_.rs index 915a245ab6..540cfd03d6 100644 --- a/crates/ide-completion/src/render/macro_.rs +++ b/crates/ide-completion/src/render/macro_.rs @@ -17,7 +17,7 @@ pub(crate) fn render_macro( name: hir::Name, macro_: hir::Macro, ) -> Builder { - let _p = profile::span("render_macro"); + let _p = tracing::span!(tracing::Level::INFO, "render_macro").entered(); render(ctx, *kind == PathKind::Use, *has_macro_bang, *has_call_parens, name, macro_) } @@ -27,7 +27,7 @@ pub(crate) fn render_macro_pat( name: hir::Name, macro_: hir::Macro, ) -> Builder { - let _p = profile::span("render_macro"); + let _p = tracing::span!(tracing::Level::INFO, "render_macro").entered(); render(ctx, false, false, false, name, macro_) } diff --git a/crates/ide-completion/src/render/pattern.rs b/crates/ide-completion/src/render/pattern.rs index 6f998119b7..a5f851566c 100644 --- a/crates/ide-completion/src/render/pattern.rs +++ b/crates/ide-completion/src/render/pattern.rs @@ -20,7 +20,7 @@ pub(crate) fn render_struct_pat( strukt: hir::Struct, local_name: Option<Name>, ) -> Option<CompletionItem> { - let _p = profile::span("render_struct_pat"); + let _p = tracing::span!(tracing::Level::INFO, "render_struct_pat").entered(); let fields = strukt.fields(ctx.db()); let (visible_fields, fields_omitted) = visible_fields(ctx.completion, &fields, strukt)?; @@ -50,7 +50,7 @@ pub(crate) fn render_variant_pat( local_name: Option<Name>, path: Option<&hir::ModPath>, ) -> Option<CompletionItem> { - let _p = profile::span("render_variant_pat"); + let _p = tracing::span!(tracing::Level::INFO, "render_variant_pat").entered(); let fields = variant.fields(ctx.db()); let (visible_fields, fields_omitted) = visible_fields(ctx.completion, &fields, variant)?; diff --git a/crates/ide-completion/src/render/type_alias.rs b/crates/ide-completion/src/render/type_alias.rs index 343ba7e28d..b192309e93 100644 --- a/crates/ide-completion/src/render/type_alias.rs +++ b/crates/ide-completion/src/render/type_alias.rs @@ -10,7 +10,7 @@ pub(crate) fn render_type_alias( ctx: RenderContext<'_>, type_alias: hir::TypeAlias, ) -> Option<CompletionItem> { - let _p = profile::span("render_type_alias"); + let _p = tracing::span!(tracing::Level::INFO, "render_type_alias").entered(); render(ctx, type_alias, false) } @@ -18,7 +18,7 @@ pub(crate) fn render_type_alias_with_eq( ctx: RenderContext<'_>, type_alias: hir::TypeAlias, ) -> Option<CompletionItem> { - let _p = profile::span("render_type_alias_with_eq"); + let _p = tracing::span!(tracing::Level::INFO, "render_type_alias_with_eq").entered(); render(ctx, type_alias, true) } diff --git a/crates/ide-db/src/apply_change.rs b/crates/ide-db/src/apply_change.rs index 766d1c1e43..296253aa1e 100644 --- a/crates/ide-db/src/apply_change.rs +++ b/crates/ide-db/src/apply_change.rs @@ -15,12 +15,13 @@ use crate::{symbol_index::SymbolsDatabase, Change, RootDatabase}; impl RootDatabase { pub fn request_cancellation(&mut self) { - let _p = profile::span("RootDatabase::request_cancellation"); + let _p = + tracing::span!(tracing::Level::INFO, "RootDatabase::request_cancellation").entered(); self.salsa_runtime_mut().synthetic_write(Durability::LOW); } pub fn apply_change(&mut self, change: Change) { - let _p = profile::span("RootDatabase::apply_change"); + let _p = tracing::span!(tracing::Level::INFO, "RootDatabase::apply_change").entered(); self.request_cancellation(); tracing::trace!("apply_change {:?}", change); if let Some(roots) = &change.source_change.roots { diff --git a/crates/ide-db/src/defs.rs b/crates/ide-db/src/defs.rs index 5995b318e8..81f2f87d96 100644 --- a/crates/ide-db/src/defs.rs +++ b/crates/ide-db/src/defs.rs @@ -404,7 +404,7 @@ impl NameClass { } pub fn classify(sema: &Semantics<'_, RootDatabase>, name: &ast::Name) -> Option<NameClass> { - let _p = profile::span("classify_name"); + let _p = tracing::span!(tracing::Level::INFO, "classify_name").entered(); let parent = name.syntax().parent()?; @@ -496,7 +496,7 @@ impl NameClass { sema: &Semantics<'_, RootDatabase>, lifetime: &ast::Lifetime, ) -> Option<NameClass> { - let _p = profile::span("classify_lifetime").detail(|| lifetime.to_string()); + let _p = tracing::span!(tracing::Level::INFO, "classify_lifetime", ?lifetime).entered(); let parent = lifetime.syntax().parent()?; if let Some(it) = ast::LifetimeParam::cast(parent.clone()) { @@ -587,7 +587,7 @@ impl NameRefClass { sema: &Semantics<'_, RootDatabase>, name_ref: &ast::NameRef, ) -> Option<NameRefClass> { - let _p = profile::span("classify_name_ref").detail(|| name_ref.to_string()); + let _p = tracing::span!(tracing::Level::INFO, "classify_name_ref", ?name_ref).entered(); let parent = name_ref.syntax().parent()?; @@ -686,7 +686,7 @@ impl NameRefClass { sema: &Semantics<'_, RootDatabase>, lifetime: &ast::Lifetime, ) -> Option<NameRefClass> { - let _p = profile::span("classify_lifetime_ref").detail(|| lifetime.to_string()); + let _p = tracing::span!(tracing::Level::INFO, "classify_lifetime_ref", ?lifetime).entered(); let parent = lifetime.syntax().parent()?; match parent.kind() { SyntaxKind::BREAK_EXPR | SyntaxKind::CONTINUE_EXPR => { diff --git a/crates/ide-db/src/helpers.rs b/crates/ide-db/src/helpers.rs index 9363bdfa14..0b5ad7060e 100644 --- a/crates/ide-db/src/helpers.rs +++ b/crates/ide-db/src/helpers.rs @@ -35,7 +35,7 @@ pub fn pick_token<T: AstToken>(mut tokens: TokenAtOffset<SyntaxToken>) -> Option /// Converts the mod path struct into its ast representation. pub fn mod_path_to_ast(path: &hir::ModPath) -> ast::Path { - let _p = profile::span("mod_path_to_ast"); + let _p = tracing::span!(tracing::Level::INFO, "mod_path_to_ast").entered(); let mut segments = Vec::new(); let mut is_abs = false; diff --git a/crates/ide-db/src/imports/import_assets.rs b/crates/ide-db/src/imports/import_assets.rs index 089bd44c2a..cb3f01f345 100644 --- a/crates/ide-db/src/imports/import_assets.rs +++ b/crates/ide-db/src/imports/import_assets.rs @@ -208,7 +208,8 @@ impl ImportAssets { prefer_no_std: bool, prefer_prelude: bool, ) -> impl Iterator<Item = LocatedImport> { - let _p = profile::span("import_assets::search_for_imports"); + let _p = + tracing::span!(tracing::Level::INFO, "import_assets::search_for_imports").entered(); self.search_for(sema, Some(prefix_kind), prefer_no_std, prefer_prelude) } @@ -219,7 +220,8 @@ impl ImportAssets { prefer_no_std: bool, prefer_prelude: bool, ) -> impl Iterator<Item = LocatedImport> { - let _p = profile::span("import_assets::search_for_relative_paths"); + let _p = tracing::span!(tracing::Level::INFO, "import_assets::search_for_relative_paths") + .entered(); self.search_for(sema, None, prefer_no_std, prefer_prelude) } @@ -260,7 +262,7 @@ impl ImportAssets { prefer_no_std: bool, prefer_prelude: bool, ) -> impl Iterator<Item = LocatedImport> { - let _p = profile::span("import_assets::search_for"); + let _p = tracing::span!(tracing::Level::INFO, "import_assets::search_for").entered(); let scope = match sema.scope(&self.candidate_node) { Some(it) => it, @@ -305,7 +307,7 @@ impl ImportAssets { } fn scope_definitions(&self, sema: &Semantics<'_, RootDatabase>) -> FxHashSet<ScopeDef> { - let _p = profile::span("import_assets::scope_definitions"); + let _p = tracing::span!(tracing::Level::INFO, "import_assets::scope_definitions").entered(); let mut scope_definitions = FxHashSet::default(); if let Some(scope) = sema.scope(&self.candidate_node) { scope.process_all_names(&mut |_, scope_def| { @@ -323,7 +325,8 @@ fn path_applicable_imports( mod_path: impl Fn(ItemInNs) -> Option<ModPath> + Copy, scope_filter: impl Fn(ItemInNs) -> bool + Copy, ) -> FxHashSet<LocatedImport> { - let _p = profile::span("import_assets::path_applicable_imports"); + let _p = + tracing::span!(tracing::Level::INFO, "import_assets::path_applicable_imports").entered(); match &path_candidate.qualifier { None => { @@ -370,7 +373,7 @@ fn import_for_item( original_item: ItemInNs, scope_filter: impl Fn(ItemInNs) -> bool, ) -> Option<LocatedImport> { - let _p = profile::span("import_assets::import_for_item"); + let _p = tracing::span!(tracing::Level::INFO, "import_assets::import_for_item").entered(); let [first_segment, ..] = unresolved_qualifier else { return None }; let item_as_assoc = item_as_assoc(db, original_item); @@ -504,7 +507,8 @@ fn trait_applicable_items( mod_path: impl Fn(ItemInNs) -> Option<ModPath>, scope_filter: impl Fn(hir::Trait) -> bool, ) -> FxHashSet<LocatedImport> { - let _p = profile::span("import_assets::trait_applicable_items"); + let _p = + tracing::span!(tracing::Level::INFO, "import_assets::trait_applicable_items").entered(); let db = sema.db; diff --git a/crates/ide-db/src/imports/insert_use.rs b/crates/ide-db/src/imports/insert_use.rs index 5f5ec44687..f29f91eea8 100644 --- a/crates/ide-db/src/imports/insert_use.rs +++ b/crates/ide-db/src/imports/insert_use.rs @@ -194,7 +194,7 @@ fn insert_use_with_alias_option( cfg: &InsertUseConfig, alias: Option<ast::Rename>, ) { - let _p = profile::span("insert_use"); + let _p = tracing::span!(tracing::Level::INFO, "insert_use").entered(); let mut mb = match cfg.granularity { ImportGranularity::Crate => Some(MergeBehavior::Crate), ImportGranularity::Module => Some(MergeBehavior::Module), diff --git a/crates/ide-db/src/items_locator.rs b/crates/ide-db/src/items_locator.rs index 432f1d745d..1b6f650768 100644 --- a/crates/ide-db/src/items_locator.rs +++ b/crates/ide-db/src/items_locator.rs @@ -20,14 +20,9 @@ pub fn items_with_name<'a>( name: NameToImport, assoc_item_search: AssocSearchMode, ) -> impl Iterator<Item = ItemInNs> + 'a { - let _p = profile::span("items_with_name").detail(|| { - format!( - "Name: {}, crate: {:?}, assoc items: {:?}", - name.text(), - assoc_item_search, - krate.display_name(sema.db).map(|name| name.to_string()), - ) - }); + let krate_name = krate.display_name(sema.db).map(|name| name.to_string()); + let _p = tracing::span!(tracing::Level::INFO, "items_with_name", name = name.text(), assoc_item_search = ?assoc_item_search, crate = ?krate_name) + .entered(); let prefix = matches!(name, NameToImport::Prefix(..)); let (local_query, external_query) = match name { @@ -77,7 +72,7 @@ fn find_items<'a>( local_query: symbol_index::Query, external_query: import_map::Query, ) -> impl Iterator<Item = ItemInNs> + 'a { - let _p = profile::span("find_items"); + let _p = tracing::span!(tracing::Level::INFO, "find_items").entered(); let db = sema.db; // NOTE: `external_query` includes `assoc_item_search`, so we don't need to diff --git a/crates/ide-db/src/search.rs b/crates/ide-db/src/search.rs index 7769d8fba1..a596134178 100644 --- a/crates/ide-db/src/search.rs +++ b/crates/ide-db/src/search.rs @@ -273,7 +273,7 @@ impl IntoIterator for SearchScope { impl Definition { fn search_scope(&self, db: &RootDatabase) -> SearchScope { - let _p = profile::span("search_scope"); + let _p = tracing::span!(tracing::Level::INFO, "search_scope").entered(); if let Definition::BuiltinType(_) = self { return SearchScope::crate_graph(db); @@ -435,7 +435,7 @@ impl<'a> FindUsages<'a> { } pub fn search(&self, sink: &mut dyn FnMut(FileId, FileReference) -> bool) { - let _p = profile::span("FindUsages:search"); + let _p = tracing::span!(tracing::Level::INFO, "FindUsages:search").entered(); let sema = self.sema; let search_scope = { diff --git a/crates/ide-db/src/symbol_index.rs b/crates/ide-db/src/symbol_index.rs index 7774b0834d..92c09089e1 100644 --- a/crates/ide-db/src/symbol_index.rs +++ b/crates/ide-db/src/symbol_index.rs @@ -124,7 +124,7 @@ pub trait SymbolsDatabase: HirDatabase + SourceDatabaseExt + Upcast<dyn HirDatab } fn library_symbols(db: &dyn SymbolsDatabase, source_root_id: SourceRootId) -> Arc<SymbolIndex> { - let _p = profile::span("library_symbols"); + let _p = tracing::span!(tracing::Level::INFO, "library_symbols").entered(); let mut symbol_collector = SymbolCollector::new(db.upcast()); @@ -142,14 +142,14 @@ fn library_symbols(db: &dyn SymbolsDatabase, source_root_id: SourceRootId) -> Ar } fn module_symbols(db: &dyn SymbolsDatabase, module: Module) -> Arc<SymbolIndex> { - let _p = profile::span("module_symbols"); + let _p = tracing::span!(tracing::Level::INFO, "module_symbols").entered(); let symbols = SymbolCollector::collect_module(db.upcast(), module); Arc::new(SymbolIndex::new(symbols)) } pub fn crate_symbols(db: &dyn SymbolsDatabase, krate: Crate) -> Box<[Arc<SymbolIndex>]> { - let _p = profile::span("crate_symbols"); + let _p = tracing::span!(tracing::Level::INFO, "crate_symbols").entered(); krate.modules(db.upcast()).into_iter().map(|module| db.module_symbols(module)).collect() } @@ -200,7 +200,7 @@ impl<DB> std::ops::Deref for Snap<DB> { // | VS Code | kbd:[Ctrl+T] // |=== pub fn world_symbols(db: &RootDatabase, query: Query) -> Vec<FileSymbol> { - let _p = profile::span("world_symbols").detail(|| query.query.clone()); + let _p = tracing::span!(tracing::Level::INFO, "world_symbols", query = ?query.query).entered(); let indices: Vec<_> = if query.libs { db.library_roots() @@ -320,7 +320,7 @@ impl Query { indices: &'sym [Arc<SymbolIndex>], cb: impl FnMut(&'sym FileSymbol), ) { - let _p = profile::span("symbol_index::Query::search"); + let _p = tracing::span!(tracing::Level::INFO, "symbol_index::Query::search").entered(); let mut op = fst::map::OpBuilder::new(); match self.mode { SearchMode::Exact => { diff --git a/crates/ide-diagnostics/Cargo.toml b/crates/ide-diagnostics/Cargo.toml index 3ed48457a2..6976804138 100644 --- a/crates/ide-diagnostics/Cargo.toml +++ b/crates/ide-diagnostics/Cargo.toml @@ -16,6 +16,7 @@ cov-mark = "2.0.0-pre.1" either.workspace = true itertools.workspace = true serde_json.workspace = true +tracing.workspace = true once_cell = "1.17.0" # local deps @@ -39,4 +40,4 @@ sourcegen.workspace = true in-rust-tree = [] [lints] -workspace = true
\ No newline at end of file +workspace = true diff --git a/crates/ide-diagnostics/src/lib.rs b/crates/ide-diagnostics/src/lib.rs index f35fc5b533..535fb45cd6 100644 --- a/crates/ide-diagnostics/src/lib.rs +++ b/crates/ide-diagnostics/src/lib.rs @@ -293,7 +293,7 @@ pub fn diagnostics( resolve: &AssistResolveStrategy, file_id: FileId, ) -> Vec<Diagnostic> { - let _p = profile::span("diagnostics"); + let _p = tracing::span!(tracing::Level::INFO, "diagnostics").entered(); let sema = Semantics::new(db); let parse = db.parse(file_id); let mut res = Vec::new(); diff --git a/crates/ide/src/highlight_related.rs b/crates/ide/src/highlight_related.rs index c3a403b107..c1c62e3cda 100644 --- a/crates/ide/src/highlight_related.rs +++ b/crates/ide/src/highlight_related.rs @@ -55,7 +55,7 @@ pub(crate) fn highlight_related( config: HighlightRelatedConfig, pos @ FilePosition { offset, file_id }: FilePosition, ) -> Option<Vec<HighlightedRange>> { - let _p = profile::span("highlight_related"); + let _p = tracing::span!(tracing::Level::INFO, "highlight_related").entered(); let syntax = sema.parse(file_id).syntax().clone(); let token = pick_best_token(syntax.token_at_offset(offset), |kind| match kind { diff --git a/crates/ide/src/inlay_hints.rs b/crates/ide/src/inlay_hints.rs index 46e5901852..8311e770b4 100644 --- a/crates/ide/src/inlay_hints.rs +++ b/crates/ide/src/inlay_hints.rs @@ -454,7 +454,7 @@ pub(crate) fn inlay_hints( range_limit: Option<RangeLimit>, config: &InlayHintsConfig, ) -> Vec<InlayHint> { - let _p = profile::span("inlay_hints"); + let _p = tracing::span!(tracing::Level::INFO, "inlay_hints").entered(); let sema = Semantics::new(db); let file = sema.parse(file_id); let file = file.syntax(); diff --git a/crates/ide/src/prime_caches.rs b/crates/ide/src/prime_caches.rs index d704d12a05..a95d1771ce 100644 --- a/crates/ide/src/prime_caches.rs +++ b/crates/ide/src/prime_caches.rs @@ -33,7 +33,7 @@ pub(crate) fn parallel_prime_caches( num_worker_threads: u8, cb: &(dyn Fn(ParallelPrimeCachesProgress) + Sync), ) { - let _p = profile::span("prime_caches"); + let _p = tracing::span!(tracing::Level::INFO, "prime_caches").entered(); let graph = db.crate_graph(); let mut crates_to_prime = { diff --git a/crates/ide/src/references.rs b/crates/ide/src/references.rs index 78fe84f70d..df7a4a3332 100644 --- a/crates/ide/src/references.rs +++ b/crates/ide/src/references.rs @@ -57,7 +57,7 @@ pub(crate) fn find_all_refs( position: FilePosition, search_scope: Option<SearchScope>, ) -> Option<Vec<ReferenceSearchResult>> { - let _p = profile::span("find_all_refs"); + let _p = tracing::span!(tracing::Level::INFO, "find_all_refs").entered(); let syntax = sema.parse(position.file_id).syntax().clone(); let make_searcher = |literal_search: bool| { move |def: Definition| { diff --git a/crates/ide/src/syntax_highlighting.rs b/crates/ide/src/syntax_highlighting.rs index 8c6f5e2e9c..dfcbaf54d4 100644 --- a/crates/ide/src/syntax_highlighting.rs +++ b/crates/ide/src/syntax_highlighting.rs @@ -186,7 +186,7 @@ pub(crate) fn highlight( file_id: FileId, range_to_highlight: Option<TextRange>, ) -> Vec<HlRange> { - let _p = profile::span("highlight"); + let _p = tracing::span!(tracing::Level::INFO, "highlight").entered(); let sema = Semantics::new(db); // Determine the root based on the given range. diff --git a/crates/proc-macro-api/src/lib.rs b/crates/proc-macro-api/src/lib.rs index 208051113a..345608d3d0 100644 --- a/crates/proc-macro-api/src/lib.rs +++ b/crates/proc-macro-api/src/lib.rs @@ -113,7 +113,7 @@ impl ProcMacroServer { } pub fn load_dylib(&self, dylib: MacroDylib) -> Result<Vec<ProcMacro>, ServerError> { - let _p = profile::span("ProcMacroClient::load_dylib"); + let _p = tracing::span!(tracing::Level::INFO, "ProcMacroClient::load_dylib").entered(); let macros = self.process.lock().unwrap_or_else(|e| e.into_inner()).find_proc_macros(&dylib.path)?; diff --git a/crates/profile/Cargo.toml b/crates/profile/Cargo.toml index 5350023c88..a87b67f5c6 100644 --- a/crates/profile/Cargo.toml +++ b/crates/profile/Cargo.toml @@ -13,6 +13,7 @@ doctest = false [dependencies] once_cell = "1.17.0" +tracing.workspace = true cfg-if = "1.0.0" la-arena.workspace = true libc.workspace = true @@ -33,4 +34,4 @@ jemalloc = ["jemalloc-ctl"] # default = [ "cpu_profiler" ] [lints] -workspace = true
\ No newline at end of file +workspace = true diff --git a/crates/profile/src/hprof.rs b/crates/profile/src/hprof.rs deleted file mode 100644 index ea89a89c5c..0000000000 --- a/crates/profile/src/hprof.rs +++ /dev/null @@ -1,326 +0,0 @@ -//! Simple hierarchical profiler -use std::{ - cell::RefCell, - collections::{BTreeMap, HashSet}, - env, fmt, - io::{stderr, Write}, - sync::{ - atomic::{AtomicBool, Ordering}, - RwLock, - }, - time::{Duration, Instant}, -}; - -use once_cell::sync::Lazy; - -use crate::tree::{Idx, Tree}; - -/// Filtering syntax -/// env RA_PROFILE=* // dump everything -/// env RA_PROFILE=foo|bar|baz // enabled only selected entries -/// env RA_PROFILE=*@3>10 // dump everything, up to depth 3, if it takes more than 10 ms -pub fn init() { - countme::enable(env::var("RA_COUNT").is_ok()); - let spec = env::var("RA_PROFILE").unwrap_or_default(); - init_from(&spec); -} - -pub fn init_from(spec: &str) { - let filter = if spec.is_empty() { Filter::disabled() } else { Filter::from_spec(spec) }; - filter.install(); -} - -type Label = &'static str; - -/// This function starts a profiling scope in the current execution stack with a given description. -/// It returns a `Profile` struct that measures elapsed time between this method invocation and `Profile` struct drop. -/// It supports nested profiling scopes in case when this function is invoked multiple times at the execution stack. -/// In this case the profiling information will be nested at the output. -/// Profiling information is being printed in the stderr. -/// -/// # Example -/// ``` -/// profile::init_from("profile1|profile2@2"); -/// profiling_function1(); -/// -/// fn profiling_function1() { -/// let _p = profile::span("profile1"); -/// profiling_function2(); -/// } -/// -/// fn profiling_function2() { -/// let _p = profile::span("profile2"); -/// } -/// ``` -/// This will print in the stderr the following: -/// ```text -/// 0ms - profile -/// 0ms - profile2 -/// ``` -#[inline] -pub fn span(label: Label) -> ProfileSpan { - debug_assert!(!label.is_empty()); - - let enabled = PROFILING_ENABLED.load(Ordering::Relaxed); - if enabled && with_profile_stack(|stack| stack.push(label)) { - ProfileSpan(Some(ProfilerImpl { label, detail: None })) - } else { - ProfileSpan(None) - } -} - -#[inline] -pub fn heartbeat_span() -> HeartbeatSpan { - let enabled = PROFILING_ENABLED.load(Ordering::Relaxed); - HeartbeatSpan::new(enabled) -} - -#[inline] -pub fn heartbeat() { - let enabled = PROFILING_ENABLED.load(Ordering::Relaxed); - if enabled { - with_profile_stack(|it| it.heartbeat(1)); - } -} - -pub struct ProfileSpan(Option<ProfilerImpl>); - -struct ProfilerImpl { - label: Label, - detail: Option<String>, -} - -impl ProfileSpan { - pub fn detail(mut self, detail: impl FnOnce() -> String) -> ProfileSpan { - if let Some(profiler) = &mut self.0 { - profiler.detail = Some(detail()); - } - self - } -} - -impl Drop for ProfilerImpl { - #[inline] - fn drop(&mut self) { - with_profile_stack(|it| it.pop(self.label, self.detail.take())); - } -} - -pub struct HeartbeatSpan { - enabled: bool, -} - -impl HeartbeatSpan { - #[inline] - pub fn new(enabled: bool) -> Self { - if enabled { - with_profile_stack(|it| it.heartbeats(true)); - } - Self { enabled } - } -} - -impl Drop for HeartbeatSpan { - fn drop(&mut self) { - if self.enabled { - with_profile_stack(|it| it.heartbeats(false)); - } - } -} - -static PROFILING_ENABLED: AtomicBool = AtomicBool::new(false); -static FILTER: Lazy<RwLock<Filter>> = Lazy::new(Default::default); - -fn with_profile_stack<T>(f: impl FnOnce(&mut ProfileStack) -> T) -> T { - thread_local!(static STACK: RefCell<ProfileStack> = RefCell::new(ProfileStack::new())); - STACK.with(|it| f(&mut it.borrow_mut())) -} - -#[derive(Default, Clone, Debug)] -struct Filter { - depth: usize, - allowed: HashSet<String>, - longer_than: Duration, - heartbeat_longer_than: Duration, - version: usize, -} - -impl Filter { - fn disabled() -> Filter { - Filter::default() - } - - fn from_spec(mut spec: &str) -> Filter { - let longer_than = if let Some(idx) = spec.rfind('>') { - let longer_than = spec[idx + 1..].parse().expect("invalid profile longer_than"); - spec = &spec[..idx]; - Duration::from_millis(longer_than) - } else { - Duration::new(0, 0) - }; - let heartbeat_longer_than = longer_than; - - let depth = if let Some(idx) = spec.rfind('@') { - let depth: usize = spec[idx + 1..].parse().expect("invalid profile depth"); - spec = &spec[..idx]; - depth - } else { - 999 - }; - let allowed = - if spec == "*" { HashSet::new() } else { spec.split('|').map(String::from).collect() }; - Filter { depth, allowed, longer_than, heartbeat_longer_than, version: 0 } - } - - fn install(mut self) { - PROFILING_ENABLED.store(self.depth > 0, Ordering::SeqCst); - let mut old = FILTER.write().unwrap(); - self.version = old.version + 1; - *old = self; - } -} - -struct ProfileStack { - frames: Vec<Frame>, - filter: Filter, - messages: Tree<Message>, - heartbeats: bool, -} - -struct Frame { - t: Instant, - heartbeats: u32, -} - -#[derive(Default)] -struct Message { - duration: Duration, - label: Label, - detail: Option<String>, -} - -impl ProfileStack { - fn new() -> ProfileStack { - ProfileStack { - frames: Vec::new(), - messages: Tree::default(), - filter: Default::default(), - heartbeats: false, - } - } - - fn push(&mut self, label: Label) -> bool { - if self.frames.is_empty() { - if let Ok(f) = FILTER.try_read() { - if f.version > self.filter.version { - self.filter = f.clone(); - } - }; - } - if self.frames.len() > self.filter.depth { - return false; - } - let allowed = &self.filter.allowed; - if self.frames.is_empty() && !allowed.is_empty() && !allowed.contains(label) { - return false; - } - - self.frames.push(Frame { t: Instant::now(), heartbeats: 0 }); - self.messages.start(); - true - } - - fn pop(&mut self, label: Label, detail: Option<String>) { - let frame = self.frames.pop().unwrap(); - let duration = frame.t.elapsed(); - - if self.heartbeats { - self.heartbeat(frame.heartbeats); - let avg_span = duration / (frame.heartbeats + 1); - if avg_span > self.filter.heartbeat_longer_than { - eprintln!("Too few heartbeats {label} ({}/{duration:?})?", frame.heartbeats); - } - } - - self.messages.finish(Message { duration, label, detail }); - if self.frames.is_empty() { - let longer_than = self.filter.longer_than; - // Convert to millis for comparison to avoid problems with rounding - // (otherwise we could print `0ms` despite user's `>0` filter when - // `duration` is just a few nanos). - if duration.as_millis() > longer_than.as_millis() { - if let Some(root) = self.messages.root() { - print(&self.messages, root, 0, longer_than, &mut stderr().lock()); - } - } - self.messages.clear(); - } - } - - fn heartbeats(&mut self, yes: bool) { - self.heartbeats = yes; - } - fn heartbeat(&mut self, n: u32) { - if let Some(frame) = self.frames.last_mut() { - frame.heartbeats += n; - } - } -} - -fn print( - tree: &Tree<Message>, - curr: Idx<Message>, - level: u32, - longer_than: Duration, - out: &mut impl Write, -) { - let current_indent = " ".repeat(level as usize); - let detail = tree[curr].detail.as_ref().map(|it| format!(" @ {it}")).unwrap_or_default(); - writeln!( - out, - "{}{} - {}{}", - current_indent, - ms(tree[curr].duration), - tree[curr].label, - detail, - ) - .expect("printing profiling info"); - - let mut accounted_for = Duration::default(); - let mut short_children = BTreeMap::new(); // Use `BTreeMap` to get deterministic output. - for child in tree.children(curr) { - accounted_for += tree[child].duration; - - if tree[child].duration.as_millis() > longer_than.as_millis() { - print(tree, child, level + 1, longer_than, out); - } else { - let (total_duration, cnt) = - short_children.entry(tree[child].label).or_insert((Duration::default(), 0)); - *total_duration += tree[child].duration; - *cnt += 1; - } - } - - for (child_msg, (duration, count)) in &short_children { - writeln!(out, " {current_indent}{} - {child_msg} ({count} calls)", ms(*duration)) - .expect("printing profiling info"); - } - - let unaccounted = tree[curr].duration - accounted_for; - if tree.children(curr).next().is_some() && unaccounted > longer_than { - writeln!(out, " {current_indent}{} - ???", ms(unaccounted)) - .expect("printing profiling info"); - } -} - -#[allow(non_camel_case_types)] -struct ms(Duration); - -impl fmt::Display for ms { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - match self.0.as_millis() { - 0 => f.write_str(" 0 "), - n => write!(f, "{n:5}ms"), - } - } -} diff --git a/crates/profile/src/lib.rs b/crates/profile/src/lib.rs index d86aa0c414..38c5b3fc9c 100644 --- a/crates/profile/src/lib.rs +++ b/crates/profile/src/lib.rs @@ -4,15 +4,12 @@ #[cfg(feature = "cpu_profiler")] mod google_cpu_profiler; -mod hprof; mod memory_usage; mod stop_watch; -mod tree; use std::cell::RefCell; pub use crate::{ - hprof::{heartbeat, heartbeat_span, init, init_from, span}, memory_usage::{Bytes, MemoryUsage}, stop_watch::{StopWatch, StopWatchSpan}, }; diff --git a/crates/profile/src/tree.rs b/crates/profile/src/tree.rs deleted file mode 100644 index 1290fba36f..0000000000 --- a/crates/profile/src/tree.rs +++ /dev/null @@ -1,84 +0,0 @@ -//! A simple tree implementation which tries to not allocate all over the place. -use std::ops; - -use la_arena::Arena; - -#[derive(Default)] -pub(crate) struct Tree<T> { - nodes: Arena<Node<T>>, - current_path: Vec<(Idx<T>, Option<Idx<T>>)>, -} - -pub(crate) type Idx<T> = la_arena::Idx<Node<T>>; - -impl<T> Tree<T> { - pub(crate) fn start(&mut self) - where - T: Default, - { - let me = self.nodes.alloc(Node::new(T::default())); - if let Some((parent, last_child)) = self.current_path.last_mut() { - let slot = match *last_child { - Some(last_child) => &mut self.nodes[last_child].next_sibling, - None => &mut self.nodes[*parent].first_child, - }; - let prev = slot.replace(me); - assert!(prev.is_none()); - *last_child = Some(me); - } - - self.current_path.push((me, None)); - } - - pub(crate) fn finish(&mut self, data: T) { - let (me, _last_child) = self.current_path.pop().unwrap(); - self.nodes[me].data = data; - } - - pub(crate) fn root(&self) -> Option<Idx<T>> { - self.nodes.iter().next().map(|(idx, _)| idx) - } - - pub(crate) fn children(&self, idx: Idx<T>) -> impl Iterator<Item = Idx<T>> + '_ { - NodeIter { nodes: &self.nodes, next: self.nodes[idx].first_child } - } - pub(crate) fn clear(&mut self) { - self.nodes.clear(); - self.current_path.clear(); - } -} - -impl<T> ops::Index<Idx<T>> for Tree<T> { - type Output = T; - fn index(&self, index: Idx<T>) -> &T { - &self.nodes[index].data - } -} - -pub(crate) struct Node<T> { - data: T, - first_child: Option<Idx<T>>, - next_sibling: Option<Idx<T>>, -} - -impl<T> Node<T> { - fn new(data: T) -> Node<T> { - Node { data, first_child: None, next_sibling: None } - } -} - -struct NodeIter<'a, T> { - nodes: &'a Arena<Node<T>>, - next: Option<Idx<T>>, -} - -impl<T> Iterator for NodeIter<'_, T> { - type Item = Idx<T>; - - fn next(&mut self) -> Option<Idx<T>> { - self.next.map(|next| { - self.next = self.nodes[next].next_sibling; - next - }) - } -} diff --git a/crates/project-model/src/rustc_cfg.rs b/crates/project-model/src/rustc_cfg.rs index c5d55f7d21..cf12d5b71d 100644 --- a/crates/project-model/src/rustc_cfg.rs +++ b/crates/project-model/src/rustc_cfg.rs @@ -26,7 +26,7 @@ pub(crate) fn get( extra_env: &FxHashMap<String, String>, config: RustcCfgConfig<'_>, ) -> Vec<CfgFlag> { - let _p = profile::span("rustc_cfg::get"); + let _p = tracing::span!(tracing::Level::INFO, "rustc_cfg::get").entered(); let mut res = Vec::with_capacity(6 * 2 + 1); // Some nightly-only cfgs, which are required for stdlib diff --git a/crates/project-model/src/workspace.rs b/crates/project-model/src/workspace.rs index 88974e889e..e6e2fa7a97 100644 --- a/crates/project-model/src/workspace.rs +++ b/crates/project-model/src/workspace.rs @@ -647,7 +647,7 @@ impl ProjectWorkspace { load: &mut dyn FnMut(&AbsPath) -> Option<FileId>, extra_env: &FxHashMap<String, String>, ) -> (CrateGraph, ProcMacroPaths) { - let _p = profile::span("ProjectWorkspace::to_crate_graph"); + let _p = tracing::span!(tracing::Level::INFO, "ProjectWorkspace::to_crate_graph").entered(); let (mut crate_graph, proc_macros) = match self { ProjectWorkspace::Json { project, sysroot, rustc_cfg, toolchain } => { @@ -891,7 +891,7 @@ fn cargo_to_crate_graph( target_layout: TargetLayoutLoadResult, toolchain: Option<&Version>, ) -> (CrateGraph, ProcMacroPaths) { - let _p = profile::span("cargo_to_crate_graph"); + let _p = tracing::span!(tracing::Level::INFO, "cargo_to_crate_graph").entered(); let mut res = (CrateGraph::default(), ProcMacroPaths::default()); let crate_graph = &mut res.0; let proc_macros = &mut res.1; @@ -1088,7 +1088,7 @@ fn detached_files_to_crate_graph( sysroot: Option<&Sysroot>, target_layout: TargetLayoutLoadResult, ) -> (CrateGraph, ProcMacroPaths) { - let _p = profile::span("detached_files_to_crate_graph"); + let _p = tracing::span!(tracing::Level::INFO, "detached_files_to_crate_graph").entered(); let mut crate_graph = CrateGraph::default(); let (public_deps, _libproc_macro) = match sysroot { Some(sysroot) => sysroot_to_crate_graph( @@ -1384,7 +1384,7 @@ fn sysroot_to_crate_graph( load: &mut dyn FnMut(&AbsPath) -> Option<FileId>, toolchain: Option<&Version>, ) -> (SysrootPublicDeps, Option<CrateId>) { - let _p = profile::span("sysroot_to_crate_graph"); + let _p = tracing::span!(tracing::Level::INFO, "sysroot_to_crate_graph").entered(); match sysroot.mode() { SysrootMode::Workspace(cargo) => { let (mut cg, mut pm) = cargo_to_crate_graph( diff --git a/crates/rust-analyzer/Cargo.toml b/crates/rust-analyzer/Cargo.toml index db5cabaf76..da421e7aaa 100644 --- a/crates/rust-analyzer/Cargo.toml +++ b/crates/rust-analyzer/Cargo.toml @@ -37,11 +37,10 @@ mimalloc = { version = "0.1.30", default-features = false, optional = true } lsp-server.workspace = true tracing.workspace = true tracing-subscriber.workspace = true -tracing-log = "0.2.0" tracing-tree.workspace = true triomphe.workspace = true nohash-hasher.workspace = true -always-assert = "0.1.2" +always-assert = "0.2.0" walkdir = "2.3.2" cfg.workspace = true diff --git a/crates/rust-analyzer/src/bin/logger.rs b/crates/rust-analyzer/src/bin/logger.rs deleted file mode 100644 index 1f923f6cf8..0000000000 --- a/crates/rust-analyzer/src/bin/logger.rs +++ /dev/null @@ -1,137 +0,0 @@ -//! Simple logger that logs either to stderr or to a file, using `tracing_subscriber` -//! filter syntax and `tracing_appender` for non blocking output. - -use std::{ - fmt, - fs::File, - io::{self, Stderr}, - sync::Arc, -}; - -use anyhow::Context; -use tracing::{level_filters::LevelFilter, Event, Subscriber}; -use tracing_log::NormalizeEvent; -use tracing_subscriber::{ - filter::Targets, - fmt::{ - format::Writer, writer::BoxMakeWriter, FmtContext, FormatEvent, FormatFields, - FormattedFields, MakeWriter, - }, - layer::SubscriberExt, - registry::LookupSpan, - util::SubscriberInitExt, - Registry, -}; -use tracing_tree::HierarchicalLayer; - -pub(crate) struct LoggerConfig { - pub(crate) log_file: Option<File>, - pub(crate) filter: String, - pub(crate) chalk_filter: Option<String>, -} - -struct MakeWriterStderr; - -impl MakeWriter<'_> for MakeWriterStderr { - type Writer = Stderr; - - fn make_writer(&self) -> Self::Writer { - io::stderr() - } -} - -impl LoggerConfig { - pub(crate) fn init(self) -> anyhow::Result<()> { - let mut filter: Targets = self - .filter - .parse() - .with_context(|| format!("invalid log filter: `{}`", self.filter))?; - - let mut chalk_layer = None; - if let Some(chalk_filter) = self.chalk_filter { - let level: LevelFilter = - chalk_filter.parse().with_context(|| "invalid chalk log filter")?; - chalk_layer = Some( - HierarchicalLayer::default() - .with_indent_lines(true) - .with_ansi(false) - .with_indent_amount(2) - .with_writer(io::stderr), - ); - filter = filter - .with_target("chalk_solve", level) - .with_target("chalk_ir", level) - .with_target("chalk_recursive", level); - }; - - let writer = match self.log_file { - Some(file) => BoxMakeWriter::new(Arc::new(file)), - None => BoxMakeWriter::new(io::stderr), - }; - let ra_fmt_layer = - tracing_subscriber::fmt::layer().event_format(LoggerFormatter).with_writer(writer); - - let registry = Registry::default().with(filter).with(ra_fmt_layer); - match chalk_layer { - Some(chalk_layer) => registry.with(chalk_layer).init(), - None => registry.init(), - } - Ok(()) - } -} - -#[derive(Debug)] -struct LoggerFormatter; - -impl<S, N> FormatEvent<S, N> for LoggerFormatter -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 { - // Write level and target - let level = *event.metadata().level(); - - // If this event is issued from `log` crate, then the value of target is - // always "log". `tracing-log` has hard coded it for some reason, so we - // need to extract it using `normalized_metadata` method which is part of - // `tracing_log::NormalizeEvent`. - let target = match event.normalized_metadata() { - // This event is issued from `log` crate - Some(log) => log.target(), - None => event.metadata().target(), - }; - write!(writer, "[{level} {target}] ")?; - - // Write spans and fields of each span - ctx.visit_spans(|span| { - write!(writer, "{}", span.name())?; - - let ext = span.extensions(); - - // `FormattedFields` is a formatted representation of the span's - // fields, which is stored in its extensions by the `fmt` layer's - // `new_span` method. The fields will have been formatted - // by the same field formatter that's provided to the event - // formatter in the `FmtContext`. - let fields = &ext.get::<FormattedFields<N>>().expect("will never be `None`"); - - if !fields.is_empty() { - write!(writer, "{{{fields}}}")?; - } - write!(writer, ": ")?; - - Ok(()) - })?; - - // Write fields on the event - ctx.field_format().format_fields(writer.by_ref(), event)?; - - writeln!(writer) - } -} diff --git a/crates/rust-analyzer/src/bin/main.rs b/crates/rust-analyzer/src/bin/main.rs index 0438729190..66b680571a 100644 --- a/crates/rust-analyzer/src/bin/main.rs +++ b/crates/rust-analyzer/src/bin/main.rs @@ -7,14 +7,14 @@ #[cfg(feature = "in-rust-tree")] extern crate rustc_driver as _; -mod logger; mod rustc_wrapper; -use std::{env, fs, path::PathBuf, process}; +use std::{env, fs, path::PathBuf, process, sync::Arc}; use anyhow::Context; use lsp_server::Connection; use rust_analyzer::{cli::flags, config::Config, from_json}; +use tracing_subscriber::fmt::writer::BoxMakeWriter; use vfs::AbsPathBuf; #[cfg(feature = "mimalloc")] @@ -123,26 +123,21 @@ fn setup_logging(log_file_flag: Option<PathBuf>) -> anyhow::Result<()> { None => None, }; - logger::LoggerConfig { - log_file, + let writer = match log_file { + Some(file) => BoxMakeWriter::new(Arc::new(file)), + None => BoxMakeWriter::new(std::io::stderr), + }; + + rust_analyzer::tracing::Config { + writer, // Deliberately enable all `error` logs if the user has not set RA_LOG, as there is usually // useful information in there for debugging. filter: env::var("RA_LOG").ok().unwrap_or_else(|| "error".to_string()), - // The meaning of CHALK_DEBUG I suspected is to tell chalk crates - // (i.e. chalk-solve, chalk-ir, chalk-recursive) how to filter tracing - // logs. But now we can only have just one filter, which means we have to - // merge chalk filter to our main filter (from RA_LOG env). - // - // The acceptable syntax of CHALK_DEBUG is `target[span{field=value}]=level`. - // As the value should only affect chalk crates, we'd better manually - // specify the target. And for simplicity, CHALK_DEBUG only accept the value - // that specify level. chalk_filter: env::var("CHALK_DEBUG").ok(), + profile_filter: env::var("RA_PROFILE").ok(), } .init()?; - profile::init(); - Ok(()) } diff --git a/crates/rust-analyzer/src/cli/parse.rs b/crates/rust-analyzer/src/cli/parse.rs index 5ef8cdff4c..757f2dd70c 100644 --- a/crates/rust-analyzer/src/cli/parse.rs +++ b/crates/rust-analyzer/src/cli/parse.rs @@ -5,7 +5,7 @@ use crate::cli::{flags, read_stdin}; impl flags::Parse { pub fn run(self) -> anyhow::Result<()> { - let _p = profile::span("parsing"); + let _p = tracing::span!(tracing::Level::INFO, "parsing").entered(); let text = read_stdin()?; let file = SourceFile::parse(&text).tree(); if !self.no_dump { diff --git a/crates/rust-analyzer/src/diagnostics.rs b/crates/rust-analyzer/src/diagnostics.rs index ab3881f438..c91b22999d 100644 --- a/crates/rust-analyzer/src/diagnostics.rs +++ b/crates/rust-analyzer/src/diagnostics.rs @@ -128,7 +128,7 @@ pub(crate) fn fetch_native_diagnostics( snapshot: GlobalStateSnapshot, subscriptions: Vec<FileId>, ) -> Vec<(FileId, Vec<lsp_types::Diagnostic>)> { - let _p = profile::span("fetch_native_diagnostics"); + let _p = tracing::span!(tracing::Level::INFO, "fetch_native_diagnostics").entered(); let _ctx = stdx::panic_context::enter("fetch_native_diagnostics".to_owned()); let convert_diagnostic = diff --git a/crates/rust-analyzer/src/dispatch.rs b/crates/rust-analyzer/src/dispatch.rs index 7da4311888..fa856a796a 100644 --- a/crates/rust-analyzer/src/dispatch.rs +++ b/crates/rust-analyzer/src/dispatch.rs @@ -1,5 +1,8 @@ //! See [RequestDispatcher]. -use std::{fmt, panic, thread}; +use std::{ + fmt::{self, Debug}, + panic, thread, +}; use ide::Cancelled; use lsp_server::ExtractError; @@ -49,6 +52,8 @@ impl RequestDispatcher<'_> { Some(it) => it, None => return self, }; + let _guard = tracing::span!(tracing::Level::INFO, "request", method = ?req.method, "request_id" = ?req.id).entered(); + tracing::debug!(?params); let result = { let _pctx = stdx::panic_context::enter(panic_context); f(self.global_state, params) @@ -74,6 +79,8 @@ impl RequestDispatcher<'_> { Some(it) => it, None => return self, }; + let _guard = tracing::span!(tracing::Level::INFO, "request", method = ?req.method, "request_id" = ?req.id).entered(); + tracing::debug!(?params); let global_state_snapshot = self.global_state.snapshot(); let result = panic::catch_unwind(move || { @@ -192,6 +199,8 @@ impl RequestDispatcher<'_> { Some(it) => it, None => return self, }; + let _guard = tracing::span!(tracing::Level::INFO, "request", method = ?req.method, "request_id" = ?req.id).entered(); + tracing::debug!(?params); let world = self.global_state.snapshot(); if MAIN_POOL { @@ -313,12 +322,16 @@ impl NotificationDispatcher<'_> { ) -> anyhow::Result<&mut Self> where N: lsp_types::notification::Notification, - N::Params: DeserializeOwned + Send, + N::Params: DeserializeOwned + Send + Debug, { let not = match self.not.take() { Some(it) => it, None => return Ok(self), }; + + let _guard = + tracing::span!(tracing::Level::INFO, "notification", method = ?not.method).entered(); + let params = match not.extract::<N::Params>(N::METHOD) { Ok(it) => it, Err(ExtractError::JsonError { method, error }) => { @@ -329,6 +342,9 @@ impl NotificationDispatcher<'_> { return Ok(self); } }; + + tracing::debug!(?params); + let _pctx = stdx::panic_context::enter(format!( "\nversion: {}\nnotification: {}", version(), diff --git a/crates/rust-analyzer/src/global_state.rs b/crates/rust-analyzer/src/global_state.rs index 232c03ae6c..2f226d0115 100644 --- a/crates/rust-analyzer/src/global_state.rs +++ b/crates/rust-analyzer/src/global_state.rs @@ -215,7 +215,7 @@ impl GlobalState { } pub(crate) fn process_changes(&mut self) -> bool { - let _p = profile::span("GlobalState::process_changes"); + let _p = tracing::span!(tracing::Level::INFO, "GlobalState::process_changes").entered(); let mut file_changes = FxHashMap::<_, (bool, ChangedFile)>::default(); let (change, modified_rust_files, workspace_structure_change) = { diff --git a/crates/rust-analyzer/src/handlers/notification.rs b/crates/rust-analyzer/src/handlers/notification.rs index c556fdee50..1f24e95010 100644 --- a/crates/rust-analyzer/src/handlers/notification.rs +++ b/crates/rust-analyzer/src/handlers/notification.rs @@ -54,7 +54,7 @@ pub(crate) fn handle_did_open_text_document( state: &mut GlobalState, params: DidOpenTextDocumentParams, ) -> anyhow::Result<()> { - let _p = profile::span("handle_did_open_text_document"); + let _p = tracing::span!(tracing::Level::INFO, "handle_did_open_text_document").entered(); if let Ok(path) = from_proto::vfs_path(¶ms.text_document.uri) { let already_exists = state @@ -79,7 +79,7 @@ pub(crate) fn handle_did_change_text_document( state: &mut GlobalState, params: DidChangeTextDocumentParams, ) -> anyhow::Result<()> { - let _p = profile::span("handle_did_change_text_document"); + let _p = tracing::span!(tracing::Level::INFO, "handle_did_change_text_document").entered(); if let Ok(path) = from_proto::vfs_path(¶ms.text_document.uri) { let data = match state.mem_docs.get_mut(&path) { @@ -113,7 +113,7 @@ pub(crate) fn handle_did_close_text_document( state: &mut GlobalState, params: DidCloseTextDocumentParams, ) -> anyhow::Result<()> { - let _p = profile::span("handle_did_close_text_document"); + let _p = tracing::span!(tracing::Level::INFO, "handle_did_close_text_document").entered(); if let Ok(path) = from_proto::vfs_path(¶ms.text_document.uri) { if state.mem_docs.remove(&path).is_err() { @@ -247,7 +247,7 @@ pub(crate) fn handle_did_change_watched_files( } fn run_flycheck(state: &mut GlobalState, vfs_path: VfsPath) -> bool { - let _p = profile::span("run_flycheck"); + let _p = tracing::span!(tracing::Level::INFO, "run_flycheck").entered(); let file_id = state.vfs.read().0.file_id(&vfs_path); if let Some(file_id) = file_id { @@ -326,13 +326,13 @@ fn run_flycheck(state: &mut GlobalState, vfs_path: VfsPath) -> bool { } pub(crate) fn handle_cancel_flycheck(state: &mut GlobalState, _: ()) -> anyhow::Result<()> { - let _p = profile::span("handle_stop_flycheck"); + let _p = tracing::span!(tracing::Level::INFO, "handle_stop_flycheck").entered(); state.flycheck.iter().for_each(|flycheck| flycheck.cancel()); Ok(()) } pub(crate) fn handle_clear_flycheck(state: &mut GlobalState, _: ()) -> anyhow::Result<()> { - let _p = profile::span("handle_clear_flycheck"); + let _p = tracing::span!(tracing::Level::INFO, "handle_clear_flycheck").entered(); state.diagnostics.clear_check_all(); Ok(()) } @@ -341,7 +341,7 @@ pub(crate) fn handle_run_flycheck( state: &mut GlobalState, params: RunFlycheckParams, ) -> anyhow::Result<()> { - let _p = profile::span("handle_run_flycheck"); + let _p = tracing::span!(tracing::Level::INFO, "handle_run_flycheck").entered(); if let Some(text_document) = params.text_document { if let Ok(vfs_path) = from_proto::vfs_path(&text_document.uri) { if run_flycheck(state, vfs_path) { diff --git a/crates/rust-analyzer/src/handlers/request.rs b/crates/rust-analyzer/src/handlers/request.rs index 1a55dcebc1..90c3a88cb8 100644 --- a/crates/rust-analyzer/src/handlers/request.rs +++ b/crates/rust-analyzer/src/handlers/request.rs @@ -70,7 +70,7 @@ pub(crate) fn handle_analyzer_status( snap: GlobalStateSnapshot, params: lsp_ext::AnalyzerStatusParams, ) -> anyhow::Result<String> { - let _p = profile::span("handle_analyzer_status"); + let _p = tracing::span!(tracing::Level::INFO, "handle_analyzer_status").entered(); let mut buf = String::new(); @@ -114,7 +114,7 @@ pub(crate) fn handle_analyzer_status( } pub(crate) fn handle_memory_usage(state: &mut GlobalState, _: ()) -> anyhow::Result<String> { - let _p = profile::span("handle_memory_usage"); + let _p = tracing::span!(tracing::Level::INFO, "handle_memory_usage").entered(); let mem = state.analysis_host.per_query_memory_usage(); let mut out = String::new(); @@ -135,7 +135,7 @@ pub(crate) fn handle_syntax_tree( snap: GlobalStateSnapshot, params: lsp_ext::SyntaxTreeParams, ) -> anyhow::Result<String> { - let _p = profile::span("handle_syntax_tree"); + let _p = tracing::span!(tracing::Level::INFO, "handle_syntax_tree").entered(); let id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let line_index = snap.file_line_index(id)?; let text_range = params.range.and_then(|r| from_proto::text_range(&line_index, r).ok()); @@ -147,7 +147,7 @@ pub(crate) fn handle_view_hir( snap: GlobalStateSnapshot, params: lsp_types::TextDocumentPositionParams, ) -> anyhow::Result<String> { - let _p = profile::span("handle_view_hir"); + let _p = tracing::span!(tracing::Level::INFO, "handle_view_hir").entered(); let position = from_proto::file_position(&snap, params)?; let res = snap.analysis.view_hir(position)?; Ok(res) @@ -157,7 +157,7 @@ pub(crate) fn handle_view_mir( snap: GlobalStateSnapshot, params: lsp_types::TextDocumentPositionParams, ) -> anyhow::Result<String> { - let _p = profile::span("handle_view_mir"); + let _p = tracing::span!(tracing::Level::INFO, "handle_view_mir").entered(); let position = from_proto::file_position(&snap, params)?; let res = snap.analysis.view_mir(position)?; Ok(res) @@ -167,7 +167,7 @@ pub(crate) fn handle_interpret_function( snap: GlobalStateSnapshot, params: lsp_types::TextDocumentPositionParams, ) -> anyhow::Result<String> { - let _p = profile::span("handle_interpret_function"); + let _p = tracing::span!(tracing::Level::INFO, "handle_interpret_function").entered(); let position = from_proto::file_position(&snap, params)?; let res = snap.analysis.interpret_function(position)?; Ok(res) @@ -185,7 +185,7 @@ pub(crate) fn handle_view_item_tree( snap: GlobalStateSnapshot, params: lsp_ext::ViewItemTreeParams, ) -> anyhow::Result<String> { - let _p = profile::span("handle_view_item_tree"); + let _p = tracing::span!(tracing::Level::INFO, "handle_view_item_tree").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let res = snap.analysis.view_item_tree(file_id)?; Ok(res) @@ -195,7 +195,7 @@ pub(crate) fn handle_view_crate_graph( snap: GlobalStateSnapshot, params: ViewCrateGraphParams, ) -> anyhow::Result<String> { - let _p = profile::span("handle_view_crate_graph"); + let _p = tracing::span!(tracing::Level::INFO, "handle_view_crate_graph").entered(); let dot = snap.analysis.view_crate_graph(params.full)?.map_err(anyhow::Error::msg)?; Ok(dot) } @@ -204,7 +204,7 @@ pub(crate) fn handle_expand_macro( snap: GlobalStateSnapshot, params: lsp_ext::ExpandMacroParams, ) -> anyhow::Result<Option<lsp_ext::ExpandedMacro>> { - let _p = profile::span("handle_expand_macro"); + let _p = tracing::span!(tracing::Level::INFO, "handle_expand_macro").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let line_index = snap.file_line_index(file_id)?; let offset = from_proto::offset(&line_index, params.position)?; @@ -217,7 +217,7 @@ pub(crate) fn handle_selection_range( snap: GlobalStateSnapshot, params: lsp_types::SelectionRangeParams, ) -> anyhow::Result<Option<Vec<lsp_types::SelectionRange>>> { - let _p = profile::span("handle_selection_range"); + let _p = tracing::span!(tracing::Level::INFO, "handle_selection_range").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let line_index = snap.file_line_index(file_id)?; let res: anyhow::Result<Vec<lsp_types::SelectionRange>> = params @@ -260,7 +260,7 @@ pub(crate) fn handle_matching_brace( snap: GlobalStateSnapshot, params: lsp_ext::MatchingBraceParams, ) -> anyhow::Result<Vec<Position>> { - let _p = profile::span("handle_matching_brace"); + let _p = tracing::span!(tracing::Level::INFO, "handle_matching_brace").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let line_index = snap.file_line_index(file_id)?; params @@ -283,7 +283,7 @@ pub(crate) fn handle_join_lines( snap: GlobalStateSnapshot, params: lsp_ext::JoinLinesParams, ) -> anyhow::Result<Vec<lsp_types::TextEdit>> { - let _p = profile::span("handle_join_lines"); + let _p = tracing::span!(tracing::Level::INFO, "handle_join_lines").entered(); let config = snap.config.join_lines(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; @@ -308,7 +308,7 @@ pub(crate) fn handle_on_enter( snap: GlobalStateSnapshot, params: lsp_types::TextDocumentPositionParams, ) -> anyhow::Result<Option<Vec<lsp_ext::SnippetTextEdit>>> { - let _p = profile::span("handle_on_enter"); + let _p = tracing::span!(tracing::Level::INFO, "handle_on_enter").entered(); let position = from_proto::file_position(&snap, params)?; let edit = match snap.analysis.on_enter(position)? { None => return Ok(None), @@ -323,7 +323,7 @@ pub(crate) fn handle_on_type_formatting( snap: GlobalStateSnapshot, params: lsp_types::DocumentOnTypeFormattingParams, ) -> anyhow::Result<Option<Vec<lsp_ext::SnippetTextEdit>>> { - let _p = profile::span("handle_on_type_formatting"); + let _p = tracing::span!(tracing::Level::INFO, "handle_on_type_formatting").entered(); let mut position = from_proto::file_position(&snap, params.text_document_position)?; let line_index = snap.file_line_index(position.file_id)?; @@ -364,7 +364,7 @@ pub(crate) fn handle_document_symbol( snap: GlobalStateSnapshot, params: lsp_types::DocumentSymbolParams, ) -> anyhow::Result<Option<lsp_types::DocumentSymbolResponse>> { - let _p = profile::span("handle_document_symbol"); + let _p = tracing::span!(tracing::Level::INFO, "handle_document_symbol").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let line_index = snap.file_line_index(file_id)?; @@ -453,7 +453,7 @@ pub(crate) fn handle_workspace_symbol( snap: GlobalStateSnapshot, params: WorkspaceSymbolParams, ) -> anyhow::Result<Option<lsp_types::WorkspaceSymbolResponse>> { - let _p = profile::span("handle_workspace_symbol"); + let _p = tracing::span!(tracing::Level::INFO, "handle_workspace_symbol").entered(); let config = snap.config.workspace_symbol(); let (all_symbols, libs) = decide_search_scope_and_kind(¶ms, &config); @@ -545,7 +545,7 @@ pub(crate) fn handle_will_rename_files( snap: GlobalStateSnapshot, params: lsp_types::RenameFilesParams, ) -> anyhow::Result<Option<lsp_types::WorkspaceEdit>> { - let _p = profile::span("handle_will_rename_files"); + let _p = tracing::span!(tracing::Level::INFO, "handle_will_rename_files").entered(); let source_changes: Vec<SourceChange> = params .files @@ -607,7 +607,7 @@ pub(crate) fn handle_goto_definition( snap: GlobalStateSnapshot, params: lsp_types::GotoDefinitionParams, ) -> anyhow::Result<Option<lsp_types::GotoDefinitionResponse>> { - let _p = profile::span("handle_goto_definition"); + let _p = tracing::span!(tracing::Level::INFO, "handle_goto_definition").entered(); let position = from_proto::file_position(&snap, params.text_document_position_params)?; let nav_info = match snap.analysis.goto_definition(position)? { None => return Ok(None), @@ -622,7 +622,7 @@ pub(crate) fn handle_goto_declaration( snap: GlobalStateSnapshot, params: lsp_types::request::GotoDeclarationParams, ) -> anyhow::Result<Option<lsp_types::request::GotoDeclarationResponse>> { - let _p = profile::span("handle_goto_declaration"); + let _p = tracing::span!(tracing::Level::INFO, "handle_goto_declaration").entered(); let position = from_proto::file_position(&snap, params.text_document_position_params.clone())?; let nav_info = match snap.analysis.goto_declaration(position)? { None => return handle_goto_definition(snap, params), @@ -637,7 +637,7 @@ pub(crate) fn handle_goto_implementation( snap: GlobalStateSnapshot, params: lsp_types::request::GotoImplementationParams, ) -> anyhow::Result<Option<lsp_types::request::GotoImplementationResponse>> { - let _p = profile::span("handle_goto_implementation"); + let _p = tracing::span!(tracing::Level::INFO, "handle_goto_implementation").entered(); let position = from_proto::file_position(&snap, params.text_document_position_params)?; let nav_info = match snap.analysis.goto_implementation(position)? { None => return Ok(None), @@ -652,7 +652,7 @@ pub(crate) fn handle_goto_type_definition( snap: GlobalStateSnapshot, params: lsp_types::request::GotoTypeDefinitionParams, ) -> anyhow::Result<Option<lsp_types::request::GotoTypeDefinitionResponse>> { - let _p = profile::span("handle_goto_type_definition"); + let _p = tracing::span!(tracing::Level::INFO, "handle_goto_type_definition").entered(); let position = from_proto::file_position(&snap, params.text_document_position_params)?; let nav_info = match snap.analysis.goto_type_definition(position)? { None => return Ok(None), @@ -667,7 +667,7 @@ pub(crate) fn handle_parent_module( snap: GlobalStateSnapshot, params: lsp_types::TextDocumentPositionParams, ) -> anyhow::Result<Option<lsp_types::GotoDefinitionResponse>> { - let _p = profile::span("handle_parent_module"); + let _p = tracing::span!(tracing::Level::INFO, "handle_parent_module").entered(); if let Ok(file_path) = ¶ms.text_document.uri.to_file_path() { if file_path.file_name().unwrap_or_default() == "Cargo.toml" { // search workspaces for parent packages or fallback to workspace root @@ -734,7 +734,7 @@ pub(crate) fn handle_runnables( snap: GlobalStateSnapshot, params: lsp_ext::RunnablesParams, ) -> anyhow::Result<Vec<lsp_ext::Runnable>> { - let _p = profile::span("handle_runnables"); + let _p = tracing::span!(tracing::Level::INFO, "handle_runnables").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let line_index = snap.file_line_index(file_id)?; let offset = params.position.and_then(|it| from_proto::offset(&line_index, it).ok()); @@ -829,7 +829,7 @@ pub(crate) fn handle_related_tests( snap: GlobalStateSnapshot, params: lsp_types::TextDocumentPositionParams, ) -> anyhow::Result<Vec<lsp_ext::TestInfo>> { - let _p = profile::span("handle_related_tests"); + let _p = tracing::span!(tracing::Level::INFO, "handle_related_tests").entered(); let position = from_proto::file_position(&snap, params)?; let tests = snap.analysis.related_tests(position, None)?; @@ -847,7 +847,7 @@ pub(crate) fn handle_completion( snap: GlobalStateSnapshot, params: lsp_types::CompletionParams, ) -> anyhow::Result<Option<lsp_types::CompletionResponse>> { - let _p = profile::span("handle_completion"); + let _p = tracing::span!(tracing::Level::INFO, "handle_completion").entered(); let text_document_position = params.text_document_position.clone(); let position = from_proto::file_position(&snap, params.text_document_position)?; let completion_trigger_character = @@ -875,7 +875,7 @@ pub(crate) fn handle_completion_resolve( snap: GlobalStateSnapshot, mut original_completion: CompletionItem, ) -> anyhow::Result<CompletionItem> { - let _p = profile::span("handle_completion_resolve"); + let _p = tracing::span!(tracing::Level::INFO, "handle_completion_resolve").entered(); if !all_edits_are_disjoint(&original_completion, &[]) { return Err(invalid_params_error( @@ -931,7 +931,7 @@ pub(crate) fn handle_folding_range( snap: GlobalStateSnapshot, params: FoldingRangeParams, ) -> anyhow::Result<Option<Vec<FoldingRange>>> { - let _p = profile::span("handle_folding_range"); + let _p = tracing::span!(tracing::Level::INFO, "handle_folding_range").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let folds = snap.analysis.folding_ranges(file_id)?; let text = snap.analysis.file_text(file_id)?; @@ -948,7 +948,7 @@ pub(crate) fn handle_signature_help( snap: GlobalStateSnapshot, params: lsp_types::SignatureHelpParams, ) -> anyhow::Result<Option<lsp_types::SignatureHelp>> { - let _p = profile::span("handle_signature_help"); + let _p = tracing::span!(tracing::Level::INFO, "handle_signature_help").entered(); let position = from_proto::file_position(&snap, params.text_document_position_params)?; let help = match snap.analysis.signature_help(position)? { Some(it) => it, @@ -963,7 +963,7 @@ pub(crate) fn handle_hover( snap: GlobalStateSnapshot, params: lsp_ext::HoverParams, ) -> anyhow::Result<Option<lsp_ext::Hover>> { - let _p = profile::span("handle_hover"); + let _p = tracing::span!(tracing::Level::INFO, "handle_hover").entered(); let range = match params.position { PositionOrRange::Position(position) => Range::new(position, position), PositionOrRange::Range(range) => range, @@ -1000,7 +1000,7 @@ pub(crate) fn handle_prepare_rename( snap: GlobalStateSnapshot, params: lsp_types::TextDocumentPositionParams, ) -> anyhow::Result<Option<PrepareRenameResponse>> { - let _p = profile::span("handle_prepare_rename"); + let _p = tracing::span!(tracing::Level::INFO, "handle_prepare_rename").entered(); let position = from_proto::file_position(&snap, params)?; let change = snap.analysis.prepare_rename(position)?.map_err(to_proto::rename_error)?; @@ -1014,7 +1014,7 @@ pub(crate) fn handle_rename( snap: GlobalStateSnapshot, params: RenameParams, ) -> anyhow::Result<Option<WorkspaceEdit>> { - let _p = profile::span("handle_rename"); + let _p = tracing::span!(tracing::Level::INFO, "handle_rename").entered(); let position = from_proto::file_position(&snap, params.text_document_position)?; let mut change = snap @@ -1051,7 +1051,7 @@ pub(crate) fn handle_references( snap: GlobalStateSnapshot, params: lsp_types::ReferenceParams, ) -> anyhow::Result<Option<Vec<Location>>> { - let _p = profile::span("handle_references"); + let _p = tracing::span!(tracing::Level::INFO, "handle_references").entered(); let position = from_proto::file_position(&snap, params.text_document_position)?; let exclude_imports = snap.config.find_all_refs_exclude_imports(); @@ -1094,7 +1094,7 @@ pub(crate) fn handle_formatting( snap: GlobalStateSnapshot, params: lsp_types::DocumentFormattingParams, ) -> anyhow::Result<Option<Vec<lsp_types::TextEdit>>> { - let _p = profile::span("handle_formatting"); + let _p = tracing::span!(tracing::Level::INFO, "handle_formatting").entered(); run_rustfmt(&snap, params.text_document, None) } @@ -1103,7 +1103,7 @@ pub(crate) fn handle_range_formatting( snap: GlobalStateSnapshot, params: lsp_types::DocumentRangeFormattingParams, ) -> anyhow::Result<Option<Vec<lsp_types::TextEdit>>> { - let _p = profile::span("handle_range_formatting"); + let _p = tracing::span!(tracing::Level::INFO, "handle_range_formatting").entered(); run_rustfmt(&snap, params.text_document, Some(params.range)) } @@ -1112,7 +1112,7 @@ pub(crate) fn handle_code_action( snap: GlobalStateSnapshot, params: lsp_types::CodeActionParams, ) -> anyhow::Result<Option<Vec<lsp_ext::CodeAction>>> { - let _p = profile::span("handle_code_action"); + let _p = tracing::span!(tracing::Level::INFO, "handle_code_action").entered(); if !snap.config.code_action_literals() { // We intentionally don't support command-based actions, as those either @@ -1186,7 +1186,7 @@ pub(crate) fn handle_code_action_resolve( snap: GlobalStateSnapshot, mut code_action: lsp_ext::CodeAction, ) -> anyhow::Result<lsp_ext::CodeAction> { - let _p = profile::span("handle_code_action_resolve"); + let _p = tracing::span!(tracing::Level::INFO, "handle_code_action_resolve").entered(); let params = match code_action.data.take() { Some(it) => it, None => return Err(invalid_params_error("code action without data".to_string()).into()), @@ -1276,7 +1276,7 @@ pub(crate) fn handle_code_lens( snap: GlobalStateSnapshot, params: lsp_types::CodeLensParams, ) -> anyhow::Result<Option<Vec<CodeLens>>> { - let _p = profile::span("handle_code_lens"); + let _p = tracing::span!(tracing::Level::INFO, "handle_code_lens").entered(); let lens_config = snap.config.lens(); if lens_config.none() { @@ -1346,7 +1346,7 @@ pub(crate) fn handle_document_highlight( snap: GlobalStateSnapshot, params: lsp_types::DocumentHighlightParams, ) -> anyhow::Result<Option<Vec<lsp_types::DocumentHighlight>>> { - let _p = profile::span("handle_document_highlight"); + let _p = tracing::span!(tracing::Level::INFO, "handle_document_highlight").entered(); let position = from_proto::file_position(&snap, params.text_document_position_params)?; let line_index = snap.file_line_index(position.file_id)?; @@ -1368,7 +1368,7 @@ pub(crate) fn handle_ssr( snap: GlobalStateSnapshot, params: lsp_ext::SsrParams, ) -> anyhow::Result<lsp_types::WorkspaceEdit> { - let _p = profile::span("handle_ssr"); + let _p = tracing::span!(tracing::Level::INFO, "handle_ssr").entered(); let selections = params .selections .iter() @@ -1388,7 +1388,7 @@ pub(crate) fn handle_inlay_hints( snap: GlobalStateSnapshot, params: InlayHintParams, ) -> anyhow::Result<Option<Vec<InlayHint>>> { - let _p = profile::span("handle_inlay_hints"); + let _p = tracing::span!(tracing::Level::INFO, "handle_inlay_hints").entered(); let document_uri = ¶ms.text_document.uri; let FileRange { file_id, range } = from_proto::file_range( &snap, @@ -1418,7 +1418,7 @@ pub(crate) fn handle_inlay_hints_resolve( snap: GlobalStateSnapshot, mut original_hint: InlayHint, ) -> anyhow::Result<InlayHint> { - let _p = profile::span("handle_inlay_hints_resolve"); + let _p = tracing::span!(tracing::Level::INFO, "handle_inlay_hints_resolve").entered(); let data = match original_hint.data.take() { Some(it) => it, @@ -1465,7 +1465,7 @@ pub(crate) fn handle_call_hierarchy_prepare( snap: GlobalStateSnapshot, params: CallHierarchyPrepareParams, ) -> anyhow::Result<Option<Vec<CallHierarchyItem>>> { - let _p = profile::span("handle_call_hierarchy_prepare"); + let _p = tracing::span!(tracing::Level::INFO, "handle_call_hierarchy_prepare").entered(); let position = from_proto::file_position(&snap, params.text_document_position_params)?; let nav_info = match snap.analysis.call_hierarchy(position)? { @@ -1487,7 +1487,7 @@ pub(crate) fn handle_call_hierarchy_incoming( snap: GlobalStateSnapshot, params: CallHierarchyIncomingCallsParams, ) -> anyhow::Result<Option<Vec<CallHierarchyIncomingCall>>> { - let _p = profile::span("handle_call_hierarchy_incoming"); + let _p = tracing::span!(tracing::Level::INFO, "handle_call_hierarchy_incoming").entered(); let item = params.item; let doc = TextDocumentIdentifier::new(item.uri); @@ -1522,7 +1522,7 @@ pub(crate) fn handle_call_hierarchy_outgoing( snap: GlobalStateSnapshot, params: CallHierarchyOutgoingCallsParams, ) -> anyhow::Result<Option<Vec<CallHierarchyOutgoingCall>>> { - let _p = profile::span("handle_call_hierarchy_outgoing"); + let _p = tracing::span!(tracing::Level::INFO, "handle_call_hierarchy_outgoing").entered(); let item = params.item; let doc = TextDocumentIdentifier::new(item.uri); @@ -1557,7 +1557,7 @@ pub(crate) fn handle_semantic_tokens_full( snap: GlobalStateSnapshot, params: SemanticTokensParams, ) -> anyhow::Result<Option<SemanticTokensResult>> { - let _p = profile::span("handle_semantic_tokens_full"); + let _p = tracing::span!(tracing::Level::INFO, "handle_semantic_tokens_full").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let text = snap.analysis.file_text(file_id)?; @@ -1587,7 +1587,7 @@ pub(crate) fn handle_semantic_tokens_full_delta( snap: GlobalStateSnapshot, params: SemanticTokensDeltaParams, ) -> anyhow::Result<Option<SemanticTokensFullDeltaResult>> { - let _p = profile::span("handle_semantic_tokens_full_delta"); + let _p = tracing::span!(tracing::Level::INFO, "handle_semantic_tokens_full_delta").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let text = snap.analysis.file_text(file_id)?; @@ -1630,7 +1630,7 @@ pub(crate) fn handle_semantic_tokens_range( snap: GlobalStateSnapshot, params: SemanticTokensRangeParams, ) -> anyhow::Result<Option<SemanticTokensRangeResult>> { - let _p = profile::span("handle_semantic_tokens_range"); + let _p = tracing::span!(tracing::Level::INFO, "handle_semantic_tokens_range").entered(); let frange = from_proto::file_range(&snap, ¶ms.text_document, params.range)?; let text = snap.analysis.file_text(frange.file_id)?; @@ -1656,7 +1656,7 @@ pub(crate) fn handle_open_docs( snap: GlobalStateSnapshot, params: lsp_types::TextDocumentPositionParams, ) -> anyhow::Result<ExternalDocsResponse> { - let _p = profile::span("handle_open_docs"); + let _p = tracing::span!(tracing::Level::INFO, "handle_open_docs").entered(); let position = from_proto::file_position(&snap, params)?; let ws_and_sysroot = snap.workspaces.iter().find_map(|ws| match ws { @@ -1695,7 +1695,7 @@ pub(crate) fn handle_open_cargo_toml( snap: GlobalStateSnapshot, params: lsp_ext::OpenCargoTomlParams, ) -> anyhow::Result<Option<lsp_types::GotoDefinitionResponse>> { - let _p = profile::span("handle_open_cargo_toml"); + let _p = tracing::span!(tracing::Level::INFO, "handle_open_cargo_toml").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let cargo_spec = match CargoTargetSpec::for_file(&snap, file_id)? { @@ -1713,7 +1713,7 @@ pub(crate) fn handle_move_item( snap: GlobalStateSnapshot, params: lsp_ext::MoveItemParams, ) -> anyhow::Result<Vec<lsp_ext::SnippetTextEdit>> { - let _p = profile::span("handle_move_item"); + let _p = tracing::span!(tracing::Level::INFO, "handle_move_item").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let range = from_proto::file_range(&snap, ¶ms.text_document, params.range)?; @@ -1735,7 +1735,7 @@ pub(crate) fn handle_view_recursive_memory_layout( snap: GlobalStateSnapshot, params: lsp_types::TextDocumentPositionParams, ) -> anyhow::Result<Option<lsp_ext::RecursiveMemoryLayout>> { - let _p = profile::span("view_recursive_memory_layout"); + let _p = tracing::span!(tracing::Level::INFO, "view_recursive_memory_layout").entered(); let file_id = from_proto::file_id(&snap, ¶ms.text_document.uri)?; let line_index = snap.file_line_index(file_id)?; let offset = from_proto::offset(&line_index, params.position)?; diff --git a/crates/rust-analyzer/src/integrated_benchmarks.rs b/crates/rust-analyzer/src/integrated_benchmarks.rs index d94f7cefa6..acc02d6447 100644 --- a/crates/rust-analyzer/src/integrated_benchmarks.rs +++ b/crates/rust-analyzer/src/integrated_benchmarks.rs @@ -60,7 +60,7 @@ fn integrated_highlighting_benchmark() { analysis.highlight_as_html(file_id, false).unwrap(); } - profile::init_from("*>100"); + crate::tracing::hprof::init("*>100"); { let _it = stdx::timeit("change"); @@ -152,8 +152,7 @@ fn integrated_completion_benchmark() { analysis.completions(&config, position, None).unwrap(); } - profile::init_from("*>5"); - // let _s = profile::heartbeat_span(); + crate::tracing::hprof::init("*>5"); let completion_offset = { let _it = stdx::timeit("change"); @@ -168,7 +167,7 @@ fn integrated_completion_benchmark() { }; { - let _p = profile::span("unqualified path completion"); + let _p = tracing::span!(tracing::Level::INFO, "unqualified path completion").entered(); let _span = profile::cpu_span(); let analysis = host.analysis(); let config = CompletionConfig { @@ -209,7 +208,7 @@ fn integrated_completion_benchmark() { }; { - let _p = profile::span("dot completion"); + let _p = tracing::span!(tracing::Level::INFO, "dot completion").entered(); let _span = profile::cpu_span(); let analysis = host.analysis(); let config = CompletionConfig { diff --git a/crates/rust-analyzer/src/lib.rs b/crates/rust-analyzer/src/lib.rs index 29bc0b80d8..b77e1dca29 100644 --- a/crates/rust-analyzer/src/lib.rs +++ b/crates/rust-analyzer/src/lib.rs @@ -39,6 +39,7 @@ mod handlers { pub mod config; pub mod lsp; +pub mod tracing; use self::lsp::ext as lsp_ext; #[cfg(test)] diff --git a/crates/rust-analyzer/src/main_loop.rs b/crates/rust-analyzer/src/main_loop.rs index 0173805d44..3c86414d02 100644 --- a/crates/rust-analyzer/src/main_loop.rs +++ b/crates/rust-analyzer/src/main_loop.rs @@ -196,7 +196,7 @@ impl GlobalState { fn handle_event(&mut self, event: Event) -> anyhow::Result<()> { let loop_start = Instant::now(); // NOTE: don't count blocking select! call as a loop-turn time - let _p = profile::span("GlobalState::handle_event"); + let _p = tracing::span!(tracing::Level::INFO, "GlobalState::handle_event").entered(); let event_dbg_msg = format!("{event:?}"); tracing::debug!("{:?} handle_event({})", loop_start, event_dbg_msg); @@ -215,7 +215,8 @@ impl GlobalState { lsp_server::Message::Response(resp) => self.complete_request(resp), }, Event::Task(task) => { - let _p = profile::span("GlobalState::handle_event/task"); + let _p = tracing::span!(tracing::Level::INFO, "GlobalState::handle_event/task") + .entered(); let mut prime_caches_progress = Vec::new(); self.handle_task(&mut prime_caches_progress, task); @@ -269,7 +270,8 @@ impl GlobalState { } } Event::Vfs(message) => { - let _p = profile::span("GlobalState::handle_event/vfs"); + let _p = + tracing::span!(tracing::Level::INFO, "GlobalState::handle_event/vfs").entered(); self.handle_vfs_msg(message); // Coalesce many VFS event into a single loop turn while let Ok(message) = self.loader.receiver.try_recv() { @@ -277,7 +279,8 @@ impl GlobalState { } } Event::Flycheck(message) => { - let _p = profile::span("GlobalState::handle_event/flycheck"); + let _p = tracing::span!(tracing::Level::INFO, "GlobalState::handle_event/flycheck") + .entered(); self.handle_flycheck_msg(message); // Coalesce many flycheck updates into a single loop turn while let Ok(message) = self.flycheck_receiver.try_recv() { diff --git a/crates/rust-analyzer/src/reload.rs b/crates/rust-analyzer/src/reload.rs index 969211f440..65c00cc08d 100644 --- a/crates/rust-analyzer/src/reload.rs +++ b/crates/rust-analyzer/src/reload.rs @@ -70,7 +70,8 @@ impl GlobalState { } pub(crate) fn update_configuration(&mut self, config: Config) { - let _p = profile::span("GlobalState::update_configuration"); + let _p = + tracing::span!(tracing::Level::INFO, "GlobalState::update_configuration").entered(); let old_config = mem::replace(&mut self.config, Arc::new(config)); if self.config.lru_parse_query_capacity() != old_config.lru_parse_query_capacity() { self.analysis_host.update_lru_capacity(self.config.lru_parse_query_capacity()); @@ -355,7 +356,7 @@ impl GlobalState { } pub(crate) fn switch_workspaces(&mut self, cause: Cause) { - let _p = profile::span("GlobalState::switch_workspaces"); + let _p = tracing::span!(tracing::Level::INFO, "GlobalState::switch_workspaces").entered(); tracing::info!(%cause, "will switch workspaces"); let Some((workspaces, force_reload_crate_graph)) = @@ -502,7 +503,7 @@ impl GlobalState { let mut crate_graph_file_dependencies = FxHashSet::default(); let mut load = |path: &AbsPath| { - let _p = profile::span("switch_workspaces::load"); + let _p = tracing::span!(tracing::Level::INFO, "switch_workspaces::load").entered(); let vfs_path = vfs::VfsPath::from(path.to_path_buf()); crate_graph_file_dependencies.insert(vfs_path.clone()); match vfs.file_id(&vfs_path) { @@ -585,7 +586,7 @@ impl GlobalState { } fn reload_flycheck(&mut self) { - let _p = profile::span("GlobalState::reload_flycheck"); + let _p = tracing::span!(tracing::Level::INFO, "GlobalState::reload_flycheck").entered(); let config = self.config.flycheck(); let sender = self.flycheck_sender.clone(); let invocation_strategy = match config { diff --git a/crates/rust-analyzer/src/tracing/hprof.rs b/crates/rust-analyzer/src/tracing/hprof.rs new file mode 100644 index 0000000000..f37262a17a --- /dev/null +++ b/crates/rust-analyzer/src/tracing/hprof.rs @@ -0,0 +1,238 @@ +//! Consumer of `tracing` data, which prints a hierarchical profile. +//! +//! Based on https://github.com/davidbarsky/tracing-tree, but does less, while +//! actually printing timings for spans by default. The code here is vendored from +//! https://github.com/matklad/tracing-span-tree. +//! +//! Usage: +//! +//! ```rust +//! let layer = hprof::SpanTree::default(); +//! Registry::default().with(layer).init(); +//! ``` +//! +//! Example output: +//! +//! ```text +//! 8.37ms top_level +//! 1.09ms middle +//! 1.06ms leaf +//! 1.06ms middle +//! 3.12ms middle +//! 1.06ms leaf +//! 3.06ms middle +//! ``` +//! +//! Same data, but with `.aggregate(true)`: +//! +//! ```text +//! 8.39ms top_level +//! 8.35ms 4 middle +//! 2.13ms 2 leaf +//! ``` + +use std::{ + fmt, mem, + time::{Duration, Instant}, +}; + +use rustc_hash::FxHashSet; +use tracing::{ + field::{Field, Visit}, + span::Attributes, + Event, Id, Level, Subscriber, +}; +use tracing_subscriber::{ + filter, + layer::{Context, SubscriberExt}, + registry::LookupSpan, + Layer, Registry, +}; + +use crate::tracing::hprof; + +pub fn init(spec: &str) { + let (write_filter, allowed_names) = WriteFilter::from_spec(spec); + + // this filter the first pass for `tracing`: these are all the "profiling" spans, but things like + // span depth or duration are not filtered here: that only occurs at write time. + let profile_filter = filter::filter_fn(move |metadata| { + let allowed = match &allowed_names { + Some(names) => names.contains(metadata.name()), + None => true, + }; + + metadata.is_span() + && allowed + && metadata.level() >= &Level::INFO + && !metadata.target().starts_with("salsa") + && !metadata.target().starts_with("chalk") + }); + + let layer = hprof::SpanTree::default() + .aggregate(true) + .spec_filter(write_filter) + .with_filter(profile_filter); + + let subscriber = Registry::default().with(layer); + tracing::subscriber::set_global_default(subscriber).unwrap(); +} + +#[derive(Default, Debug)] +pub(crate) struct SpanTree { + aggregate: bool, + write_filter: WriteFilter, +} + +impl SpanTree { + /// Merge identical sibling spans together. + pub(crate) fn aggregate(self, yes: bool) -> SpanTree { + SpanTree { aggregate: yes, ..self } + } + + /// Add a write-time filter for span duration or tree depth. + pub(crate) fn spec_filter(self, write_filter: WriteFilter) -> SpanTree { + SpanTree { write_filter, ..self } + } +} + +struct Data { + start: Instant, + children: Vec<Node>, +} + +impl Data { + fn new(attrs: &Attributes<'_>) -> Self { + let mut span = Self { start: Instant::now(), children: Vec::new() }; + attrs.record(&mut span); + span + } + fn into_node(self, name: &'static str) -> Node { + Node { name, count: 1, duration: self.start.elapsed(), children: self.children } + } +} + +impl Visit for Data { + fn record_debug(&mut self, _field: &Field, _value: &dyn fmt::Debug) {} +} + +impl<S> Layer<S> for SpanTree +where + S: Subscriber + for<'span> LookupSpan<'span>, +{ + fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { + let span = ctx.span(id).unwrap(); + + let data = Data::new(attrs); + span.extensions_mut().insert(data); + } + + fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, S>) {} + + fn on_close(&self, id: Id, ctx: Context<'_, S>) { + let span = ctx.span(&id).unwrap(); + let data = span.extensions_mut().remove::<Data>().unwrap(); + let mut node = data.into_node(span.name()); + + match span.parent() { + Some(parent_span) => { + parent_span.extensions_mut().get_mut::<Data>().unwrap().children.push(node); + } + None => { + if self.aggregate { + node.aggregate() + } + node.print(&self.write_filter) + } + } + } +} + +#[derive(Default)] +struct Node { + name: &'static str, + count: u32, + duration: Duration, + children: Vec<Node>, +} + +impl Node { + fn print(&self, filter: &WriteFilter) { + self.go(0, filter) + } + + fn go(&self, level: usize, filter: &WriteFilter) { + if self.duration > filter.longer_than && level < filter.depth { + let duration = format!("{:3.2?}", self.duration); + let count = if self.count > 1 { self.count.to_string() } else { String::new() }; + eprintln!( + "{:width$} {:<9} {:<6} {}", + "", + duration, + count, + self.name, + width = level * 2 + ); + for child in &self.children { + child.go(level + 1, filter) + } + } + } + + fn aggregate(&mut self) { + if self.children.is_empty() { + return; + } + + self.children.sort_by_key(|it| it.name); + let mut idx = 0; + for i in 1..self.children.len() { + if self.children[idx].name == self.children[i].name { + let child = mem::take(&mut self.children[i]); + self.children[idx].duration += child.duration; + self.children[idx].count += child.count; + self.children[idx].children.extend(child.children); + } else { + idx += 1; + assert!(idx <= i); + self.children.swap(idx, i); + } + } + self.children.truncate(idx + 1); + for child in &mut self.children { + child.aggregate() + } + } +} + +#[derive(Default, Clone, Debug)] +pub(crate) struct WriteFilter { + depth: usize, + longer_than: Duration, +} + +impl WriteFilter { + pub(crate) fn from_spec(mut spec: &str) -> (WriteFilter, Option<FxHashSet<String>>) { + let longer_than = if let Some(idx) = spec.rfind('>') { + let longer_than = spec[idx + 1..].parse().expect("invalid profile longer_than"); + spec = &spec[..idx]; + Duration::from_millis(longer_than) + } else { + Duration::new(0, 0) + }; + + let depth = if let Some(idx) = spec.rfind('@') { + let depth: usize = spec[idx + 1..].parse().expect("invalid profile depth"); + spec = &spec[..idx]; + depth + } else { + 999 + }; + let allowed = if spec == "*" { + None + } else { + Some(FxHashSet::from_iter(spec.split('|').map(String::from))) + }; + (WriteFilter { depth, longer_than }, allowed) + } +} diff --git a/crates/rust-analyzer/src/tracing/mod.rs b/crates/rust-analyzer/src/tracing/mod.rs new file mode 100644 index 0000000000..0e681c3709 --- /dev/null +++ b/crates/rust-analyzer/src/tracing/mod.rs @@ -0,0 +1,108 @@ +//! Simple logger that logs either to stderr or to a file, using `tracing_subscriber` +//! filter syntax and `tracing_appender` for non blocking output. + +use std::io; + +use anyhow::Context; +use tracing::{level_filters::LevelFilter, Level}; +use tracing_subscriber::{ + filter::{self, Targets}, + fmt::{format::FmtSpan, MakeWriter}, + layer::SubscriberExt, + util::SubscriberInitExt, + Layer, Registry, +}; +use tracing_tree::HierarchicalLayer; + +pub mod hprof; + +pub struct Config<T> { + pub writer: T, + pub filter: String, + /// The meaning of CHALK_DEBUG is to tell chalk crates + /// (i.e. chalk-solve, chalk-ir, chalk-recursive) how to filter tracing + /// logs. But now we can only have just one filter, which means we have to + /// merge chalk filter to our main filter (from RA_LOG env). + /// + /// The acceptable syntax of CHALK_DEBUG is `target[span{field=value}]=level`. + /// As the value should only affect chalk crates, we'd better manually + /// specify the target. And for simplicity, CHALK_DEBUG only accept the value + /// that specify level. + pub chalk_filter: Option<String>, + /// Filtering syntax, set in a shell: + /// ``` + /// env RA_PROFILE=* // dump everything + /// env RA_PROFILE=foo|bar|baz // enabled only selected entries + /// env RA_PROFILE=*@3>10 // dump everything, up to depth 3, if it takes more than 10 + /// ``` + pub profile_filter: Option<String>, +} + +impl<T> Config<T> +where + T: for<'writer> MakeWriter<'writer> + Send + Sync + 'static, +{ + pub fn init(self) -> anyhow::Result<()> { + let filter: Targets = self + .filter + .parse() + .with_context(|| format!("invalid log filter: `{}`", self.filter))?; + + let writer = self.writer; + + let ra_fmt_layer = tracing_subscriber::fmt::layer() + .with_span_events(FmtSpan::CLOSE) + .with_writer(writer) + .with_filter(filter); + + let mut chalk_layer = None; + if let Some(chalk_filter) = self.chalk_filter { + let level: LevelFilter = + chalk_filter.parse().with_context(|| "invalid chalk log filter")?; + + let chalk_filter = Targets::new() + .with_target("chalk_solve", level) + .with_target("chalk_ir", level) + .with_target("chalk_recursive", level); + chalk_layer = Some( + HierarchicalLayer::default() + .with_indent_lines(true) + .with_ansi(false) + .with_indent_amount(2) + .with_writer(io::stderr) + .with_filter(chalk_filter), + ); + }; + + let mut profiler_layer = None; + if let Some(spec) = self.profile_filter { + let (write_filter, allowed_names) = hprof::WriteFilter::from_spec(&spec); + + // this filter the first pass for `tracing`: these are all the "profiling" spans, but things like + // span depth or duration are not filtered here: that only occurs at write time. + let profile_filter = filter::filter_fn(move |metadata| { + let allowed = match &allowed_names { + Some(names) => names.contains(metadata.name()), + None => true, + }; + + metadata.is_span() + && allowed + && metadata.level() >= &Level::INFO + && !metadata.target().starts_with("salsa") + && !metadata.target().starts_with("chalk") + }); + + let layer = hprof::SpanTree::default() + .aggregate(true) + .spec_filter(write_filter) + .with_filter(profile_filter); + + profiler_layer = Some(layer); + } + + Registry::default().with(ra_fmt_layer).with(chalk_layer).with(profiler_layer).try_init()?; + + Ok(()) + } +} diff --git a/crates/rust-analyzer/tests/slow-tests/main.rs b/crates/rust-analyzer/tests/slow-tests/main.rs index 58a99cc447..f7f654b890 100644 --- a/crates/rust-analyzer/tests/slow-tests/main.rs +++ b/crates/rust-analyzer/tests/slow-tests/main.rs @@ -38,9 +38,6 @@ use crate::{ testdir::TestDir, }; -const PROFILE: &str = ""; -// const PROFILE: &'static str = "*@3>100"; - #[test] fn completes_items_from_standard_library() { if skip_slow_tests() { diff --git a/crates/rust-analyzer/tests/slow-tests/support.rs b/crates/rust-analyzer/tests/slow-tests/support.rs index e16990eabd..d699374f9c 100644 --- a/crates/rust-analyzer/tests/slow-tests/support.rs +++ b/crates/rust-analyzer/tests/slow-tests/support.rs @@ -9,11 +9,11 @@ use std::{ use crossbeam_channel::{after, select, Receiver}; use lsp_server::{Connection, Message, Notification, Request}; use lsp_types::{notification::Exit, request::Shutdown, TextDocumentIdentifier, Url}; -use rust_analyzer::{config::Config, lsp, main_loop}; +use rust_analyzer::{config::Config, lsp, main_loop, tracing}; use serde::Serialize; use serde_json::{json, to_string_pretty, Value}; use test_utils::FixtureWithProjectMeta; -use tracing_subscriber::{prelude::*, Layer}; +use tracing_subscriber::fmt::TestWriter; use vfs::AbsPathBuf; use crate::testdir::TestDir; @@ -91,12 +91,14 @@ impl Project<'_> { static INIT: Once = Once::new(); INIT.call_once(|| { - let filter: tracing_subscriber::filter::Targets = - std::env::var("RA_LOG").ok().and_then(|it| it.parse().ok()).unwrap_or_default(); - let layer = - tracing_subscriber::fmt::Layer::new().with_test_writer().with_filter(filter); - tracing_subscriber::Registry::default().with(layer).init(); - profile::init_from(crate::PROFILE); + let _ = tracing::Config { + writer: TestWriter::default(), + // Deliberately enable all `error` logs if the user has not set RA_LOG, as there is usually + // useful information in there for debugging. + filter: std::env::var("RA_LOG").ok().unwrap_or_else(|| "error".to_string()), + chalk_filter: std::env::var("CHALK_DEBUG").ok(), + profile_filter: std::env::var("RA_PROFILE").ok(), + }; }); let FixtureWithProjectMeta { fixture, mini_core, proc_macro_names, toolchain } = diff --git a/crates/stdx/Cargo.toml b/crates/stdx/Cargo.toml index e6014cf812..2e3f9113b0 100644 --- a/crates/stdx/Cargo.toml +++ b/crates/stdx/Cargo.toml @@ -13,7 +13,7 @@ doctest = false [dependencies] backtrace = { version = "0.3.67", optional = true } -always-assert = { version = "0.1.2", features = ["log"] } +always-assert = { version = "0.2.0", features = ["tracing"] } jod-thread = "0.1.2" libc.workspace = true crossbeam-channel = "0.5.5" diff --git a/crates/syntax/Cargo.toml b/crates/syntax/Cargo.toml index 9f78614bba..a0fd73ee13 100644 --- a/crates/syntax/Cargo.toml +++ b/crates/syntax/Cargo.toml @@ -22,6 +22,7 @@ once_cell = "1.17.0" indexmap.workspace = true smol_str.workspace = true triomphe.workspace = true +tracing.workspace = true ra-ap-rustc_lexer.workspace = true diff --git a/crates/syntax/src/algo.rs b/crates/syntax/src/algo.rs index c4548b1647..01f2af419e 100644 --- a/crates/syntax/src/algo.rs +++ b/crates/syntax/src/algo.rs @@ -120,7 +120,7 @@ pub struct TreeDiff { impl TreeDiff { pub fn into_text_edit(&self, builder: &mut TextEditBuilder) { - let _p = profile::span("into_text_edit"); + let _p = tracing::span!(tracing::Level::INFO, "into_text_edit").entered(); for (anchor, to) in &self.insertions { let offset = match anchor { @@ -149,7 +149,7 @@ impl TreeDiff { /// /// This function tries to find a fine-grained diff. pub fn diff(from: &SyntaxNode, to: &SyntaxNode) -> TreeDiff { - let _p = profile::span("diff"); + let _p = tracing::span!(tracing::Level::INFO, "diff").entered(); let mut diff = TreeDiff { replacements: FxHashMap::default(), diff --git a/crates/test-utils/Cargo.toml b/crates/test-utils/Cargo.toml index 56067d8341..2ff1fad6c2 100644 --- a/crates/test-utils/Cargo.toml +++ b/crates/test-utils/Cargo.toml @@ -15,10 +15,11 @@ doctest = false # Avoid adding deps here, this crate is widely used in tests it should compile fast! dissimilar = "1.0.7" text-size.workspace = true +tracing.workspace = true rustc-hash.workspace = true stdx.workspace = true profile.workspace = true [lints] -workspace = true
\ No newline at end of file +workspace = true |