fix(sessions): measure reclaimed space with SQLite page accounting

Builds on @ms-alan's label fix: the negative figure had a second cause
that relabelling alone leaves in place.

`hermes sessions optimize-storage` reported "reclaimed -3820.1 MB" on a
database that had in fact shrunk 60% (25069 MB -> 9975 MB). Both figures
came from os.path.getsize(). In WAL mode a VACUUM's rewrite lands in the
-wal file, and the checkpoint that folds it back is REFUSED
(SQLITE_BUSY) while any other connection holds a read-mark — e.g. the
live gateway. So the main file still carried its pre-VACUUM size AND kept
growing while the command ran, making the after-figure larger than the
before-figure. The TRUNCATE checkpoint in close() lands after the caller
has already measured and printed.

- hermes_state.py: add SessionDB.logical_size_bytes() — page_count *
  page_size, the size the file settles at once the WAL is folded back.
  Correct immediately, readers or not; returns None when the connection
  is gone so callers fall back to stat().
- hermes_state.py: best-effort TRUNCATE checkpoint after the optimize
  VACUUM so the file settles promptly when nothing else holds the DB.
  Documented as insufficient alone (busy under a live gateway) so the
  stat() approach is not reintroduced.
- hermes_cli/main.py: both `optimize-storage` and `optimize` report via
  logical_size_bytes(); fixing only the reported command would have left
  the same bug class next door.
- hermes_cli/main.py: lift the contributor's inline label to a
  module-level _size_delta_label() shared by both sites, so the "grew by"
  wording is consistent and unit-testable without reading source.

The two halves are complementary: page accounting removes the phantom
negative, and "grew by" still covers a genuine increase when concurrent
session writes outweigh what the rebuild freed.

Verified: sabotaging logical_size_bytes() back to stat() fails the new
test with a 22 MB overstatement, reproducing the report. The test asserts
its own precondition (stat() must actually be lagging) so it cannot
silently stop exercising the bug.

Tests: 464 passed (test_hermes_state.py + the new label tests).

Co-authored-by: chenbin <h-chenbin@voyah.com.cn>
This commit is contained in:
teknium1 2026-07-24 21:58:17 -07:00 committed by Teknium
parent 58b2a8c192
commit 0b3a50f108
4 changed files with 190 additions and 3 deletions

View file

