Auto merge of #16394 - davidbarsky:david/add-more-tracing-spans, r=Veykril

internal: add some `tracing` to {Request, Notification}Dispatch

Some of the tracing config would need to be changed in order to benefit more from this (especially `.with_span_events(FmtSpan::CLOSE)`), which provides span events like the following:

```
2024-01-18T02:41:06.675779Z  INFO request{method="textDocument/codeLens" request_id=RequestId(I32(17))}: rust_analyzer::dispatch: close time.busy=61.8µs time.idle=5.29µs
```

I dunno if y'all need `LoggerFormatter` in here, but if you don't, I'd be happy to yeet it out of rust-analyzer. In any case, this provided a pretty decent amount of information in the logs, and I can expand this as needed or we can land this PR and expand later.

Author: bors

Cargo.lock

@@ -113,7 +113,7 @@ itertools = "0.12.0"
 libc = "0.2.150"
 nohash-hasher = "0.2.0"
 rayon = "1.8.0"
-rust-analyzer-salsa = "0.17.0-pre.5"
+rust-analyzer-salsa = "0.17.0-pre.6"
 rustc-hash = "1.1.0"
 semver = "1.0.14"
 serde = { version = "1.0.192", features = ["derive"] }
@@ -128,9 +128,9 @@ text-size = "1.1.1"
 tracing = "0.1.40"
 tracing-tree = "0.3.0"
 tracing-subscriber = { version = "0.3.18", default-features = false, features = [
-    "registry",
-    "fmt",
-    "tracing-log",
+  "registry",
+  "fmt",
+  "tracing-log",
 ] }
 triomphe = { version = "0.1.10", default-features = false, features = ["std"] }
 xshell = "0.2.5"

Cargo.toml

@@ -17,6 +17,7 @@ rust-analyzer-salsa.workspace = true
 rustc-hash.workspace = true
 triomphe.workspace = true
 semver.workspace = true
+tracing.workspace = true
 
 # local deps
 cfg.workspace = true
@@ -27,4 +28,4 @@ vfs.workspace = true
 span.workspace = true
 
 [lints]
-workspace = true
+workspace = true

crates/base-db/Cargo.toml

@@ -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/change.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/input.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/base-db/src/lib.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/attr.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/body.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/data.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)
 }