From c6043126db8ca5401085854b64cb94dfce49b430 Mon Sep 17 00:00:00 2001 From: xli-oai Date: Wed, 13 May 2026 23:38:53 -0700 Subject: [PATCH] Add latency logs for plugin and mention flows --- codex-rs/app-server/src/fuzzy_file_search.rs | 29 ++ codex-rs/app-server/src/message_processor.rs | 4 +- .../src/request_processors/plugins.rs | 379 +++++++++++++++++- .../src/request_processors/search.rs | 37 ++ codex-rs/core-plugins/src/remote.rs | 220 +++++++++- codex-rs/tui/src/app/background_requests.rs | 30 +- codex-rs/tui/src/app/plugin_mentions.rs | 38 +- codex-rs/tui/src/bottom_pane/chat_composer.rs | 12 + codex-rs/tui/src/file_search.rs | 44 +- 9 files changed, 751 insertions(+), 42 deletions(-) diff --git a/codex-rs/app-server/src/fuzzy_file_search.rs b/codex-rs/app-server/src/fuzzy_file_search.rs index f8cd61e3ad..ea550fe656 100644 --- a/codex-rs/app-server/src/fuzzy_file_search.rs +++ b/codex-rs/app-server/src/fuzzy_file_search.rs @@ -4,6 +4,7 @@ use std::sync::Arc; use std::sync::Mutex; use std::sync::atomic::AtomicBool; use std::sync::atomic::Ordering; +use std::time::Instant; use codex_app_server_protocol::FuzzyFileSearchMatchType; use codex_app_server_protocol::FuzzyFileSearchResult; @@ -26,6 +27,7 @@ pub(crate) async fn run_fuzzy_file_search( if roots.is_empty() { return Vec::new(); } + let started_at = Instant::now(); #[expect(clippy::expect_used)] let limit = NonZero::new(MATCH_LIMIT).expect("MATCH_LIMIT should be a valid non-zero usize"); @@ -87,6 +89,11 @@ pub(crate) async fn run_fuzzy_file_search( _, >(|f| f.score, |f| f.path.as_str())); + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + file_count = files.len(), + "fuzzy file search completed" + ); files } @@ -105,6 +112,11 @@ impl FuzzyFileSearchSession { let mut latest_query = self.shared.latest_query.lock().unwrap(); *latest_query = query.clone(); } + { + #[expect(clippy::unwrap_used)] + let mut latest_query_started_at = self.shared.latest_query_started_at.lock().unwrap(); + *latest_query_started_at = Some(Instant::now()); + } self.session.update_query(&query); } } @@ -133,6 +145,7 @@ pub(crate) fn start_fuzzy_file_search_session( let shared = Arc::new(SessionShared { session_id, + latest_query_started_at: Mutex::new(None), latest_query: Mutex::new(String::new()), outgoing, runtime: tokio::runtime::Handle::current(), @@ -159,6 +172,7 @@ pub(crate) fn start_fuzzy_file_search_session( struct SessionShared { session_id: String, + latest_query_started_at: Mutex>, latest_query: Mutex, outgoing: Arc, runtime: tokio::runtime::Handle, @@ -179,6 +193,14 @@ impl SessionReporterImpl { #[expect(clippy::unwrap_used)] self.shared.latest_query.lock().unwrap().clone() }; + let elapsed_ms = { + #[expect(clippy::unwrap_used)] + self.shared + .latest_query_started_at + .lock() + .unwrap() + .map(|started_at| started_at.elapsed().as_millis()) + }; if snapshot.query != query { return; } @@ -188,6 +210,13 @@ impl SessionReporterImpl { } else { collect_files(snapshot) }; + tracing::info!( + elapsed_ms = ?elapsed_ms, + session_id = %self.shared.session_id, + query_len = query.len(), + file_count = files.len(), + "fuzzy file search session snapshot delivered" + ); let notification = ServerNotification::FuzzyFileSearchSessionUpdated( FuzzyFileSearchSessionUpdatedNotification { diff --git a/codex-rs/app-server/src/message_processor.rs b/codex-rs/app-server/src/message_processor.rs index 0f291abfcc..113a6a3a22 100644 --- a/codex-rs/app-server/src/message_processor.rs +++ b/codex-rs/app-server/src/message_processor.rs @@ -1095,10 +1095,10 @@ impl MessageProcessor { self.marketplace_processor.marketplace_upgrade(params).await } ClientRequest::PluginList { params, .. } => { - self.plugin_processor.plugin_list(params).await + self.plugin_processor.plugin_list(&request_id, params).await } ClientRequest::PluginRead { params, .. } => { - self.plugin_processor.plugin_read(params).await + self.plugin_processor.plugin_read(&request_id, params).await } ClientRequest::PluginSkillRead { params, .. } => { self.plugin_processor.plugin_skill_read(params).await diff --git a/codex-rs/app-server/src/request_processors/plugins.rs b/codex-rs/app-server/src/request_processors/plugins.rs index c290d2091a..1e6a123a4f 100644 --- a/codex-rs/app-server/src/request_processors/plugins.rs +++ b/codex-rs/app-server/src/request_processors/plugins.rs @@ -12,6 +12,7 @@ use codex_mcp::McpOAuthLoginSupport; use codex_mcp::oauth_login_support; use codex_mcp::should_retry_without_scopes; use codex_rmcp_client::perform_oauth_login_silent; +use std::time::Instant; #[derive(Clone)] pub(crate) struct PluginRequestProcessor { @@ -261,18 +262,20 @@ impl PluginRequestProcessor { pub(crate) async fn plugin_list( &self, + request_id: &ConnectionRequestId, params: PluginListParams, ) -> Result, JSONRPCErrorError> { - self.plugin_list_response(params) + self.plugin_list_response(request_id, params) .await .map(|response| Some(response.into())) } pub(crate) async fn plugin_read( &self, + request_id: &ConnectionRequestId, params: PluginReadParams, ) -> Result, JSONRPCErrorError> { - self.plugin_read_response(params) + self.plugin_read_response(request_id, params) .await .map(|response| Some(response.into())) } @@ -420,8 +423,11 @@ impl PluginRequestProcessor { async fn plugin_list_response( &self, + request_id: &ConnectionRequestId, params: PluginListParams, ) -> Result { + let request_id = request_id.request_id.to_string(); + let started_at = Instant::now(); let plugins_manager = self.thread_manager.plugins_manager(); let PluginListParams { cwds, @@ -432,33 +438,85 @@ impl PluginRequestProcessor { let marketplace_kinds = marketplace_kinds.unwrap_or_else(|| vec![PluginListMarketplaceKind::Local]); let include_local = marketplace_kinds.contains(&PluginListMarketplaceKind::Local); + tracing::info!( + request_id = %request_id, + root_count = roots.len(), + explicit_marketplace_kinds, + marketplace_kinds = ?marketplace_kinds, + include_local, + "plugin/list request started" + ); + let config_started_at = Instant::now(); let config = self.load_latest_config(/*fallback_cwd*/ None).await?; + tracing::info!( + request_id = %request_id, + elapsed_ms = config_started_at.elapsed().as_millis(), + plugins_enabled = config.features.enabled(Feature::Plugins), + remote_plugins_enabled = config.features.enabled(Feature::RemotePlugin), + plugin_sharing_enabled = config.features.enabled(Feature::PluginSharing), + "plugin/list loaded config" + ); let empty_response = || PluginListResponse { marketplaces: Vec::new(), marketplace_load_errors: Vec::new(), featured_plugin_ids: Vec::new(), }; if !config.features.enabled(Feature::Plugins) { + tracing::info!( + request_id = %request_id, + elapsed_ms = started_at.elapsed().as_millis(), + "plugin/list completed with plugins feature disabled" + ); return Ok(empty_response()); } + let auth_started_at = Instant::now(); let auth = self.auth_manager.auth().await; + tracing::info!( + request_id = %request_id, + elapsed_ms = auth_started_at.elapsed().as_millis(), + has_auth = auth.is_some(), + "plugin/list loaded auth state" + ); + let workspace_setting_started_at = Instant::now(); if !self .workspace_codex_plugins_enabled(&config, auth.as_ref()) .await { + tracing::info!( + request_id = %request_id, + elapsed_ms = started_at.elapsed().as_millis(), + workspace_check_elapsed_ms = workspace_setting_started_at.elapsed().as_millis(), + "plugin/list completed with workspace Codex plugins disabled" + ); return Ok(empty_response()); } + tracing::info!( + request_id = %request_id, + elapsed_ms = workspace_setting_started_at.elapsed().as_millis(), + "plugin/list checked workspace Codex plugins setting" + ); let plugins_input = config.plugins_config_input(); if include_local || marketplace_kinds.contains(&PluginListMarketplaceKind::SharedWithMe) { + let background_tasks_started_at = Instant::now(); plugins_manager.maybe_start_plugin_list_background_tasks_for_config( &plugins_input, auth.clone(), &roots, Some(self.effective_plugins_changed_callback()), ); + tracing::info!( + request_id = %request_id, + elapsed_us = background_tasks_started_at.elapsed().as_micros(), + root_count = roots.len(), + include_local, + include_shared_with_me = + marketplace_kinds.contains(&PluginListMarketplaceKind::SharedWithMe), + "plugin/list scheduled background refresh tasks" + ); } let (mut data, marketplace_load_errors) = if include_local { + let local_started_at = Instant::now(); let config_for_marketplace_listing = plugins_input.clone(); let plugins_manager_for_marketplace_listing = plugins_manager.clone(); let shared_plugin_ids_by_local_path = load_shared_plugin_ids_by_local_path(&config)?; @@ -524,11 +582,36 @@ impl PluginRequestProcessor { }) .await { - Ok(Ok(outcome)) => outcome, + Ok(Ok(outcome)) => { + let plugin_count: usize = outcome + .0 + .iter() + .map(|marketplace| marketplace.plugins.len()) + .sum(); + tracing::info!( + request_id = %request_id, + elapsed_ms = local_started_at.elapsed().as_millis(), + marketplace_count = outcome.0.len(), + plugin_count, + marketplace_load_error_count = outcome.1.len(), + "plugin/list local marketplace listing completed" + ); + outcome + } Ok(Err(err)) => { + tracing::warn!( + request_id = %request_id, + elapsed_ms = local_started_at.elapsed().as_millis(), + "plugin/list local marketplace listing failed: {err}" + ); return Err(Self::marketplace_error(err, "list marketplace plugins")); } Err(err) => { + tracing::warn!( + request_id = %request_id, + elapsed_ms = local_started_at.elapsed().as_millis(), + "plugin/list local marketplace listing task failed: {err}" + ); return Err(internal_error(format!( "failed to list marketplace plugins: {err}" ))); @@ -550,10 +633,23 @@ impl PluginRequestProcessor { { remote_sources.push(RemoteMarketplaceSource::SharedWithMe); } - if !remote_sources.is_empty() { + if remote_sources.is_empty() { + tracing::info!( + request_id = %request_id, + remote_plugins_enabled = config.features.enabled(Feature::RemotePlugin), + plugin_sharing_enabled = config.features.enabled(Feature::PluginSharing), + "plugin/list remote marketplace fetch skipped" + ); + } else { let remote_plugin_service_config = RemotePluginServiceConfig { chatgpt_base_url: config.chatgpt_base_url.clone(), }; + let remote_started_at = Instant::now(); + tracing::info!( + request_id = %request_id, + remote_sources = ?remote_sources, + "plugin/list remote marketplace fetch started" + ); match codex_core_plugins::remote::fetch_remote_marketplaces( &remote_plugin_service_config, auth.as_ref(), @@ -562,6 +658,17 @@ impl PluginRequestProcessor { .await { Ok(remote_marketplaces) => { + let remote_plugin_count: usize = remote_marketplaces + .iter() + .map(|marketplace| marketplace.plugins.len()) + .sum(); + tracing::info!( + request_id = %request_id, + elapsed_ms = remote_started_at.elapsed().as_millis(), + marketplace_count = remote_marketplaces.len(), + plugin_count = remote_plugin_count, + "plugin/list remote marketplace fetch completed" + ); for remote_marketplace in remote_marketplaces .into_iter() .map(remote_marketplace_to_info) @@ -580,16 +687,35 @@ impl PluginRequestProcessor { err @ (RemotePluginCatalogError::AuthRequired | RemotePluginCatalogError::UnsupportedAuthMode), ) if explicit_marketplace_kinds => { + warn!( + request_id = %request_id, + error = %err, + elapsed_ms = remote_started_at.elapsed().as_millis(), + "plugin/list remote plugin catalog fetch failed for explicit remote request" + ); return Err(remote_plugin_catalog_error_to_jsonrpc( err, "list remote plugin catalog", )); } Err( - RemotePluginCatalogError::AuthRequired - | RemotePluginCatalogError::UnsupportedAuthMode, - ) => {} + err @ (RemotePluginCatalogError::AuthRequired + | RemotePluginCatalogError::UnsupportedAuthMode), + ) => { + tracing::info!( + request_id = %request_id, + error = %err, + elapsed_ms = remote_started_at.elapsed().as_millis(), + "plugin/list remote plugin catalog fetch skipped because auth is unavailable" + ); + } Err(err) if explicit_marketplace_kinds => { + warn!( + request_id = %request_id, + error = %err, + elapsed_ms = remote_started_at.elapsed().as_millis(), + "plugin/list remote plugin catalog fetch failed for explicit remote request" + ); return Err(remote_plugin_catalog_error_to_jsonrpc( err, "list remote plugin catalog", @@ -597,34 +723,65 @@ impl PluginRequestProcessor { } Err(err) => { warn!( + request_id = %request_id, error = %err, + elapsed_ms = remote_started_at.elapsed().as_millis(), "plugin/list remote plugin catalog fetch failed; returning local marketplaces only" ); } } } - let featured_plugin_ids = if data + let has_openai_curated_marketplace = data .iter() - .any(|marketplace| marketplace.name == OPENAI_CURATED_MARKETPLACE_NAME) - { + .any(|marketplace| marketplace.name == OPENAI_CURATED_MARKETPLACE_NAME); + let featured_plugin_ids = if has_openai_curated_marketplace { + let featured_started_at = Instant::now(); match plugins_manager .featured_plugin_ids_for_config(&plugins_input, auth.as_ref()) .await { - Ok(featured_plugin_ids) => featured_plugin_ids, + Ok(featured_plugin_ids) => { + tracing::info!( + request_id = %request_id, + elapsed_ms = featured_started_at.elapsed().as_millis(), + featured_plugin_id_count = featured_plugin_ids.len(), + "plugin/list featured plugin ids fetched" + ); + featured_plugin_ids + } Err(err) => { warn!( + request_id = %request_id, error = %err, + elapsed_ms = featured_started_at.elapsed().as_millis(), "plugin/list featured plugin fetch failed; returning empty featured ids" ); Vec::new() } } } else { + tracing::info!( + request_id = %request_id, + marketplace_count = data.len(), + "plugin/list featured plugin fetch skipped because curated marketplace is absent" + ); Vec::new() }; + let plugin_count: usize = data + .iter() + .map(|marketplace| marketplace.plugins.len()) + .sum(); + tracing::info!( + request_id = %request_id, + elapsed_ms = started_at.elapsed().as_millis(), + marketplace_count = data.len(), + plugin_count, + marketplace_load_error_count = marketplace_load_errors.len(), + featured_plugin_id_count = featured_plugin_ids.len(), + "plugin/list request completed" + ); Ok(PluginListResponse { marketplaces: data, marketplace_load_errors, @@ -634,8 +791,11 @@ impl PluginRequestProcessor { async fn plugin_read_response( &self, + request_id: &ConnectionRequestId, params: PluginReadParams, ) -> Result { + let request_id = request_id.request_id.to_string(); + let started_at = Instant::now(); let plugins_manager = self.thread_manager.plugins_manager(); let PluginReadParams { marketplace_path, @@ -646,30 +806,106 @@ impl PluginRequestProcessor { (Some(marketplace_path), None) => Ok(marketplace_path), (None, Some(remote_marketplace_name)) => Err(remote_marketplace_name), (Some(_), Some(_)) | (None, None) => { + tracing::warn!( + request_id = %request_id, + elapsed_us = started_at.elapsed().as_micros(), + "plugin/read rejected request with invalid source selector" + ); return Err(invalid_request( "plugin/read requires exactly one of marketplacePath or remoteMarketplaceName", )); } }; + let source_kind = if read_source.is_ok() { + "local" + } else { + "remote" + }; + tracing::info!( + request_id = %request_id, + source_kind, + plugin_name = %plugin_name, + marketplace_path = ?read_source.as_ref().ok(), + remote_marketplace_name = ?read_source.as_ref().err(), + "plugin/read request started" + ); let config_cwd = read_source.as_ref().ok().and_then(|marketplace_path| { marketplace_path.as_path().parent().map(Path::to_path_buf) }); + let config_started_at = Instant::now(); let config = self.load_latest_config(config_cwd).await?; + tracing::info!( + request_id = %request_id, + elapsed_ms = config_started_at.elapsed().as_millis(), + plugins_enabled = config.features.enabled(Feature::Plugins), + remote_plugins_enabled = config.features.enabled(Feature::RemotePlugin), + plugin_sharing_enabled = config.features.enabled(Feature::PluginSharing), + "plugin/read loaded config" + ); let plugins_input = config.plugins_config_input(); let plugin = match read_source { Ok(marketplace_path) => { + let marketplace_path_for_log = marketplace_path.clone(); + let local_started_at = Instant::now(); let request = PluginReadRequest { plugin_name, marketplace_path, }; - let outcome = plugins_manager + tracing::info!( + request_id = %request_id, + marketplace_path = %marketplace_path_for_log.display(), + plugin_name = %request.plugin_name, + "plugin/read local marketplace read started" + ); + let outcome = match plugins_manager .read_plugin_for_config(&plugins_input, &request) .await - .map_err(|err| Self::marketplace_error(err, "read plugin details"))?; + { + Ok(outcome) => { + tracing::info!( + request_id = %request_id, + elapsed_ms = local_started_at.elapsed().as_millis(), + plugin_id = ?outcome.plugin.id, + skill_count = outcome.plugin.skills.len(), + app_count = outcome.plugin.apps.len(), + mcp_server_count = outcome.plugin.mcp_server_names.len(), + "plugin/read local marketplace read completed" + ); + outcome + } + Err(err) => { + tracing::warn!( + request_id = %request_id, + elapsed_ms = local_started_at.elapsed().as_millis(), + "plugin/read local marketplace read failed: {err}" + ); + return Err(Self::marketplace_error(err, "read plugin details")); + } + }; + let share_mapping_started_at = Instant::now(); let shared_plugin_ids_by_local_path = - load_shared_plugin_ids_by_local_path(&config)?; + match load_shared_plugin_ids_by_local_path(&config) { + Ok(shared_plugin_ids_by_local_path) => { + tracing::info!( + request_id = %request_id, + elapsed_us = share_mapping_started_at.elapsed().as_micros(), + shared_plugin_path_count = shared_plugin_ids_by_local_path.len(), + "plugin/read loaded local share mappings" + ); + shared_plugin_ids_by_local_path + } + Err(err) => { + tracing::warn!( + request_id = %request_id, + elapsed_us = share_mapping_started_at.elapsed().as_micros(), + error = ?err, + "plugin/read failed to load local share mappings" + ); + return Err(err); + } + }; let share_context = share_context_for_source( &outcome.plugin.source, &shared_plugin_ids_by_local_path, @@ -680,6 +916,7 @@ impl PluginRequestProcessor { let remote_plugin_service_config = RemotePluginServiceConfig { chatgpt_base_url: config.chatgpt_base_url.clone(), }; + let share_context_started_at = Instant::now(); match codex_core_plugins::remote::fetch_remote_plugin_share_context( &remote_plugin_service_config, auth.as_ref(), @@ -688,12 +925,22 @@ impl PluginRequestProcessor { .await { Ok(Some(remote_share_context)) => { + tracing::info!( + request_id = %request_id, + elapsed_ms = share_context_started_at.elapsed().as_millis(), + remote_plugin_id = %context.remote_plugin_id, + has_share_principals = remote_share_context + .share_principals + .is_some(), + "plugin/read hydrated local plugin share context" + ); if remote_share_context.share_principals.is_some() { Some(remote_plugin_share_context_to_info(remote_share_context)) } else { let remote_version = remote_share_context.remote_version; let remote_plugin_id = context.remote_plugin_id.clone(); warn!( + request_id = %request_id, remote_plugin_id = %remote_plugin_id, "remote shared plugin detail did not include share principals; returning local share mapping context with remote version" ); @@ -705,6 +952,8 @@ impl PluginRequestProcessor { } Ok(None) => { warn!( + request_id = %request_id, + elapsed_ms = share_context_started_at.elapsed().as_millis(), remote_plugin_id = %context.remote_plugin_id, "remote shared plugin detail did not include share context; returning local share mapping context" ); @@ -712,6 +961,8 @@ impl PluginRequestProcessor { } Err(err) => { warn!( + request_id = %request_id, + elapsed_ms = share_context_started_at.elapsed().as_millis(), remote_plugin_id = %context.remote_plugin_id, error = %err, "failed to hydrate local plugin share context; returning local share mapping context" @@ -723,9 +974,17 @@ impl PluginRequestProcessor { None => None, }; let environment_manager = self.thread_manager.environment_manager(); + let apps_started_at = Instant::now(); let app_summaries = load_plugin_app_summaries(&config, &outcome.plugin.apps, &environment_manager) .await; + tracing::info!( + request_id = %request_id, + elapsed_ms = apps_started_at.elapsed().as_millis(), + requested_app_count = outcome.plugin.apps.len(), + resolved_app_count = app_summaries.len(), + "plugin/read loaded local plugin app summaries" + ); let visible_skills = outcome .plugin .skills @@ -775,25 +1034,89 @@ impl PluginRequestProcessor { } Err(remote_marketplace_name) => { if !config.features.enabled(Feature::Plugins) { + tracing::info!( + request_id = %request_id, + elapsed_ms = started_at.elapsed().as_millis(), + remote_marketplace_name = %remote_marketplace_name, + "plugin/read completed with plugins feature disabled" + ); return Err(invalid_request(format!( "remote plugin read is not enabled for marketplace {remote_marketplace_name}" ))); } + let auth_started_at = Instant::now(); let auth = self.auth_manager.auth().await; + tracing::info!( + request_id = %request_id, + elapsed_ms = auth_started_at.elapsed().as_millis(), + has_auth = auth.is_some(), + remote_marketplace_name = %remote_marketplace_name, + "plugin/read loaded auth state for remote detail" + ); let remote_plugin_service_config = RemotePluginServiceConfig { chatgpt_base_url: config.chatgpt_base_url.clone(), }; - validate_remote_plugin_id(&plugin_name)?; - let remote_detail = codex_core_plugins::remote::fetch_remote_plugin_detail( + let validate_started_at = Instant::now(); + if let Err(err) = validate_remote_plugin_id(&plugin_name) { + tracing::warn!( + request_id = %request_id, + elapsed_us = validate_started_at.elapsed().as_micros(), + remote_marketplace_name = %remote_marketplace_name, + plugin_name = %plugin_name, + error = ?err, + "plugin/read rejected invalid remote plugin id" + ); + return Err(err); + } + tracing::info!( + request_id = %request_id, + elapsed_us = validate_started_at.elapsed().as_micros(), + remote_marketplace_name = %remote_marketplace_name, + plugin_name = %plugin_name, + "plugin/read validated remote plugin id" + ); + let remote_detail_started_at = Instant::now(); + tracing::info!( + request_id = %request_id, + remote_marketplace_name = %remote_marketplace_name, + plugin_name = %plugin_name, + "plugin/read remote detail fetch started" + ); + let remote_detail = match codex_core_plugins::remote::fetch_remote_plugin_detail( &remote_plugin_service_config, auth.as_ref(), &remote_marketplace_name, &plugin_name, ) .await - .map_err(|err| { - remote_plugin_catalog_error_to_jsonrpc(err, "read remote plugin details") - })?; + { + Ok(remote_detail) => { + tracing::info!( + request_id = %request_id, + elapsed_ms = remote_detail_started_at.elapsed().as_millis(), + remote_marketplace_name = %remote_marketplace_name, + remote_plugin_id = %remote_detail.summary.remote_plugin_id, + skill_count = remote_detail.skills.len(), + app_count = remote_detail.app_ids.len(), + has_bundle_download_url = remote_detail.bundle_download_url.is_some(), + "plugin/read remote detail fetch completed" + ); + remote_detail + } + Err(err) => { + tracing::warn!( + request_id = %request_id, + elapsed_ms = remote_detail_started_at.elapsed().as_millis(), + remote_marketplace_name = %remote_marketplace_name, + plugin_name = %plugin_name, + "plugin/read remote detail fetch failed: {err}" + ); + return Err(remote_plugin_catalog_error_to_jsonrpc( + err, + "read remote plugin details", + )); + } + }; let plugin_apps = remote_detail .app_ids .iter() @@ -801,12 +1124,30 @@ impl PluginRequestProcessor { .map(codex_plugin::AppConnectorId) .collect::>(); let environment_manager = self.thread_manager.environment_manager(); + let apps_started_at = Instant::now(); let app_summaries = load_plugin_app_summaries(&config, &plugin_apps, &environment_manager).await; + tracing::info!( + request_id = %request_id, + elapsed_ms = apps_started_at.elapsed().as_millis(), + requested_app_count = plugin_apps.len(), + resolved_app_count = app_summaries.len(), + "plugin/read loaded remote plugin app summaries" + ); remote_plugin_detail_to_info(remote_detail, app_summaries) } }; + tracing::info!( + request_id = %request_id, + elapsed_ms = started_at.elapsed().as_millis(), + marketplace_name = %plugin.marketplace_name, + plugin_name = %plugin.summary.name, + skill_count = plugin.skills.len(), + app_count = plugin.apps.len(), + mcp_server_count = plugin.mcp_servers.len(), + "plugin/read request completed" + ); Ok(PluginReadResponse { plugin }) } diff --git a/codex-rs/app-server/src/request_processors/search.rs b/codex-rs/app-server/src/request_processors/search.rs index d683c6f10a..71f72b2ee3 100644 --- a/codex-rs/app-server/src/request_processors/search.rs +++ b/codex-rs/app-server/src/request_processors/search.rs @@ -2,6 +2,7 @@ use std::collections::HashMap; use std::sync::Arc; use std::sync::atomic::AtomicBool; use std::sync::atomic::Ordering; +use std::time::Instant; use crate::error_code::internal_error; use crate::error_code::invalid_request; @@ -45,6 +46,13 @@ impl SearchRequestProcessor { roots, cancellation_token, } = params; + let started_at = Instant::now(); + tracing::info!( + query_len = query.len(), + root_count = roots.len(), + has_cancellation_token = cancellation_token.is_some(), + "fuzzyFileSearch request started" + ); let cancel_flag = match cancellation_token.clone() { Some(token) => { @@ -75,6 +83,11 @@ impl SearchRequestProcessor { } } + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + file_count = results.len(), + "fuzzyFileSearch request completed" + ); Ok(FuzzyFileSearchResponse { files: results }) } @@ -87,6 +100,12 @@ impl SearchRequestProcessor { return Err(invalid_request("sessionId must not be empty")); } + let started_at = Instant::now(); + tracing::info!( + session_id = %session_id, + root_count = roots.len(), + "fuzzyFileSearch session start requested" + ); let session = start_fuzzy_file_search_session(session_id.clone(), roots, self.outgoing.clone()) .map_err(|err| { @@ -96,6 +115,10 @@ impl SearchRequestProcessor { .lock() .await .insert(session_id, session); + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + "fuzzyFileSearch session started" + ); Ok(FuzzyFileSearchSessionStartResponse {}) } @@ -104,6 +127,8 @@ impl SearchRequestProcessor { params: FuzzyFileSearchSessionUpdateParams, ) -> Result { let FuzzyFileSearchSessionUpdateParams { session_id, query } = params; + let started_at = Instant::now(); + let query_len = query.len(); let found = { let sessions = self.fuzzy_search_sessions.lock().await; if let Some(session) = sessions.get(&session_id) { @@ -119,6 +144,12 @@ impl SearchRequestProcessor { ))); } + tracing::info!( + elapsed_us = started_at.elapsed().as_micros(), + session_id = %session_id, + query_len, + "fuzzyFileSearch session query dispatched" + ); Ok(FuzzyFileSearchSessionUpdateResponse {}) } @@ -127,8 +158,14 @@ impl SearchRequestProcessor { params: FuzzyFileSearchSessionStopParams, ) -> Result { let FuzzyFileSearchSessionStopParams { session_id } = params; + let started_at = Instant::now(); self.fuzzy_search_sessions.lock().await.remove(&session_id); + tracing::info!( + elapsed_us = started_at.elapsed().as_micros(), + session_id = %session_id, + "fuzzyFileSearch session stopped" + ); Ok(FuzzyFileSearchSessionStopResponse {}) } } diff --git a/codex-rs/core-plugins/src/remote.rs b/codex-rs/core-plugins/src/remote.rs index 4dde224039..099ddc7e8f 100644 --- a/codex-rs/core-plugins/src/remote.rs +++ b/codex-rs/core-plugins/src/remote.rs @@ -18,6 +18,7 @@ use std::collections::HashSet; use std::fs; use std::path::PathBuf; use std::time::Duration; +use std::time::Instant; use url::Url; mod remote_installed_plugin_sync; @@ -458,6 +459,12 @@ pub async fn fetch_remote_marketplaces( auth: Option<&CodexAuth>, sources: &[RemoteMarketplaceSource], ) -> Result, RemotePluginCatalogError> { + let started_at = Instant::now(); + tracing::info!( + source_count = sources.len(), + sources = ?sources, + "remote plugin marketplace fetch started" + ); let auth = ensure_chatgpt_auth(auth)?; let mut marketplaces = Vec::new(); let needs_workspace_installed = sources.iter().any(|source| { @@ -467,12 +474,21 @@ pub async fn fetch_remote_marketplaces( ) }); let workspace_installed_plugins = if needs_workspace_installed { - Some(fetch_installed_plugins_for_scope(config, auth, RemotePluginScope::Workspace).await?) + let workspace_installed_started_at = Instant::now(); + let plugins = + fetch_installed_plugins_for_scope(config, auth, RemotePluginScope::Workspace).await?; + tracing::info!( + elapsed_ms = workspace_installed_started_at.elapsed().as_millis(), + plugin_count = plugins.len(), + "remote plugin workspace installed prerequisite fetched" + ); + Some(plugins) } else { None }; for source in sources { + let source_started_at = Instant::now(); match source { RemoteMarketplaceSource::Global => { let scope = RemotePluginScope::Global; @@ -480,6 +496,8 @@ pub async fn fetch_remote_marketplaces( fetch_directory_plugins_for_scope(config, auth, scope), fetch_installed_plugins_for_scope(config, auth, scope), )?; + let directory_plugin_count = directory_plugins.len(); + let installed_plugin_count = installed_plugins.len(); if let Some(marketplace) = build_remote_marketplace( scope.marketplace_name(), scope.marketplace_display_name(), @@ -487,13 +505,34 @@ pub async fn fetch_remote_marketplaces( installed_plugins, /*include_installed_only*/ true, )? { + tracing::info!( + elapsed_ms = source_started_at.elapsed().as_millis(), + source = ?source, + directory_plugin_count, + installed_plugin_count, + plugin_count = marketplace.plugins.len(), + "remote plugin marketplace source fetched" + ); marketplaces.push(marketplace); + } else { + tracing::info!( + elapsed_ms = source_started_at.elapsed().as_millis(), + source = ?source, + directory_plugin_count, + installed_plugin_count, + plugin_count = 0, + "remote plugin marketplace source fetched empty" + ); } } RemoteMarketplaceSource::WorkspaceDirectory => { let scope = RemotePluginScope::Workspace; let directory_plugins = fetch_directory_plugins_for_scope(config, auth, scope).await?; + let directory_plugin_count = directory_plugins.len(); + let installed_plugin_count = workspace_installed_plugins + .as_ref() + .map_or(0, std::vec::Vec::len); if let Some(marketplace) = build_remote_marketplace( scope.marketplace_name(), scope.marketplace_display_name(), @@ -501,7 +540,24 @@ pub async fn fetch_remote_marketplaces( workspace_installed_plugins.clone().unwrap_or_default(), /*include_installed_only*/ false, )? { + tracing::info!( + elapsed_ms = source_started_at.elapsed().as_millis(), + source = ?source, + directory_plugin_count, + installed_plugin_count, + plugin_count = marketplace.plugins.len(), + "remote plugin marketplace source fetched" + ); marketplaces.push(marketplace); + } else { + tracing::info!( + elapsed_ms = source_started_at.elapsed().as_millis(), + source = ?source, + directory_plugin_count, + installed_plugin_count, + plugin_count = 0, + "remote plugin marketplace source fetched empty" + ); } } RemoteMarketplaceSource::SharedWithMe => { @@ -509,6 +565,7 @@ pub async fn fetch_remote_marketplaces( // with the user. Installed unlisted plugins that are not returned there are // link-installed and stay in the separate unlisted bucket. let shared_plugins = fetch_shared_workspace_plugins(config, auth).await?; + let shared_plugin_count = shared_plugins.len(); let shared_plugin_ids = shared_plugins .iter() .map(|plugin| plugin.id.clone()) @@ -531,6 +588,14 @@ pub async fn fetch_remote_marketplaces( workspace_installed_plugins.clone().unwrap_or_default(), /*include_installed_only*/ false, )? { + tracing::info!( + elapsed_ms = source_started_at.elapsed().as_millis(), + source = ?source, + shared_plugin_count, + plugin_count = marketplace.plugins.len(), + marketplace_name = %REMOTE_WORKSPACE_SHARED_WITH_ME_PRIVATE_MARKETPLACE_NAME, + "remote plugin shared marketplace bucket fetched" + ); marketplaces.push(marketplace); } @@ -559,12 +624,36 @@ pub async fn fetch_remote_marketplaces( unlisted_installed_plugins, /*include_installed_only*/ true, )? { + tracing::info!( + elapsed_ms = source_started_at.elapsed().as_millis(), + source = ?source, + shared_plugin_count, + plugin_count = marketplace.plugins.len(), + marketplace_name = %REMOTE_WORKSPACE_SHARED_WITH_ME_UNLISTED_MARKETPLACE_NAME, + "remote plugin shared marketplace bucket fetched" + ); marketplaces.push(marketplace); } + tracing::info!( + elapsed_ms = source_started_at.elapsed().as_millis(), + source = ?source, + shared_plugin_count, + "remote plugin marketplace source fetched" + ); } } } + let plugin_count: usize = marketplaces + .iter() + .map(|marketplace| marketplace.plugins.len()) + .sum(); + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + marketplace_count = marketplaces.len(), + plugin_count, + "remote plugin marketplace fetch completed" + ); Ok(marketplaces) } @@ -1088,17 +1177,35 @@ async fn fetch_directory_plugins_for_scope( auth: &CodexAuth, scope: RemotePluginScope, ) -> Result, RemotePluginCatalogError> { + let started_at = Instant::now(); let mut plugins = Vec::new(); let mut page_token = None; + let mut page_count = 0usize; loop { + let page_started_at = Instant::now(); let response = get_remote_plugin_list_page(config, auth, scope, page_token.as_deref()).await?; + page_count += 1; + tracing::info!( + elapsed_ms = page_started_at.elapsed().as_millis(), + scope = ?scope, + page_plugin_count = response.plugins.len(), + has_next_page = response.pagination.next_page_token.is_some(), + "remote plugin directory page fetched" + ); plugins.extend(response.plugins); let Some(next_page_token) = response.pagination.next_page_token else { break; }; page_token = Some(next_page_token); } + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + scope = ?scope, + page_count, + plugin_count = plugins.len(), + "remote plugin directory fetched" + ); Ok(plugins) } @@ -1106,17 +1213,33 @@ async fn fetch_shared_workspace_plugins( config: &RemotePluginServiceConfig, auth: &CodexAuth, ) -> Result, RemotePluginCatalogError> { + let started_at = Instant::now(); let mut plugins = Vec::new(); let mut page_token = None; + let mut page_count = 0usize; loop { + let page_started_at = Instant::now(); let response = get_remote_shared_workspace_plugins_page(config, auth, page_token.as_deref()).await?; + page_count += 1; + tracing::info!( + elapsed_ms = page_started_at.elapsed().as_millis(), + page_plugin_count = response.plugins.len(), + has_next_page = response.pagination.next_page_token.is_some(), + "remote shared workspace plugin page fetched" + ); plugins.extend(response.plugins); let Some(next_page_token) = response.pagination.next_page_token else { break; }; page_token = Some(next_page_token); } + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + page_count, + plugin_count = plugins.len(), + "remote shared workspace plugins fetched" + ); Ok(plugins) } @@ -1137,9 +1260,12 @@ async fn fetch_installed_plugins_for_scope_with_download_url( scope: RemotePluginScope, include_download_urls: bool, ) -> Result, RemotePluginCatalogError> { + let started_at = Instant::now(); let mut plugins = Vec::new(); let mut page_token = None; + let mut page_count = 0usize; loop { + let page_started_at = Instant::now(); let response = get_remote_plugin_installed_page( config, auth, @@ -1148,12 +1274,29 @@ async fn fetch_installed_plugins_for_scope_with_download_url( include_download_urls, ) .await?; + page_count += 1; + tracing::info!( + elapsed_ms = page_started_at.elapsed().as_millis(), + scope = ?scope, + include_download_urls, + page_plugin_count = response.plugins.len(), + has_next_page = response.pagination.next_page_token.is_some(), + "remote installed plugin page fetched" + ); plugins.extend(response.plugins); let Some(next_page_token) = response.pagination.next_page_token else { break; }; page_token = Some(next_page_token); } + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + scope = ?scope, + include_download_urls, + page_count, + plugin_count = plugins.len(), + "remote installed plugins fetched" + ); Ok(plugins) } @@ -1272,16 +1415,51 @@ async fn send_and_decode Deserialize<'de>>( request: RequestBuilder, url: &str, ) -> Result { - let response = request - .send() - .await - .map_err(|source| RemotePluginCatalogError::Request { - url: url.to_string(), - source, - })?; + let started_at = Instant::now(); + let url_path = Url::parse(url) + .map(|url| url.path().to_string()) + .unwrap_or_else(|_| "".to_string()); + let response = match request.send().await { + Ok(response) => { + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + url_path = %url_path, + status = %response.status(), + "remote plugin HTTP response received" + ); + response + } + Err(source) => { + tracing::warn!( + elapsed_ms = started_at.elapsed().as_millis(), + url_path = %url_path, + "remote plugin HTTP request failed: {source}" + ); + return Err(RemotePluginCatalogError::Request { + url: url.to_string(), + source, + }); + } + }; let status = response.status(); + let body_started_at = Instant::now(); let body = response.text().await.unwrap_or_default(); + tracing::info!( + elapsed_ms = body_started_at.elapsed().as_millis(), + total_elapsed_ms = started_at.elapsed().as_millis(), + url_path = %url_path, + status = %status, + body_bytes = body.len(), + "remote plugin HTTP body read" + ); if !status.is_success() { + tracing::warn!( + elapsed_ms = started_at.elapsed().as_millis(), + url_path = %url_path, + status = %status, + body_bytes = body.len(), + "remote plugin HTTP request returned unexpected status" + ); return Err(RemotePluginCatalogError::UnexpectedStatus { url: url.to_string(), status, @@ -1289,8 +1467,26 @@ async fn send_and_decode Deserialize<'de>>( }); } - serde_json::from_str(&body).map_err(|source| RemotePluginCatalogError::Decode { - url: url.to_string(), - source, - }) + let decode_started_at = Instant::now(); + let decoded = serde_json::from_str(&body).map_err(|source| { + tracing::warn!( + elapsed_ms = decode_started_at.elapsed().as_millis(), + total_elapsed_ms = started_at.elapsed().as_millis(), + url_path = %url_path, + body_bytes = body.len(), + "remote plugin HTTP response decode failed: {source}" + ); + RemotePluginCatalogError::Decode { + url: url.to_string(), + source, + } + })?; + tracing::info!( + elapsed_ms = decode_started_at.elapsed().as_millis(), + total_elapsed_ms = started_at.elapsed().as_millis(), + url_path = %url_path, + body_bytes = body.len(), + "remote plugin HTTP response decoded" + ); + Ok(decoded) } diff --git a/codex-rs/tui/src/app/background_requests.rs b/codex-rs/tui/src/app/background_requests.rs index c323a2d5bf..5349d2229d 100644 --- a/codex-rs/tui/src/app/background_requests.rs +++ b/codex-rs/tui/src/app/background_requests.rs @@ -19,6 +19,7 @@ use crate::hooks_rpc::fetch_hooks_list; use crate::hooks_rpc::write_hook_trust; use crate::hooks_rpc::write_hook_trusts; use codex_utils_absolute_path::AbsolutePathBuf; +use std::time::Instant; impl App { pub(super) fn fetch_mcp_inventory( @@ -658,17 +659,38 @@ pub(super) async fn request_plugin_list( cwd: PathBuf, ) -> Result { let cwd = AbsolutePathBuf::try_from(cwd).wrap_err("plugin list cwd must be absolute")?; - let request_id = RequestId::String(format!("plugin-list-{}", Uuid::new_v4())); - request_handle + let request_id = format!("plugin-list-{}", Uuid::new_v4()); + let started_at = Instant::now(); + tracing::info!( + request_id = %request_id, + root_count = 1, + "plugin/list TUI request started" + ); + let response: PluginListResponse = request_handle .request_typed(ClientRequest::PluginList { - request_id, + request_id: RequestId::String(request_id.clone()), params: PluginListParams { cwds: Some(vec![cwd]), marketplace_kinds: None, }, }) .await - .wrap_err("plugin/list failed in TUI") + .wrap_err("plugin/list failed in TUI")?; + let plugin_count: usize = response + .marketplaces + .iter() + .map(|marketplace| marketplace.plugins.len()) + .sum(); + tracing::info!( + request_id = %request_id, + elapsed_ms = started_at.elapsed().as_millis(), + marketplace_count = response.marketplaces.len(), + plugin_count, + marketplace_load_error_count = response.marketplace_load_errors.len(), + featured_plugin_id_count = response.featured_plugin_ids.len(), + "plugin/list TUI request completed" + ); + Ok(response) } pub(super) async fn fetch_plugin_detail( diff --git a/codex-rs/tui/src/app/plugin_mentions.rs b/codex-rs/tui/src/app/plugin_mentions.rs index ef300896bc..2e04b0d4e2 100644 --- a/codex-rs/tui/src/app/plugin_mentions.rs +++ b/codex-rs/tui/src/app/plugin_mentions.rs @@ -12,6 +12,7 @@ use codex_app_server_protocol::PluginSummary; use codex_core_plugins::PluginsManager; use codex_plugin::PluginCapabilitySummary; use std::collections::HashMap; +use std::time::Instant; #[derive(Debug, Clone)] struct PluginMentionEntry { @@ -41,14 +42,47 @@ pub(super) async fn fetch_plugin_mentions( request_handle: AppServerRequestHandle, config: crate::legacy_core::config::Config, ) -> Result> { + let started_at = Instant::now(); + let list_started_at = Instant::now(); let response = request_plugin_list(request_handle, config.cwd.to_path_buf()).await?; + let list_elapsed_ms = list_started_at.elapsed().as_millis(); + let marketplace_count = response.marketplaces.len(); + let list_plugin_count: usize = response + .marketplaces + .iter() + .map(|marketplace| marketplace.plugins.len()) + .sum(); + tracing::info!( + elapsed_ms = list_elapsed_ms, + marketplace_count, + plugin_count = list_plugin_count, + marketplace_load_error_count = response.marketplace_load_errors.len(), + featured_plugin_id_count = response.featured_plugin_ids.len(), + "plugin mention plugin/list phase completed" + ); let mention_entries = plugin_mention_entries_from_list_response(response); + tracing::info!( + mention_entry_count = mention_entries.len(), + "plugin mention list response filtered" + ); + let capabilities_started_at = Instant::now(); let capabilities_by_config_name = load_plugin_mention_capabilities(&config).await; + tracing::info!( + elapsed_ms = capabilities_started_at.elapsed().as_millis(), + capability_count = capabilities_by_config_name.len(), + "plugin mention local capability phase completed" + ); - Ok(mention_entries + let plugins = mention_entries .into_iter() .filter_map(|entry| entry.capability_summary(&capabilities_by_config_name)) - .collect()) + .collect::>(); + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + mention_count = plugins.len(), + "plugin mentions fetched" + ); + Ok(plugins) } async fn load_plugin_mention_capabilities( diff --git a/codex-rs/tui/src/bottom_pane/chat_composer.rs b/codex-rs/tui/src/bottom_pane/chat_composer.rs index 4bfd5da17c..e30da11b1f 100644 --- a/codex-rs/tui/src/bottom_pane/chat_composer.rs +++ b/codex-rs/tui/src/bottom_pane/chat_composer.rs @@ -3961,6 +3961,7 @@ impl ChatComposer { return; } + let started_at = Instant::now(); if query.is_empty() { self.app_event_tx .send(AppEvent::StartFileSearch(String::new())); @@ -3975,6 +3976,9 @@ impl ChatComposer { self.skills.as_deref(), self.plugins.as_deref(), ); + let candidate_count = candidates.len(); + let skill_count = self.skills.as_ref().map_or(0, std::vec::Vec::len); + let plugin_count = self.plugins.as_ref().map_or(0, std::vec::Vec::len); match &mut self.popups.active { ActivePopup::MentionV2(popup) => { @@ -3988,6 +3992,14 @@ impl ChatComposer { } } + tracing::info!( + elapsed_us = started_at.elapsed().as_micros(), + query_len = query.len(), + candidate_count, + skill_count, + plugin_count, + "mentions v2 @ popup synchronized" + ); self.popups.dismissed_mention_token = None; } diff --git a/codex-rs/tui/src/file_search.rs b/codex-rs/tui/src/file_search.rs index 70ac98de11..8bc08d4389 100644 --- a/codex-rs/tui/src/file_search.rs +++ b/codex-rs/tui/src/file_search.rs @@ -9,6 +9,7 @@ use codex_file_search as file_search; use std::path::PathBuf; use std::sync::Arc; use std::sync::Mutex; +use std::time::Instant; use crate::app_event::AppEvent; use crate::app_event_sender::AppEventSender; @@ -21,6 +22,7 @@ pub(crate) struct FileSearchManager { struct SearchState { latest_query: String, + latest_query_started_at: Option, session: Option, session_token: usize, } @@ -30,6 +32,7 @@ impl FileSearchManager { Self { state: Arc::new(Mutex::new(SearchState { latest_query: String::new(), + latest_query_started_at: None, session: None, session_token: 0, })), @@ -47,6 +50,7 @@ impl FileSearchManager { let mut st = self.state.lock().unwrap(); st.session.take(); st.latest_query.clear(); + st.latest_query_started_at = None; } /// Call whenever the user edits the `@` token. @@ -58,21 +62,33 @@ impl FileSearchManager { } st.latest_query.clear(); st.latest_query.push_str(&query); + st.latest_query_started_at = Some(Instant::now()); if query.is_empty() { + tracing::info!("TUI @ file search query cleared"); + st.latest_query_started_at = None; st.session.take(); return; } - if st.session.is_none() { + let session_was_missing = st.session.is_none(); + if session_was_missing { self.start_session_locked(&mut st); } if let Some(session) = st.session.as_ref() { + let update_started_at = Instant::now(); session.update_query(&query); + tracing::info!( + elapsed_us = update_started_at.elapsed().as_micros(), + query_len = query.len(), + session_was_missing, + "TUI @ file search query dispatched" + ); } } fn start_session_locked(&self, st: &mut SearchState) { + let started_at = Instant::now(); st.session_token = st.session_token.wrapping_add(1); let session_token = st.session_token; let reporter = Arc::new(TuiSessionReporter { @@ -90,9 +106,21 @@ impl FileSearchManager { /*cancel_flag*/ None, ); match session { - Ok(session) => st.session = Some(session), + Ok(session) => { + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + session_token, + root_count = 1, + "TUI @ file search session started" + ); + st.session = Some(session); + } Err(err) => { - tracing::warn!("file search session failed to start: {err}"); + tracing::warn!( + elapsed_ms = started_at.elapsed().as_millis(), + root_count = 1, + "file search session failed to start: {err}" + ); st.session = None; } } @@ -109,6 +137,9 @@ impl TuiSessionReporter { fn send_snapshot(&self, snapshot: &file_search::FileSearchSnapshot) { #[expect(clippy::unwrap_used)] let st = self.state.lock().unwrap(); + let elapsed_ms = st + .latest_query_started_at + .map(|started_at| started_at.elapsed().as_millis()); if st.session_token != self.session_token || st.latest_query.is_empty() || snapshot.query.is_empty() @@ -116,7 +147,14 @@ impl TuiSessionReporter { return; } let query = snapshot.query.clone(); + let match_count = snapshot.matches.len(); drop(st); + tracing::info!( + elapsed_ms = ?elapsed_ms, + query_len = query.len(), + match_count, + "TUI @ file search snapshot delivered" + ); self.app_tx.send(AppEvent::FileSearchResult { query, matches: snapshot.matches.clone(),