diff --git a/crates/goose-acp/acp-meta.json b/crates/goose-acp/acp-meta.json index 7743ab6b..944d227b 100644 --- a/crates/goose-acp/acp-meta.json +++ b/crates/goose-acp/acp-meta.json @@ -40,11 +40,6 @@ "requestType": "GetSessionExtensionsRequest", "responseType": "GetSessionExtensionsResponse" }, - { - "method": "_goose/session/provider/update", - "requestType": "UpdateProviderRequest", - "responseType": "UpdateProviderResponse" - }, { "method": "_goose/providers/list", "requestType": "ListProvidersRequest", diff --git a/crates/goose-acp/acp-schema.json b/crates/goose-acp/acp-schema.json index 590d8a87..0f0db175 100644 --- a/crates/goose-acp/acp-schema.json +++ b/crates/goose-acp/acp-schema.json @@ -195,61 +195,6 @@ "x-side": "agent", "x-method": "_goose/session/extensions" }, - "UpdateProviderRequest": { - "type": "object", - "properties": { - "sessionId": { - "type": "string" - }, - "provider": { - "type": "string" - }, - "model": { - "type": [ - "string", - "null" - ] - }, - "contextLimit": { - "type": [ - "integer", - "null" - ], - "format": "uint", - "minimum": 0 - }, - "requestParams": { - "type": [ - "object", - "null" - ], - "additionalProperties": {} - } - }, - "required": [ - "sessionId", - "provider" - ], - "description": "Atomically update the provider for a live session.", - "x-side": "agent", - "x-method": "_goose/session/provider/update" - }, - "UpdateProviderResponse": { - "type": "object", - "properties": { - "configOptions": { - "type": "array", - "items": {}, - "description": "Refreshed session config options after the provider/model change." - } - }, - "required": [ - "configOptions" - ], - "description": "Provider update response.", - "x-side": "agent", - "x-method": "_goose/session/provider/update" - }, "ListProvidersRequest": { "type": "object", "description": "List providers available through goose, including the config-default sentinel.", @@ -746,15 +691,6 @@ "description": "Params for _goose/session/extensions", "title": "GetSessionExtensionsRequest" }, - { - "allOf": [ - { - "$ref": "#/$defs/UpdateProviderRequest" - } - ], - "description": "Params for _goose/session/provider/update", - "title": "UpdateProviderRequest" - }, { "allOf": [ { @@ -942,14 +878,6 @@ ], "title": "GetSessionExtensionsResponse" }, - { - "allOf": [ - { - "$ref": "#/$defs/UpdateProviderResponse" - } - ], - "title": "UpdateProviderResponse" - }, { "allOf": [ { diff --git a/crates/goose-acp/src/server.rs b/crates/goose-acp/src/server.rs index daa0eec8..eeeae74d 100644 --- a/crates/goose-acp/src/server.rs +++ b/crates/goose-acp/src/server.rs @@ -128,6 +128,13 @@ pub struct GooseAcpAgent { disable_session_naming: bool, } +/// Shorten a session/thread id for perf log correlation. +/// All `perf:` logs use `sid=<8-char-prefix>` so a single session's activity +/// can be extracted with `grep 'perf:' | grep 'sid=abc12345'`. +fn sid_short(id: &str) -> String { + id.chars().take(8).collect() +} + fn extract_timeout_from_meta(meta: &Option) -> Option { meta.as_ref() .and_then(|m| m.get("timeout")) @@ -660,6 +667,7 @@ impl GooseAcpAgent { let goose_mode = goose_session.goose_mode; let internal_session_id = goose_session.id.clone(); let agent_session_id = SessionId::new(internal_session_id.clone()); + let sid = sid_short(session_id.0.as_ref()); let cx = cx.clone(); let sessions = Arc::clone(&self.sessions); @@ -677,6 +685,8 @@ impl GooseAcpAgent { let disable_session_naming = self.disable_session_naming; tokio::spawn(async move { + let t_setup = std::time::Instant::now(); + debug!(target: "perf", sid = %sid, "perf: agent_setup start (background)"); let result: Result<(), String> = async { let agent = Arc::new(Agent::with_config(AgentConfig::new( session_manager, @@ -746,18 +756,28 @@ impl GooseAcpAgent { } let ext_manager = &agent.extension_manager; + let ext_count = extensions.len(); + let t_ext = std::time::Instant::now(); let extension_futures = extensions .into_iter() .map(|ext| { let ext_manager = Arc::clone(ext_manager); - let sid = sid_str.clone(); + let sid_inner = sid_str.clone(); + let sid_log = sid.clone(); async move { let name = ext.name().to_string(); + let t_one = std::time::Instant::now(); match ext_manager - .add_extension(ext, None, None, sid.as_deref()) + .add_extension(ext, None, None, sid_inner.as_deref()) .await { - Ok(_) => info!(extension = %name, "extension loaded"), + Ok(_) => debug!( + target: "perf", + sid = %sid_log, + extension = %name, + ms = t_one.elapsed().as_millis() as u64, + "perf: agent_setup extension_loaded" + ), Err(e) => { warn!(extension = %name, error = %e, "extension load failed") } @@ -766,6 +786,13 @@ impl GooseAcpAgent { }) .collect::>(); futures::future::join_all(extension_futures).await; + debug!( + target: "perf", + sid = %sid, + ms = t_ext.elapsed().as_millis() as u64, + extensions = ext_count, + "perf: agent_setup extensions_total" + ); if let Some((client, config)) = acp_developer { let info = client.get_info().cloned(); @@ -778,6 +805,7 @@ impl GooseAcpAgent { // Init provider — reuse the pre-resolved name + model when // available (already computed in on_new_session), otherwise // fall back to reading config (e.g. load_session path). + let t_prov = std::time::Instant::now(); let config = Config::new(config_dir.join(CONFIG_YAML_NAME), "goose") .map_err(|e| e.to_string())?; let (provider_name, model_config) = match resolved_provider { @@ -800,10 +828,20 @@ impl GooseAcpAgent { .update_goose_mode(goose_mode, &internal_session_id) .await .map_err(|e| e.to_string())?; + debug!(target: "perf", sid = %sid, ms = t_prov.elapsed().as_millis() as u64, "perf: agent_setup provider_init"); + let t_mcp = std::time::Instant::now(); + let mcp_count = mcp_servers.len(); GooseAcpAgent::add_mcp_extensions(&agent, mcp_servers, &internal_session_id) .await .map_err(|e| e.to_string())?; + debug!( + target: "perf", + sid = %sid, + ms = t_mcp.elapsed().as_millis() as u64, + mcp_servers = mcp_count, + "perf: agent_setup mcp_extensions" + ); // Apply any working directory that was set while we were loading. { @@ -822,9 +860,23 @@ impl GooseAcpAgent { } .await; - if let Err(e) = &result { - error!(error = %e, "Background agent setup failed"); - let _ = agent_tx.send(Some(Err(e.clone()))); + match &result { + Ok(()) => debug!( + target: "perf", + sid = %sid, + ms = t_setup.elapsed().as_millis() as u64, + "perf: agent_setup done" + ), + Err(e) => { + error!(error = %e, "Background agent setup failed"); + debug!( + target: "perf", + sid = %sid, + ms = t_setup.elapsed().as_millis() as u64, + "perf: agent_setup failed" + ); + let _ = agent_tx.send(Some(Err(e.clone()))); + } } }); } @@ -1266,6 +1318,7 @@ impl GooseAcpAgent { args: NewSessionRequest, ) -> Result { debug!(?args, "new session request"); + let t_start = std::time::Instant::now(); let requested_provider = args .meta @@ -1280,6 +1333,7 @@ impl GooseAcpAgent { mode: Some(self.goose_mode.to_string()), ..Default::default() }; + let t0 = std::time::Instant::now(); let thread = self .thread_manager .create_thread( @@ -1292,8 +1346,11 @@ impl GooseAcpAgent { sacp::Error::internal_error().data(format!("Failed to create thread: {}", e)) })?; let thread_id = thread.id.clone(); + let sid = sid_short(&thread_id); + debug!(target: "perf", sid = %sid, ms = t0.elapsed().as_millis() as u64, "perf: new_session create_thread"); // Create the first internal Session linked to this thread. + let t1 = std::time::Instant::now(); let goose_session = self .create_internal_session( &thread_id, @@ -1302,6 +1359,7 @@ impl GooseAcpAgent { None, ) .await?; + debug!(target: "perf", sid = %sid, ms = t1.elapsed().as_millis() as u64, "perf: new_session create_internal_session"); let internal_session_id = goose_session.id.clone(); @@ -1346,6 +1404,12 @@ impl GooseAcpAgent { if let Some(co) = config_options { response = response.config_options(co); } + debug!( + target: "perf", + sid = %sid, + ms = t_start.elapsed().as_millis() as u64, + "perf: new_session done (agent setup continues in background)" + ); Ok(response) } @@ -1473,7 +1537,11 @@ impl GooseAcpAgent { // The ACP session_id IS the thread ID. let thread_id = args.session_id.0.to_string(); + let sid = sid_short(&thread_id); + let t_start = std::time::Instant::now(); + debug!(target: "perf", sid = %sid, "perf: load_session start"); + let t0 = std::time::Instant::now(); let thread = self .thread_manager .get_thread(&thread_id) @@ -1482,6 +1550,7 @@ impl GooseAcpAgent { sacp::Error::resource_not_found(Some(thread_id.clone())) .data(format!("Session not found: {}", thread_id)) })?; + debug!(target: "perf", sid = %sid, ms = t0.elapsed().as_millis() as u64, "perf: load_session get_thread"); // Reuse the thread's current internal session so the agent retains // conversation context (compaction state, full message history, etc.). @@ -1490,6 +1559,7 @@ impl GooseAcpAgent { sacp::Error::internal_error() .data(format!("Thread {} has no internal session", thread_id)) })?; + let t1 = std::time::Instant::now(); let goose_session = self .session_manager .get_session(&internal_session_id, false) @@ -1498,6 +1568,7 @@ impl GooseAcpAgent { sacp::Error::internal_error() .data(format!("Failed to load internal session: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t1.elapsed().as_millis() as u64, "perf: load_session get_session"); let loaded_mode = goose_session.goose_mode; // ── REPLAY MESSAGES FIRST ── @@ -1505,6 +1576,7 @@ impl GooseAcpAgent { // immediately, before the slow agent/provider/extension setup. The // replay only needs the thread_manager (SQLite reads) so the UI gets // messages while the agent is still booting. + let t2 = std::time::Instant::now(); let thread_messages = self .thread_manager .list_messages(&thread_id) @@ -1512,6 +1584,13 @@ impl GooseAcpAgent { .map_err(|e| { sacp::Error::internal_error().data(format!("Failed to load thread messages: {}", e)) })?; + debug!( + target: "perf", + sid = %sid, + ms = t2.elapsed().as_millis() as u64, + messages = thread_messages.len(), + "perf: load_session list_messages" + ); // Lightweight tool_requests map for the replay loop — we only need it // so that handle_tool_response can extract file locations from the @@ -1519,6 +1598,8 @@ impl GooseAcpAgent { let mut replay_tool_requests = HashMap::::new(); + let t_replay = std::time::Instant::now(); + let mut replay_notifications: u32 = 0; for message in &thread_messages { if !message.metadata.user_visible { continue; @@ -1538,6 +1619,7 @@ impl GooseAcpAgent { args.session_id.clone(), update, ))?; + replay_notifications += 1; } MessageContent::ToolRequest(tool_request) => { // Replay-only: emit the ToolCall notification and @@ -1560,6 +1642,7 @@ impl GooseAcpAgent { .status(ToolCallStatus::Pending), ), ))?; + replay_notifications += 1; } MessageContent::ToolResponse(tool_response) => { // Replay-only: emit the ToolCallUpdate notification, @@ -1602,6 +1685,7 @@ impl GooseAcpAgent { fields, )), ))?; + replay_notifications += 1; } MessageContent::Thinking(thinking) => { cx.send_notification(SessionNotification::new( @@ -1610,13 +1694,22 @@ impl GooseAcpAgent { ContentBlock::Text(TextContent::new(thinking.thinking.clone())), )), ))?; + replay_notifications += 1; } _ => {} } } } + debug!( + target: "perf", + sid = %sid, + ms = t_replay.elapsed().as_millis() as u64, + notifications = replay_notifications, + "perf: load_session replay_loop" + ); // ── Lightweight DB updates (fast) ── + let t_db = std::time::Instant::now(); self.session_manager .update(&internal_session_id) .working_dir(args.cwd.clone()) @@ -1634,6 +1727,7 @@ impl GooseAcpAgent { sacp::Error::internal_error() .data(format!("Failed to update thread working directory: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t_db.elapsed().as_millis() as u64, "perf: load_session db_updates"); // ── Register the session immediately with a Loading handle ── let (agent_tx, agent_rx) = @@ -1675,6 +1769,12 @@ impl GooseAcpAgent { if let Some(co) = config_options { response = response.config_options(co); } + debug!( + target: "perf", + sid = %sid, + ms = t_start.elapsed().as_millis() as u64, + "perf: load_session done (agent setup continues in background)" + ); Ok(response) } @@ -1685,21 +1785,29 @@ impl GooseAcpAgent { ) -> Result { // The ACP session_id IS the thread ID. let thread_id = args.session_id.0.to_string(); + let sid = sid_short(&thread_id); + let t_start = std::time::Instant::now(); + debug!(target: "perf", sid = %sid, "perf: prompt start"); + let cancel_token = CancellationToken::new(); let internal_session_id = self.internal_session_id(&thread_id).await?; + let t_agent = std::time::Instant::now(); let agent = self .get_session_agent(&thread_id, Some(cancel_token.clone())) .await?; + debug!(target: "perf", sid = %sid, ms = t_agent.elapsed().as_millis() as u64, "perf: prompt get_session_agent (waits for agent setup)"); let user_message = self.convert_acp_prompt_to_message(args.prompt); + let t_persist = std::time::Instant::now(); self.thread_manager .append_message(&thread_id, Some(&internal_session_id), &user_message) .await .map_err(|e| { sacp::Error::internal_error().data(format!("Failed to persist message: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t_persist.elapsed().as_millis() as u64, "perf: prompt append_user_message"); let session_config = SessionConfig { id: internal_session_id.clone(), @@ -1708,22 +1816,36 @@ impl GooseAcpAgent { retry_config: None, }; + let t_reply = std::time::Instant::now(); let mut stream = agent .reply(user_message, session_config, Some(cancel_token.clone())) .await .map_err(|e| { sacp::Error::internal_error().data(format!("Error getting agent reply: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t_reply.elapsed().as_millis() as u64, "perf: prompt agent.reply() setup"); use futures::StreamExt; let mut was_cancelled = false; + let mut first_event_logged = false; + let mut event_count: u32 = 0; while let Some(event) = stream.next().await { if cancel_token.is_cancelled() { was_cancelled = true; break; } + event_count += 1; + if !first_event_logged { + debug!( + target: "perf", + sid = %sid, + ttft_ms = t_start.elapsed().as_millis() as u64, + "perf: prompt first stream event (time-to-first-token from prompt start)" + ); + first_event_logged = true; + } match event { Ok(goose::agents::AgentEvent::Message(message)) => { @@ -1764,6 +1886,14 @@ impl GooseAcpAgent { if let Some(session) = sessions.get_mut(&thread_id) { session.cancel_token = None; } + debug!( + target: "perf", + sid = %sid, + ms = t_start.elapsed().as_millis() as u64, + events = event_count, + cancelled = was_cancelled, + "perf: prompt done" + ); Ok(PromptResponse::new(if was_cancelled { StopReason::Cancelled } else { @@ -1794,11 +1924,25 @@ impl GooseAcpAgent { thread_id: &str, model_id: &str, ) -> Result { + let sid = sid_short(thread_id); + let t_total = std::time::Instant::now(); + debug!(target: "perf", sid = %sid, model = %model_id, "perf: set_model start"); + + let t_step = std::time::Instant::now(); let internal_id = self.internal_session_id(thread_id).await?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: set_model internal_session_id"); + + let t_step = std::time::Instant::now(); let config = self.load_config().map_err(|e| { sacp::Error::internal_error().data(format!("Failed to read config: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: set_model load_config"); + + let t_step = std::time::Instant::now(); let agent = self.get_session_agent(thread_id, None).await?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: set_model get_session_agent (waits for agent setup)"); + + let t_step = std::time::Instant::now(); let current_provider = agent.provider().await.map_err(|e| { sacp::Error::internal_error().data(format!("Failed to get provider: {}", e)) })?; @@ -1810,20 +1954,27 @@ impl GooseAcpAgent { sacp::Error::invalid_params().data(format!("Invalid model config: {}", e)) })? .with_canonical_limits(&provider_name); + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, provider = %provider_name, "perf: set_model build_model_config"); + + let t_step = std::time::Instant::now(); let provider = self .create_provider(&provider_name, model_config, extensions) .await .map_err(|e| { sacp::Error::internal_error().data(format!("Failed to create provider: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, provider = %provider_name, "perf: set_model create_provider"); + let t_step = std::time::Instant::now(); agent .update_provider(provider, &internal_id) .await .map_err(|e| { sacp::Error::internal_error().data(format!("Failed to update provider: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: set_model agent.update_provider"); + let t_step = std::time::Instant::now(); let mode = agent.goose_mode().await; agent .update_goose_mode(mode, &internal_id) @@ -1831,13 +1982,17 @@ impl GooseAcpAgent { .map_err(|e| { sacp::Error::internal_error().data(format!("Failed to propagate mode: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: set_model update_goose_mode"); - let model_id = model_id.to_string(); + let t_step = std::time::Instant::now(); + let model_id_owned = model_id.to_string(); self.update_thread_metadata(thread_id, move |meta| { - meta.model_name = Some(model_id); + meta.model_name = Some(model_id_owned); }) .await?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: set_model update_thread_metadata"); + debug!(target: "perf", sid = %sid, ms = t_total.elapsed().as_millis() as u64, model = %model_id, "perf: set_model done"); Ok(SetSessionModelResponse::new()) } @@ -1930,12 +2085,26 @@ impl GooseAcpAgent { model_name: Option<&str>, context_limit: Option, request_params: Option>, - ) -> Result, sacp::Error> { + ) -> Result<(), sacp::Error> { + let sid = sid_short(thread_id); + let t_total = std::time::Instant::now(); + debug!(target: "perf", sid = %sid, provider = %provider_name, "perf: update_provider start"); + + let t_step = std::time::Instant::now(); let internal_id = self.internal_session_id(thread_id).await?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: update_provider internal_session_id"); + + let t_step = std::time::Instant::now(); let config = self.load_config().map_err(|e| { sacp::Error::internal_error().data(format!("Failed to read config: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: update_provider load_config"); + + let t_step = std::time::Instant::now(); let agent = self.get_session_agent(thread_id, None).await?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: update_provider get_session_agent (waits for agent setup)"); + + let t_step = std::time::Instant::now(); let current_provider = agent.provider().await.map_err(|e| { sacp::Error::internal_error().data(format!("Failed to get provider: {}", e)) })?; @@ -1977,22 +2146,41 @@ impl GooseAcpAgent { .with_canonical_limits(&resolved_provider_name) .with_context_limit(context_limit) .with_request_params(request_params); + debug!( + target: "perf", + sid = %sid, + ms = t_step.elapsed().as_millis() as u64, + resolved_provider = %resolved_provider_name, + current_provider = %current_provider_name, + changing = is_changing_provider, + has_overrides = has_default_overrides, + "perf: update_provider resolve_defaults" + ); + + let t_step = std::time::Instant::now(); let extensions = EnabledExtensionsState::for_session(&self.session_manager, &internal_id, &config).await; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: update_provider build_extensions"); + + let t_step = std::time::Instant::now(); let new_provider = self .create_provider(&resolved_provider_name, model_config, extensions) .await .map_err(|e| { sacp::Error::internal_error().data(format!("Failed to create provider: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, provider = %resolved_provider_name, "perf: update_provider create_provider"); + let t_step = std::time::Instant::now(); agent .update_provider(new_provider, &internal_id) .await .map_err(|e| { sacp::Error::internal_error().data(format!("Failed to update provider: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: update_provider agent.update_provider"); + let t_step = std::time::Instant::now(); let mode = agent.goose_mode().await; agent .update_goose_mode(mode, &internal_id) @@ -2000,17 +2188,21 @@ impl GooseAcpAgent { .map_err(|e| { sacp::Error::internal_error().data(format!("Failed to propagate mode: {}", e)) })?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: update_provider update_goose_mode"); let provider = agent.provider().await.map_err(|e| { sacp::Error::internal_error().data(format!("Failed to get provider: {}", e)) })?; + let t_step = std::time::Instant::now(); let provider_name_owned = provider_name.to_string(); self.update_thread_metadata(thread_id, move |meta| { meta.provider_id = Some(provider_name_owned); }) .await?; + debug!(target: "perf", sid = %sid, ms = t_step.elapsed().as_millis() as u64, "perf: update_provider update_thread_metadata"); + let t_step = std::time::Instant::now(); if use_default_provider { let update = self .session_manager @@ -2037,11 +2229,24 @@ impl GooseAcpAgent { })?; } } + debug!( + target: "perf", + sid = %sid, + ms = t_step.elapsed().as_millis() as u64, + persisted = use_default_provider, + "perf: update_provider persist_session" + ); - let (_, config_options) = self - .build_config_update(&SessionId::new(thread_id.to_string())) - .await?; - Ok(config_options) + debug!( + target: "perf", + sid = %sid, + ms = t_total.elapsed().as_millis() as u64, + provider = %provider_name, + resolved_provider = %resolved_provider_name, + changing = is_changing_provider, + "perf: update_provider done" + ); + Ok(()) } async fn on_list_sessions(&self) -> Result { @@ -2320,28 +2525,6 @@ impl GooseAcpAgent { }) } - #[custom_method(UpdateProviderRequest)] - async fn on_update_provider( - &self, - req: UpdateProviderRequest, - ) -> Result { - let config_options = self - .update_provider( - &req.session_id, - &req.provider, - req.model.as_deref(), - req.context_limit, - req.request_params, - ) - .await?; - let config_options = config_options - .into_iter() - .map(|option| serde_json::to_value(&option)) - .collect::, _>>() - .map_err(|e| sacp::Error::internal_error().data(e.to_string()))?; - Ok(UpdateProviderResponse { config_options }) - } - #[custom_method(ListProvidersRequest)] async fn on_list_providers( &self, @@ -2741,7 +2924,11 @@ impl HandleDispatchFrom for GooseAcpHandler { .ok_or_else(|| sacp::Error::invalid_params().data("Expected a value ID"))? .clone(); let session_id = req.session_id.clone(); - match req.config_id.0.as_ref() { + let sid = sid_short(session_id.0.as_ref()); + let config_id = req.config_id.0.to_string(); + let t_handler = std::time::Instant::now(); + debug!(target: "perf", sid = %sid, config_id = %config_id, value = %value_id.0, "perf: set_config_option start"); + match config_id.as_ref() { "provider" => { match agent.update_provider(&session_id.0, &value_id.0, None, None, None).await { Ok(_) => {} @@ -2767,9 +2954,12 @@ impl HandleDispatchFrom for GooseAcpHandler { return Ok(()); } } + let t_tail = std::time::Instant::now(); let (notification, config_options) = agent.build_config_update(&session_id).await?; cx.send_notification(notification)?; responder.respond(SetSessionConfigOptionResponse::new(config_options))?; + debug!(target: "perf", sid = %sid, ms = t_tail.elapsed().as_millis() as u64, "perf: set_config_option notification_and_respond"); + debug!(target: "perf", sid = %sid, ms = t_handler.elapsed().as_millis() as u64, config_id = %config_id, "perf: set_config_option done"); Ok(()) } }) diff --git a/crates/goose-acp/tests/custom_requests_test.rs b/crates/goose-acp/tests/custom_requests_test.rs index 989636f8..06c970f6 100644 --- a/crates/goose-acp/tests/custom_requests_test.rs +++ b/crates/goose-acp/tests/custom_requests_test.rs @@ -208,48 +208,15 @@ fn test_provider_switching_updates_session_state() { conn.set_config_option(&session_id, "provider", "anthropic") .await - .expect("provider config option should succeed"); + .expect("provider switch to anthropic should succeed"); - let response = send_custom( - conn.cx(), - "_goose/session/provider/update", - serde_json::json!({ - "sessionId": session_id, - "provider": "openai", - "model": "o4-mini", - }), - ) - .await - .expect("provider update should succeed"); - let config_options = response - .get("configOptions") - .and_then(|value| value.as_array()) - .expect("missing config options"); - assert!( - !config_options.is_empty(), - "expected refreshed config options" - ); + conn.set_config_option(&session_id, "provider", "openai") + .await + .expect("provider switch to openai should succeed"); - let response = send_custom( - conn.cx(), - "_goose/session/provider/update", - serde_json::json!({ - "sessionId": session_id, - "provider": "goose", - }), - ) - .await - .expect("provider reset to goose should succeed"); - let config_options = response - .get("configOptions") - .and_then(|value| value.as_array()) - .expect("missing config options after reset"); - assert!( - config_options - .iter() - .any(|option| option.get("id") == Some(&serde_json::json!("provider"))), - "missing provider config option after reset" - ); + conn.set_config_option(&session_id, "provider", "goose") + .await + .expect("provider reset to goose should succeed"); }); } diff --git a/crates/goose-sdk/src/custom_requests.rs b/crates/goose-sdk/src/custom_requests.rs index e1df7414..bbc375be 100644 --- a/crates/goose-sdk/src/custom_requests.rs +++ b/crates/goose-sdk/src/custom_requests.rs @@ -1,7 +1,6 @@ use sacp::{JsonRpcRequest, JsonRpcResponse}; use schemars::JsonSchema; use serde::{Deserialize, Serialize}; -use std::collections::HashMap; /// Schema descriptor for a single custom method, produced by the /// `#[custom_methods]` macro's generated `custom_method_schemas()` function. @@ -116,26 +115,6 @@ pub struct GetSessionExtensionsResponse { pub extensions: Vec, } -/// Atomically update the provider for a live session. -#[derive(Debug, Default, Clone, Serialize, Deserialize, JsonSchema, JsonRpcRequest)] -#[request(method = "_goose/session/provider/update", response = UpdateProviderResponse)] -#[serde(rename_all = "camelCase")] -pub struct UpdateProviderRequest { - pub session_id: String, - pub provider: String, - pub model: Option, - pub context_limit: Option, - pub request_params: Option>, -} - -/// Provider update response. -#[derive(Debug, Default, Clone, Serialize, Deserialize, JsonSchema, JsonRpcResponse)] -#[serde(rename_all = "camelCase")] -pub struct UpdateProviderResponse { - /// Refreshed session config options after the provider/model change. - pub config_options: Vec, -} - /// Read a single non-secret config value. #[derive(Debug, Default, Clone, Serialize, Deserialize, JsonSchema, JsonRpcRequest)] #[request(method = "_goose/config/read", response = ReadConfigResponse)] diff --git a/ui/goose2/AGENTS.md b/ui/goose2/AGENTS.md index 47c7d3bd..3e3d2587 100644 --- a/ui/goose2/AGENTS.md +++ b/ui/goose2/AGENTS.md @@ -161,6 +161,12 @@ Additional tooling notes: - Pre-push hooks run `just fmt-check`, `just clippy`, `just check`, `just test`, `just build`, and `just tauri-check`. - Do not use `--no-verify` to bypass hooks. Fix the underlying issue instead. +## Performance Logging + +- Frontend perf logs use `perfLog()` from `@/shared/lib/perfLog`. Messages are tagged `[perf:]` (startup, conn, load, newtab, prepare, send, api, stream, replay, chatview). Enabled automatically in Vite dev mode, or opt-in via `localStorage.setItem("goose.perf", "1")` in a release build. +- Backend perf logs live in `crates/goose-acp/src/server.rs` under `target: "perf"` at `debug!` level. Off by default; enable with `RUST_LOG=perf=debug,info` on the `goose serve` process. +- `just dev` and `just dev-debug` export `RUST_LOG=perf=debug,info` so the child `goose serve` emits perf logs without extra setup. Override by setting `RUST_LOG` in the environment before invoking `just`. + ## Testing & Verification - Unit/component tests use Vitest and Testing Library via `just test` or `pnpm test`. diff --git a/ui/goose2/justfile b/ui/goose2/justfile index 2d0ce066..f02b33a8 100644 --- a/ui/goose2/justfile +++ b/ui/goose2/justfile @@ -84,6 +84,9 @@ dev: VITE_PORT={{ vite_port }} export VITE_PORT + # Enable perf logs in the child `goose serve` process by default. + # Override with e.g. RUST_LOG=info just dev to disable. + export RUST_LOG="${RUST_LOG:-perf=debug,info}" PROJECT_DIR=$(pwd) GOOSE_BIN="${PROJECT_DIR}/../../target/debug/goose" export GOOSE_BIN @@ -114,8 +117,9 @@ dev-debug: #!/usr/bin/env bash set -euo pipefail - VITE_PORT={{ vite_port }} - export VITE_PORT + # Enable perf logs in the child `goose serve` process by default. + # Override with e.g. RUST_LOG=info just dev-debug to disable. + export RUST_LOG="${RUST_LOG:-perf=debug,info}" PROJECT_DIR=$(pwd) GOOSE_BIN="${PROJECT_DIR}/../../target/debug/goose" export GOOSE_BIN diff --git a/ui/goose2/scripts/check-file-sizes.mjs b/ui/goose2/scripts/check-file-sizes.mjs index ed74d763..5d2066a1 100644 --- a/ui/goose2/scripts/check-file-sizes.mjs +++ b/ui/goose2/scripts/check-file-sizes.mjs @@ -11,9 +11,9 @@ const EXCEPTIONS = { "Drag-and-drop handlers for session-to-project moves and project reorder, plus activeProjectId highlight.", }, "src/features/chat/ui/ChatView.tsx": { - limit: 560, + limit: 570, justification: - "ACP prewarm guards, project-aware working dir selection, working context sync, and chat bootstrapping still live together here.", + "ACP prewarm guards, project-aware working dir selection, working context sync, and chat bootstrapping still live together here. Includes gated [perf:chatview] logging via perfLog (dev-only by default).", }, "src/features/chat/ui/__tests__/ContextPanel.test.tsx": { limit: 550, @@ -26,9 +26,9 @@ const EXCEPTIONS = { "Search-as-you-type filtering and draft-aware sidebar highlight logic.", }, "src/app/AppShell.tsx": { - limit: 650, + limit: 660, justification: - "Shell still coordinates ACP session loading, replay-buffer cleanup on load failure, project reassignment, and app-level chat routing.", + "Shell still coordinates ACP session loading, replay-buffer cleanup on load failure, project reassignment, and app-level chat routing. Includes gated [perf:load]/[perf:newtab] logging via perfLog (dev-only by default).", }, "src/features/chat/stores/__tests__/chatSessionStore.test.ts": { limit: 540, diff --git a/ui/goose2/src/app/AppShell.tsx b/ui/goose2/src/app/AppShell.tsx index f2564195..a38dde0b 100644 --- a/ui/goose2/src/app/AppShell.tsx +++ b/ui/goose2/src/app/AppShell.tsx @@ -22,6 +22,7 @@ import { getAndDeleteReplayBuffer, } from "@/features/chat/hooks/replayBuffer"; import { resolveSessionCwd } from "@/features/projects/lib/sessionCwdSelection"; +import { perfLog } from "@/shared/lib/perfLog"; export type AppView = | "home" @@ -65,43 +66,43 @@ export function AppShell({ children }: { children?: React.ReactNode }) { ); const loadSessionMessages = useCallback(async (sessionId: string) => { - const existing = useChatStore.getState().messagesBySession[sessionId]; - if (existing && existing.length > 0) { - console.log( - `[perf:load] ${sessionId.slice(0, 8)} skip — already has messages`, - ); + const sid = sessionId.slice(0, 8); + const existingMsgs = useChatStore.getState().messagesBySession[sessionId]; + if ((existingMsgs?.length ?? 0) > 0) { + perfLog(`[perf:load] ${sid} skip — has messages`); return; } - const t0 = performance.now(); - console.log(`[perf:load] ${sessionId.slice(0, 8)} start`); - const store = useChatStore.getState(); - store.setSessionLoading(sessionId, true); + perfLog(`[perf:load] ${sid} start`); + useChatStore.getState().setSessionLoading(sessionId, true); try { + const [{ acpLoadSession }, { getReplayPerf, clearReplayPerf }] = + await Promise.all([ + import("@/shared/api/acp"), + import("@/shared/api/acpNotificationHandler"), + ]); const t1 = performance.now(); - const { acpLoadSession } = await import("@/shared/api/acp"); - const t2 = performance.now(); - console.log( - `[perf:load] ${sessionId.slice(0, 8)} import took ${(t2 - t1).toFixed(1)}ms`, - ); + perfLog(`[perf:load] ${sid} import in ${(t1 - t0).toFixed(1)}ms`); const session = useChatSessionStore.getState().getSession(sessionId); const gooseSessionId = session?.acpSessionId ?? sessionId; const project = session?.projectId ? (useProjectStore .getState() - .projects.find((candidate) => candidate.id === session.projectId) ?? - null) + .projects.find((p) => p.id === session.projectId) ?? null) : null; const workingDir = await resolveSessionCwd(project); await acpLoadSession(sessionId, gooseSessionId, workingDir); + const tFlush = performance.now(); useChatStore.getState().setSessionLoading(sessionId, false); const buffer = getAndDeleteReplayBuffer(sessionId); + const replayStats = getReplayPerf(sessionId); + clearReplayPerf(sessionId); if (buffer && buffer.length > 0) { useChatStore.getState().setMessages(sessionId, buffer); } - const t3 = performance.now(); - console.log( - `[perf:load] ${sessionId.slice(0, 8)} acpLoadSession resolved in ${(t3 - t2).toFixed(1)}ms (total ${(t3 - t0).toFixed(1)}ms)`, + const t2 = performance.now(); + perfLog( + `[perf:load] ${sid} replay: notifs=${replayStats?.count ?? 0} span=${replayStats?.spanMs.toFixed(1) ?? "0"}ms msgs=${buffer?.length ?? 0} flush=${(t2 - tFlush).toFixed(1)}ms total=${(t2 - t0).toFixed(1)}ms`, ); } catch (err) { console.error("Failed to load session messages:", err); @@ -160,6 +161,10 @@ export function AppShell({ children }: { children?: React.ReactNode }) { const createNewTab = useCallback( (title = DEFAULT_CHAT_TITLE, project?: ProjectInfo) => { + const tStart = performance.now(); + perfLog( + `[perf:newtab] createNewTab start (project=${project?.id ?? "none"})`, + ); const agentId = agentStore.activeAgentId ?? undefined; const providerId = project?.preferredProvider ?? homeSelectedProvider; const personaId = homeSelectedPersonaId; @@ -186,11 +191,12 @@ export function AppShell({ children }: { children?: React.ReactNode }) { sessionState.setActiveSession(existingDraft.id); setActiveView("chat"); chatStore.setActiveSession(existingDraft.id); + perfLog( + `[perf:newtab] ${existingDraft.id.slice(0, 8)} reused draft in ${(performance.now() - tStart).toFixed(1)}ms`, + ); return existingDraft; } - cleanupEmptyDraft(sessionState.activeSessionId); - const session = sessionStore.createDraftSession({ title, projectId: project?.id, @@ -198,11 +204,12 @@ export function AppShell({ children }: { children?: React.ReactNode }) { providerId, personaId, }); - sessionStore.setActiveSession(session.id); setActiveView("chat"); chatStore.setActiveSession(session.id); - + perfLog( + `[perf:newtab] ${session.id.slice(0, 8)} created draft in ${(performance.now() - tStart).toFixed(1)}ms`, + ); return session; }, [ diff --git a/ui/goose2/src/app/hooks/useAppStartup.ts b/ui/goose2/src/app/hooks/useAppStartup.ts index 06227154..fb5da2b8 100644 --- a/ui/goose2/src/app/hooks/useAppStartup.ts +++ b/ui/goose2/src/app/hooks/useAppStartup.ts @@ -3,24 +3,35 @@ import { useAgentStore } from "@/features/agents/stores/agentStore"; import { useChatSessionStore } from "@/features/chat/stores/chatSessionStore"; import { setNotificationHandler, getClient } from "@/shared/api/acpConnection"; import notificationHandler from "@/shared/api/acpNotificationHandler"; +import { perfLog } from "@/shared/lib/perfLog"; export function useAppStartup() { useEffect(() => { (async () => { + const tStartup = performance.now(); + perfLog("[perf:startup] useAppStartup begin"); try { + const tConn = performance.now(); setNotificationHandler(notificationHandler); await getClient(); + perfLog( + `[perf:startup] ACP getClient ready in ${(performance.now() - tConn).toFixed(1)}ms`, + ); } catch (err) { console.error("Failed to initialize ACP connection:", err); } const store = useAgentStore.getState(); const loadPersonas = async () => { + const t0 = performance.now(); store.setPersonasLoading(true); try { const { listPersonas } = await import("@/shared/api/agents"); const personas = await listPersonas(); store.setPersonas(personas); + perfLog( + `[perf:startup] loadPersonas done in ${(performance.now() - t0).toFixed(1)}ms (n=${personas.length})`, + ); } catch (err) { console.error("Failed to load personas on startup:", err); } finally { @@ -29,11 +40,15 @@ export function useAppStartup() { }; const loadProviders = async () => { + const t0 = performance.now(); store.setProvidersLoading(true); try { const { discoverAcpProviders } = await import("@/shared/api/acp"); const providers = await discoverAcpProviders(); store.setProviders(providers); + perfLog( + `[perf:startup] loadProviders done in ${(performance.now() - t0).toFixed(1)}ms (n=${providers.length})`, + ); } catch (err) { console.error("Failed to load ACP providers on startup:", err); } finally { @@ -43,11 +58,11 @@ export function useAppStartup() { const loadSessionState = async () => { const t0 = performance.now(); - console.log("[perf:startup] loadSessionState start"); + perfLog("[perf:startup] loadSessionState start"); const { loadSessions, setActiveSession } = useChatSessionStore.getState(); await loadSessions(); - console.log( + perfLog( `[perf:startup] loadSessions done in ${(performance.now() - t0).toFixed(1)}ms`, ); setActiveSession(null); @@ -58,6 +73,9 @@ export function useAppStartup() { loadProviders(), loadSessionState(), ]); + perfLog( + `[perf:startup] useAppStartup complete in ${(performance.now() - tStartup).toFixed(1)}ms`, + ); })(); }, []); } diff --git a/ui/goose2/src/features/chat/hooks/useChat.ts b/ui/goose2/src/features/chat/hooks/useChat.ts index 6f7868d6..3f16395a 100644 --- a/ui/goose2/src/features/chat/hooks/useChat.ts +++ b/ui/goose2/src/features/chat/hooks/useChat.ts @@ -19,6 +19,7 @@ import { isDefaultChatTitle, } from "../lib/sessionTitle"; import { findLastIndex } from "@/shared/lib/arrays"; +import { perfLog } from "@/shared/lib/perfLog"; import { buildAcpImages, buildAttachmentPromptPreamble, @@ -129,6 +130,8 @@ export function useChat( overridePersona?: { id: string; name?: string }, attachments?: ChatAttachmentDraft[], ) => { + const sid = sessionId.slice(0, 8); + const tSendStart = performance.now(); const images = buildAcpImages(attachments); const hasAttachments = (attachments?.length ?? 0) > 0; if ( @@ -137,6 +140,9 @@ export function useChat( chatState === "thinking" ) return; + perfLog( + `[perf:send] ${sid} useChat.sendMessage start (textLen=${text.length}, attachments=${attachments?.length ?? 0})`, + ); const effectivePersonaInfo = resolvePersonaInfo( overridePersona?.id, @@ -222,11 +228,19 @@ export function useChat( if (!workingDir) { throw new Error("Missing session working directory"); } + const tPrep = performance.now(); await acpPrepareSession(sessionId, providerId, workingDir, { personaId: effectivePersonaInfo?.id, }); + perfLog( + `[perf:send] ${sid} acpPrepareSession in ${(performance.now() - tPrep).toFixed(1)}ms (wasDraft=${wasDraft})`, + ); if (selectedModelId) { + const tModel = performance.now(); await acpSetModel(sessionId, selectedModelId); + perfLog( + `[perf:send] ${sid} acpSetModel(${selectedModelId}) in ${(performance.now() - tModel).toFixed(1)}ms`, + ); } } @@ -237,6 +251,10 @@ export function useChat( buildAttachmentPromptPreamble(attachments); const promptBody = text.trim() || (images?.length ? " " : text); const acpPrompt = `${attachmentPromptPreamble}${promptBody}`; + const tAcp = performance.now(); + perfLog( + `[perf:send] ${sid} → acpSendMessage (setup took ${(tAcp - tSendStart).toFixed(1)}ms)`, + ); await acpSendMessage(sessionId, acpPrompt, { systemPrompt, personaId: effectivePersonaInfo?.id, @@ -245,6 +263,9 @@ export function useChat( (img) => [img.base64, img.mimeType] as [string, string], ), }); + perfLog( + `[perf:send] ${sid} acpSendMessage returned after ${(performance.now() - tAcp).toFixed(1)}ms (total sendMessage ${(performance.now() - tSendStart).toFixed(1)}ms)`, + ); store.setChatState(sessionId, "idle"); store.setStreamingMessageId(sessionId, null); diff --git a/ui/goose2/src/features/chat/ui/ChatView.tsx b/ui/goose2/src/features/chat/ui/ChatView.tsx index 495f757b..f71313a3 100644 --- a/ui/goose2/src/features/chat/ui/ChatView.tsx +++ b/ui/goose2/src/features/chat/ui/ChatView.tsx @@ -25,6 +25,7 @@ import { resolveSessionCwd } from "@/features/projects/lib/sessionCwdSelection"; import { ArtifactPolicyProvider } from "../hooks/ArtifactPolicyContext"; import type { ModelOption } from "../types"; import { ChatContextPanel } from "./ChatContextPanel"; +import { perfLog } from "@/shared/lib/perfLog"; const EMPTY_MODELS: ModelOption[] = []; @@ -51,6 +52,12 @@ export function ChatView({ }: ChatViewProps) { const { t } = useTranslation("chat"); const activeSessionId = sessionId; + const mountStart = useRef(performance.now()); + // biome-ignore lint/correctness/useExhaustiveDependencies: log once on mount per session + useEffect(() => { + const ms = (performance.now() - mountStart.current).toFixed(1); + perfLog(`[perf:chatview] ${sessionId.slice(0, 8)} mounted in ${ms}ms`); + }, [sessionId]); const isContextPanelOpen = useChatSessionStore( (s) => s.contextPanelOpenBySession[activeSessionId] ?? false, ); diff --git a/ui/goose2/src/shared/api/acp.ts b/ui/goose2/src/shared/api/acp.ts index 10d17c0f..85fa8dd5 100644 --- a/ui/goose2/src/shared/api/acp.ts +++ b/ui/goose2/src/shared/api/acp.ts @@ -6,6 +6,7 @@ import { clearActiveMessageId, } from "./acpNotificationHandler"; import { searchSessionsViaExports } from "./sessionSearch"; +import { perfLog } from "@/shared/lib/perfLog"; export interface AcpProvider { id: string; @@ -36,6 +37,8 @@ export async function acpSendMessage( options: AcpSendMessageOptions = {}, ): Promise { const { systemPrompt, personaId, images } = options; + const sid = sessionId.slice(0, 8); + const tStart = performance.now(); const gooseSessionId = sessionTracker.getGooseSessionId(sessionId, personaId); if (!gooseSessionId) { @@ -57,7 +60,15 @@ export async function acpSendMessage( const messageId = crypto.randomUUID(); setActiveMessageId(gooseSessionId, messageId); + perfLog( + `[perf:send] ${sid} acpSendMessage → prompt(len=${prompt.length}, imgs=${images?.length ?? 0})`, + ); + const tPrompt = performance.now(); await directAcp.prompt(gooseSessionId, content); + const tDone = performance.now(); + perfLog( + `[perf:send] ${sid} prompt() resolved in ${(tDone - tPrompt).toFixed(1)}ms (total acpSendMessage ${(tDone - tStart).toFixed(1)}ms)`, + ); clearActiveMessageId(gooseSessionId); } @@ -69,12 +80,20 @@ export async function acpPrepareSession( workingDir: string, options: AcpPrepareSessionOptions = {}, ): Promise { + const sid = sessionId.slice(0, 8); + const t0 = performance.now(); + perfLog( + `[perf:prepare] ${sid} acpPrepareSession start (provider=${providerId})`, + ); await sessionTracker.prepareSession( sessionId, providerId, workingDir, options.personaId, ); + perfLog( + `[perf:prepare] ${sid} acpPrepareSession done in ${(performance.now() - t0).toFixed(1)}ms`, + ); } export async function acpSetModel( @@ -125,7 +144,13 @@ export async function acpLoadSession( workingDir?: string, ): Promise { const effectiveWorkingDir = workingDir ?? "~/.goose/artifacts"; + const sid = sessionId.slice(0, 8); + const t0 = performance.now(); + perfLog(`[perf:load] ${sid} acpLoadSession → client.loadSession`); await directAcp.loadSession(gooseSessionId, effectiveWorkingDir); + perfLog( + `[perf:load] ${sid} client.loadSession resolved in ${(performance.now() - t0).toFixed(1)}ms`, + ); sessionTracker.registerSession( sessionId, gooseSessionId, diff --git a/ui/goose2/src/shared/api/acpApi.ts b/ui/goose2/src/shared/api/acpApi.ts index b992c1be..015e7be1 100644 --- a/ui/goose2/src/shared/api/acpApi.ts +++ b/ui/goose2/src/shared/api/acpApi.ts @@ -5,6 +5,7 @@ import type { PromptResponse, } from "@agentclientprotocol/sdk"; import { getClient } from "./acpConnection"; +import { perfLog } from "@/shared/lib/perfLog"; export interface AcpProvider { id: string; @@ -84,24 +85,36 @@ export async function setModel( sessionId: string, modelId: string, ): Promise { + const sid = sessionId.slice(0, 8); + const tClient = performance.now(); const client = await getClient(); + const tCall = performance.now(); await client.setSessionConfigOption({ sessionId, configId: "model", value: modelId, }); + perfLog( + `[perf:api] ${sid} setModel(${modelId}) getClient=${(tCall - tClient).toFixed(1)}ms wire=${(performance.now() - tCall).toFixed(1)}ms`, + ); } export async function setProvider( sessionId: string, providerId: string, ): Promise { + const sid = sessionId.slice(0, 8); + const tClient = performance.now(); const client = await getClient(); + const tCall = performance.now(); await client.setSessionConfigOption({ sessionId, configId: "provider", value: providerId, }); + perfLog( + `[perf:api] ${sid} setProvider(${providerId}) getClient=${(tCall - tClient).toFixed(1)}ms wire=${(performance.now() - tCall).toFixed(1)}ms`, + ); } export async function updateWorkingDir( @@ -120,16 +133,34 @@ export async function cancelSession(sessionId: string): Promise { export async function newSession( workingDir: string, ): Promise { + const tClient = performance.now(); const client = await getClient(); - return client.newSession({ cwd: workingDir, mcpServers: [] }); + const tCall = performance.now(); + const response = await client.newSession({ cwd: workingDir, mcpServers: [] }); + const sid = response.sessionId.slice(0, 8); + perfLog( + `[perf:api] ${sid} newSession getClient=${(tCall - tClient).toFixed(1)}ms wire=${(performance.now() - tCall).toFixed(1)}ms`, + ); + return response; } export async function loadSession( sessionId: string, workingDir: string, ): Promise { + const sid = sessionId.slice(0, 8); + const tClient = performance.now(); const client = await getClient(); - return client.loadSession({ sessionId, cwd: workingDir, mcpServers: [] }); + const tCall = performance.now(); + const response = await client.loadSession({ + sessionId, + cwd: workingDir, + mcpServers: [], + }); + perfLog( + `[perf:api] ${sid} loadSession getClient=${(tCall - tClient).toFixed(1)}ms wire=${(performance.now() - tCall).toFixed(1)}ms`, + ); + return response; } export async function prompt( diff --git a/ui/goose2/src/shared/api/acpConnection.ts b/ui/goose2/src/shared/api/acpConnection.ts index cac618b2..5a369d3d 100644 --- a/ui/goose2/src/shared/api/acpConnection.ts +++ b/ui/goose2/src/shared/api/acpConnection.ts @@ -8,6 +8,7 @@ import { type RequestPermissionResponse, } from "@agentclientprotocol/sdk"; import { createWebSocketStream } from "./createWebSocketStream"; +import { perfLog } from "@/shared/lib/perfLog"; let notificationHandler: AcpNotificationHandler | null = null; @@ -63,12 +64,21 @@ function monitorConnection(client: GooseClient): void { } async function initializeConnection(): Promise { + const tStart = performance.now(); const wsUrl: string = await invoke("get_goose_serve_url"); + perfLog( + `[perf:conn] get_goose_serve_url in ${(performance.now() - tStart).toFixed(1)}ms`, + ); + const tStream = performance.now(); const stream = createWebSocketStream(wsUrl); const client = new GooseClient(createClientCallbacks(), stream); + perfLog( + `[perf:conn] ws stream + client created in ${(performance.now() - tStream).toFixed(1)}ms`, + ); + const tInit = performance.now(); await client.initialize({ protocolVersion: PROTOCOL_VERSION, clientCapabilities: {}, @@ -77,6 +87,9 @@ async function initializeConnection(): Promise { version: "0.1.0", }, }); + perfLog( + `[perf:conn] client.initialize in ${(performance.now() - tInit).toFixed(1)}ms (total ${(performance.now() - tStart).toFixed(1)}ms)`, + ); monitorConnection(client); @@ -89,6 +102,7 @@ export async function getClient(): Promise { } if (!clientPromise) { + perfLog("[perf:conn] getClient() → initializing new ACP connection"); clientPromise = initializeConnection() .then((client) => { resolvedClient = client; @@ -98,6 +112,8 @@ export async function getClient(): Promise { clientPromise = null; throw error; }); + } else { + perfLog("[perf:conn] getClient() awaiting in-flight initializeConnection"); } return clientPromise; diff --git a/ui/goose2/src/shared/api/acpNotificationHandler.ts b/ui/goose2/src/shared/api/acpNotificationHandler.ts index cc215613..b0d8d8a5 100644 --- a/ui/goose2/src/shared/api/acpNotificationHandler.ts +++ b/ui/goose2/src/shared/api/acpNotificationHandler.ts @@ -15,19 +15,52 @@ import type { } from "@/shared/types/messages"; import type { AcpNotificationHandler } from "./acpConnection"; import { getLocalSessionId } from "./acpSessionTracker"; +import { perfLog } from "@/shared/lib/perfLog"; // Pre-set message ID for the next live stream per goose session const presetMessageIds = new Map(); +// Per-session perf counters for replay/live streaming. +interface ReplayPerf { + firstAt: number; + lastAt: number; + count: number; +} +const replayPerf = new Map(); +interface LivePerf { + sendStartedAt: number; + firstChunkAt: number | null; + chunkCount: number; +} +const livePerf = new Map(); + export function setActiveMessageId( gooseSessionId: string, messageId: string, ): void { presetMessageIds.set(gooseSessionId, messageId); + livePerf.set(gooseSessionId, { + sendStartedAt: performance.now(), + firstChunkAt: null, + chunkCount: 0, + }); } export function clearActiveMessageId(gooseSessionId: string): void { presetMessageIds.delete(gooseSessionId); + const perf = livePerf.get(gooseSessionId); + if (perf) { + const sid = gooseSessionId.slice(0, 8); + const total = performance.now() - perf.sendStartedAt; + const ttft = + perf.firstChunkAt !== null + ? (perf.firstChunkAt - perf.sendStartedAt).toFixed(1) + : "n/a"; + perfLog( + `[perf:stream] ${sid} stream ended — ttft=${ttft}ms total=${total.toFixed(1)}ms chunks=${perf.chunkCount}`, + ); + livePerf.delete(gooseSessionId); + } } export async function handleSessionNotification( @@ -39,12 +72,45 @@ export async function handleSessionNotification( const isReplay = useChatStore.getState().loadingSessionIds.has(sessionId); if (isReplay) { + const sid = sessionId.slice(0, 8); + let perf = replayPerf.get(sessionId); + const now = performance.now(); + if (!perf) { + perf = { firstAt: now, lastAt: now, count: 0 }; + replayPerf.set(sessionId, perf); + perfLog(`[perf:replay] ${sid} first notification received`); + } + perf.lastAt = now; + perf.count += 1; handleReplay(sessionId, update); } else { + const perf = livePerf.get(gooseSessionId); + if (perf && update.sessionUpdate === "agent_message_chunk") { + perf.chunkCount += 1; + if (perf.firstChunkAt === null) { + perf.firstChunkAt = performance.now(); + const sid = gooseSessionId.slice(0, 8); + perfLog( + `[perf:stream] ${sid} first agent_message_chunk at ttft=${(perf.firstChunkAt - perf.sendStartedAt).toFixed(1)}ms`, + ); + } + } handleLive(sessionId, gooseSessionId, update); } } +export function getReplayPerf( + sessionId: string, +): { count: number; spanMs: number } | null { + const perf = replayPerf.get(sessionId); + if (!perf) return null; + return { count: perf.count, spanMs: perf.lastAt - perf.firstAt }; +} + +export function clearReplayPerf(sessionId: string): void { + replayPerf.delete(sessionId); +} + function handleReplay(sessionId: string, update: SessionUpdate): void { switch (update.sessionUpdate) { case "agent_message_chunk": { diff --git a/ui/goose2/src/shared/api/acpSessionTracker.ts b/ui/goose2/src/shared/api/acpSessionTracker.ts index 78310ebb..835bcc19 100644 --- a/ui/goose2/src/shared/api/acpSessionTracker.ts +++ b/ui/goose2/src/shared/api/acpSessionTracker.ts @@ -1,4 +1,5 @@ import * as acpApi from "./acpApi"; +import { perfLog } from "@/shared/lib/perfLog"; interface PreparedSession { gooseSessionId: string; @@ -22,34 +23,63 @@ export async function prepareSession( workingDir: string, personaId?: string, ): Promise { + const sid = sessionId.slice(0, 8); const key = makeKey(sessionId, personaId); const existing = prepared.get(key) ?? prepared.get(sessionId); if (existing) { + const tReuse = performance.now(); + let changed = false; if (existing.workingDir !== workingDir) { await acpApi.updateWorkingDir(existing.gooseSessionId, workingDir); existing.workingDir = workingDir; + changed = true; } if (existing.providerId !== providerId) { + const tProv = performance.now(); await acpApi.setProvider(existing.gooseSessionId, providerId); + perfLog( + `[perf:prepare] ${sid} reuse setProvider(${providerId}) in ${(performance.now() - tProv).toFixed(1)}ms (goose_sid=${existing.gooseSessionId.slice(0, 8)})`, + ); existing.providerId = providerId; + changed = true; } + perfLog( + `[perf:prepare] ${sid} reuse existing session (updates=${changed}) in ${(performance.now() - tReuse).toFixed(1)}ms`, + ); return existing.gooseSessionId; } let gooseSessionId: string | null = null; + const tLoad = performance.now(); try { await acpApi.loadSession(sessionId, workingDir); gooseSessionId = sessionId; - } catch {} - - if (!gooseSessionId) { - const response = await acpApi.newSession(workingDir); - gooseSessionId = response.sessionId; + perfLog( + `[perf:prepare] ${sid} tracker loadSession ok in ${(performance.now() - tLoad).toFixed(1)}ms`, + ); + } catch { + perfLog( + `[perf:prepare] ${sid} tracker loadSession failed in ${(performance.now() - tLoad).toFixed(1)}ms → newSession`, + ); } + if (!gooseSessionId) { + const tNew = performance.now(); + const response = await acpApi.newSession(workingDir); + gooseSessionId = response.sessionId; + perfLog( + `[perf:prepare] ${sid} tracker newSession done in ${(performance.now() - tNew).toFixed(1)}ms (goose_sid=${gooseSessionId.slice(0, 8)})`, + ); + } + + const gooseSid = gooseSessionId.slice(0, 8); + const tProv = performance.now(); await acpApi.setProvider(gooseSessionId, providerId); + perfLog( + `[perf:prepare] ${sid} tracker setProvider(${providerId}) in ${(performance.now() - tProv).toFixed(1)}ms (goose_sid=${gooseSid})`, + ); prepared.set(key, { gooseSessionId, providerId, workingDir }); prepared.set(sessionId, { gooseSessionId, providerId, workingDir }); diff --git a/ui/goose2/src/shared/lib/perfLog.ts b/ui/goose2/src/shared/lib/perfLog.ts new file mode 100644 index 00000000..5bfaa811 --- /dev/null +++ b/ui/goose2/src/shared/lib/perfLog.ts @@ -0,0 +1,39 @@ +/** + * Gated performance logger for frontend timing instrumentation. + * + * Enabled when any of the following is true: + * - Running under Vite dev (`import.meta.env.DEV`) + * - `localStorage.getItem("goose.perf") === "1"` + * + * Otherwise a no-op, so perf call sites add zero runtime cost in release + * builds for users who have not opted in. + * + * Messages are prefixed with `[perf:]` by callers; this helper + * is intentionally dumb and forwards the already-formatted string. + */ +function isEnabled(): boolean { + try { + if (import.meta.env?.DEV) return true; + } catch { + // import.meta may be unavailable in some test contexts + } + try { + if ( + typeof localStorage !== "undefined" && + localStorage.getItem("goose.perf") === "1" + ) { + return true; + } + } catch { + // localStorage can throw in restricted contexts + } + return false; +} + +const enabled = isEnabled(); + +export function perfLog(message: string): void { + if (!enabled) return; + // eslint-disable-next-line no-console + console.log(message); +} diff --git a/ui/sdk/src/generated/client.gen.ts b/ui/sdk/src/generated/client.gen.ts index 69324605..3bd1e0d1 100644 --- a/ui/sdk/src/generated/client.gen.ts +++ b/ui/sdk/src/generated/client.gen.ts @@ -37,8 +37,6 @@ import type { RemoveExtensionRequest, RemoveSecretRequest, UnarchiveSessionRequest, - UpdateProviderRequest, - UpdateProviderResponse, UpdateWorkingDirRequest, UpsertConfigRequest, UpsertSecretRequest, @@ -55,7 +53,6 @@ import { zListProvidersResponse, zReadConfigResponse, zReadResourceResponse, - zUpdateProviderResponse, } from './zod.gen.js'; export class GooseExtClient { @@ -105,16 +102,6 @@ export class GooseExtClient { ) as GetSessionExtensionsResponse; } - async GooseSessionProviderUpdate( - params: UpdateProviderRequest, - ): Promise { - const raw = await this.conn.extMethod( - "_goose/session/provider/update", - params, - ); - return zUpdateProviderResponse.parse(raw) as UpdateProviderResponse; - } - async GooseProvidersList( params: ListProvidersRequest, ): Promise { diff --git a/ui/sdk/src/generated/index.ts b/ui/sdk/src/generated/index.ts index f9190a09..aa103a43 100644 --- a/ui/sdk/src/generated/index.ts +++ b/ui/sdk/src/generated/index.ts @@ -1,6 +1,6 @@ // This file is auto-generated by @hey-api/openapi-ts -export type { AddExtensionRequest, ArchiveSessionRequest, CheckSecretRequest, CheckSecretResponse, DeleteSessionRequest, EmptyResponse, ExportSessionRequest, ExportSessionResponse, ExtRequest, ExtResponse, GetExtensionsRequest, GetExtensionsResponse, GetProviderDetailsRequest, GetProviderDetailsResponse, GetProviderModelsRequest, GetProviderModelsResponse, GetSessionExtensionsRequest, GetSessionExtensionsResponse, GetToolsRequest, GetToolsResponse, ImportSessionRequest, ImportSessionResponse, ListProvidersRequest, ListProvidersResponse, ModelEntry, ProviderConfigKey, ProviderDetailEntry, ProviderListEntry, ReadConfigRequest, ReadConfigResponse, ReadResourceRequest, ReadResourceResponse, RemoveConfigRequest, RemoveExtensionRequest, RemoveSecretRequest, UnarchiveSessionRequest, UpdateProviderRequest, UpdateProviderResponse, UpdateWorkingDirRequest, UpsertConfigRequest, UpsertSecretRequest } from './types.gen.js'; +export type { AddExtensionRequest, ArchiveSessionRequest, CheckSecretRequest, CheckSecretResponse, DeleteSessionRequest, EmptyResponse, ExportSessionRequest, ExportSessionResponse, ExtRequest, ExtResponse, GetExtensionsRequest, GetExtensionsResponse, GetProviderDetailsRequest, GetProviderDetailsResponse, GetProviderModelsRequest, GetProviderModelsResponse, GetSessionExtensionsRequest, GetSessionExtensionsResponse, GetToolsRequest, GetToolsResponse, ImportSessionRequest, ImportSessionResponse, ListProvidersRequest, ListProvidersResponse, ModelEntry, ProviderConfigKey, ProviderDetailEntry, ProviderListEntry, ReadConfigRequest, ReadConfigResponse, ReadResourceRequest, ReadResourceResponse, RemoveConfigRequest, RemoveExtensionRequest, RemoveSecretRequest, UnarchiveSessionRequest, UpdateWorkingDirRequest, UpsertConfigRequest, UpsertSecretRequest } from './types.gen.js'; export const GOOSE_EXT_METHODS = [ { @@ -43,11 +43,6 @@ export const GOOSE_EXT_METHODS = [ requestType: "GetSessionExtensionsRequest", responseType: "GetSessionExtensionsResponse", }, - { - method: "_goose/session/provider/update", - requestType: "UpdateProviderRequest", - responseType: "UpdateProviderResponse", - }, { method: "_goose/providers/list", requestType: "ListProvidersRequest", diff --git a/ui/sdk/src/generated/types.gen.ts b/ui/sdk/src/generated/types.gen.ts index b89b8ced..e2716083 100644 --- a/ui/sdk/src/generated/types.gen.ts +++ b/ui/sdk/src/generated/types.gen.ts @@ -104,29 +104,6 @@ export type GetSessionExtensionsResponse = { extensions: Array; }; -/** - * Atomically update the provider for a live session. - */ -export type UpdateProviderRequest = { - sessionId: string; - provider: string; - model?: string | null; - contextLimit?: number | null; - requestParams?: { - [key: string]: unknown; - } | null; -}; - -/** - * Provider update response. - */ -export type UpdateProviderResponse = { - /** - * Refreshed session config options after the provider/model change. - */ - configOptions: Array; -}; - /** * List providers available through goose, including the config-default sentinel. */ @@ -307,14 +284,14 @@ export type UnarchiveSessionRequest = { export type ExtRequest = { id: string; method: string; - params?: AddExtensionRequest | RemoveExtensionRequest | GetToolsRequest | ReadResourceRequest | UpdateWorkingDirRequest | DeleteSessionRequest | GetExtensionsRequest | GetSessionExtensionsRequest | UpdateProviderRequest | ListProvidersRequest | GetProviderDetailsRequest | GetProviderModelsRequest | ReadConfigRequest | UpsertConfigRequest | RemoveConfigRequest | CheckSecretRequest | UpsertSecretRequest | RemoveSecretRequest | ExportSessionRequest | ImportSessionRequest | ArchiveSessionRequest | UnarchiveSessionRequest | { + params?: AddExtensionRequest | RemoveExtensionRequest | GetToolsRequest | ReadResourceRequest | UpdateWorkingDirRequest | DeleteSessionRequest | GetExtensionsRequest | GetSessionExtensionsRequest | ListProvidersRequest | GetProviderDetailsRequest | GetProviderModelsRequest | ReadConfigRequest | UpsertConfigRequest | RemoveConfigRequest | CheckSecretRequest | UpsertSecretRequest | RemoveSecretRequest | ExportSessionRequest | ImportSessionRequest | ArchiveSessionRequest | UnarchiveSessionRequest | { [key: string]: unknown; } | null; }; export type ExtResponse = { id: string; - result?: EmptyResponse | GetToolsResponse | ReadResourceResponse | GetExtensionsResponse | GetSessionExtensionsResponse | UpdateProviderResponse | ListProvidersResponse | GetProviderDetailsResponse | GetProviderModelsResponse | ReadConfigResponse | CheckSecretResponse | ExportSessionResponse | ImportSessionResponse | unknown; + result?: EmptyResponse | GetToolsResponse | ReadResourceResponse | GetExtensionsResponse | GetSessionExtensionsResponse | ListProvidersResponse | GetProviderDetailsResponse | GetProviderModelsResponse | ReadConfigResponse | CheckSecretResponse | ExportSessionResponse | ImportSessionResponse | unknown; } | { error: { code: number; diff --git a/ui/sdk/src/generated/zod.gen.ts b/ui/sdk/src/generated/zod.gen.ts index 2bf62f02..1679d0ae 100644 --- a/ui/sdk/src/generated/zod.gen.ts +++ b/ui/sdk/src/generated/zod.gen.ts @@ -89,33 +89,6 @@ export const zGetSessionExtensionsResponse = z.object({ extensions: z.array(z.unknown()) }); -/** - * Atomically update the provider for a live session. - */ -export const zUpdateProviderRequest = z.object({ - sessionId: z.string(), - provider: z.string(), - model: z.union([ - z.string(), - z.null() - ]).optional(), - contextLimit: z.union([ - z.number().int().gte(0), - z.null() - ]).optional(), - requestParams: z.union([ - z.record(z.unknown()), - z.null() - ]).optional() -}); - -/** - * Provider update response. - */ -export const zUpdateProviderResponse = z.object({ - configOptions: z.array(z.unknown()) -}); - /** * List providers available through goose, including the config-default sentinel. */ @@ -311,7 +284,6 @@ export const zExtRequest = z.object({ zDeleteSessionRequest, zGetExtensionsRequest, zGetSessionExtensionsRequest, - zUpdateProviderRequest, zListProvidersRequest, zGetProviderDetailsRequest, zGetProviderModelsRequest, @@ -343,7 +315,6 @@ export const zExtResponse = z.union([ zReadResourceResponse, zGetExtensionsResponse, zGetSessionExtensionsResponse, - zUpdateProviderResponse, zListProvidersResponse, zGetProviderDetailsResponse, zGetProviderModelsResponse,