@ -10228,6 +10228,19 @@ def _ensure_fhs_path_guard() -> None:
print(" (reload your shell or run 'source ~/.bashrc' to pick it up)")
def _size_delta_label(saved_mb: float) -> str:
"""Human label for a before/after database size delta, in MB.
A negative delta means the file GREW concurrent session writes during a
long optimize can outweigh what the rebuild freed. Printing
"reclaimed -163.0 MB" for that reads as data loss, so say "grew by"
instead.
"""
if saved_mb >= 0:
return f"reclaimed {saved_mb:.1f} MB"
return f"grew by {-saved_mb:.1f} MB"
_PRE_UPDATE_SNAPSHOT_KEEP = 1
# Per-file size cap for the pre-update quick snapshot. Anything larger is
@ -16674,11 +16687,18 @@ def main():
if db_path.exists()
else 0.0
)
# Same WAL caveat as optimize-storage: after a VACUUM the main file
# on disk lags until the WAL is checkpointed back (refused while a
# live gateway holds a read-mark), so stat() understates the win and
# can go negative. SQLite's page accounting is correct immediately.
logical_after = db.logical_size_bytes()
if logical_after is not None:
after_mb = logical_after / (1024 * 1024)
saved = before_mb - after_mb
print(f"Optimized {n} FTS index(es).")
print(
f"Database size: {before_mb:.1f} MB -> {after_mb:.1f} MB "
f"(reclaimed {saved:.1f} MB)"
f"({_size_delta_label(saved)})"
)
elif action == "optimize-storage":
@ -16761,12 +16781,21 @@ def main():
after_mb = (
os.path.getsize(db_path) / (1024 * 1024) if db_path.exists() else 0.0
)
# Prefer SQLite's own page accounting over stat(). In WAL mode a
# VACUUM's rewrite sits in the -wal file until a checkpoint folds it
# back, and that checkpoint is refused while another connection (a
# live gateway) holds a read-mark — so the main file on disk still
# reads at its pre-VACUUM size and keeps growing. stat()ing it here
# reported "reclaimed -3820.1 MB" on a DB that had actually shrunk
# 60%. page_count * page_size is correct immediately.
logical_after = db.logical_size_bytes()
if logical_after is not None:
after_mb = logical_after / (1024 * 1024)
saved = before_mb - after_mb
saved_label = f"reclaimed {saved:.1f} MB" if saved >= 0 else f"grew by {-saved:.1f} MB"
print(f"\n✓ Search index optimized.")
print(
f" Database size: {before_mb:.1f} MB -> {after_mb:.1f} MB "
f"({saved_label})"
f"({_size_delta_label(saved)})"
)
if result.get("vacuumed") is False:
print(" (VACUUM was skipped or failed — run "

View file

@ -2811,6 +2811,21 @@ class SessionDB:
# reclaimed until a later VACUUM. Non-fatal.
logger.warning("VACUUM after FTS optimize failed: %s", exc)
vacuum_ok = False
# Best-effort: fold the WAL back into the main file so the on-disk
# size settles now rather than at close(). NOTE this is REFUSED
# (SQLITE_BUSY) while any other connection holds a WAL read-mark —
# e.g. a live gateway sharing the DB — so it is not sufficient on
# its own. Callers must therefore NOT size the result by stat()ing
# the file; use :meth:`logical_size_bytes`, which is truthful
# immediately regardless of readers.
try:
with self._lock:
self._conn.execute("PRAGMA wal_checkpoint(TRUNCATE)")
except Exception as exc:
logger.debug(
"WAL checkpoint (TRUNCATE) after optimize VACUUM failed: %s",
exc,
)
# Phase 4: stamp the FTS storage layout as current, clear the "available"
# flag, and advance schema_version if it was somehow still behind (the
@ -10180,6 +10195,34 @@ class SessionDB:
)
return rebuilt
def logical_size_bytes(self) -> Optional[int]:
"""Database size in bytes as SQLite itself accounts for it.
``page_count * page_size`` the size the main DB file will have once
the WAL is checkpointed back into it.
Prefer this over ``os.path.getsize(db_path)`` when reporting the effect
of a VACUUM. In WAL mode a VACUUM's rewrite lands in the ``-wal`` file,
and the checkpoint that folds it back is refused while any other
connection (a live gateway) holds a read-mark. Until that happens the
main file on disk still carries its pre-VACUUM size and keeps growing,
so a stat()-based before/after delta understates the win and can go
negative the "reclaimed -3820.1 MB" report on a database that had
actually shrunk 60%.
Returns None if the pragmas cannot be read.
"""
try:
with self._lock:
if self._conn is None:
return None
page_count = self._conn.execute("PRAGMA page_count").fetchone()[0]
page_size = self._conn.execute("PRAGMA page_size").fetchone()[0]
return int(page_count) * int(page_size)
except Exception as exc:
logger.debug("Could not read logical DB size: %s", exc)
return None
def vacuum(self) -> int:
"""Run VACUUM to reclaim disk space after large deletes.

View file

@ -0,0 +1,28 @@
"""Tests for the session-store size-delta label (`hermes sessions optimize*`).
A negative before/after delta means the DB grew printing
"reclaimed -163.0 MB" for that reads as data loss (issue #70146).
"""
from hermes_cli.main import _size_delta_label
def test_shrink_reports_reclaimed():
assert _size_delta_label(15094.1) == "reclaimed 15094.1 MB"
def test_growth_reports_grew_by_not_negative_reclaimed():
label = _size_delta_label(-163.0)
assert label == "grew by 163.0 MB"
assert "reclaimed" not in label
assert "-" not in label
def test_zero_delta_reports_reclaimed_zero():
assert _size_delta_label(0.0) == "reclaimed 0.0 MB"
def test_no_negative_number_ever_rendered():
"""Whatever the sign, the rendered number is never negative."""
for value in (-9999.9, -0.1, 0.0, 0.1, 9999.9):
assert "-" not in _size_delta_label(value), value

View file

@ -5929,6 +5929,93 @@ class TestFTSExternalContentMigration:
finally:
db.close()
def test_optimize_fts_storage_vacuum_reports_truthful_size(self, tmp_path):
"""``logical_size_bytes()`` must be truthful the moment optimize returns.
In WAL mode VACUUM's rewrite lands in the ``-wal`` file, and the
checkpoint that folds it back is REFUSED (SQLITE_BUSY) while another
connection a live gateway holds a read-mark. A caller that sizes
the result with ``os.path.getsize()`` therefore reads the stale,
still-growing main file: that is how `hermes sessions optimize-storage`
reported "reclaimed -3820.1 MB" on a DB that had actually shrunk 60%.
SQLite's own page accounting is correct immediately.
"""
db_path = tmp_path / "v22.db"
self._build_v22_db(db_path)
# Bulk the DB up so VACUUM actually has pages to move: with only a
# handful of rows the whole file fits in the WAL's first frames and the
# stale-stat() bug is invisible.
bulk = sqlite3.connect(str(db_path))
bulk.executemany(
"INSERT INTO messages (session_id, timestamp, role, content) "
"VALUES ('s1', ?, 'user', ?)",
[(time.time(), "filler " + "q" * 2000) for _ in range(4000)],
)
bulk.commit()
bulk.close()
db = SessionDB(db_path=db_path)
reader = None
try:
if db._conn.execute("PRAGMA journal_mode").fetchone()[0].lower() != "wal":
pytest.skip("WAL unavailable on this SQLite build")
# A live gateway/CLI session pinning a WAL read-mark, which is what
# blocks the post-VACUUM checkpoint.
reader = sqlite3.connect(str(db_path))
reader.execute("BEGIN")
reader.execute("SELECT COUNT(*) FROM messages").fetchone()
assert db.optimize_fts_storage(vacuum=True)["ok"] is True
reported = db.logical_size_bytes()
assert reported is not None
stat_size = db_path.stat().st_size
# Settle for real: release the reader, then checkpoint.
reader.rollback()
reader.close()
reader = None
db._conn.execute("PRAGMA wal_checkpoint(TRUNCATE)")
settled = db_path.stat().st_size
page_size = db._conn.execute("PRAGMA page_size").fetchone()[0]
# Precondition for this test to mean anything: stat() must actually
# be lagging here, otherwise it isn't exercising the bug.
assert stat_size > settled + page_size, (
"test precondition failed: stat() did not lag the settled size, "
"so this case does not exercise the reporting bug"
)
# The contract: the reported size tracks where the file lands, not
# the stale on-disk size.
assert abs(reported - settled) <= page_size, (
f"logical_size_bytes() reported {reported} but the file settled "
f"at {settled} (stale stat() read {stat_size}) — a "
f"reclaimed-bytes delta built on this would be wrong"
)
finally:
if reader is not None:
reader.close()
db.close()
def test_logical_size_bytes_matches_page_accounting(self, tmp_path):
"""Sanity: the helper returns page_count * page_size, or None if closed."""
db_path = tmp_path / "v22.db"
self._build_v22_db(db_path)
db = SessionDB(db_path=db_path)
try:
pc = db._conn.execute("PRAGMA page_count").fetchone()[0]
ps = db._conn.execute("PRAGMA page_size").fetchone()[0]
assert db.logical_size_bytes() == pc * ps
finally:
db.close()
# After close the connection is gone — must degrade to None, not raise,
# so callers can fall back to stat().
assert db.logical_size_bytes() is None
def test_optimize_fts_storage_resumable_after_interrupt(self, tmp_path):
"""A partially-completed optimize resumes on re-run: after demote +
one chunk, re-invoking finishes without duplicating rows."""