diff --git a/crates/pet/src/jsonrpc.rs b/crates/pet/src/jsonrpc.rs index 83318c1c..3881975c 100644 --- a/crates/pet/src/jsonrpc.rs +++ b/crates/pet/src/jsonrpc.rs @@ -7,7 +7,7 @@ use crate::find::identify_python_executables_using_locators; use crate::find::SearchScope; use crate::locators::create_locators; use lazy_static::lazy_static; -use log::{error, info, trace}; +use log::{error, info, trace, warn}; use pet::initialize_tracing; use pet::resolve::resolve_environment; use pet_conda::Conda; @@ -46,7 +46,7 @@ use std::{ path::PathBuf, sync::{Arc, RwLock}, thread, - time::SystemTime, + time::{Instant, SystemTime}, }; use tracing::info_span; @@ -110,28 +110,60 @@ pub struct ConfigureOptions { pub cache_directory: Option, } +/// Threshold for glob expansion duration before emitting a warning. +/// The client has a 30-second timeout for configure requests. +const GLOB_EXPANSION_WARN_THRESHOLD: Duration = Duration::from_secs(5); + pub fn handle_configure(context: Arc, id: u32, params: Value) { match serde_json::from_value::(params.clone()) { Ok(configure_options) => { + info!("Received configure request"); // Start in a new thread, we can have multiple requests. thread::spawn(move || { - let mut cfg = context.configuration.write().unwrap(); - // Expand glob patterns in workspace_directories - cfg.workspace_directories = configure_options.workspace_directories.map(|dirs| { - expand_glob_patterns(&dirs) + let now = Instant::now(); + + // Expand glob patterns before acquiring the write lock so we + // don't block readers/writers while traversing the filesystem. + let workspace_directories = configure_options.workspace_directories.map(|dirs| { + let start = Instant::now(); + let result: Vec = expand_glob_patterns(&dirs) .into_iter() .filter(|p| p.is_dir()) - .collect() + .collect(); + trace!( + "Expanded workspace directory patterns ({:?}) in {:?}", + dirs, + start.elapsed() + ); + result }); - cfg.conda_executable = configure_options.conda_executable; - // Expand glob patterns in environment_directories - cfg.environment_directories = + let environment_directories = configure_options.environment_directories.map(|dirs| { - expand_glob_patterns(&dirs) + let start = Instant::now(); + let result: Vec = expand_glob_patterns(&dirs) .into_iter() .filter(|p| p.is_dir()) - .collect() + .collect(); + trace!( + "Expanded environment directory patterns ({:?}) in {:?}", + dirs, + start.elapsed() + ); + result }); + let glob_elapsed = now.elapsed(); + trace!("Glob expansion completed in {:?}", glob_elapsed); + if glob_elapsed >= GLOB_EXPANSION_WARN_THRESHOLD { + warn!( + "Glob expansion took {:?}, this may cause client timeouts", + glob_elapsed + ); + } + + let mut cfg = context.configuration.write().unwrap(); + cfg.workspace_directories = workspace_directories; + cfg.conda_executable = configure_options.conda_executable; + cfg.environment_directories = environment_directories; cfg.pipenv_executable = configure_options.pipenv_executable; cfg.poetry_executable = configure_options.poetry_executable; // We will not support changing the cache directories once set. @@ -146,6 +178,7 @@ pub fn handle_configure(context: Arc, id: u32, params: Value) { for locator in context.locators.iter() { locator.configure(&config); } + info!("Configure completed in {:?}", now.elapsed()); send_reply(id, None::<()>); }); } @@ -390,6 +423,8 @@ pub fn handle_find(context: Arc, id: u32, params: Value) { thread::spawn( move || match serde_json::from_value::(params.clone()) { Ok(find_options) => { + let now = Instant::now(); + trace!("Finding environments in {:?}", find_options.search_path); let global_env_search_paths: Vec = get_search_paths_from_env_variables(context.os_environment.as_ref()); @@ -424,6 +459,12 @@ pub fn handle_find(context: Arc, id: u32, params: Value) { .lock() .expect("environments mutex poisoned") .clone(); + trace!( + "Find completed in {:?}, found {} environments in {:?}", + now.elapsed(), + envs.len(), + find_options.search_path + ); if envs.is_empty() { send_reply(id, None::>); } else { @@ -444,6 +485,7 @@ pub fn handle_find(context: Arc, id: u32, params: Value) { pub fn handle_conda_telemetry(context: Arc, id: u32, _params: Value) { thread::spawn(move || { + trace!("Gathering conda telemetry"); let conda_locator = context.conda_locator.clone(); let conda_executable = context .configuration @@ -452,6 +494,7 @@ pub fn handle_conda_telemetry(context: Arc, id: u32, _params: Value) { .conda_executable .clone(); let info = conda_locator.get_info_for_telemetry(conda_executable); + trace!("Conda telemetry complete"); send_reply(id, info.into()); }); }