Auto merge of #17102 - davidbarsky:david/add-some-tracing-to-project-loading, r=lnicola

chore: add some `tracing` to project loading

I wanted to see what's happening during project loading and if it could be parallelized. I'm thinking maybe, but it's not this PR :)

Author: bors

Cargo.lock

@@ -17,6 +17,7 @@ use itertools::Itertools;
 use proc_macro_api::{MacroDylib, ProcMacroServer};
 use project_model::{CargoConfig, PackageRoot, ProjectManifest, ProjectWorkspace};
 use span::Span;
+use tracing::{instrument, Level};
 use vfs::{file_set::FileSetConfig, loader::Handle, AbsPath, AbsPathBuf, VfsPath};
 
 pub struct LoadCargoConfig {
@@ -50,6 +51,7 @@ pub fn load_workspace_at(
     load_workspace(workspace, &cargo_config.extra_env, load_config)
 }
 
+#[instrument(skip_all)]
 pub fn load_workspace(
     ws: ProjectWorkspace,
     extra_env: &FxHashMap<String, String>,
@@ -350,6 +352,7 @@ fn load_crate_graph(
                 }
             }
             vfs::loader::Message::Loaded { files } | vfs::loader::Message::Changed { files } => {
+                let _p = tracing::span!(Level::INFO, "LoadCargo::load_file_contents").entered();
                 for (path, contents) in files {
                     vfs.set_file_contents(path.into(), contents);
                 }

crates/load-cargo/src/lib.rs

@@ -15,6 +15,7 @@ use rustc_hash::{FxHashMap, FxHashSet};
 use semver::Version;
 use span::Edition;
 use toolchain::Tool;
+use tracing::instrument;
 use triomphe::Arc;
 
 use crate::{
@@ -885,6 +886,7 @@ impl ProjectWorkspace {
     }
 }
 
+#[instrument(skip_all)]
 fn project_json_to_crate_graph(
     rustc_cfg: Vec<CfgFlag>,
     load: FileLoader<'_>,

crates/project-model/src/workspace.rs

@@ -23,6 +23,7 @@ use project_model::{
     WorkspaceBuildScripts,
 };
 use rustc_hash::{FxHashMap, FxHashSet};
+use tracing::{span, Level};
 use triomphe::Arc;
 use vfs::{AnchoredPathBuf, ChangedFile, Vfs};
 
@@ -252,8 +253,7 @@ impl GlobalState {
     }
 
     pub(crate) fn process_changes(&mut self) -> bool {
-        let _p = tracing::span!(tracing::Level::INFO, "GlobalState::process_changes").entered();
-
+        let _p = span!(Level::INFO, "GlobalState::process_changes").entered();
         let mut file_changes = FxHashMap::<_, (bool, ChangedFile)>::default();
         let (change, modified_rust_files, workspace_structure_change) = {
             let mut change = ChangeWithProcMacros::new();
@@ -263,6 +263,8 @@ impl GlobalState {
                 return false;
             }
 
+            let _p =
+                span!(Level::INFO, "GlobalState::process_changes/gather_changed_files").entered();
             // downgrade to read lock to allow more readers while we are normalizing text
             let guard = RwLockWriteGuard::downgrade_to_upgradable(guard);
             let vfs: &Vfs = &guard.0;
@@ -301,6 +303,8 @@ impl GlobalState {
                 }
             }
 
+            let _p = span!(Level::INFO, "GlobalState::process_changes/calculate_changed_files")
+                .entered();
             let changed_files: Vec<_> = file_changes
                 .into_iter()
                 .filter(|(_, (just_created, change))| {
@@ -366,6 +370,7 @@ impl GlobalState {
             (change, modified_rust_files, workspace_structure_change)
         };
 
+        let _p = span!(Level::INFO, "GlobalState::process_changes/apply_change").entered();
         self.analysis_host.apply_change(change);
 
         {
@@ -379,6 +384,9 @@ impl GlobalState {
             // but something's going wrong with the source root business when we add a new local
             // crate see https://github.com/rust-lang/rust-analyzer/issues/13029
             if let Some((path, force_crate_graph_reload)) = workspace_structure_change {
+                let _p = span!(Level::INFO, "GlobalState::process_changes/ws_structure_change")
+                    .entered();
+
                 self.fetch_workspaces_queue.request_op(
                     format!("workspace vfs file change: {path}"),
                     force_crate_graph_reload,

crates/rust-analyzer/src/global_state.rs

@@ -12,6 +12,7 @@ use ide_db::base_db::{SourceDatabase, SourceDatabaseExt, VfsPath};
 use lsp_server::{Connection, Notification, Request};
 use lsp_types::{notification::Notification as _, TextDocumentIdentifier};
 use stdx::thread::ThreadIntent;
+use tracing::{span, Level};
 use vfs::FileId;
 
 use crate::{
@@ -229,8 +230,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 = tracing::span!(tracing::Level::INFO, "GlobalState::handle_event", event = %event)
-            .entered();
+        let _p = tracing::span!(Level::INFO, "GlobalState::handle_event", event = %event).entered();
 
         let event_dbg_msg = format!("{event:?}");
         tracing::debug!(?loop_start, ?event, "handle_event");
@@ -669,9 +669,12 @@ impl GlobalState {
     }
 
     fn handle_vfs_msg(&mut self, message: vfs::loader::Message) {
+        let _p = tracing::span!(Level::INFO, "GlobalState::handle_vfs_msg").entered();
         let is_changed = matches!(message, vfs::loader::Message::Changed { .. });
         match message {
             vfs::loader::Message::Changed { files } | vfs::loader::Message::Loaded { files } => {
+                let _p = tracing::span!(Level::INFO, "GlobalState::handle_vfs_msg{changed/load}")
+                    .entered();
                 let vfs = &mut self.vfs.write().0;
                 for (path, contents) in files {
                     let path = VfsPath::from(path);
@@ -685,6 +688,8 @@ impl GlobalState {
                 }
             }
             vfs::loader::Message::Progress { n_total, n_done, dir, config_version } => {
+                let _p =
+                    tracing::span!(Level::INFO, "GlobalState::handle_vfs_mgs/progress").entered();
                 always!(config_version <= self.vfs_config_version);
 
                 let state = match n_done {
@@ -867,6 +872,8 @@ impl GlobalState {
 
     /// Registers and handles a request. This should only be called once per incoming request.
     fn on_new_request(&mut self, request_received: Instant, req: Request) {
+        let _p =
+            span!(Level::INFO, "GlobalState::on_new_request", req.method = ?req.method).entered();
         self.register_request(&req, request_received);
         self.on_request(req);
     }
@@ -980,6 +987,8 @@ impl GlobalState {
 
     /// Handles an incoming notification.
     fn on_notification(&mut self, not: Notification) -> anyhow::Result<()> {
+        let _p =
+            span!(Level::INFO, "GlobalState::on_notification", not.method = ?not.method).entered();
         use crate::handlers::notification as handlers;
         use lsp_types::notification as notifs;
 

crates/rust-analyzer/src/main_loop.rs

@@ -13,6 +13,7 @@ doctest = false
 
 [dependencies]
 rustc-hash.workspace = true
+tracing.workspace = true
 fst = "0.4.7"
 indexmap.workspace = true
 nohash-hasher.workspace = true
@@ -21,4 +22,4 @@ paths.workspace = true
 stdx.workspace = true
 
 [lints]
-workspace = true
+workspace = true

crates/vfs/Cargo.toml

@@ -56,6 +56,8 @@ pub use crate::{
 };
 pub use paths::{AbsPath, AbsPathBuf};
 
+use tracing::{span, Level};
+
 /// Handle to a file in [`Vfs`]
 ///
 /// Most functions in rust-analyzer use this when they need to refer to a file.
@@ -210,6 +212,7 @@ impl Vfs {
     /// If the path does not currently exists in the `Vfs`, allocates a new
     /// [`FileId`] for it.
     pub fn set_file_contents(&mut self, path: VfsPath, contents: Option<Vec<u8>>) -> bool {
+        let _p = span!(Level::INFO, "Vfs::set_file_contents").entered();
         let file_id = self.alloc_file_id(path);
         let state = self.get(file_id);
         let change_kind = match (state, contents) {
@@ -236,6 +239,7 @@ impl Vfs {
 
     /// Drain and returns all the changes in the `Vfs`.
     pub fn take_changes(&mut self) -> Vec<ChangedFile> {
+        let _p = span!(Level::INFO, "Vfs::take_changes").entered();
         for file_id in self.created_this_cycle.drain(..) {
             if self.data[file_id.0 as usize] == FileState::Created {
                 // downgrade the file from `Created` to `Exists` as the cycle is done