From 0b3a50f1088bbcc6333f9bafd18937c8ea8e78a1 Mon Sep 17 00:00:00 2001 From: teknium1 <127238744+teknium1@users.noreply.github.com> Date: Fri, 24 Jul 2026 21:58:17 -0700 Subject: [PATCH] fix(sessions): measure reclaimed space with SQLite page accounting MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- hermes_cli/main.py | 35 +++++++- hermes_state.py | 43 +++++++++ .../test_sessions_size_delta_label.py | 28 ++++++ tests/test_hermes_state.py | 87 +++++++++++++++++++ 4 files changed, 190 insertions(+), 3 deletions(-) create mode 100644 tests/hermes_cli/test_sessions_size_delta_label.py diff --git a/hermes_cli/main.py b/hermes_cli/main.py index 8ea4c22132bc..e33ba92c35a6 100644 --- a/hermes_cli/main.py +++ b/hermes_cli/main.py @@ -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 " diff --git a/hermes_state.py b/hermes_state.py index 63e3caa51b4b..ac9ed5e5b2c2 100644 --- a/hermes_state.py +++ b/hermes_state.py @@ -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. diff --git a/tests/hermes_cli/test_sessions_size_delta_label.py b/tests/hermes_cli/test_sessions_size_delta_label.py new file mode 100644 index 000000000000..88e90ce18dd6 --- /dev/null +++ b/tests/hermes_cli/test_sessions_size_delta_label.py @@ -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 diff --git a/tests/test_hermes_state.py b/tests/test_hermes_state.py index 74af22c08e1f..bd53684ed58e 100644 --- a/tests/test_hermes_state.py +++ b/tests/test_hermes_state.py @@ -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."""