openai/codex
1
0
Fork 0
mirror of https://github.com/openai/codex.git synced 2026-11-05 20:10:33 +00:00
Code Issues Packages Projects Releases Wiki Activity

Add latency logs for plugin and mention flows

Browse Source
This commit is contained in:
xli-oai
2026-05-18 17:14:28 -07:00
parent 5696167fe8
commit c33adf538b
9 changed files with 751 additions and 42 deletions
Download Patch File Download Diff File Expand all files Collapse all files
codex-rs/app-server/src/fuzzy_file_search.rs
+29
View File
@@ -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<Option<Instant>>,
latest_query: Mutex<String>,
outgoing: Arc<OutgoingMessageSender>,
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 {
codex-rs/app-server/src/message_processor.rs
+2 -2
View File
@@ -1100,13 +1100,13 @@ 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::PluginInstalled { params, .. } => {
self.plugin_processor.plugin_installed(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
codex-rs/app-server/src/request_processors/plugins.rs
+360 -19
View File
@@ -13,6 +13,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 {
@@ -295,9 +296,10 @@ impl PluginRequestProcessor {
pub(crate) async fn plugin_list(
&self,
request_id: &ConnectionRequestId,
params: PluginListParams,
) -> Result<Option<ClientResponsePayload>, JSONRPCErrorError> {
self.plugin_list_response(params)
self.plugin_list_response(request_id, params)
.await
.map(|response| Some(response.into()))
}
@@ -313,9 +315,10 @@ impl PluginRequestProcessor {
pub(crate) async fn plugin_read(
&self,
request_id: &ConnectionRequestId,
params: PluginReadParams,
) -> Result<Option<ClientResponsePayload>, JSONRPCErrorError> {
self.plugin_read_response(params)
self.plugin_read_response(request_id, params)
.await
.map(|response| Some(response.into()))
}
@@ -463,8 +466,11 @@ impl PluginRequestProcessor {
async fn plugin_list_response(
&self,
request_id: &ConnectionRequestId,
params: PluginListParams,
) -> Result<PluginListResponse, JSONRPCErrorError> {
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,
@@ -475,33 +481,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)?;
@@ -550,11 +608,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}"
)));
@@ -576,10 +659,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(),
@@ -588,6 +684,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)
@@ -606,16 +713,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",
@@ -623,34 +749,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,
@@ -847,8 +1004,11 @@ impl PluginRequestProcessor {
async fn plugin_read_response(
&self,
request_id: &ConnectionRequestId,
params: PluginReadParams,
) -> Result<PluginReadResponse, JSONRPCErrorError> {
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,
@@ -859,30 +1019,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,
@@ -893,6 +1129,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(),
@@ -901,12 +1138,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"
);
@@ -918,6 +1165,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"
);
@@ -925,6 +1174,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"
@@ -936,9 +1187,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
@@ -988,25 +1247,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()
@@ -1014,12 +1337,30 @@ impl PluginRequestProcessor {
.map(codex_plugin::AppConnectorId)
.collect::<Vec<_>>();
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 })
}
codex-rs/app-server/src/request_processors/search.rs
+37
View File
@@ -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<FuzzyFileSearchSessionUpdateResponse, JSONRPCErrorError> {
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<FuzzyFileSearchSessionStopResponse, JSONRPCErrorError> {
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 {})
}
}
codex-rs/core-plugins/src/remote.rs
+208 -12
View File
@@ -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;
@@ -485,6 +486,12 @@ pub async fn fetch_remote_marketplaces(
auth: Option<&CodexAuth>,
sources: &[RemoteMarketplaceSource],
) -> Result<Vec<RemoteMarketplace>, 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| {
@@ -494,12 +501,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;
@@ -507,6 +523,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(),
@@ -514,13 +532,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(),
@@ -528,7 +567,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 => {
@@ -536,6 +592,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())
@@ -558,6 +615,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);
}
@@ -586,12 +651,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)
}
@@ -1175,17 +1264,35 @@ async fn fetch_directory_plugins_for_scope(
auth: &CodexAuth,
scope: RemotePluginScope,
) -> Result<Vec<RemotePluginDirectoryItem>, 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)
}
@@ -1193,17 +1300,33 @@ async fn fetch_shared_workspace_plugins(
config: &RemotePluginServiceConfig,
auth: &CodexAuth,
) -> Result<Vec<RemotePluginDirectoryItem>, 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)
}
@@ -1224,9 +1347,12 @@ async fn fetch_installed_plugins_for_scope_with_download_url(
scope: RemotePluginScope,
include_download_urls: bool,
) -> Result<Vec<RemotePluginInstalledItem>, 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,
@@ -1235,12 +1361,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)
}
@@ -1359,16 +1502,51 @@ async fn send_and_decode<T: for<'de> Deserialize<'de>>(
request: RequestBuilder,
url: &str,
) -> Result<T, RemotePluginCatalogError> {
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(|_| "<invalid-url>".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,
@@ -1376,8 +1554,26 @@ async fn send_and_decode<T: for<'de> 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)
}
codex-rs/tui/src/app/background_requests.rs
+26 -4
View File
@@ -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<PluginListResponse> {
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(
codex-rs/tui/src/app/plugin_mentions.rs
+36 -2
View File
@@ -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<Vec<PluginCapabilitySummary>> {
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::<Vec<_>>();
tracing::info!(
elapsed_ms = started_at.elapsed().as_millis(),
mention_count = plugins.len(),
"plugin mentions fetched"
);
Ok(plugins)
}
async fn load_plugin_mention_capabilities(
codex-rs/tui/src/bottom_pane/chat_composer.rs
+12
View File
@@ -3969,6 +3969,7 @@ impl ChatComposer {
return;
}
let started_at = Instant::now();
if query.is_empty() {
self.app_event_tx
.send(AppEvent::StartFileSearch(String::new()));
@@ -3983,6 +3984,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) => {
@@ -3996,6 +4000,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;
}
codex-rs/tui/src/file_search.rs
+41 -3
View File
@@ -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<Instant>,
session: Option<file_search::FileSearchSession>,
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(),