perf: gate perf logs and dedup build_config_update on first message#8627
perf: gate perf logs and dedup build_config_update on first message#8627
Conversation
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 3945362b11
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| Ok(_) => info!( | ||
| target: "perf", |
There was a problem hiding this comment.
This log site still uses info!(target: "perf", ...), so any runtime configured with RUST_LOG=info will emit high-volume perf traces from hot paths and defeat the intended "perf logs only when explicitly enabled" behavior. Converting perf-target instrumentation to debug! keeps normal info logging usable while preserving opt-in perf tracing via RUST_LOG=perf=debug,....
Useful? React with 👍 / 👎.
Backend (goose-acp): demote perf logs from info! to debug! with
target: "perf". Off by default; enable with RUST_LOG=perf=debug.
Frontend (goose2): add shared/lib/perfLog.ts which no-ops unless
Vite DEV or localStorage['goose.perf']='1'. Replace all bare
console.log('[perf:...') call sites with perfLog(...).
Dev ergonomics: just dev and just dev-debug export
RUST_LOG=perf=debug,info so the child goose serve emits perf
logs without extra setup. Documented the toggles in AGENTS.md
and refreshed the file-size justifications for AppShell and
ChatView to reflect the gated logging.
Signed-off-by: Bradley Axen <baxen@squareup.com>
The custom _goose/session/provider/update method duplicated the SACP 11
set_config_option path for config_id="provider". Having both meant:
1. Two separate wire entry points for the same operation.
2. The set_config_option handler called build_config_update twice
per request — once inside update_provider (which built and
discarded the Vec<SessionConfigOption>) and once in the handler
tail. On providers that refresh their model list over HTTP
(e.g. Databricks) each call costs ~1s, for ~2s of wasted work
per provider switch.
Nothing in this codebase calls the custom method; goose2 uses
set_config_option exclusively.
Changes:
- Remove UpdateProviderRequest/UpdateProviderResponse from goose-sdk.
- Remove on_update_provider from goose-acp server.
- Change internal update_provider helper to return () and stop
calling build_config_update at the end — the set_config_option
handler's single trailing build_config_update is now the only one.
- Rewrite test_provider_switching_updates_session_state to exercise
the set_config_option path three times instead of the removed
custom method.
- Regenerate acp-schema.json, acp-meta.json, and ui/sdk/src/generated.
Verified:
- cargo test -p goose-acp (35 passed)
- cargo clippy --all-targets -- -D warnings
- ui/goose2 pnpm typecheck
Signed-off-by: Bradley Axen <baxen@squareup.com>
baxen
force-pushed
the
baxen/first-message-perf
branch
from
3945362 to
f993a3f
Compare
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: f993a3f593
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| method: "_goose/providers/list", | ||
| requestType: "ListProvidersRequest", |
There was a problem hiding this comment.
This change removes the _goose/session/provider/update extension method from the generated SDK/protocol surface, but the text UI still calls client.goose.GooseSessionProviderUpdate(...) during provider/model apply (ui/text/src/configure.tsx:435). As soon as ui/text picks up this SDK/protocol revision, that onboarding/configure path will fail (missing client method or method-not-found from server), which blocks provider setup in the terminal product. Please keep a compatibility shim (or migrate ui/text in the same commit) before deleting this RPC.
Useful? React with 👍 / 👎.
| export RUST_LOG="${RUST_LOG:-perf=debug,info}" | ||
| PROJECT_DIR=$(pwd) | ||
| GOOSE_BIN="${PROJECT_DIR}/../../target/debug/goose" | ||
| export GOOSE_BIN |
There was a problem hiding this comment.
The dev-debug recipe now enables set -u but no longer sets VITE_PORT before using ${VITE_PORT} in EXTRA_CONFIG_ARGS, so the recipe exits early with an unbound-variable error instead of launching the app. This breaks a documented local workflow for anyone running just dev-debug; reintroduce VITE_PORT={{ vite_port }} (and export it) as done in dev.
Useful? React with 👍 / 👎.
2 participants
Two small wins for first-message latency, discovered while tracing the full lifecycle from "new tab" → first token.
1. Gate perf logs so they're off by default
Previously,
[perf:...]logs fired unconditionally on every session, both in the Rust backend (info!) and the goose2 frontend (console.log). Useful for debugging, noisy otherwise.info!(target: "perf", ...)→debug!(target: "perf", ...)(35 sites ingoose-acp/src/server.rs). Silent by default, on withRUST_LOG=perf=debug.console.log("[perf:...")call sites across 9 files replaced with a gatedperfLog()helper atsrc/shared/lib/perfLog.ts. Logs only whenimport.meta.env.DEVorlocalStorage['goose.perf'] === '1'.just devandjust dev-debugexportRUST_LOG=${RUST_LOG:-perf=debug,info}so local dev gets perf logs out of the box, overrideable.2. Remove redundant
build_config_updateonsetProviderWhile tracing the first-message path, I noticed
build_config_update— which does an HTTP GET to the Databricksserving-endpointsAPI — was being called twice perset_config_option("provider"):update_providerhelper (result discarded).The first call was only needed to populate the response of the now-unused
_goose/session/provider/updateACP custom method (on_update_provider). That method had no callers inside this repo, andset_config_optionis the standard replacement.Changes
UpdateProviderRequest/UpdateProviderResponsefromcrates/goose-sdk/src/custom_requests.rs.on_update_providerhandler and the_goose/session/provider/updatecustom method registration fromcrates/goose-acp/src/server.rs.update_providerhelper now returns()and no longer callsbuild_config_update.crates/goose-acp/acp-schema.json,crates/goose-acp/acp-meta.json, andui/sdk/src/generated/*.crates/goose-acp/tests/custom_requests_test.rs) to useset_config_option.Measured impact
End-to-end "new tab → first message sent → stream ended" (Databricks, default model):
setProvider(server total)sendMessage(client total)The remaining
set_config_optioncost is almost entirely onefetch_recommended_modelscall against Databricks (measured at ~950ms – 2300ms across runs — highly variable). That's the next target, but worth its own PR.Validation
cargo clippy --workspace --all-targets -- -D warnings✅cargo test -p goose-acp -p goose-sdk✅just check(biome, file-sizes, i18n, typecheck) inui/goose2✅Not in this PR
fetch_recommended_models(biggest remaining win, ~1–2s).setProviderwhen the server default already matches.agent_setupextension loads (~500ms on the critical path).