diff --git a/CHANGELOG.md b/CHANGELOG.md index bef76a90..83fc0a34 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/bench/startup/PREREGISTRATION.md b/bench/startup/PREREGISTRATION.md new file mode 100644 index 00000000..840f9efb --- /dev/null +++ b/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. diff --git a/bench/startup/RESULTS.md b/bench/startup/RESULTS.md new file mode 100644 index 00000000..bf4736b5 --- /dev/null +++ b/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. diff --git a/bench/startup/probe_connect.py b/bench/startup/probe_connect.py new file mode 100644 index 00000000..88a513af --- /dev/null +++ b/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 # 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() diff --git a/bench/startup/results/table_after.json b/bench/startup/results/table_after.json new file mode 100644 index 00000000..e6b1875f --- /dev/null +++ b/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": "" + }, + { + "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 + } +} \ No newline at end of file diff --git a/bench/startup/results/table_before.json b/bench/startup/results/table_before.json new file mode 100644 index 00000000..f6260e9f --- /dev/null +++ b/bench/startup/results/table_before.json @@ -0,0 +1,120 @@ +{ + "python": "3.11.15", + "platform": "win32", + "cold_start": { + "runs": [ + { + "spawn_to_bound_s": 1.063, + "bound_to_health_s": 0.542, + "spawn_to_health_s": 1.605, + "rss_mb_after_boot": 91.8 + }, + { + "spawn_to_bound_s": 1.012, + "bound_to_health_s": 0.509, + "spawn_to_health_s": 1.521, + "rss_mb_after_boot": 91.1 + }, + { + "spawn_to_bound_s": 1.033, + "bound_to_health_s": 0.536, + "spawn_to_health_s": 1.569, + "rss_mb_after_boot": 88.1 + }, + { + "spawn_to_bound_s": 1.015, + "bound_to_health_s": 0.532, + "spawn_to_health_s": 1.547, + "rss_mb_after_boot": 88.3 + }, + { + "spawn_to_bound_s": 1.026, + "bound_to_health_s": 0.523, + "spawn_to_health_s": 1.549, + "rss_mb_after_boot": 91.4 + } + ], + "first_run_bound_s": 1.063, + "first_run_health_s": 1.605, + "warm_median_bound_s": 1.02, + "warm_spread_bound_s": [ + 1.012, + 1.033 + ], + "warm_median_health_s": 1.548 + }, + "importtime": [ + { + "cumulative_ms": 897.7, + "module": "" + }, + { + "cumulative_ms": 454.4, + "module": "chimera.cli.main" + }, + { + "cumulative_ms": 130.9, + "module": "httpcore" + }, + { + "cumulative_ms": 122.5, + "module": "fastapi" + }, + { + "cumulative_ms": 92.6, + "module": "chimera.api.code_api" + }, + { + "cumulative_ms": 31.3, + "module": "uvicorn" + }, + { + "cumulative_ms": 16.9, + "module": "site" + }, + { + "cumulative_ms": 7.6, + "module": "chimera.api.sessions" + }, + { + "cumulative_ms": 3.9, + "module": "encodings" + }, + { + "cumulative_ms": 3.8, + "module": "chimera.sandbox.confirm" + }, + { + "cumulative_ms": 2.7, + "module": "chimera.providers.listing" + }, + { + "cumulative_ms": 2.5, + "module": "chimera.api.runs" + }, + { + "cumulative_ms": 2.3, + "module": "rich._emoji_codes" + }, + { + "cumulative_ms": 2.3, + "module": "sse_starlette.sse" + }, + { + "cumulative_ms": 2.2, + "module": "importlib.readers" + }, + { + "cumulative_ms": 2.1, + "module": "chimera.api.governance" + } + ], + "turn_overhead": { + "turns": 20, + "median_ms": 16.4, + "p95_ms": 19.0, + "min_ms": 14.1, + "rss_mb_after_turns": 241.1, + "idle_cpu_s_over_10s": 0.0 + } +} \ No newline at end of file diff --git a/bench/startup/run.py b/bench/startup/run.py new file mode 100644 index 00000000..365ea44d --- /dev/null +++ b/bench/startup/run.py @@ -0,0 +1,266 @@ +"""What Chimera itself costs to start and to run a turn, outside the model. Registered in +`PREREGISTRATION.md`. + +Deterministic apart from the clock, no model, US$ 0. Four numbers: cold start to bound and to a +health answer, where the start goes (importtime), harness overhead per turn against an instant +agent, and idle RSS/CPU. + + python bench/startup/run.py # prints; writes results/table.json (before/after copies kept by hand) +""" + +from __future__ import annotations + +import contextlib +import json +import os +import statistics +import subprocess +import sys +import tempfile +import time +import urllib.request +from pathlib import Path +from typing import Any + +REPO = Path(__file__).resolve().parents[2] +sys.path.insert(0, str(REPO)) + +PY = sys.executable +RUNS = 5 +TURNS = 20 + + +def _wait_for(path: Path, seconds: float) -> float | None: + began = time.perf_counter() + while time.perf_counter() - began < seconds: + if path.is_file() and path.read_text(encoding="utf-8").strip(): + return time.perf_counter() - began + time.sleep(0.005) + return None + + +def _health(url: str, seconds: float) -> float | None: + began = time.perf_counter() + while time.perf_counter() - began < seconds: + try: + with urllib.request.urlopen(f"{url}/api/health", timeout=1) as resp: # noqa: S310 + if resp.status == 200: + return time.perf_counter() - began + except Exception: # noqa: BLE001 — not bound yet + time.sleep(0.005) + return None + + +def cold_start(home: Path, runs: int) -> list[dict[str, Any]]: + """Spawn the app `runs` times; each row is (spawn→bound, bound→health, rss after health).""" + out: list[dict[str, Any]] = [] + env = {**os.environ, "CHIMERA_HOME": str(home), "CHIMERA_APP_CRON": "false", "PYTHONUTF8": "1"} + env.pop("CHIMERA_MEMORY_BACKEND", None) + for i in range(runs): + port_file = home / f"port.{i}" + port_file.unlink(missing_ok=True) + began = time.perf_counter() + proc = subprocess.Popen( + [PY, "-c", "from chimera.cli.main import app; app()", + "app", "--no-open", "--port", "0", "--emit-port-file", str(port_file)], + cwd=str(REPO), env=env, stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL, + ) + try: + bound = _wait_for(port_file, 60) + url = port_file.read_text(encoding="utf-8").strip() if bound is not None else "" + healthy = _health(url, 30) if url else None + # The venv's python.exe on Windows is a trampoline that spawns the real interpreter; + # the server is the whole tree, and so is the kill below. + rss = max(p.memory_info().rss for p in _tree(proc.pid)) + out.append({ + "spawn_to_bound_s": round(bound, 3) if bound is not None else None, + "bound_to_health_s": round(healthy, 3) if healthy is not None else None, + "spawn_to_health_s": ( + round(bound + healthy, 3) if bound is not None and healthy is not None else None + ), + "rss_mb_after_boot": round(rss / 1e6, 1), + }) + _ = began + finally: + _kill_tree(proc.pid) + proc.wait(timeout=10) + return out + + +def _tree(pid: int) -> list[Any]: + import psutil + + root = psutil.Process(pid) + return [root, *root.children(recursive=True)] + + +def _kill_tree(pid: int) -> None: + import psutil + + for p in reversed(_tree(pid)): + with contextlib.suppress(psutil.NoSuchProcess): + p.kill() + + +def importtime_of_boot(home: Path, top: int = 15) -> list[tuple[int, str]]: + """The `top` largest cumulative imports of the app's ACTUAL boot, in microseconds. + + Not `import chimera.cli.main` alone: the app imports its server, its routes and its agent + lazily inside the command, and a profile of the module import would miss all of them. + """ + port_file = home / "port.importtime" + port_file.unlink(missing_ok=True) + env = {**os.environ, "CHIMERA_HOME": str(home), "CHIMERA_APP_CRON": "false", "PYTHONUTF8": "1"} + env.pop("CHIMERA_MEMORY_BACKEND", None) + proc = subprocess.Popen( + [PY, "-X", "importtime", "-c", "from chimera.cli.main import app; app()", + "app", "--no-open", "--port", "0", "--emit-port-file", str(port_file)], + cwd=str(REPO), env=env, stdout=subprocess.DEVNULL, stderr=subprocess.PIPE, text=True, + encoding="utf-8", errors="replace", + ) + # Read stderr on a thread: importtime writes a line per import and a full pipe would block + # the boot this is timing. + import threading + + lines: list[str] = [] + + def _drain() -> None: + assert proc.stderr is not None + for line in proc.stderr: + lines.append(line) + + drain = threading.Thread(target=_drain, daemon=True) + drain.start() + _wait_for(port_file, 60) + url = port_file.read_text(encoding="utf-8").strip() if port_file.is_file() else "" + if url: + _health(url, 30) + _kill_tree(proc.pid) + proc.wait(timeout=30) + drain.join(timeout=10) + rows: list[tuple[int, str]] = [] + for line in lines: + if not line.startswith("import time:") or "cumulative" in line: + continue + parts = line.split("|") + try: + cumulative = int(parts[1].strip()) + except (IndexError, ValueError): + continue + rows.append((cumulative, parts[2].rstrip(chr(10)))) + # Top-level modules only — importtime indents a nested import two spaces per level under the + # statement that pulled it in, and a top-level one carries exactly one leading space. Nested + # entries are already inside their parent's cumulative total; counting them too (the first + # draft stripped the indentation first and did) reports one cost several times. + top_level = [(c, n.strip()) for c, n in rows if n.startswith(" ") and not n.startswith(" ")] + total = sum(c for c, _ in top_level) + top_level.sort(reverse=True) + return [(total, ""), *top_level[:top]] + + +def turn_overhead(home: Path, turns: int) -> dict[str, Any]: + """Median wall time of `POST /api/code/turn` against an agent that answers at once, in-process.""" + import psutil + from fastapi.testclient import TestClient + + import chimera.core + from chimera.api import build_api_app + from chimera.config import Settings, get_settings + from chimera.core.agent import AgentResult + from chimera.interface import ChatSession + + class _Instant: + def __init__(self, *_a: Any, **_k: Any) -> None: + pass + + def run(self, task: str, **kw: Any) -> AgentResult: + history = list(kw.get("history") or []) + return AgentResult( + answer="ok", steps=1, stopped_reason="final", + transcript=[*history, {"role": "user", "content": task}, {"role": "assistant", "content": "ok"}], + model="test/model", + ) + + os.environ["CHIMERA_HOME"] = str(home) + os.environ.pop("CHIMERA_MEMORY_BACKEND", None) + get_settings.cache_clear() + chimera.core.Agent = _Instant # type: ignore[assignment,misc] + ws = home / "ws" + ws.mkdir(parents=True, exist_ok=True) + settings = Settings(CHIMERA_HOME=str(home)) # type: ignore[call-arg] + client = TestClient(build_api_app(lambda: ChatSession(_Instant()), workspace=ws, settings=settings)) + # Warm-up: the first turn pays one-time imports and the memory graph. + first = client.post("/api/code/turn", json={"message": "warm up"}) + session_id = "" + for line in first.text.splitlines(): + if line.startswith("data: ") and '"session_id"' in line: + session_id = json.loads(line[6:])["session_id"] + break + times: list[float] = [] + for i in range(turns): + began = time.perf_counter() + client.post("/api/code/turn", json={"message": f"turn {i}", "session_id": session_id}) + times.append(time.perf_counter() - began) + times.sort() + me = psutil.Process() + cpu_before = me.cpu_times() + time.sleep(10) + cpu_after = me.cpu_times() + idle_cpu = (cpu_after.user - cpu_before.user) + (cpu_after.system - cpu_before.system) + return { + "turns": turns, + "median_ms": round(1000 * statistics.median(times), 1), + "p95_ms": round(1000 * times[int(0.95 * (len(times) - 1))], 1), + "min_ms": round(1000 * times[0], 1), + "rss_mb_after_turns": round(me.memory_info().rss / 1e6, 1), + "idle_cpu_s_over_10s": round(idle_cpu, 3), + } + + +def main() -> None: + table: dict[str, Any] = {"python": sys.version.split()[0], "platform": sys.platform} + with tempfile.TemporaryDirectory(ignore_cleanup_errors=True) as tmp: + home = Path(tmp) / "home" + home.mkdir() + print("== cold start (spawn -> bound -> health), warm OS cache after run 1") + starts = cold_start(home, RUNS) + for i, row in enumerate(starts, 1): + print( + f" run {i}: bound {row['spawn_to_bound_s']} s, +health {row['bound_to_health_s']} s" + f" = {row['spawn_to_health_s']} s, rss {row['rss_mb_after_boot']} MB" + ) + bounds = [r["spawn_to_bound_s"] for r in starts[1:] if r["spawn_to_bound_s"] is not None] + healths = [r["spawn_to_health_s"] for r in starts[1:] if r["spawn_to_health_s"] is not None] + table["cold_start"] = { + "runs": starts, + "first_run_bound_s": starts[0]["spawn_to_bound_s"], + "first_run_health_s": starts[0]["spawn_to_health_s"], + "warm_median_bound_s": round(statistics.median(bounds), 3) if bounds else None, + "warm_spread_bound_s": [min(bounds), max(bounds)] if bounds else None, + "warm_median_health_s": round(statistics.median(healths), 3) if healths else None, + } + print( + f" warm median: to bound {table['cold_start']['warm_median_bound_s']} s, " + f"to health {table['cold_start']['warm_median_health_s']} s" + ) + + print("\n== where the start goes (importtime of the real boot, cumulative, top-level)") + rows = importtime_of_boot(home) + table["importtime"] = [{"cumulative_ms": round(c / 1000, 1), "module": n} for c, n in rows] + for c, n in rows: + print(f" {c / 1000:8.1f} ms {n}") + + print("\n== harness overhead per turn (instant agent, in-process)") + overhead = turn_overhead(home / "turns", TURNS) + table["turn_overhead"] = overhead + print(f" median {overhead['median_ms']} ms, p95 {overhead['p95_ms']} ms, min {overhead['min_ms']} ms") + print(f" rss after turns {overhead['rss_mb_after_turns']} MB, idle cpu over 10 s {overhead['idle_cpu_s_over_10s']} s") + + out = REPO / "bench" / "startup" / "results" + out.mkdir(parents=True, exist_ok=True) + (out / "table.json").write_text(json.dumps(table, indent=2), encoding="utf-8") + print(f"\nwrote {out / 'table.json'}") + + +if __name__ == "__main__": + main() diff --git a/chimera/cli/main.py b/chimera/cli/main.py index df59d6f3..617c32d7 100644 --- a/chimera/cli/main.py +++ b/chimera/cli/main.py @@ -2587,11 +2587,20 @@ def _hold(ledger: Any) -> None: def _bind_app_socket(host: str, port: int) -> tuple[Any, int]: """Bind the app's listening socket, falling back to a free port if ``port`` is taken. - Returns the bound socket (handed straight to uvicorn so there is no close-then-rebind race) and - the actual port. ``port=0`` asks the OS for any free port. A fixed port that is already in use - no longer crashes the app — it drops to an OS-assigned free port (so a second `chimera app`, or a - Tauri sidecar, just works). No ``SO_REUSEADDR`` on purpose: on Windows that would let the bind - succeed on a port another server already holds, defeating the busy-detection. + Returns the bound, **listening** socket (handed straight to uvicorn so there is no + close-then-rebind race) and the actual port. ``port=0`` asks the OS for any free port. A fixed + port that is already in use no longer crashes the app — it drops to an OS-assigned free port (so + a second `chimera app`, or a Tauri sidecar, just works). No ``SO_REUSEADDR`` on purpose: on + Windows that would let the bind succeed on a port another server already holds, defeating the + busy-detection. + + ``listen()`` is called HERE and not left to uvicorn, because the port file — the sidecar's + discovery channel — is written between this return and uvicorn's own ``listen()``. Measured on + 2026-09-17 (`bench/startup`): a connection attempted in that window met a bound socket that was + not listening, and on Windows the SYN is dropped rather than refused, so the client's first + connect sat on the 500 ms retransmit timer — a half-second of every desktop launch, paid between + "the backend reported its port" and "the window loaded". Listening first means a connect made + the moment the port file exists is queued in the backlog and served as soon as uvicorn accepts. """ import socket @@ -2603,6 +2612,7 @@ def _bind_app_socket(host: str, port: int) -> tuple[Any, int]: sock.close() raise sock.bind((host, 0)) # requested port busy → OS picks a free one + sock.listen(128) return sock, sock.getsockname()[1] diff --git a/tests/test_cli.py b/tests/test_cli.py index cb49e374..3e6be345 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -3,6 +3,7 @@ from __future__ import annotations import json +import time from pathlib import Path import pytest @@ -389,6 +390,29 @@ def test_solve_edit_requires_answer() -> None: assert "--answer" in result.stdout +def test_the_app_socket_listens_before_the_port_is_announced() -> None: + """A connect made the instant the port file appears must succeed, with nobody accepting yet. + + The sidecar reads the port file and connects at once; before this, the socket was bound but not + listening until uvicorn got to it, and on Windows a SYN to a bound-not-listening socket is + dropped — the client waited out the 500 ms retransmit timer on every launch (`bench/startup`). + The kernel completes the handshake from the backlog, so this connect needs no server at all: + with `listen()` missing it is refused (POSIX) or times out (Windows), and either fails the test. + """ + import socket + + from chimera.cli.main import _bind_app_socket + + sock, port = _bind_app_socket("127.0.0.1", 0) + try: + began = time.monotonic() + client = socket.create_connection(("127.0.0.1", port), timeout=2) + client.close() + assert time.monotonic() - began < 0.4, "the connect waited on a retransmit" + finally: + sock.close() + + def test_bind_app_socket_picks_and_falls_back() -> None: import socket