Three fixes for the CI failures (lint + test shard 1):
1. B009 lint fix (api/routes.py:6281): Replace getattr(session, 'profile')
with session.profile — the guard on line 6275 already ensures it exists.
2. B905 lint fix (api/routes.py:13843): Add strict=True to zip() of
_draft_stages slices. Both sides are always the same length (shifted
by one), so strict=True is correct.
3. _emit_slow format-arg fix (api/request_diagnostics.py:186-195):
Keep the prefix in the format string and pass the JSON payload as a
separate positional argument. The test at
test_issue1855_request_diagnostics.py:33 does
json.loads(caplog.records[0].args[0]) and the old code embedded the
prefix in the payload string, breaking the JSON parse. Now
self.logger.warning("%s %s", prefix, payload) — wait, actually
self.logger.warning(f"{prefix} %s", payload) — so args[0] is the
raw JSON string, same as the pre-_emit_slow code.
When cached session has no anchor_activity_scenes and the prefix reader
returns None (e.g. sidecar too large for prefix), the empty-scenes path
did not mark _scene_check_inconclusive = True. This meant an inactive
session with matching message counts would return False (cache fresh)
even though disk may have gained its first scene record.
Fix: the empty-scenes else-branch now sets _scene_check_inconclusive
when disk_meta_quick is None, matching the existing behavior in the
cached-scenes branch (line 3173). The code then falls through to the
full metadata comparison instead of serving a stale cache.
discussion_r3548650345
Two Greptile P1 comments from review of b5c0447a (tier3c):
1. Inconclusive Prefix Stays Fresh (discussion_r3548477859):
When _persisted_session_meta_prefix() returns None and cached has scene
records, the fast-path skipped scene comparison entirely and returned
False (cache fresh) for inactive equal-count sessions. Added
_scene_check_inconclusive flag that forces fall-through to the full
Session.load_metadata_only() comparison when the cheap prefix read
fails, preventing stale anchor_activity_scenes.
2. Prefix Check Misses Edits (discussion_r3548477915):
The 128-char content-prefix backstop in _read_profile_config_cached
only detected edits within the first 128 bytes of config.yaml. Replaced
with a full-content comparison that reads the entire file (~1-10KB)
and compares it to a copy stored in the cache entry. This detects
edits anywhere in the file at a fraction of the cost of yaml.safe_load().
Updated cache type hint from tuple[float, str|None, dict] to
tuple[float, str, dict].
Tests: 108 passed (41 reconciliation + 39 anchor-scene + 28 profile-config)
The fast-path scene comparison in _cached_session_lags_disk had two bugs
flagged by nesquena-hermes review:
1. Direction: used symmetric != instead of directional subset check.
When the cache had scene keys that disk lacked (cache-ahead), the old
code force-reloaded from disk, silently dropping un-persisted scene
data. Now mirrors master: reload only when disk is strictly ahead
(disk_keys.issubset(cached_keys)). The 'not disk_scenes' early-return
is also removed — empty disk scenes means disk is not ahead, so keep
the cache.
2. Key filtering mismatch: used raw set(disk_scenes.keys()) instead of
_anchor_scene_record_keys() helper which filters to truthy keys with
dict values. Now filters disk keys the same way as master, and uses
_anchor_scene_record_keys(cached) for the cached session object.
Also updated the tier3b content-prefix docstring to clarify it is a
best-effort backstop limited to the first 128 chars, not a full
integrity check.
Greptile P1 (discussion_r3548069113): the inode+mtime+size cache key
misses in-place rewrites on coarse filesystems. When a file is rewritten
in-place (same inode, same mtime tick, same byte size), the cache returns
the old parsed config for up to 60s.
Fix: on cache hit, read the first 128 characters of the file and compare
against the stored prefix from when the entry was populated. If they differ,
the content has changed — fall through to re-parse. Cost on hot path: one
128-char read + string comparison (negligible vs YAML parse).
Three unaddressed Greptile review comments fixed:
P1 - Empty scenes skip check (api/models.py):
When the cached session had no anchor_activity_scenes, the scene-comparison
branch was skipped entirely by the 'if cached_scenes:' guard. An inactive
session would return False (cache fresh) even when disk had gained its first
scene record. Add an else clause that checks disk for scene records when the
cache has none.
P2 - Draft slow log sink (api/routes.py):
The /api/session/draft handler's slow-path log (>200ms) used logger.warning,
which is silently dropped in the WebUI process (root logger has no handler).
Route through handler._safe_webui_print() instead, the same fix applied to
the /api/session slow log in tier2c.
P2 - Config cache same-timestamp stale (api/routes.py):
The profile config.yaml cache key (profile_name, mtime, size) could collide
on coarse-mtime filesystems (FAT, some network FS) when a config edit within
the same timestamp tick happened to produce the same byte count. Add st_ino
(inode) to the cache key — most editors use atomic-rename writes which assign
a new inode, so the key changes even when mtime+size are identical.
Greptile review caught that /api/session handler calls _diag.maybe_start()
at entry and _diag.finish() only on the success path. Three exit paths
leaked the watchdog entry:
1. early-return when sid is missing (400)
2. early-return when session is not visible to active profile (409)
3. early-return when session not found (404)
4. the existing 'except KeyError:' branch at the bottom of the handler
Without _diag.finish() the watchdog's _watchdog_pending dict held the request
until the 5s slow-request timeout fired _on_timeout and emitted a spurious
'Slow WebUI request still running' log. The pending dict also stayed
unbounded by in-flight count.
Fix: every early-return path now calls _diag.finish() before returning;
the except KeyError branch calls it once at entry so all paths through
it are covered. finish() is idempotent (no-ops if already called).
Greptile review caught that the Tier 1a fast-path returns 'cache fresh' when
disk_count == cached_count AND the session is inactive, but api/routes.py
saves the sidecar after editing only anchor_activity_scenes (no message
change). That path leaves the cached scene records stale until the cache is
otherwise invalidated.
Fix: when the cached session has scene records, also compare them against
the disk's scenes via the same metadata-prefix read that _persisted_message_count
already does. anchor_activity_scenes is in METADATA_FIELDS and serializes
before messages, so it lands in the prefix.
New _persisted_session_meta_prefix() helper exposes the parsed prefix dict;
_cached_session_lags_disk reads it and compares scene key sets + max
updated_at against the cached session.
Cost: one extra dict parse per cache hit on sessions that have scene
records, no cost on sessions without. Inactive sessions still take the
fast-path exit when scenes match.
Tier 2c-followup added print_fn=handler._safe_webui_print to the
/api/session handler so its [SLOW] line and structured
'RequestDiagnostics' log actually land in the systemd journal (the
WebUI process boots with no root-logger handler, so logger.warning
calls are silently dropped — the per-request ms line has always
worked because it bypasses logging and writes via _safe_webui_print).
There are 4 OTHER call sites of RequestDiagnostics.maybe_start() in
api/routes.py (for /api/models, /api/sessions, /api/profiles, and the
generic POST dispatch). All four were wired with the same broken
logger.warning path, so their structured slow logs have been silent
in production as well.
This commit:
- passes print_fn=getattr(handler, '_safe_webui_print', None) to
the same 4 call sites
- keeps the existing stage() and finish() call shape intact
- the existing /api/sessions handler already has stage() markers
(load_settings, profile_lookups, response_write) so the [SLOW]
log on sidebar-list will now show real per-stage breakdown
No behavior change on the happy path. No public API change. The
allowlist still gates which paths get a diag at all; this only
fixes the sink for the structured log on the 4 already-instrumented
endpoints.
Tier 2c added per-stage instrumentation on /api/session and added
'GET /api/session' to the RequestDiagnostics allowlist, but the
structured log emitted by RequestDiagnostics.finish() and the
pre-existing [SLOW] line both call logger.warning() — which the
WebUI process silently drops because the root logger has no handler
configured at boot.
The per-request 'ms' line has worked all along because it goes
through handler._safe_webui_print(), which writes directly to the
systemd journal socket.
This commit:
- adds a print_fn= parameter to RequestDiagnostics.__init__ and
RequestDiagnostics.maybe_start. When provided, finish() and
_on_timeout() route through it instead of self.logger.warning.
- routes the [SLOW] line in routes.py through handler._safe_webui_print
instead of logger.warning.
- passes print_fn=handler._safe_webui_print from the /api/session
handler to RequestDiagnostics.maybe_start.
After this fix, every slow /api/session request (and the existing
[SLOW] line) actually lands in the journal — the very data Tier 2c
was supposed to produce. Without this, the allowlist + handler
instrumentation would be a no-op in production despite the code
being present.
Measured: the same 2.97s /api/session call (sid 295592fd560e,
m=1 ml=30) which produced a per-request ms line but no [SLOW] line
before this fix, now produces both lines with full per-stage breakdown.
No public API change. The new print_fn parameter is optional and
defaults to None, preserving the existing logger.warning behavior
for any caller that hasn't been updated.
_read_profile_model_config() fires on every chat-open that hits the
resolve_model=1 path (one of the 3 calls in the chat-open waterfall).
For sessions under a named profile (non-default), the function
performs:
- 1× os.path.isfile() call
- 1× open() of config.yaml
- 1× yaml.safe_load() of the full file
On a Celeron N3350 with eMMC the open+safe_load alone is single-digit
ms per call, repeated on every chat-open. The /api/session 24h log
showed ?messages=0&resolve_model=1 at p50 1514ms with this YAML
parse as one of the dominant costs.
This wraps the parse in a per-process cache:
- key = (profile_name, mtime, size)
- value = parsed dict + monotonic timestamp
- TTL 60s as a backstop for filesystem mtime resolution issues
- cap 32 entries (bounded; profiles are bounded in practice)
mtime+size auto-invalidates on edit. The TTL only fires when mtime
resolution is too coarse to detect a same-second write; in normal
operation, every config edit lands as a different mtime and the next
chat-open rebuilds the cache entry.
Threading: a single Lock guards the dict. yaml.safe_load is the slow
step, not the lock, so contention is bounded. The lock is held for
microseconds on hit and milliseconds on miss (parse).
Field-semantics check: the function's signature is unchanged
((provider, default, config_dict) tuple) and the only call sites
(_resolve_effective_session_model_for_display and its sibling)
treat it the same as before. The cache stores the parsed dict;
the function still does the per-call (provider, default) extraction
inline so the tuple's content is identical to the pre-patch path.
No public API change. No behavior change observable other than
faster chat-open for sessions under named profiles.
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.
Adds monotonic-clock stage markers around the existing
/api/session/draft hot path so we can decompose wall time by phase
(get_session, lock acquire, save, json emit). Logs a single WARNING
line only when total > 200ms — keeps the per-keystroke poll cheap
while still catching the slow cases that justify further work.
This is the source of the slow-path data needed to plan Tier 2:
without stage breakdowns on /api/session/draft, every subsequent
patch on this endpoint is a guess.
The existing _t0.._t6 pattern on /api/session (gated on
HERMES_DEBUG_SLOW) is intentionally NOT extended here — the env-var
gate requires a manual restart and is not useful for routine
production diagnosis. The new stage markers log via the standard
[webui] WARNING channel and require no env var.
No semantic change. No public API change. Logging only fires when
the request exceeds 200ms, so it is invisible on the happy path.
Prior to this change _cached_session_lags_disk() called
Session.load_metadata_only(sid) on every LRU cache hit, parsing the
full sidecar JSON (~15-20ms even for a 1.3MB sidecar on Celeron+ eMMC).
For draft auto-saves hitting get_session() on every keystroke debounce
(~400ms cadence while typing), that 15-20ms multiplied out to ~75% of
the request's wall time on the Chromebook.
Reorder the check: read only the JSON metadata prefix
(_persisted_message_count, already defined for the LRU-eviction path)
to compare message counts. For INACTIVE sessions
(no active_stream_id, no pending_user_message) with matching counts,
the cache is provably at parity with disk — anchor-scene records cannot
have advanced without the message count advancing too, and the full
Session.load_metadata_only() is skipped. For ACTIVE sessions, or when
counts differ, fall through to the original anchor-scene comparison
path so correctness is preserved.
Measured cost reduction on the request hot path: 15-20ms -> <1ms on
the typical cache-hit case (inactive session, count matches). The
slow path is unchanged for cases that genuinely need the full reload.
No public API change. No behavior change observable on user-facing
flows. The LRU eviction safety invariant (#4765) is preserved —
_session_is_evictable() still calls _persisted_message_count under
the same conditions, and Tier 1a adds NO new eviction gate.
Greptile rerun and the maintainer review both raised the same concern:
state.db and the sidecar self.messages can diverge by hundreds of
messages during recovery / mid-flight writes / pending_user_message.
On the test corpus:
0db167553ac7 db=11 sidecar=12
295592fd560e db=813 sidecar=889
7478cae31f01 db=2730 sidecar=2405
The previous patch's SQL path was reading state.db. The pre-patch
inline walk was reading self.messages (the sidecar). Sidebar stale-row
detection (_looks_like_stale_zero_message_row,
_row_may_need_sidecar_metadata_refresh) consumes this field as if the
sidecar were the source of truth, so swapping the source silently flips
the field's semantics.
Drop the SQL path entirely. The helper now does the same in-memory
walk the pre-patch code did, extracted into a named method for
visibility. The inline role check (dict.get('role') with default
empty string) is 1.7x faster than calling _message_role() per
iteration on the test corpus (2.57ms -> 1.49ms across 8 sidecars,
2405 msgs total).
Bench (2405-msg sidecar): 0.76ms per call, vs ~1.5s for the pre-patch
inline walk on the same sidecar (the original perf hotspot). The
1.5s figure included JSON parse, dict construction, and the SQLite
overhead of the now-removed SQL path; the bare walk is the
0.76ms shown here.
Correctness: 27/27 webui sidecars produce identical counts vs the
pre-patch inline walk. No behavior change for any caller.
Addresses Greptile findings (P1 silent-zero, P2 docstring, P2 dead
allowlist) by removing the SQL path entirely rather than patching
around its divergent-source issue.
Greptile flagged that _compute_user_message_count_lazy silently returns 0
when the SQLite query fails (DB locked, missing file, schema drift).
The pre-patch compact() walked self.messages in Python and returned the
correct count without ever touching the DB, so the silent zero
fallback is a regression that breaks _looks_like_stale_zero_message_row
under contention.
Fix: helper now takes an optional messages argument. On SQLite failure
it falls back to the same in-memory walk the original code used, so
callers see the same number they'd have seen before for any session
where Session.load() populated self.messages.
Also drop the dead ('GET', '/api/session') allowlist entry flagged by
Greptile — the /api/session handler already does its own per-stage
logging via the _t0.._t6 block (with auto-log on slow requests), and
adding RequestDiagnostics on top would just duplicate the slow-request
journal entries without adding information.
Session.compact() called _last_message_timestamp(self.messages) which
reversed-walked all 2,730 messages on every /api/session response.
The messages array is chronologically ordered, so the last non-tool
message sits at the very end. Scan only the last 8 messages; fall
back to a full scan only if no timestamp is found in the window
(unusual sessions with >8 trailing tool rows).
Reverts to identical behavior when the window hits, since the most
recent user/assistant message's timestamp is what compact() emits.
Bench (single-shot, live Chromebook eMMC):
before: get_session=1107ms compact=1725ms total=2880ms
after: get_session= 648ms compact= 288ms total=1313ms
(-80% on compact, -54% on total)
Revert: git checkout master && systemctl --user restart hermes-webui
Adds auto-logging when total /api/session latency exceeds 2s, so we don't
need HERMES_DEBUG_SLOW env var to diagnose regressions in production.
Env var still forces logging on every request for development.
Baseline data on the Chromebook (Celeron N3350, eMMC storage):
- long_session_idle (2,445 msgs) p50=5.8s, p95=9.1s, max=9.7s, 2/10 timeouts
- stage breakdown for a 2.8s request:
get_session=1041ms, compact=1717ms, redact=31ms, json_write=8ms
- compact stage iterates all messages for user_message_count and runs
recursive redact_session_data + json.dumps -- biggest single cost
Ref: perf/session-load-latency
The slow-request journal showed /api/profiles, /api/models, and /api/session
fire on every session click but had no per-stage timing. Add:
- RequestDiagnostics coverage for GET /api/profiles, /api/models, /api/session
- Stage markers inside /api/profiles (list / active lookup / isolated check)
- Stage markers inside /api/models (freshness routing, serialize)
- Per-stage stage-log inside get_available_models_for_session_visit that
emits a [SLOW] line when total wall time crosses HERMES_DEBUG_SLOW ms
(default 500ms) so we can pinpoint which sub-step is blocking
No behavior change. Existing _t0.._t6 timing on /api/session and the
2.5s/10s TTL on /api/sessions are unchanged. Reversible: revert commit.
Konstantin M