perf(app): the backend listens before it announces its port — a launch stops paying half a second

CHANGELOG.md

@@ -28,6 +28,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/).
 
 ### Fixed
 
+- **The desktop backend listens before it announces its port, and a launch stops paying half a second for a connection that met a socket nobody was listening on yet.** Item 8 of the list audited on 2026-09-16 ("Speed"), measured first: `bench/startup` (registered, US$ 0) timed the app from spawn to a bound socket (1.02 s, warm), to a health answer (1.55 s), the boot's imports (0.90 s summed, no single one above 15% — `litellm` is not imported at boot at all, which the registration predicted wrongly), the harness's own cost per turn against an instant agent (16 ms median: recall, registry, prompt, session save and history record together), idle CPU (0.0 s over 10 s) and RSS (91 MB). The 0.53 s between the bind and the first answer was not the server — its event loop was idle 10 ms after the port file was written — it was the client's connect: `_bind_app_socket` bound the socket but left `listen()` to uvicorn, the port file was written in between, and on Windows a SYN to a bound-but-not-listening socket is dropped rather than refused, so the shell's first connect sat on the 500 ms retransmit timer on every launch (on POSIX it is refused and the shell retries after 150 ms). Now the socket listens before it is announced; a connect made the instant the port file exists is queued in the backlog and served when uvicorn accepts. Re-measured: bound → health 0.02 s, spawn → health **1.03 s from 1.55 s (−34%)**; nothing else moved. Pinned by a test that connects to the returned socket with no server accepting and fails on either OS without the `listen()`. Nothing under 20% of the boot was touched, by the registered rule; `probe_connect.py` beside the bench is the diagnostic that found it.
+
 - **A streamed turn's receipt learns which route answered when the conversation is reopened — at the end of the turn it cannot know.** 0.58.0 put `provider` on the Code screen's turn receipt and, tested on the installed build the same day, it came back empty on every turn: the desktop streams, and measured with `litellm` against OpenRouter a streamed chunk exposes no provider anywhere (not on the chunk, not in `_hidden_params`, not in `provider_specific_fields`), while the same request without streaming answers it (`Relace`). What a chunk does carry is its `id`, and the router's generation record (`GET /api/v1/generation?id=…`) names the route — **~9–11 s after the stream ends**, 404 before that in 3/3 trials, and three different routes for three identical calls (`Mancer 2`, `OpenInference`, `Together`). So nothing on the request path waits: `CompletionResult.generation_id` → `StepRecord.generation_id` → `generation_ids` on the turn receipt, and the conversation's replay (`GET /api/code/sessions/{id}`) fills `provider` for the receipts that have ids and no route — one request each, no retry, newest first, 2.5 s for the whole pass, written back so it is asked once, skipped when a turn holds the session or there is no OpenRouter key. Never guessed: a record not there yet stays empty and is tried on the next reopen. The badge #494 added therefore shows on a reopened conversation, not on the live one, and the field means the same thing on both receipts — the route the trajectory was set by. Sabotage-verified: with the replay's fill-in severed, the two end-to-end tests fail. Not done here: the same record carries `total_cost` (what the router actually billed) and `native_tokens_cached`; the receipt's `usd` is still the list-rate estimate.
 
 ## [0.58.0] - 2026-09-16

bench/startup/PREREGISTRATION.md

