Unnamed repository; edit this file 'description' to name the repository.
Track salsa cancellation time in loop turn warning
| -rw-r--r-- | crates/ide-db/src/apply_change.rs | 7 | ||||
| -rw-r--r-- | crates/ide/src/lib.rs | 5 | ||||
| -rw-r--r-- | crates/rust-analyzer/src/global_state.rs | 8 | ||||
| -rw-r--r-- | crates/rust-analyzer/src/main_loop.rs | 85 | ||||
| -rw-r--r-- | crates/rust-analyzer/src/reload.rs | 44 | ||||
| -rw-r--r-- | crates/rust-analyzer/src/task_pool.rs | 4 |
6 files changed, 91 insertions, 62 deletions
diff --git a/crates/ide-db/src/apply_change.rs b/crates/ide-db/src/apply_change.rs index b77a18f56e..7a3c466daa 100644 --- a/crates/ide-db/src/apply_change.rs +++ b/crates/ide-db/src/apply_change.rs @@ -1,16 +1,21 @@ //! Applies changes to the IDE state transactionally. +use std::time::{Duration, Instant}; + use profile::Bytes; use salsa::Database as _; use crate::{ChangeWithProcMacros, RootDatabase}; impl RootDatabase { - pub fn apply_change(&mut self, change: ChangeWithProcMacros) { + pub fn apply_change(&mut self, change: ChangeWithProcMacros) -> Duration { let _p = tracing::info_span!("RootDatabase::apply_change").entered(); + let now = Instant::now(); self.trigger_cancellation(); + let elapsed = now.elapsed(); tracing::trace!("apply_change {:?}", change); change.apply(self); + elapsed } // Feature: Memory Usage diff --git a/crates/ide/src/lib.rs b/crates/ide/src/lib.rs index 88cb570c6b..dded01520f 100644 --- a/crates/ide/src/lib.rs +++ b/crates/ide/src/lib.rs @@ -60,6 +60,7 @@ mod view_mir; mod view_syntax_tree; use std::panic::{AssertUnwindSafe, UnwindSafe}; +use std::time::Duration; use cfg::CfgOptions; use fetch_crates::CrateInfo; @@ -197,8 +198,8 @@ impl AnalysisHost { /// Applies changes to the current state of the world. If there are /// outstanding snapshots, they will be canceled. - pub fn apply_change(&mut self, change: ChangeWithProcMacros) { - self.db.apply_change(change); + pub fn apply_change(&mut self, change: ChangeWithProcMacros) -> Duration { + self.db.apply_change(change) } /// NB: this clears the database diff --git a/crates/rust-analyzer/src/global_state.rs b/crates/rust-analyzer/src/global_state.rs index afd4162de6..f91e9532aa 100644 --- a/crates/rust-analyzer/src/global_state.rs +++ b/crates/rust-analyzer/src/global_state.rs @@ -330,7 +330,7 @@ impl GlobalState { this } - pub(crate) fn process_changes(&mut self) -> bool { + pub(crate) fn process_changes(&mut self) -> (bool, Option<Duration>) { let _p = span!(Level::INFO, "GlobalState::process_changes").entered(); // We cannot directly resolve a change in a ratoml file to a format // that can be used by the config module because config talks @@ -343,7 +343,7 @@ impl GlobalState { let mut guard = self.vfs.write(); let changed_files = guard.0.take_changes(); if changed_files.is_empty() { - return false; + return (false, None); } let (change, modified_rust_files, workspace_structure_change) = @@ -439,7 +439,7 @@ impl GlobalState { (change, modified_rust_files, workspace_structure_change) }); - self.analysis_host.apply_change(change); + let cancellation_time = self.analysis_host.apply_change(change); if !modified_ratoml_files.is_empty() || !self.config.same_source_root_parent_map(&self.local_roots_parent_map) @@ -561,7 +561,7 @@ impl GlobalState { } } - true + (true, Some(cancellation_time)) } pub(crate) fn snapshot(&self) -> GlobalStateSnapshot { diff --git a/crates/rust-analyzer/src/main_loop.rs b/crates/rust-analyzer/src/main_loop.rs index 628e708c6a..d966e29ede 100644 --- a/crates/rust-analyzer/src/main_loop.rs +++ b/crates/rust-analyzer/src/main_loop.rs @@ -307,15 +307,11 @@ impl GlobalState { let _p = tracing::info_span!("GlobalState::handle_event", event = %event).entered(); let event_dbg_msg = format!("{event:?}"); - tracing::debug!(?loop_start, ?event, "handle_event"); - if tracing::enabled!(tracing::Level::TRACE) { - let task_queue_len = self.task_pool.handle.len(); - if task_queue_len > 0 { - tracing::trace!("task queue len: {}", task_queue_len); - } - } + tracing::debug!(?event, "handle_event"); let was_quiescent = self.is_quiescent(); + + let mut cancellation_time = None; match event { Event::Lsp(msg) => match msg { lsp_server::Message::Request(req) => self.on_new_request(loop_start, req), @@ -326,7 +322,9 @@ impl GlobalState { let _p = tracing::info_span!("GlobalState::handle_event/queued_task").entered(); self.handle_deferred_task(task); // Coalesce multiple deferred task events into one loop turn - while let Ok(task) = self.deferred_task_queue.receiver.try_recv() { + while loop_start.elapsed() < Duration::from_millis(50) + && let Ok(task) = self.deferred_task_queue.receiver.try_recv() + { self.handle_deferred_task(task); } } @@ -334,14 +332,16 @@ impl GlobalState { let _p = tracing::info_span!("GlobalState::handle_event/task").entered(); let mut prime_caches_progress = Vec::new(); - self.handle_task(&mut prime_caches_progress, task); + cancellation_time = self.handle_task(&mut prime_caches_progress, task); // Coalesce multiple task events into one loop turn - while let Ok(task) = self.task_pool.receiver.try_recv() { + while loop_start.elapsed() < Duration::from_millis(50) + && let Ok(task) = self.task_pool.receiver.try_recv() + { self.handle_task(&mut prime_caches_progress, task); } let title = "Indexing"; - let cancel_token = Some("rustAnalyzer/cachePriming".to_owned()); + let cancel_token = || Some("rustAnalyzer/cachePriming".to_owned()); let mut last_report = None; for progress in prime_caches_progress { @@ -352,7 +352,7 @@ impl GlobalState { Progress::Begin, None, Some(0.0), - cancel_token.clone(), + cancel_token(), ); } PrimeCachesProgress::Report(report) => { @@ -404,7 +404,7 @@ impl GlobalState { Progress::Report, message, Some(fraction), - cancel_token.clone(), + cancel_token(), ); } self.report_progress( @@ -412,7 +412,7 @@ impl GlobalState { Progress::End, None, Some(1.0), - cancel_token.clone(), + cancel_token(), ); } }; @@ -423,7 +423,7 @@ impl GlobalState { Progress::Report, message, Some(fraction), - cancel_token.clone(), + cancel_token(), ); } } @@ -432,7 +432,9 @@ impl GlobalState { let mut last_progress_report = None; self.handle_vfs_msg(message, &mut last_progress_report); // Coalesce many VFS event into a single loop turn - while let Ok(message) = self.loader.receiver.try_recv() { + while loop_start.elapsed() < Duration::from_millis(50) + && let Ok(message) = self.loader.receiver.try_recv() + { self.handle_vfs_msg(message, &mut last_progress_report); } if let Some((message, fraction)) = last_progress_report { @@ -449,7 +451,9 @@ impl GlobalState { let mut cargo_finished = false; self.handle_flycheck_msg(message, &mut cargo_finished); // Coalesce many flycheck updates into a single loop turn - while let Ok(message) = self.flycheck_receiver.try_recv() { + while loop_start.elapsed() < Duration::from_millis(50) + && let Ok(message) = self.flycheck_receiver.try_recv() + { self.handle_flycheck_msg(message, &mut cargo_finished); } if cargo_finished { @@ -463,14 +467,18 @@ impl GlobalState { let _p = tracing::info_span!("GlobalState::handle_event/test_result").entered(); self.handle_cargo_test_msg(message); // Coalesce many test result event into a single loop turn - while let Ok(message) = self.test_run_receiver.try_recv() { + while loop_start.elapsed() < Duration::from_millis(50) + && let Ok(message) = self.test_run_receiver.try_recv() + { self.handle_cargo_test_msg(message); } } Event::DiscoverProject(message) => { self.handle_discover_msg(message); // Coalesce many project discovery events into a single loop turn. - while let Ok(message) = self.discover_receiver.try_recv() { + while loop_start.elapsed() < Duration::from_millis(50) + && let Ok(message) = self.discover_receiver.try_recv() + { self.handle_discover_msg(message); } } @@ -479,13 +487,23 @@ impl GlobalState { } } let event_handling_duration = loop_start.elapsed(); - let (state_changed, memdocs_added_or_removed) = if self.vfs_done { - if let Some(cause) = self.wants_to_switch.take() { - self.switch_workspaces(cause); - } - (self.process_changes(), self.mem_docs.take_changes()) - } else { - (false, false) + let ((state_changed, changes_cancellation_time), memdocs_added_or_removed) = + if self.vfs_done { + if let Some(cause) = self.wants_to_switch.take() { + cancellation_time = match (cancellation_time, self.switch_workspaces(cause)) { + (Some(a), Some(b)) => Some(a + b), + (Some(d), None) | (None, Some(d)) => Some(d), + (None, None) => None, + }; + } + (self.process_changes(), self.mem_docs.take_changes()) + } else { + ((false, None), false) + }; + cancellation_time = match (cancellation_time, changes_cancellation_time) { + (Some(a), Some(b)) => Some(a + b), + (Some(d), None) | (None, Some(d)) => Some(d), + (None, None) => None, }; let mut gc_elapsed = None; @@ -609,11 +627,13 @@ impl GlobalState { tracing::warn!( "overly long loop turn took {loop_duration:?}:\n\ (event handling took {event_handling_duration:?}): {event_dbg_msg}\n\ + (cancellation took {cancellation_time:?}) (garbage collection took {gc_elapsed:?})" ); self.poke_rust_analyzer_developer(format!( "overly long loop turn took {loop_duration:?}:\n\ (event handling took {event_handling_duration:?}): {event_dbg_msg}\n\ + (cancellation took {cancellation_time:?}) (garbage collection took {gc_elapsed:?})" )); } @@ -819,7 +839,12 @@ impl GlobalState { } } - fn handle_task(&mut self, prime_caches_progress: &mut Vec<PrimeCachesProgress>, task: Task) { + fn handle_task( + &mut self, + prime_caches_progress: &mut Vec<PrimeCachesProgress>, + task: Task, + ) -> Option<Duration> { + let mut cancellation_time = None; match task { Task::Response(response) => self.respond(response), // Only retry requests that haven't been cancelled. Otherwise we do unnecessary work. @@ -922,8 +947,9 @@ impl GlobalState { ProcMacroProgress::Report(msg) => (Some(Progress::Report), Some(msg)), ProcMacroProgress::End(change) => { self.fetch_proc_macros_queue.op_completed(true); - self.analysis_host.apply_change(change); - self.finish_loading_crate_graph(); + cancellation_time = Some(self.analysis_host.apply_change(change)); + // FIXME This feels a bit off, this should go through similar machinery as build scripts? + _ = self.finish_loading_crate_graph(); (Some(Progress::End), None) } }; @@ -937,6 +963,7 @@ impl GlobalState { self.send_notification::<lsp_ext::DiscoveredTests>(tests); } } + cancellation_time } fn handle_vfs_msg( diff --git a/crates/rust-analyzer/src/reload.rs b/crates/rust-analyzer/src/reload.rs index 74fd0e6533..4940defed2 100644 --- a/crates/rust-analyzer/src/reload.rs +++ b/crates/rust-analyzer/src/reload.rs @@ -13,7 +13,7 @@ //! project is currently loading and we don't have a full project model, we //! still want to respond to various requests. // FIXME: This is a mess that needs some untangling work -use std::{iter, mem, sync::atomic::AtomicUsize}; +use std::{iter, mem, sync::atomic::AtomicUsize, time::Duration}; use hir::{ChangeWithProcMacros, ProcMacrosBuilder, db::DefDatabase}; use ide_db::{ @@ -468,25 +468,22 @@ impl GlobalState { }); } - pub(crate) fn switch_workspaces(&mut self, cause: Cause) { + pub(crate) fn switch_workspaces(&mut self, cause: Cause) -> Option<Duration> { let _p = tracing::info_span!("GlobalState::switch_workspaces").entered(); tracing::info!(%cause, "will switch workspaces"); - let Some(FetchWorkspaceResponse { workspaces, force_crate_graph_reload }) = - self.fetch_workspaces_queue.last_op_result() - else { - return; - }; + let FetchWorkspaceResponse { workspaces, force_crate_graph_reload } = + self.fetch_workspaces_queue.last_op_result()?; let switching_from_empty_workspace = self.workspaces.is_empty(); info!(%cause, ?force_crate_graph_reload, %switching_from_empty_workspace); if self.fetch_workspace_error().is_err() && !switching_from_empty_workspace { if *force_crate_graph_reload { - self.recreate_crate_graph(cause, false); + return self.recreate_crate_graph(cause, false); } // It only makes sense to switch to a partially broken workspace // if we don't have any workspace at all yet. - return; + return None; } let workspaces = @@ -501,7 +498,7 @@ impl GlobalState { if same_workspaces { if switching_from_empty_workspace { // Switching from empty to empty is a no-op - return; + return None; } if let Some(FetchBuildDataResponse { workspaces, build_scripts }) = self.fetch_build_data_queue.last_op_result() @@ -524,20 +521,20 @@ impl GlobalState { } else { info!("build scripts do not match the version of the active workspace"); if *force_crate_graph_reload { - self.recreate_crate_graph(cause, switching_from_empty_workspace); + return self.recreate_crate_graph(cause, switching_from_empty_workspace); } // Current build scripts do not match the version of the active // workspace, so there's nothing for us to update. - return; + return None; } } else { if *force_crate_graph_reload { - self.recreate_crate_graph(cause, switching_from_empty_workspace); + return self.recreate_crate_graph(cause, switching_from_empty_workspace); } // No build scripts but unchanged workspaces, nothing to do here - return; + return None; } } else { info!("abandon build scripts for workspaces"); @@ -560,7 +557,7 @@ impl GlobalState { // `switch_workspaces()` will be called again when build scripts already run, which should // take a short time. If we update the workspace now we will invalidate proc macros and cfgs, // and then when build scripts complete we will invalidate them again. - return; + return None; } } } @@ -733,13 +730,15 @@ impl GlobalState { self.local_roots_parent_map = Arc::new(self.source_root_config.source_root_parent_map()); info!(?cause, "recreating the crate graph"); - self.recreate_crate_graph(cause, switching_from_empty_workspace); + let cancellation_time = self.recreate_crate_graph(cause, switching_from_empty_workspace); info!("did switch workspaces"); + cancellation_time } - fn recreate_crate_graph(&mut self, cause: String, initial_build: bool) { + fn recreate_crate_graph(&mut self, cause: String, initial_build: bool) -> Option<Duration> { info!(?cause, "Building Crate Graph"); + let mut cancellation_time = None; self.report_progress( "Building CrateGraph", crate::lsp::utils::Progress::Begin, @@ -795,9 +794,8 @@ impl GlobalState { } change.set_crate_graph(crate_graph); - self.analysis_host.apply_change(change); - - self.finish_loading_crate_graph(); + cancellation_time = Some(self.analysis_host.apply_change(change)); + _ = self.finish_loading_crate_graph(); } else { change.set_crate_graph(crate_graph); self.fetch_proc_macros_queue.request_op(cause, (change, proc_macro_paths)); @@ -810,11 +808,13 @@ impl GlobalState { None, None, ); + cancellation_time } - pub(crate) fn finish_loading_crate_graph(&mut self) { - self.process_changes(); + pub(crate) fn finish_loading_crate_graph(&mut self) -> Option<Duration> { + let (_, cancellation_time) = self.process_changes(); self.reload_flycheck(); + cancellation_time } pub(super) fn fetch_workspace_error(&self) -> Result<(), String> { diff --git a/crates/rust-analyzer/src/task_pool.rs b/crates/rust-analyzer/src/task_pool.rs index 104cd3d2ea..2da52f7480 100644 --- a/crates/rust-analyzer/src/task_pool.rs +++ b/crates/rust-analyzer/src/task_pool.rs @@ -40,10 +40,6 @@ impl<T> TaskPool<T> { }) } - pub(crate) fn len(&self) -> usize { - self.pool.len() - } - pub(crate) fn is_empty(&self) -> bool { self.pool.is_empty() } |