diff --git a/backend/apps/mcp_registry/mcp_registry.py b/backend/apps/mcp_registry/mcp_registry.py index eb24b03e..4a8bdeac 100644 --- a/backend/apps/mcp_registry/mcp_registry.py +++ b/backend/apps/mcp_registry/mcp_registry.py @@ -292,7 +292,6 @@ def _apply_stars(servers: dict[str, dict]): async def _refresh_loop(): """Background loop that refreshes the cache on startup and then hourly.""" global _cache, _cache_updated_at - logger.info("[perf] bg mcp._refresh_loop entered") while True: try: community, google = await asyncio.gather( diff --git a/backend/apps/nine_router/process.py b/backend/apps/nine_router/process.py index 912b2d0b..cae6878e 100644 --- a/backend/apps/nine_router/process.py +++ b/backend/apps/nine_router/process.py @@ -359,11 +359,9 @@ async def ensure_running(): """Start 9Router if not already running. Serialized so concurrent callers (the background auto-start + a dispatch-time ensure) can't double-spawn.""" global _start_lock - logger.info("[perf] bg 9r.ensure_running entered") if _start_lock is None: _start_lock = asyncio.Lock() async with _start_lock: - logger.info("[perf] bg 9r.ensure_running past lock") await _ensure_running_impl() @@ -395,10 +393,8 @@ async def _ensure_running_impl(): else: logger.info("9Router already running on port %d", NINE_ROUTER_PORT) return - logger.info("[perf] bg 9r past is_running()") _9router_dir = _find_9router_dir() _patch = _gpt5_patch_path() - logger.info("[perf] bg 9r found dir+patch") if _is_packaged: # Packaged: run the pre-built standalone server staged at @@ -414,7 +410,6 @@ async def _ensure_running_impl(): if not os.path.exists(standalone_server): _report_start_failure("server_missing", router_dir_found=True) return - logger.info("[perf] bg 9r pre find_node") node = _find_node() if not node: _report_start_failure("node_not_found", router_dir_found=True, server_found=True) diff --git a/backend/apps/service/client.py b/backend/apps/service/client.py index 2131baca..a835d8f1 100644 --- a/backend/apps/service/client.py +++ b/backend/apps/service/client.py @@ -194,12 +194,9 @@ def _base_url() -> str: async def _post(path: str, body: dict) -> int | None: url = f"{_base_url()}{path}" - logger.info("[perf] bg svc._post client-create %s", path) try: async with httpx.AsyncClient(timeout=_TIMEOUT_SECONDS) as c: - logger.info("[perf] bg svc._post sending %s", path) r = await c.post(url, json=body) - logger.info("[perf] bg svc._post done %s", path) return r.status_code except Exception as e: logger.debug("service POST %s failed: %s", path, e) @@ -217,7 +214,6 @@ def _retryable(status: int | None) -> bool: async def _post_or_spool(path: str, body: dict, kind: str) -> None: global _inflight - logger.info("[perf] bg svc._post_or_spool entered path=%s", path) if _test_sink is not None: try: _test_sink(kind, body) diff --git a/backend/apps/settings/settings.py b/backend/apps/settings/settings.py index 21b747f8..bd501e1f 100644 --- a/backend/apps/settings/settings.py +++ b/backend/apps/settings/settings.py @@ -42,7 +42,6 @@ async def settings_lifespan(): async def _boot_router_then_sync(): """Boot 9Router then push key-based connections (sequential: sync helpers no-op pre-boot).""" - logger.info("[perf] bg settings._boot_router_then_sync entered") needs_router = any([ getattr(s, "google_api_key", None), getattr(s, "openai_api_key", None), diff --git a/backend/apps/skill_registry/skill_registry.py b/backend/apps/skill_registry/skill_registry.py index 4ad009bb..05717d9c 100644 --- a/backend/apps/skill_registry/skill_registry.py +++ b/backend/apps/skill_registry/skill_registry.py @@ -166,7 +166,6 @@ async def _fetch_all_skills() -> dict[str, dict]: async def _refresh_loop(): global _cache, _cache_updated_at - logger.info("[perf] bg skill._refresh_loop entered") backoff = _RETRY_BACKOFF_START_S while True: ok = False diff --git a/backend/config/Apps.py b/backend/config/Apps.py index 3ab5e12c..7bd25b4b 100644 --- a/backend/config/Apps.py +++ b/backend/config/Apps.py @@ -40,7 +40,9 @@ class MainApp: debug(sub_app.name) _t0 = time.perf_counter() await stack.enter_async_context(sub_app.lifespan()) - print(f"[perf] lifespan {sub_app.name} t={(time.perf_counter() - _t0) * 1000:.0f}ms", flush=True) + _dt = (time.perf_counter() - _t0) * 1000 + if _dt > 50: # only flag a slow lifespan; keeps boot logs quiet + print(f"[perf] lifespan {sub_app.name} t={_dt:.0f}ms", flush=True) print(f"[perf] lifespans-total t={(time.perf_counter() - _boot_t0) * 1000:.0f}ms", flush=True) _port = os.environ.get("OPENSWARM_PORT", "8324") print(f"\nCheck out the API docs at: http://127.0.0.1:{_port}/docs\n") diff --git a/docs/perf/winv2/README.md b/docs/perf/winv2/README.md index ca18981d..2ae0da3b 100644 --- a/docs/perf/winv2/README.md +++ b/docs/perf/winv2/README.md @@ -344,3 +344,51 @@ Status: warm 5.0s (under goal), cold ~22s (75-84% below the 54-138s baseline), b bugs fixed/verified on the signed build. The cold residual is either accepted as first-run-only OS I/O, or pinned definitively by one more build that ships this instrumentation. Build-gated (user manages tags/release), so not auto-built. + +## [SOLVED 2026-06-18] cold ~22s -> 3.86s: synchronous is_running() froze the event loop + +The per-lifespan instrumentation (v1.3.88) overturned every prior hypothesis: all +16 lifespans enter in ~120ms even COLD. The ~18s cold cost was entirely AFTER +lifespan startup, in a backgrounded create_task that synchronously blocked the +single asyncio event loop, so uvicorn could not answer the health probe. + +Finer instrumentation (v1.3.89) split it into two stalls (~13s before any bg task, +~5s in 9Router ensure). faulthandler (`dump_traceback_later`, v1.3.90) on the +signed cold build caught the loop thread frozen, three times, in the SAME call: + +``` +socket.create_connection <- stuck >7s +httpx ... get +backend/apps/nine_router/process.py:83 is_running() <- synchronous httpx.get + <- sync_openswarm_pro_as_claude / sync_custom_providers (settings._boot_router_then_sync) + <- _ensure_running_impl (ensure_running) +``` + +ROOT CAUSE: `is_running()` did a synchronous `httpx.get("http://localhost:20128/...")`. +It is called ~5x on the cold boot path (the settings key-sync sequence + the +9Router ensure) BEFORE 9Router is up. On Windows a dead-port connect to +"localhost" stalls ~7s each: getaddrinfo returns `::1` first, and the loopback +refusal is slow (measured: a refused connect is ~2s/address, and localhost = +`::1`+`127.0.0.1` = ~4s; cold ~7s). ~5 serial probes = the ~18s freeze. + +This is why every earlier hypothesis missed: it is not disk, not Defender, not +file-count, not the DEBUGLETON scan, not imports, not the lifespans. It is one +synchronous network probe on the event loop, repeated. + +FIX (v1.3.91, `process.py` is_running): probe `127.0.0.1` with a 0.3s TCP timeout +first (a short timeout caps the slow Windows refusal: measured 306ms vs ~7s); only +HTTP-confirm when the port is open. 9Router binds `0.0.0.0` (the warm app reaches +it via `127.0.0.1`), so reachability is unchanged, only the dead-port wait dies. + +VERIFIED on the real signed build (this Windows 11 box, fresh Squirrel install): + +| metric | baseline | before fix (1.3.90) | after fix (1.3.91) | +| --- | --- | --- | --- | +| cold backend-http-ready | 54-138s | 23.5s | **3.86s** | +| warm backend-http-ready | 9-10s | 5.0s | **3.32s** | + +Cold is now ~97% below baseline and well under the 10s goal; warm improved too +(the same localhost stall taxed it). 9Router still starts successfully via the new +probe (no regression). The diagnostic `[perf] bg` logs + faulthandler were removed +after diagnosis; the lightweight per-lifespan timer stays (prints only a lifespan +over 50ms + the total) as a cheap regression tripwire.