diff --git a/api/models.py b/api/models.py index 9f945693..38c3dfc0 100644 --- a/api/models.py +++ b/api/models.py @@ -3095,24 +3095,122 @@ def _cached_session_lags_disk(cached) -> bool: id. Serving the cache then makes recent assistant results disappear from GET /api/session even though disk and _index.json are correct. Compare only cheap metadata here; full reload happens only if disk is strictly ahead. + + perf(webui/session-load-latency) cheap-first ordering: the function used to + call Session.load_metadata_only(sid) on every cache hit, which parses the + full sidecar JSON (~15-20ms even for 1.3MB sidecars on Celeron+ eMMC). + For draft auto-saves that hit get_session() on every keystroke debounce + (every ~400ms while typing), that 15-20ms multiplied out to ~75% of the + request's wall time on the Chromebook. We now do a single fast check + first: read only the JSON metadata prefix to compare message counts. + The full Session.load_metadata_only() and its anchor-scene comparisons + only run when the count check is inconclusive or when disk appears to be + ahead of cache. """ if cached is None: return False sid = getattr(cached, 'session_id', None) if not sid: return False + cached_count = len(getattr(cached, 'messages', None) or []) + # Fast path: prefix read of just the metadata header. + disk_count = _persisted_message_count(sid) + if disk_count is not None: + if disk_count > cached_count: + return True + # Disk is at most as far as cache. Even when counts match, anchor scene + # records can advance independently (api/routes.py saves a session + # with `s.save(touch_updated_at=False, skip_index=True)` after editing + # only the scene dict; message_count is len(messages) so it stays the + # same). Greptile flagged this in PR review. Cheaply check the disk's + # scene records from the same prefix we already read. + cached_scenes = getattr(cached, 'anchor_activity_scenes', None) or {} + if not isinstance(cached_scenes, dict): + cached_scenes = {} + # Track whether the cheap scene check was inconclusive — when it is, + # we must fall through to the full metadata comparison instead of + # returning False for inactive sessions with matching counts. + _scene_check_inconclusive = False + if cached_scenes: + disk_meta_quick = _persisted_session_meta_prefix(sid) + if disk_meta_quick is not None: + disk_scenes = disk_meta_quick.get('anchor_activity_scenes') or {} + if not isinstance(disk_scenes, dict): + disk_scenes = {} + if disk_scenes: + # Directional: only reload when disk is strictly ahead + # of cache. Mirror master's subset comparison — cache + # that is ahead of disk must NOT force a reload, or + # un-persisted scene data is silently dropped. + disk_keys = {str(key) for key, value in disk_scenes.items() + if key and isinstance(value, dict)} + cached_keys = _anchor_scene_record_keys(cached) + if disk_keys and not disk_keys.issubset(cached_keys): + return True + # Same key set (or disk is subset): check the latest + # updated_at timestamp. + def _max_updated(records): + latest = 0.0 + for record in records.values(): + if not isinstance(record, dict): + continue + try: + ua = float(record.get('updated_at') or 0) + except (TypeError, ValueError): + ua = 0.0 + if ua > latest: + latest = ua + return latest + if _max_updated(disk_scenes) > _anchor_scene_records_updated_at(cached): + return True + # disk has no scenes, cache does -> cache is ahead; keep it. + else: + # Can't cheaply verify scene freshness from disk. The prefix + # reader may have failed while _persisted_message_count + # succeeded via index fallback. Fall through to the full + # metadata load so we don't serve stale scenes on the next + # equal-count inactive session path. Greptile P1. + _scene_check_inconclusive = True + else: + # Cached session has no scene records. Check if disk has gained + # the first scene record — without this the fast-path would miss + # a newly persisted scene and return the stale cache. Greptile P1. + disk_meta_quick = _persisted_session_meta_prefix(sid) + if disk_meta_quick is not None: + disk_scenes = disk_meta_quick.get('anchor_activity_scenes') or {} + if isinstance(disk_scenes, dict) and disk_scenes: + return True + else: + # Prefix read failed (may still succeed via index fallback for + # message count). Mark inconclusive so we fall through to the + # full metadata comparison instead of returning False with + # stale cache. Greptile P1 (discussion_r3548650345). + _scene_check_inconclusive = True + if getattr(cached, 'active_stream_id', None) or getattr(cached, 'pending_user_message', None): + # Active session: messages may be in flight; fall through to the + # full check to be safe. + pass + elif _scene_check_inconclusive: + # Could not cheaply verify scene freshness from disk; fall through + # to the full metadata comparison rather than returning False + # (which would serve a potentially stale cache). Greptile P1. + pass + else: + # Inactive session, count matches, scene records match — cache is + # at parity with disk. + return False try: disk_meta = Session.load_metadata_only(sid) except Exception: return False if disk_meta is None: return False - cached_count = len(getattr(cached, 'messages', None) or []) - disk_count = _parse_nonnegative_int(getattr(disk_meta, '_metadata_message_count', None)) if disk_count is None: - disk_count = _lookup_index_message_count(sid) - if disk_count is not None and disk_count > cached_count: - return True + disk_count = _parse_nonnegative_int(getattr(disk_meta, '_metadata_message_count', None)) + if disk_count is None: + disk_count = _lookup_index_message_count(sid) + if disk_count is not None and disk_count > cached_count: + return True if not getattr(cached, 'active_stream_id', None) and not getattr(cached, 'pending_user_message', None): cached_scene_keys = _anchor_scene_record_keys(cached) disk_scene_keys = _anchor_scene_record_keys(disk_meta) @@ -3153,6 +3251,29 @@ def _persisted_message_count(sid) -> int | None: return _parse_nonnegative_int(_lookup_index_message_count(sid)) +def _persisted_session_meta_prefix(sid) -> dict | None: + """Return the parsed metadata prefix dict for *sid*, or None on error. + + Used by ``_cached_session_lags_disk`` to compare additional fields (e.g. + anchor scene records) cheaply against the cached in-memory session without + paying for a full ``Session.load_metadata_only`` parse. Returns the same + shape as ``_persisted_message_count`` callers would expect — a dict that + only contains the metadata-prefix fields, NOT ``messages`` / ``tool_calls``. + """ + if not is_safe_session_id(sid): + return None + p = SESSION_DIR / f'{sid}.json' + if not p.exists(): + return None + try: + prefix = _read_metadata_json_prefix(p) + if not prefix: + return None + return json.loads(prefix) + except Exception: + return None + + def _session_is_evictable(s) -> bool: """Return True only when *s* can be safely dropped from the LRU (#4765). diff --git a/api/request_diagnostics.py b/api/request_diagnostics.py index 71fb1f3e..2199567c 100644 --- a/api/request_diagnostics.py +++ b/api/request_diagnostics.py @@ -106,11 +106,22 @@ class RequestDiagnostics: logger: logging.Logger | None = None, timeout_seconds: float | None = None, auto_start: bool = True, + print_fn: "callable | None" = None, ) -> None: self.request_id = uuid.uuid4().hex[:10] self.method = str(method or "-") self.path = str(path or "-").split("?", 1)[0] self.logger = logger or logging.getLogger(__name__) + # perf(webui/session-load-latency) tier2c: when the WebUI process + # boots without configuring a root-logger handler, logger.warning + # calls are silently dropped (the [SLOW] / "Slow WebUI request" + # lines have been invisible in production for some time — only the + # per-request ms line, which goes through _safe_webui_print, kept + # working). Callers that need the structured log to actually land + # in the systemd journal can pass print_fn=handler._safe_webui_print. + # When provided, finish() and _on_timeout() route through it + # instead of self.logger.warning. + self._print_fn = print_fn self.timeout_seconds = _slow_request_seconds() if timeout_seconds is None else max(0.0, float(timeout_seconds)) self.started_monotonic = time.monotonic() self.started_wall = time.time() @@ -134,6 +145,7 @@ class RequestDiagnostics: path: str, *, logger: logging.Logger | None = None, + print_fn: "callable | None" = None, ) -> "RequestDiagnostics | None": clean_path = str(path or "").split("?", 1)[0] if (method.upper(), clean_path) not in { @@ -144,9 +156,17 @@ 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) + return cls(method, clean_path, logger=logger, print_fn=print_fn) def stage(self, name: str) -> None: now = time.monotonic() @@ -163,6 +183,18 @@ class RequestDiagnostics: self._current_stage = clean self._current_stage_started = now + def _emit_slow(self, prefix: str, record: dict) -> None: + payload = json.dumps(record, sort_keys=True) + log_msg = f"{prefix} %s" + if self._print_fn is not None: + try: + self._print_fn(log_msg % payload) + except Exception: + # print_fn is best-effort; never break a request thread. + pass + else: + self.logger.warning(log_msg, payload) + def finish(self) -> None: record = None with self._lock: @@ -175,10 +207,7 @@ class RequestDiagnostics: # bounded by the number of in-flight requests). _watchdog_unregister(self.request_id) if record and self.timeout_seconds > 0 and record["elapsed_ms"] >= self.timeout_seconds * 1000: - self.logger.warning( - "Slow WebUI request completed: %s", - json.dumps(record, sort_keys=True), - ) + self._emit_slow("Slow WebUI request completed:", record) def _on_timeout(self) -> None: with self._lock: @@ -186,10 +215,7 @@ class RequestDiagnostics: return self._watchdog_logged = True record = self._build_record_locked(include_stacks=True) - self.logger.warning( - "Slow WebUI request still running: %s", - json.dumps(record, sort_keys=True), - ) + self._emit_slow("Slow WebUI request still running:", record) def _build_record_locked(self, *, include_stacks: bool) -> dict[str, Any]: now = time.monotonic() diff --git a/api/routes.py b/api/routes.py index ec750f47..7be43586 100644 --- a/api/routes.py +++ b/api/routes.py @@ -6262,6 +6262,15 @@ def _read_profile_model_config( does not override the session provider. ``profile_default_model`` is still returned for suffix repair (#5127) only when the profile's configured provider matches ``requested_provider`` after normalization. + + perf(webui/session-load-latency) tier2a: the parse is wrapped in a + per-process LRU keyed by (profile_name, config_mtime, size). The + function fires on every chat-open for sessions under a named + profile (resolve_model=1 path), and the YAML parse alone is + hundreds of µs to single-digit ms on the Chromebook. Cache TTL + 60s is a backstop in case mtime resolution is poor on a given + filesystem; under normal edits the mtime changes and invalidates + immediately. """ if not getattr(session, "profile", None): return None, None, None @@ -6269,15 +6278,13 @@ def _read_profile_model_config( try: from api.profiles import get_hermes_home_for_profile - _profile_home = get_hermes_home_for_profile(session.profile) + _profile_name = str(session.profile or "") + _profile_home = get_hermes_home_for_profile(_profile_name) _profile_cfg_path = os.path.join(str(_profile_home), "config.yaml") if not os.path.isfile(_profile_cfg_path): return None, None, None - import yaml - - with open(_profile_cfg_path, encoding="utf-8") as _f: - _pcfg = yaml.safe_load(_f) or {} - if not isinstance(_pcfg, dict): + _pcfg = _read_profile_config_cached(_profile_name, _profile_cfg_path) + if _pcfg is None: return None, None, None _model_cfg = _pcfg.get("model") or {} if not isinstance(_model_cfg, dict): @@ -6301,6 +6308,89 @@ def _read_profile_model_config( return _provider, _default, _pcfg +# perf(webui/session-load-latency) tier2a: process-wide cache for parsed +# profile config.yaml. Key = (profile_name, inode, mtime, size); value = parsed +# dict. inode tracks atomic-rename edits (most editors replace files, giving a +# new inode on Linux). mtime+size auto-invalidates on in-place edits; a 60s TTL +# is the backstop in case of coarse mtime resolution (some network filesystems +# round mtime to whole seconds — the size guard catches a write of equal-length +# bytes within the same second). On cache hit, a full-content comparison catches +# any in-place rewrite that inode+mtime+size missed (Greptile P1, PR#5803 +# discussion_r3548477915). Reading and comparing the full file content (~1-10KB) +# is much cheaper than yaml.safe_load(). Reads are guarded by a single Lock to +# keep the hot path simple; the underlying yaml.safe_load is the slow step, not +# the lock, so contention is bounded. +_PROFILE_CONFIG_CACHE: "dict[tuple, tuple[float, str, dict]]" = {} +_PROFILE_CONFIG_CACHE_TTL_SECONDS = 60.0 +_PROFILE_CONFIG_CACHE_LOCK = threading.Lock() + + +def _read_profile_config_cached(profile_name: str, cfg_path: str) -> dict | None: + """Return parsed profile config, caching by (inode, mtime, size) with + TTL backstop and full-content verification. + + The full-content comparison reads the current file and compares it to a + copy stored in the cache entry. This catches any in-place rewrite where + inode+mtime+size are identical, regardless of where in the file the change + occurs — unlike a fixed-length prefix comparison, edits to fields after the + first N characters are always detected. Reading and comparing the full file + content (~1-10KB for a typical config.yaml) is much cheaper than + yaml.safe_load(). + + NOTE: The cache key uses inode+mtime+size to handle the common cases + (atomic-rename editors -> new inode; in-place editors -> mtime/size + change). The full-content comparison is a backstop for the rare case where + all three collide (e.g., sed -i on a filesystem with coarse mtime + resolution, writing the same byte count). + """ + try: + st = os.stat(cfg_path) + except OSError: + return None + mtime = float(getattr(st, "st_mtime", 0.0) or 0.0) + size = int(getattr(st, "st_size", 0) or 0) + inode = int(getattr(st, "st_ino", 0) or 0) + key = (str(profile_name or ""), inode, mtime, size) + now = time.monotonic() + with _PROFILE_CONFIG_CACHE_LOCK: + cached = _PROFILE_CONFIG_CACHE.get(key) + if cached is not None: + cached_at, cached_content, cached_dict = cached + if (now - cached_at) <= _PROFILE_CONFIG_CACHE_TTL_SECONDS: + # Full content comparison catches any in-place rewrite where + # inode+mtime+size are identical but the file content changed. + # Reading and comparing the full file (~1-10KB) is cheaper than + # yaml.safe_load(). Unlike a fixed-length prefix, this detects + # edits anywhere in the file. Greptile P1 (PR#5803). + _current_content = None + try: + with open(cfg_path, "r", encoding="utf-8") as _f: + _current_content = _f.read() + except Exception: + pass + if _current_content == cached_content: + return cached_dict + # Content changed while key collided — fall through to re-parse + import yaml + try: + with open(cfg_path, encoding="utf-8") as _f: + content = _f.read() + parsed = yaml.safe_load(content) or {} + except Exception: + return None + if not isinstance(parsed, dict): + return None + with _PROFILE_CONFIG_CACHE_LOCK: + _PROFILE_CONFIG_CACHE[key] = (now, content, parsed) + # Cap the cache at 32 entries; profiles are bounded in practice + # and unbounded growth would be a leak. + if len(_PROFILE_CONFIG_CACHE) > 32: + # Drop the oldest entry by insertion order (dict is ordered). + for old_key in list(_PROFILE_CONFIG_CACHE.keys())[:max(0, len(_PROFILE_CONFIG_CACHE) - 32)]: + _PROFILE_CONFIG_CACHE.pop(old_key, None) + return parsed + + def _load_profile_config_dict(session) -> dict | None: """Load the session profile's config.yaml as a dict, or None.""" if not getattr(session, "profile", None): @@ -11506,7 +11596,7 @@ def handle_get(handler, parsed) -> bool: # which the request-thread wrapper could not reach. See # api.config.get_available_models cold path + profile_scope_for_detached_worker. freshness = parse_qs(parsed.query or "").get("freshness", [""])[0].strip().lower() - diag = RequestDiagnostics.maybe_start("GET", parsed.path, logger=logger) + diag = RequestDiagnostics.maybe_start("GET", parsed.path, logger=logger, print_fn=getattr(handler, '_safe_webui_print', None)) try: diag.stage(f"enter:freshness={freshness or 'default'}") if diag else None if freshness == "session_visit": @@ -11710,9 +11800,22 @@ 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, print_fn=getattr(handler, '_safe_webui_print', None)) + # perf(webui/session-load-latency) tier2c-followup: every early-return + # in this handler calls `_diag.finish()` before returning so the + # watchdog's _watchdog_pending dict stays bounded to in-flight requests. + # Greptile flagged this in PR review — finish() unregisters the + # pending watchdog entry; without it the entry stays for the full + # 5s slow-request timeout and emits a spurious "Slow WebUI request + # still running" log. Idempotent — finish() no-ops if already called. query = parse_qs(parsed.query) sid = query.get("session_id", [""])[0] if not sid: + if _diag: _diag.finish() return j(handler, {"error": "session_id is required"}, status=400) # ?messages=0 skips the message payload for fast session switching. # The frontend uses this when switching conversations in the sidebar @@ -11745,12 +11848,14 @@ 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): if _session_profile: # Valid session owned by a KNOWN other profile: 409 so the # client can offer to switch to it (#5419). + if _diag: _diag.finish() return j(handler, { "error": "Session belongs to a different profile", "code": "session_profile_mismatch", @@ -11762,6 +11867,7 @@ def handle_get(handler, parsed) -> bool: # fires. _profiles_match coerces None->'default', so a truly # missing/legacy session under a non-default active profile would # otherwise emit a useless 409 with profile=null. + if _diag: _diag.finish() return bad(handler, "Session not found", 404) original_stream_id = getattr(s, "active_stream_id", None) _clear_stale_stream_state(s) @@ -11799,6 +11905,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 @@ -11810,6 +11917,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 @@ -12052,6 +12160,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: @@ -12067,22 +12176,42 @@ 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 # logging on every request for development. if _debug_slow or _total_ms >= 2000: - logger.warning( + # perf(webui/session-load-latency) tier2c: route the [SLOW] line + # through handler._safe_webui_print() rather than logger.warning(). + # The WebUI process starts the root logger without any handler, so + # logger.warning() calls are silently dropped (the [SLOW] line + # previously worked only on PIDs that happened to have a logger + # handler set up by an earlier run; today the line is invisible). + # _safe_webui_print writes to the systemd journal socket directly, + # same as the per-request ms line — which is why THAT line keeps + # working. + handler._safe_webui_print( "[SLOW] session_id=%s get_session=%.1fms model_resolve=%.1fms " - "compact=%.1fms redact=%.1fms json_write=%.1fms total=%.1fms", - sid, - (_t2-_t1)*1000, (_t3-_t2)*1000, (_t4-_t3)*1000, - (_t5-_t4)*1000, (_t6-_t5)*1000, _total_ms, + "compact=%.1fms redact=%.1fms json_write=%.1fms total=%.1fms" % ( + sid, + (_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: + # perf(webui/session-load-latency) tier2c-followup: fire + # _diag.finish() in the exception branch too. Greptile flagged + # this in PR review — finish() unregisters the pending watchdog + # entry; without it the entry stays for the full 5s slow-request + # timeout and emits a spurious "Slow WebUI request still + # running" log. Idempotent — finish() no-ops if already called. + if _diag: _diag.finish() # No WebUI sidecar. Delegate to the shared foreign-session # synthesizer so GET and POST have symmetric writeable/read-only # behaviour for CLI/TUI/Desktop sessions. The helper enforces the @@ -12214,7 +12343,7 @@ def handle_get(handler, parsed) -> bool: return j(handler, {"results": get_results(sid)}) if parsed.path == "/api/sessions": - diag = RequestDiagnostics.maybe_start("GET", parsed.path, logger=logger) + diag = RequestDiagnostics.maybe_start("GET", parsed.path, logger=logger, print_fn=getattr(handler, '_safe_webui_print', None)) try: from api import profiles as profiles_api @@ -12713,7 +12842,7 @@ def handle_get(handler, parsed) -> bool: # ── Profile API (GET) ── if parsed.path == "/api/profiles": from api import profiles as profiles_api - diag = RequestDiagnostics.maybe_start("GET", parsed.path, logger=logger) + diag = RequestDiagnostics.maybe_start("GET", parsed.path, logger=logger, print_fn=getattr(handler, '_safe_webui_print', None)) try: diag.stage("list_profiles_api") if diag else None profiles_payload = profiles_api.list_profiles_api() @@ -12969,7 +13098,7 @@ def _validate_session_toolsets_shape(toolsets): def handle_post(handler, parsed) -> bool: """Handle all POST routes. Returns True if handled, False for 404.""" - diag = RequestDiagnostics.maybe_start("POST", parsed.path, logger=logger) + diag = RequestDiagnostics.maybe_start("POST", parsed.path, logger=logger, print_fn=getattr(handler, '_safe_webui_print', None)) if parsed.path == "/api/csp-report": if diag: diag.stage("csp_report") @@ -13650,6 +13779,13 @@ def handle_post(handler, parsed) -> bool: # GET ?session_id=X → return current draft # POST body → save draft { session_id, text?, files? } # HTTP method is in handler.command (e.g. "POST", "GET"), parsed has no .method + import time as _draft_time + _draft_t0 = _draft_time.monotonic() + _draft_stages = [] + + def _draft_mark(name): + _draft_stages.append((name, _draft_time.monotonic())) + _draft_mark("enter") if handler.command == "GET": query = parse_qs(parsed.query) sid = query.get("session_id", [""])[0] if parsed.query else "" @@ -13689,8 +13825,10 @@ def handle_post(handler, parsed) -> bool: s = get_session(sid) except KeyError: return bad(handler, "Session not found", 404) + _draft_mark("after_get_session") unchanged = False with _get_session_agent_lock(sid): + _draft_mark("acquired_lock") current_draft = dict(getattr(s, "composer_draft", {}) or {}) next_draft = dict(current_draft) if text is not None: @@ -13706,12 +13844,29 @@ def handle_post(handler, parsed) -> bool: # here makes the active-session external-refresh poll force-reload the # current chat every few seconds while the user is typing, and that # delayed reload can restore an older draft over newer local input. + _draft_mark("before_save") s.save(touch_updated_at=False, skip_index=True) + _draft_mark("after_save") saved_draft = s.composer_draft + _draft_mark("released_lock") payload = {"ok": True, "draft": saved_draft} if unchanged: payload["unchanged"] = True + _draft_mark("before_json") j(handler, payload) + _draft_mark("after_json") + _draft_stages.append(("end", _draft_time.monotonic())) + if _draft_stages[-1][1] - _draft_t0 > 0.2: + parts = " ".join( + f"{n}={((t - prev[1]) * 1000):.1f}ms" + for (n, t), prev in zip(_draft_stages[1:], _draft_stages[:-1], strict=True) + ) + handler._safe_webui_print( + "[SLOW] /api/session/draft total=%.1fms stages: %s" % ( + (_draft_stages[-1][1] - _draft_t0) * 1000, + parts, + ) + ) return True if parsed.path == "/api/session/update":