internal: switch to tracing from log

This commit also adds `tracing` to NotificationDispatcher/RequestDispatcher,
bumps `rust-analyzer-salsa` to 0.17.0-pre.6, `always-assert` to 0.2, and
removes the homegrown `hprof` implementation in favor of a vendored
tracing-span-tree.

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]]

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",
+  "registry",
-    "fmt",
+  "fmt",
-    "tracing-log",
+  "tracing-log",
 ] }
 triomphe = { version = "0.1.10", default-features = false, features = ["std"] }
 xshell = "0.2.5"

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

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);

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)?;
 

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)
     }

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) => {

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;

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);

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)
 }
 

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

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();

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();
 

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);

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();
 

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(|| {
+        let crate_graph = db.crate_graph();
-            db.crate_graph()[krate].display_name.as_deref().unwrap_or_default().to_string()
+        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();
 

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")
+        let _p = tracing::span!(tracing::Level::INFO, "resolve_import", import_path = %import.path.display(self.db.upcast()))
-            .detail(|| format!("{}", 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 {

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()

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),

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;

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_)

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)
 }
 

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

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);

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);

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) {

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();
 

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 {

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)?;

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 {

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"
 

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(|| {
+        let name = self.name(db);
-            format!(
+        let _p = tracing::span!(tracing::Level::INFO, "Module::diagnostics", ?name);
-                "{:?}",
-                self.name(db)
-                    .map_or("<unknown>".into(), |name| name.display(db.upcast()).to_string())
-            )
-        });
         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| {

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))?;

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()
     }

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

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)?;
 

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

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;
     }

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)?;
 

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));
     }

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

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::*};

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);

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;
 

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;

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);

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);

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_)
 }
 

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))
 }
 

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));

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_)
 }
 

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)?;

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)
 }
 

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 {

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 => {

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;

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;
 

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),

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(|| {
+    let krate_name = krate.display_name(sema.db).map(|name| name.to_string());
-        format!(
+    let _p = tracing::span!(tracing::Level::INFO, "items_with_name", name = name.text(), assoc_item_search = ?assoc_item_search, crate = ?krate_name)
-            "Name: {}, crate: {:?}, assoc items: {:?}",
+        .entered();
-            name.text(),
-            assoc_item_search,
-            krate.display_name(sema.db).map(|name| name.to_string()),
-        )
-    });
 
     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

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 = {

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 => {

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

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();

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 {

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();

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 = {

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| {

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.

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)?;
 

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

crates/profile/src/hprof.rs

@@ -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"),
-        }
-    }
-}

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},
 };

crates/profile/src/tree.rs

@@ -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
-        })
-    }
-}

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

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(

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

crates/rust-analyzer/src/bin/logger.rs

@@ -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)
-    }
-}

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 {
+    let writer = match log_file {
-        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(())
 }
 

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 {

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 =

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(),

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) = {

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(&params.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(&params.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(&params.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) {

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, &params.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, &params.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, &params.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, &params.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, &params.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, &params.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, &params.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(&params, &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) = &params.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, &params.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, &params.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 = &params.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, &params.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, &params.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, &params.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, &params.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, &params.text_document.uri)?;
     let range = from_proto::file_range(&snap, &params.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, &params.text_document.uri)?;
     let line_index = snap.file_line_index(file_id)?;
     let offset = from_proto::offset(&line_index, params.position)?;

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");
+    crate::tracing::hprof::init("*>5");
-    // let _s = profile::heartbeat_span();
 
     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 {

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)]

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() {

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 {

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)
+    }
+}

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(())
+    }
+}

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() {

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 =
+            let _ = tracing::Config {
-                std::env::var("RA_LOG").ok().and_then(|it| it.parse().ok()).unwrap_or_default();
+                writer: TestWriter::default(),
-            let layer =
+                // Deliberately enable all `error` logs if the user has not set RA_LOG, as there is usually
-                tracing_subscriber::fmt::Layer::new().with_test_writer().with_filter(filter);
+                // useful information in there for debugging.
-            tracing_subscriber::Registry::default().with(layer).init();
+                filter: std::env::var("RA_LOG").ok().unwrap_or_else(|| "error".to_string()),
-            profile::init_from(crate::PROFILE);
+                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 } =

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"

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
 

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(),

crates/test-utils/Cargo.toml

@@ -15,6 +15,7 @@ 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