@@ -0,0 +1,50 @@
+# Pre-registration — what does Chimera itself cost to start and to run a turn, outside the model?
+
+**Registered 2026-09-17 against `649a7ab` (v0.58.0 + #499–#504), before the script was run.**
+Deterministic apart from the clock; no model, no key, US$ 0. Item 8 of the list audited on
+2026-09-16 ("Speed"). The audit found the numbers on the marketing list (4.3 s → 0.9 s, 14× CPU)
+are not ours and must not be cited; this is the measurement of our own.
+
+## What is measured, and why these
+
+A person launches the desktop app and waits for the backend before the first screen is useful; then
+every turn pays the harness before the model is even asked. Three numbers, on this machine (i7
+laptop, Windows 11, Python 3.11 in the repo venv — stated because a latency is of a machine):
+
+1. **Cold start to bound.** `python -m chimera app --no-open --port 0 --emit-port-file F`, from
+   process spawn until `F` exists (the server is bound) and then until `GET /api/health` answers
+   200. Five runs, median and spread. Warm-cache runs (the OS file cache is warm after the first),
+   which is the ordinary launch; the true cold disk read is one run and reported apart.
+2. **Where the start goes.** `python -X importtime -c "import chimera.cli.main"` and the same for
+   `chimera.api`, the top ten cumulative import costs. An import that is paid at boot and used only
+   by a command nobody ran at boot is the candidate to defer.
+3. **Harness overhead per turn.** `POST /api/code/turn` against an agent stub that answers at once
+   (the shape every API test uses), 20 turns in one session after a warm-up turn: median wall time
+   of the request. This is everything a turn pays that is not the model — registry build, memory
+   recall, prompt assembly, session save, history record. Reported with `steps=1` so the number is
+   the harness's alone.
+4. **Idle cost.** RSS of the backend process after boot and after the 20 turns; CPU time consumed
+   over 10 idle seconds (from the process's own counters, not a sampler).
+
+## Registered predictions
+
+1. Cold start to bound is between 1.5 s and 4 s on this machine, and the health answer follows
+   within 100 ms of the bind. The import of `litellm` (pulled in by the provider gateway at boot)
+   is the single largest item, above 0.5 s, and is paid before any request needs a provider.
+2. Harness overhead per turn is between 30 and 150 ms with the SQLite memory default; the largest
+   part is memory recall plus the entity graph, not the session save.
+3. Idle CPU over 10 s is under 0.5 s of process time (the cron daemon is off in the API; nothing
+   polls), and RSS after boot is between 120 and 250 MB.
+
+## Decision rule
+
+The worst of the three by proportion is what gets optimised, in the same PR, only if the fix is a
+deferral or a cache that changes no behaviour — never a change to what a turn does. If prediction 1
+holds on `litellm`, the fix is to import it lazily on first provider use and the bench is re-run to
+report the delta. If nothing costs more than 20% of its total, nothing is changed and the numbers
+are published as the baseline.
+
+## What this cannot show
+
+The packaged desktop sidecar is a frozen build whose imports are unpacked from an archive; its cold
+start differs from the venv's and is not measured here. One machine. No model call is timed.

bench/startup/RESULTS.md

@@ -0,0 +1,82 @@
+# Results — what Chimera itself costs to start and to run a turn, outside the model
+
+**Run 2026-09-17 against `649a7ab`, as registered in `PREREGISTRATION.md`.** i7 laptop, Windows 11,
+Python 3.11 in the repo venv; no model, US$ 0. Raw tables: `results/table_before.json` (the tree as
+registered) and `results/table_after.json` (with the one fix below).
+
+## The numbers, before anything was changed
+
+| what | measured |
+|---|---|
+| spawn → socket bound (port file written), warm cache, median of 4 | **1.02 s** (1.01–1.03); first run 1.06 s |
+| bound → `/api/health` answers 200 | **+0.53 s** |
+| spawn → health, warm median | **1.55 s**; first run 1.61 s |
+| imports at boot, every top-level import summed | **0.90 s** — `chimera.cli.main` 454 ms, `httpcore` 131 ms (the price-cache thread's `httpx`), `fastapi` 123 ms, `chimera.api.code_api` 93 ms, `uvicorn` 31 ms |
+| inside `chimera.cli.main` | `chimera.config` 140 ms (pydantic-settings 79, of which `importlib.metadata` 71; keyring 48 for the credential vault), `chimera.providers.gateway` 137 ms (asyncio 38), typer 48, rich 28 |
+| `litellm` at boot | **not imported** — already lazy on first provider use |
+| harness overhead per turn (instant agent, 20 turns, in-process) | median **16.4 ms**, p95 19.0, min 14.1 |
+| RSS after boot / after 20 turns | 91 MB / 241 MB (the in-process figure includes the test client and the bench) |
+| idle CPU over 10 s | **0.0 s** |
+
+## Predictions against the numbers
+
+1. **Cold start 1.5–4 s, health within 100 ms of the bind — half held.** 1.55 s to health is inside
+   the range, but the health answer came **530 ms** after the bind, not 100. And the named culprit
+   was wrong: `litellm` is not imported at boot at all. The boot *is* imports — 0.90 of the 1.02 s to
+   bind — spread over the CLI module, FastAPI and the API routes, with no single item above 15%.
+2. **Turn overhead 30–150 ms — wrong, lower.** 16 ms. The memory recall, registry build, prompt
+   assembly, session save and history record together cost less than a frame of video.
+3. **Idle under 0.5 s CPU, RSS 120–250 MB — held on CPU, RSS is below the range.** 0.0 s and 91 MB.
+
+## Where the half second went — and it was not the server
+
+The main thread was idle in the event loop 10 ms after the port file was written (sampled at
+10 ms intervals), and a request sent 1.5 s after the bind was answered in 12 ms. The 530 ms was on
+the **client's** side of the connect: `_bind_app_socket` bound the socket but did not `listen()`;
+the port file was written; uvicorn called `listen()` ~20 ms later. A connect made in that window
+met a bound-but-not-listening socket, and on Windows that SYN is **dropped, not refused** — the
+client sat on the 500 ms retransmit timer, and the second SYN found the socket listening. On
+POSIX the same SYN is refused, and the desktop shell's `wait_for_listening` sleeps 150 ms before
+trying again.
+
+This is the desktop's launch path exactly: the Tauri shell reads the port file and connects at
+once (`wait_for_listening`, `connect_timeout(500 ms)`, retry every 150 ms), so **every launch paid
+~0.5 s on Windows and ~150–650 ms elsewhere** between "the backend reported its port" and "the
+window loaded". Found by timing a raw-socket client from inside the process
+(`probe_connect.py`, kept beside this file): `connect()` took 0.51 s, the request 6 ms.
+
+## The fix, and the number after it
+
+`_bind_app_socket` now calls `listen(128)` before returning, so the socket is listening when the
+port file is written; a connect made that instant is queued in the backlog and served the moment
+uvicorn accepts. One line; uvicorn's own `listen()` on an already-listening socket is a no-op.
+
+| what | before | after | Δ |
+|---|---:|---:|---:|
+| bound → health, warm median | 0.53 s | **0.02 s** | −0.51 s |
+| spawn → health, warm median | 1.55 s | **1.03 s** | **−34%** |
+| spawn → bound | 1.02 s | 1.01 s | — (unchanged, as it should be) |
+| turn overhead, median | 16.4 ms | 15.0 ms | noise |
+
+Pinned by `test_the_app_socket_listens_before_the_port_is_announced`: a connect to the returned
+socket succeeds within 400 ms with no server accepting; with `listen()` removed the test fails on
+Windows (2 s timeout) and on POSIX (refused) — sabotage-verified on Windows.
+
+## Not changed, and why
+
+- **Imports (0.90 s).** No single import is above 20% of the boot: the largest deferrable ones are
+  `keyring` (48 ms, but it loads the credential vault that the first turn needs) and
+  `importlib.metadata` (71 ms, but pydantic-settings imports it regardless, so a lazy `__version__`
+  would save nothing). The registered rule says nothing under 20% moves, and nothing did.
+- **The shell's port-file poll (200 ms).** Up to 200 ms, ~100 ms on average, of the remaining
+  1.03 s is the Tauri side reading the port file every 200 ms. A 7–10% item, below the rule; noted
+  for the shell.
+- **The packaged sidecar** was not measured (a frozen build unpacks its imports from an archive);
+  the listen-before-announce fix applies to it identically, because the port-file sequence is the
+  same code.
+
+## What this cannot show
+
+One machine, one OS. The 500 ms is Windows' SYN retransmit timer; on macOS and Linux the saving is
+the shell's retry interval instead. No model call was timed, so nothing here says what a turn
+costs — only what the harness adds to one.

bench/startup/probe_connect.py

@@ -0,0 +1,87 @@
+"""The diagnostic that found the half second: a raw-socket client inside the app's own boot.
+
+Runs `chimera app` in-process with three hooks — the moment `_bind_app_socket` returns (the port
+file is written right after), uvicorn's `Server.startup`, and an ASGI wrapper that stamps the first
+HTTP request — and, from a thread, connects to the port the instant it is bound and times the
+connect and the request separately. Before the fix the connect took ~0.5 s on Windows (a SYN to a
+bound-but-not-listening socket is dropped and retransmitted after 500 ms) and the request 6 ms;
+after it both are milliseconds.
+
+    python bench/startup/probe_connect.py <port-file>      # prints the timeline to stderr
+"""
+
+from __future__ import annotations
+
+import socket
+import sys
+import threading
+import time
+from typing import Any
+
+T0 = time.perf_counter()
+
+
+def mark(label: str) -> None:
+    print(f"[{time.perf_counter() - T0:7.3f}s] {label}", file=sys.stderr, flush=True)
+
+
+import uvicorn  # noqa: E402
+
+_startup = uvicorn.Server.startup
+
+
+async def startup(self: Any, *a: Any, **k: Any) -> None:
+    mark("Server.startup begin")
+    await _startup(self, *a, **k)
+    mark("Server.startup end (create_server done)")
+
+
+uvicorn.Server.startup = startup  # type: ignore[method-assign]
+
+import chimera.api as capi  # noqa: E402
+import chimera.cli.main as cli  # noqa: E402
+
+_bind = cli._bind_app_socket
+
+
+def bind(*a: Any, **k: Any) -> Any:
+    sock, port = _bind(*a, **k)
+    mark(f"socket bound port {port}")
+
+    def client() -> None:
+        began = time.perf_counter()
+        s = socket.create_connection(("127.0.0.1", port), timeout=5)
+        mark(f"client connected after {time.perf_counter() - began:.3f}s, sending")
+        began = time.perf_counter()
+        s.sendall(b"GET /api/health HTTP/1.1\r\nHost: x\r\nConnection: close\r\n\r\n")
+        s.recv(4096)
+        s.close()
+        mark(f"client got the response after {time.perf_counter() - began:.3f}s")
+
+    threading.Thread(target=client, daemon=True).start()
+    return sock, port
+
+
+cli._bind_app_socket = bind  # type: ignore[assignment]
+
+_build = capi.build_api_app
+
+
+def build(*a: Any, **k: Any) -> Any:
+    app = _build(*a, **k)
+
+    async def timing(scope: Any, receive: Any, send: Any) -> None:
+        if scope["type"] == "http":
+            mark(f"ASGI http request enters {scope['path']}")
+        elif scope["type"] == "lifespan":
+            mark("ASGI lifespan begins")
+        await app(scope, receive, send)
+
+    return timing
+
+
+capi.build_api_app = build  # type: ignore[assignment]
+
+if __name__ == "__main__":
+    sys.argv = ["chimera", "app", "--no-open", "--port", "0", "--emit-port-file", sys.argv[1]]
+    cli.app()

bench/startup/results/table_after.json

@@ -0,0 +1,120 @@
+{
+  "python": "3.11.15",
+  "platform": "win32",
+  "cold_start": {
+    "runs": [
+      {
+        "spawn_to_bound_s": 1.107,
+        "bound_to_health_s": 0.027,
+        "spawn_to_health_s": 1.133,
+        "rss_mb_after_boot": 87.4
+      },
+      {
+        "spawn_to_bound_s": 1.028,
+        "bound_to_health_s": 0.015,
+        "spawn_to_health_s": 1.043,
+        "rss_mb_after_boot": 87.1
+      },
+      {
+        "spawn_to_bound_s": 1.021,
+        "bound_to_health_s": 0.028,
+        "spawn_to_health_s": 1.049,
+        "rss_mb_after_boot": 86.9
+      },
+      {
+        "spawn_to_bound_s": 0.994,
+        "bound_to_health_s": 0.019,
+        "spawn_to_health_s": 1.013,
+        "rss_mb_after_boot": 86.4
+      },
+      {
+        "spawn_to_bound_s": 0.988,
+        "bound_to_health_s": 0.024,
+        "spawn_to_health_s": 1.012,
+        "rss_mb_after_boot": 87.1
+      }
+    ],
+    "first_run_bound_s": 1.107,
+    "first_run_health_s": 1.133,
+    "warm_median_bound_s": 1.007,
+    "warm_spread_bound_s": [
+      0.988,
+      1.028
+    ],
+    "warm_median_health_s": 1.028
+  },
+  "importtime": [
+    {
+      "cumulative_ms": 891.3,
+      "module": "<every top-level import, summed>"
+    },
+    {
+      "cumulative_ms": 449.7,
+      "module": "chimera.cli.main"
+    },
+    {
+      "cumulative_ms": 131.9,
+      "module": "httpcore"
+    },
+    {
+      "cumulative_ms": 127.6,
+      "module": "fastapi"
+    },
+    {
+      "cumulative_ms": 86.8,
+      "module": "chimera.api.code_api"
+    },
+    {
+      "cumulative_ms": 31.7,
+      "module": "uvicorn"
+    },
+    {
+      "cumulative_ms": 17.9,
+      "module": "site"
+    },
+    {
+      "cumulative_ms": 7.6,
+      "module": "chimera.api.sessions"
+    },
+    {
+      "cumulative_ms": 3.8,
+      "module": "encodings"
+    },
+    {
+      "cumulative_ms": 3.6,
+      "module": "chimera.sandbox.confirm"
+    },
+    {
+      "cumulative_ms": 2.6,
+      "module": "importlib.readers"
+    },
+    {
+      "cumulative_ms": 2.6,
+      "module": "chimera.api.runs"
+    },
+    {
+      "cumulative_ms": 2.2,
+      "module": "chimera.api.governance"
+    },
+    {
+      "cumulative_ms": 2.1,
+      "module": "sse_starlette.sse"
+    },
+    {
+      "cumulative_ms": 1.9,
+      "module": "encodings.idna"
+    },
+    {
+      "cumulative_ms": 1.8,
+      "module": "chimera.api.maturity_api"
+    }
+  ],
+  "turn_overhead": {
+    "turns": 20,
+    "median_ms": 15.0,
+    "p95_ms": 18.1,
+    "min_ms": 14.1,
+    "rss_mb_after_turns": 241.4,
+    "idle_cpu_s_over_10s": 0.0
+  }
+}