From 3a330ceff5f3353bff2a5d287c71543378896d58 Mon Sep 17 00:00:00 2001 From: Konstantin M Date: Wed, 8 Jul 2026 16:46:32 +0000 Subject: [PATCH] perf(webui/session-load-latency) tier2c: per-stage breakdown on /api/session MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The /api/session handler already has _t0.._t6 local timers plus an env-var-gated [SLOW] WARNING that logs the total wall time and the _tN-to-_tN+1 deltas, but only when HERMES_DEBUG_SLOW is set or total >= 2s. In production we cannot rely on the env var, and the 2s threshold means the typical chat-open (sub-2s on Tier 1) never logs at all — we only see the worst cases, never the marginal ones that would tell us where the next bottleneck is. This wires the handler into the existing RequestDiagnostics framework: - add ('GET', '/api/session') to the allowlist - call RequestDiagnostics.maybe_start() at the _t0 boundary - call stage() at each of _t1.._t6 - call finish() before the response returns The watchdog fires _on_timeout (with thread stack snapshot) when the request crosses the per-path slow threshold, and finish() emits a single structured log line on the same threshold crossing. The existing env-var-gated [SLOW] log stays as a no-diag fallback. Greptile P1 trap avoidance: previous allowlist additions for similar endpoints were flagged as dead code because the handler was never updated to call maybe_start/finish. Both halves are present in this commit so the watchdog entry actually registers. No behavior change observable on the happy path (diag is None for non-allowlisted paths; the existing _tN log is the fallback for both None-diag and slow cases). No public API change. The /api/sessions and /api/profiles handlers already use this pattern. --- api/request_diagnostics.py | 8 ++++++++ api/routes.py | 12 ++++++++++++ 2 files changed, 20 insertions(+) diff --git a/api/request_diagnostics.py b/api/request_diagnostics.py index 71fb1f3ee..3a08cce4f 100644 --- a/api/request_diagnostics.py +++ b/api/request_diagnostics.py @@ -144,6 +144,14 @@ class RequestDiagnostics: # of the multi-second waterfalls in the slow-request logs. ("GET", "/api/profiles"), ("GET", "/api/models"), + # perf(webui/session-load-latency) tier2c: /api/session is the + # chat-open hot path. The handler also calls maybe_start() and + # finish() at its _t0/_t6 boundaries, so adding this entry to + # the allowlist is NOT a dead-code addition (the Greptile P1 + # trap for previous similar entries): without the handler call + # the watchdog entry would never register and the structured + # log would never fire. + ("GET", "/api/session"), }: return None return cls(method, clean_path, logger=logger) diff --git a/api/routes.py b/api/routes.py index f27b70d17..037ed0279 100644 --- a/api/routes.py +++ b/api/routes.py @@ -11700,6 +11700,11 @@ def handle_get(handler, parsed) -> bool: import time as _time _t0 = _time.monotonic() _debug_slow = os.environ.get("HERMES_DEBUG_SLOW", "") + # perf(webui/session-load-latency) tier2c: per-stage breakdown via + # RequestDiagnostics. maybe_start() returns None for paths not in + # the allowlist, in which case the existing _tN-driven [SLOW] log + # is the only signal — same as before. + _diag = RequestDiagnostics.maybe_start("GET", parsed.path, logger=logger) query = parse_qs(parsed.query) sid = query.get("session_id", [""])[0] if not sid: @@ -11735,6 +11740,7 @@ def handle_get(handler, parsed) -> bool: expand_renderable = str(_expand_renderable).strip() in ("1", "true", "True") try: _t1 = _time.monotonic() + if _diag: _diag.stage("t1_after_get_session_check") s = get_session(sid, metadata_only=(not load_messages)) _session_profile = getattr(s, 'profile', None) or None if not _session_visible_to_active_profile(_session_profile, handler): @@ -11789,6 +11795,7 @@ def handle_get(handler, parsed) -> bool: # honor #2827's TLS-vs-thread fix. metadata_summary = _metadata_only_message_summary(sid, profile=_session_profile) _t2 = _time.monotonic() + if _diag: _diag.stage("t2_after_state_db_load") effective_model = ( _resolve_effective_session_model_for_display(s) if resolve_model @@ -11800,6 +11807,7 @@ def handle_get(handler, parsed) -> bool: else None ) _t3 = _time.monotonic() + if _diag: _diag.stage("t3_after_model_resolve") if load_messages: if is_messaging_session and cli_messages: # Recovery/aggregate sidecars can intentionally contain a @@ -12042,6 +12050,7 @@ def handle_get(handler, parsed) -> bool: raw["_messages_truncated"] = _truncated raw["_messages_offset"] = _messages_offset _t4 = _time.monotonic() + if _diag: _diag.stage("t4_after_compact_and_merge") if effective_model: raw["model"] = effective_model if effective_provider: @@ -12057,8 +12066,10 @@ def handle_get(handler, parsed) -> bool: raw["read_only"] = True redact = redact_session_data(raw) _t5 = _time.monotonic() + if _diag: _diag.stage("t5_after_redact") resp = j(handler, {"session": redact}) _t6 = _time.monotonic() + if _diag: _diag.stage("t6_after_json_write") _total_ms = (_t6 - _t0) * 1000 # Always log when slow (>2s) so we don't need HERMES_DEBUG_SLOW env var # to diagnose latency regressions. Opt-in env var still forces @@ -12071,6 +12082,7 @@ def handle_get(handler, parsed) -> bool: (_t2-_t1)*1000, (_t3-_t2)*1000, (_t4-_t3)*1000, (_t5-_t4)*1000, (_t6-_t5)*1000, _total_ms, ) + if _diag: _diag.finish() return resp except KeyError: # No WebUI sidecar. Delegate to the shared foreign-session