tkmind/tkmind_go
1
0
Fork 0
Code Issues Pull Requests Actions 4 Packages Projects Releases Wiki Activity

perf: gate perf logs and dedup build_config_update on first message (#8627)

Browse Source 
Signed-off-by: Bradley Axen <baxen@squareup.com>
This commit is contained in:
Bradley Axen
2026-04-17 12:43:36 -07:00
committed by GitHub
parent 7fa662bcac
commit 8a51e34891
22 changed files with 544 additions and 285 deletions
Download Patch File Download Diff File Expand all files Collapse all files
crates/goose-acp/acp-meta.json
-5
View File
@@ -40,11 +40,6 @@
"requestType": "GetSessionExtensionsRequest",
"responseType": "GetSessionExtensionsResponse"
},
{
"method": "_goose/session/provider/update",
"requestType": "UpdateProviderRequest",
"responseType": "UpdateProviderResponse"
},
{
"method": "_goose/providers/list",
"requestType": "ListProvidersRequest",
crates/goose-acp/acp-schema.json
-72
View File
@@ -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": [
{
crates/goose-acp/src/server.rs
+226 -36
View File
@@ -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:' <log> | grep 'sid=abc12345'`.
fn sid_short(id: &str) -> String {
id.chars().take(8).collect()
}
fn extract_timeout_from_meta(meta: &Option<Meta>) -> Option<u64> {
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::<Vec<_>>();
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<NewSessionResponse, sacp::Error> {
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::<String, goose::conversation::message::ToolRequest>::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<PromptResponse, sacp::Error> {
// 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<SetSessionModelResponse, sacp::Error> {
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<usize>,
request_params: Option<std::collections::HashMap<String, serde_json::Value>>,
) -> Result<Vec<SessionConfigOption>, 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<ListSessionsResponse, sacp::Error> {
@@ -2320,28 +2525,6 @@ impl GooseAcpAgent {
})
}
#[custom_method(UpdateProviderRequest)]
async fn on_update_provider(
&self,
req: UpdateProviderRequest,
) -> Result<UpdateProviderResponse, sacp::Error> {
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::<Result<Vec<_>, _>>()
.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<Client> 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<Client> 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(())
}
})
crates/goose-acp/tests/custom_requests_test.rs
+7 -40
View File
@@ -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");
});
}
crates/goose-sdk/src/custom_requests.rs
-21
View File
@@ -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<serde_json::Value>,
}
/// 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<String>,
pub context_limit: Option<usize>,
pub request_params: Option<HashMap<String, serde_json::Value>>,
}
/// 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<serde_json::Value>,
}
/// Read a single non-secret config value.
#[derive(Debug, Default, Clone, Serialize, Deserialize, JsonSchema, JsonRpcRequest)]
#[request(method = "_goose/config/read", response = ReadConfigResponse)]
ui/goose2/AGENTS.md
+6
View File
@@ -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:<channel>]` (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`.
ui/goose2/justfile
+6 -2
View File
@@ -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
ui/goose2/scripts/check-file-sizes.mjs
+4 -4
View File
@@ -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,
ui/goose2/src/app/AppShell.tsx
+30 -23
View File
@@ -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;
},
[
ui/goose2/src/app/hooks/useAppStartup.ts
+20 -2
View File
@@ -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`,
);
})();
}, []);
}
ui/goose2/src/features/chat/hooks/useChat.ts
+21
View File
@@ -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);
ui/goose2/src/features/chat/ui/ChatView.tsx
+7
View File
@@ -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,
);
ui/goose2/src/shared/api/acp.ts
+25
View File
@@ -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<void> {
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<void> {
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<void> {
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,
ui/goose2/src/shared/api/acpApi.ts
+33 -2
View File
@@ -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<void> {
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<void> {
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<void> {
export async function newSession(
workingDir: string,
): Promise<NewSessionResponse> {
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<LoadSessionResponse> {
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(
ui/goose2/src/shared/api/acpConnection.ts
+16
View File
@@ -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<GooseClient> {
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<GooseClient> {
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<GooseClient> {
}
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<GooseClient> {
clientPromise = null;
throw error;
});
} else {
perfLog("[perf:conn] getClient() awaiting in-flight initializeConnection");
}
return clientPromise;
ui/goose2/src/shared/api/acpNotificationHandler.ts
+66
View File
@@ -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<string, string>();
// Per-session perf counters for replay/live streaming.
interface ReplayPerf {
firstAt: number;
lastAt: number;
count: number;
}
const replayPerf = new Map<string, ReplayPerf>();
interface LivePerf {
sendStartedAt: number;
firstChunkAt: number | null;
chunkCount: number;
}
const livePerf = new Map<string, LivePerf>();
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": {
ui/goose2/src/shared/api/acpSessionTracker.ts
+35 -5
View File
@@ -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<string> {
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 });
ui/goose2/src/shared/lib/perfLog.ts
+39
View File
@@ -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:<channel>]` 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);
}
ui/sdk/src/generated/client.gen.ts
-13
View File
@@ -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<UpdateProviderResponse> {
const raw = await this.conn.extMethod(
"_goose/session/provider/update",
params,
);
return zUpdateProviderResponse.parse(raw) as UpdateProviderResponse;
}
async GooseProvidersList(
params: ListProvidersRequest,
): Promise<ListProvidersResponse> {
ui/sdk/src/generated/index.ts
+1 -6
View File
@@ -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",
ui/sdk/src/generated/types.gen.ts
+2 -25
View File
@@ -104,29 +104,6 @@ export type GetSessionExtensionsResponse = {
extensions: Array<unknown>;
};
/**
* 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<unknown>;
};
/**
* 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;
ui/sdk/src/generated/zod.gen.ts
-29
View File
@@ -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,