From 2a030ba7557b41194f08015235100dd691294794 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Thu, 18 Apr 2024 14:39:43 -0400 Subject: [PATCH] chore: add some `tracing` to project loading --- Cargo.lock | 1 + crates/load-cargo/src/lib.rs | 3 +++ crates/project-model/src/workspace.rs | 2 ++ crates/rust-analyzer/src/global_state.rs | 12 ++++++++++-- crates/rust-analyzer/src/main_loop.rs | 13 +++++++++++-- crates/vfs/Cargo.toml | 3 ++- crates/vfs/src/lib.rs | 4 ++++ 7 files changed, 33 insertions(+), 5 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index a6e460134f21..55709f8d45fa 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2255,6 +2255,7 @@ dependencies = [ "paths", "rustc-hash", "stdx", + "tracing", ] [[package]] diff --git a/crates/load-cargo/src/lib.rs b/crates/load-cargo/src/lib.rs index 79d6fe36b561..f7950162057a 100644 --- a/crates/load-cargo/src/lib.rs +++ b/crates/load-cargo/src/lib.rs @@ -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, @@ -352,6 +354,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); } diff --git a/crates/project-model/src/workspace.rs b/crates/project-model/src/workspace.rs index 00e9c1298801..5fa5383cf96e 100644 --- a/crates/project-model/src/workspace.rs +++ b/crates/project-model/src/workspace.rs @@ -16,6 +16,7 @@ use semver::Version; use span::Edition; use stdx::always; use toolchain::Tool; +use tracing::instrument; use triomphe::Arc; use crate::{ @@ -863,6 +864,7 @@ impl ProjectWorkspace { } } +#[instrument(skip_all)] fn project_json_to_crate_graph( rustc_cfg: Vec, load: &mut dyn FnMut(&AbsPath) -> Option, diff --git a/crates/rust-analyzer/src/global_state.rs b/crates/rust-analyzer/src/global_state.rs index ec10bc7ccdaa..8cfb1ece7d3f 100644 --- a/crates/rust-analyzer/src/global_state.rs +++ b/crates/rust-analyzer/src/global_state.rs @@ -20,6 +20,7 @@ use parking_lot::{ use proc_macro_api::ProcMacroServer; use project_model::{CargoWorkspace, ProjectWorkspace, Target, WorkspaceBuildScripts}; use rustc_hash::{FxHashMap, FxHashSet}; +use tracing::{span, Level}; use triomphe::Arc; use vfs::{AnchoredPathBuf, ChangedFile, Vfs}; @@ -247,8 +248,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(); @@ -258,6 +258,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; @@ -296,6 +298,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))| { @@ -361,6 +365,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); { @@ -374,6 +379,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, diff --git a/crates/rust-analyzer/src/main_loop.rs b/crates/rust-analyzer/src/main_loop.rs index f37b25fb9558..95b3d3ecb3c4 100644 --- a/crates/rust-analyzer/src/main_loop.rs +++ b/crates/rust-analyzer/src/main_loop.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; diff --git a/crates/vfs/Cargo.toml b/crates/vfs/Cargo.toml index c88f34665598..84f2110ebad1 100644 --- a/crates/vfs/Cargo.toml +++ b/crates/vfs/Cargo.toml @@ -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 \ No newline at end of file +workspace = true diff --git a/crates/vfs/src/lib.rs b/crates/vfs/src/lib.rs index ddd6bbe3f7a4..cb3e058355c3 100644 --- a/crates/vfs/src/lib.rs +++ b/crates/vfs/src/lib.rs @@ -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>) -> 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 { + 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