phase: 14_store_performance
**Phase 14 `store_performance` — final verification pass (all 4 tasks already in `complete/`)** - Re-verified every task's work in the tree: read caches (`series_names`/`stats`), capped compound `pick_res_many`, `history_many` + `api._history_batch`, windowed `maintain()` + per-resolution prune + `PRAGMA optimize`/`automatic_analyze=0`/WAL pragmas, `store_perf.BUDGETS` (14 ceilings), probe, live watch. - **Completion criteria:** baseline+after side by side in `data/logs/NOTES-store-perf.md` ✅ · budget tests green (`uv run pytest -m store_perf --store-perf` → **4 passed**, 14/14 inside) ✅ · 25-min dev-server watch re-run **independently** (74 passes, `scripts/watch-store-perf.py`): **0 `store-error`** (total still 190, newest 2026‑10‑18 06:33:30), WAL 7.77 MB ≤ 67.1 MB, medians 1.7–3.2 ms, p95 720/613 ms = the documented cold-cache window; a 3rd 27-pass watch on a freshly restarted server reproduced it (3.1/708, 1.8/572) ✅ · `maintain()` 5,368 ms → 2.7–6.8 ms and WAL bounded across two cycles (test + notes) ✅ · no behaviour change (all four history routes pinned against `query()`) ✅ - **Full gates:** `uv run pytest` → **1267 passed, 15 skipped**; `bash .agents/validate.sh` → **exit 0**, coverage **98.75%** (floor 94), `ruff check src tests agent` clean, `pyright` 0 errors, `node --check` ok, repo hygiene ok; `uv run pytest -m live --live` → **11 passed**; dev server up, 9/9 sources `ok`, pages 200 in 1.5–3.3 ms. - **Docs fixed:** README/AGENTS still claimed a flat "20 s per pass" while `host_agent.py` (in this same uncommitted change) scales the budget to 5 s × disk count — corrected in both plus the two illustrative "20 s of wedged disk" sentences; broken bold (`` `driveripper** ``) repaired; stale gap-4 title + "tuning is its own phase" wording updated to say phase 14 ran; README's absolute "nothing … is answered by a whole-table scan" qualified to *per call* with the cold-window cost named; "third opt-in marker" → second; conftest `--store-perf` help named the real marker; **`data/logs/watch-store-perf.py` moved to `scripts/watch-store-perf.py`** (both docs told a clone to run a gitignored path) with root-anchored paths, `DASH_WATCH_OUT`, and dead code removed. - **New finding recorded:** gap 9's "~10 s process-wide stall is still gap 4's / `14_store_performance`'s problem" is now closed — coincident >8 s `llm` + >12 s `ups` raw-stream gaps went 393 (00:00–12:00) and 198 (12:00–21:36) to **0** across 110+ min of the phase-14 store; written into AGENTS.md gaps 4 and 9 and the notes table. - **Deviations:** did *not* pull either deferred cost knob (`STATS_CACHE_TTL_SECONDS`, warming caches from the maintenance tick) — AGENTS.md records that decision and its reasoning; `uv pip list --outdated` still reports certifi/fastapi/starlette/websockets (pre-existing advisory, no dependency touched this phase, gate treats it as advisory). Overwrote nothing: task 04's watch preserved as `store-perf-watch.task04.*`, my two runs as `.verify25.*` / `.current-code.*`. - **Next pending phase:** `15_agent_mtls`, then `16_agent_smart_pass_budget` (owns the scaled-budget tests + its doc criterion, now partly pre-satisfied by this pass), `17_installer_device_filter`.
This commit is contained in:
Executable
+194
@@ -0,0 +1,194 @@
|
||||
#!/usr/bin/env python3
|
||||
"""Phase 14 task 04: watch the running dev server for `database is locked`.
|
||||
|
||||
Sampled, not exhaustive: every ~20 s a signed-in pass hits the paths a page actually loads
|
||||
(``/api/health``, ``/api/summary``, ``/api/metrics``, a 3-host x 9-metric 90-day
|
||||
``/api/system/history``) and records the wall time beside the store's own evidence — the
|
||||
``store-error`` rows in the ``event`` table, the WAL file size, the database size.
|
||||
|
||||
Run it in the background while the dev server keeps polling the fleet:
|
||||
|
||||
set -a; . ./.env.dev; set +a
|
||||
setsid nohup uv run python scripts/watch-store-perf.py > /tmp/watch.out 2>&1 < /dev/null &
|
||||
|
||||
Writes ``data/logs/store-perf-watch.log`` (human), ``store-perf-watch.tsv`` (machine) and
|
||||
``store-perf-watch.json`` (the summary every path ran against). ``data/`` is gitignored, so those
|
||||
are local evidence for ``data/logs/NOTES-store-perf.md``, never tracked artifacts.
|
||||
"""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import json
|
||||
import os
|
||||
import sqlite3
|
||||
import statistics
|
||||
import sys
|
||||
import time
|
||||
from pathlib import Path
|
||||
|
||||
import httpx
|
||||
|
||||
#: Repo root, so the paths below mean the same tree wherever the watch is invoked from
|
||||
#: (the same anchor ``scripts/store_perf_probe.py`` uses).
|
||||
ROOT = Path(__file__).resolve().parents[1]
|
||||
|
||||
BASE_URL = os.environ.get("DASH_WATCH_URL", "http://127.0.0.1:8090")
|
||||
ADMIN_PASSWORD = os.environ.get("DASH_ADMIN_PASSWORD", "")
|
||||
DB_PATH = Path(os.environ.get("DASH_WATCH_DB", ROOT / "data" / "dashboards.sqlite3"))
|
||||
OUT = Path(os.environ.get("DASH_WATCH_OUT", ROOT / "data" / "logs"))
|
||||
DURATION_SECONDS = float(os.environ.get("DASH_WATCH_SECONDS", "1500"))
|
||||
INTERVAL_SECONDS = float(os.environ.get("DASH_WATCH_INTERVAL", "20"))
|
||||
|
||||
#: What a page load may cost. Everything here is a panel the operator is looking at.
|
||||
PAGE_BUDGET_MS = 250.0
|
||||
|
||||
METRICS = [
|
||||
"cpu.usage_pct", "cpu.temp_c", "cpu.load1", "mem.used_pct", "disk.used_pct@/",
|
||||
"disk.used_pct@/home", "net.rx_bps", "net.tx_bps", "gpu.busy_pct@0",
|
||||
]
|
||||
|
||||
|
||||
def store_evidence(db: sqlite3.Connection, since: float) -> dict[str, float | int | str]:
|
||||
"""The store's own record, read on a separate connection while the server runs."""
|
||||
total = db.execute("SELECT COUNT(*) FROM event WHERE kind='store-error'").fetchone()[0]
|
||||
recent = db.execute(
|
||||
"SELECT COUNT(*) FROM event WHERE kind='store-error' AND ts>=?", (since,)
|
||||
).fetchone()[0]
|
||||
last = db.execute(
|
||||
"SELECT message FROM event WHERE kind='store-error' ORDER BY ts DESC LIMIT 1"
|
||||
).fetchone()
|
||||
return {
|
||||
"store_errors_total": total,
|
||||
"store_errors_in_window": recent,
|
||||
"last_store_error": (last[0] if last else ""),
|
||||
}
|
||||
|
||||
|
||||
def timed(client: httpx.Client, path: str) -> tuple[float, int]:
|
||||
started = time.perf_counter()
|
||||
try:
|
||||
response = client.get(path)
|
||||
code = response.status_code
|
||||
except httpx.HTTPError: # a refused request is a sample too
|
||||
return (time.perf_counter() - started) * 1000.0, -1
|
||||
return (time.perf_counter() - started) * 1000.0, code
|
||||
|
||||
|
||||
def main() -> int:
|
||||
started = time.perf_counter()
|
||||
OUT.mkdir(parents=True, exist_ok=True)
|
||||
log_path = OUT / "store-perf-watch.log"
|
||||
tsv_path = OUT / "store-perf-watch.tsv"
|
||||
json_path = OUT / "store-perf-watch.json"
|
||||
samples: list[dict[str, float | int | str]] = []
|
||||
|
||||
client = httpx.Client(base_url=BASE_URL, timeout=60.0, follow_redirects=False)
|
||||
login = client.post("/api/auth/login", json={"username": "admin", "password": ADMIN_PASSWORD})
|
||||
if login.status_code != 200:
|
||||
print(f"login failed: {login.status_code} {login.text[:200]}", flush=True)
|
||||
return 1
|
||||
client.headers["X-CSRF-Token"] = login.json()["csrf"]
|
||||
|
||||
hosts = [t["name"] for t in client.get("/api/config").json()["system"]["targets"]]
|
||||
host_query = "".join(f"hosts={h}&" for h in hosts) or "hosts=driveripper&"
|
||||
metrics_query = "".join(f"metrics={m}&" for m in METRICS)
|
||||
paths = {
|
||||
"health": "/api/health",
|
||||
"summary": "/api/summary",
|
||||
"metrics": "/api/metrics?source=host",
|
||||
"history_90d": f"/api/system/history?{host_query}{metrics_query}range=90d",
|
||||
}
|
||||
|
||||
db = sqlite3.connect(f"file:{DB_PATH}?mode=ro", uri=True, timeout=30.0)
|
||||
started_wall = time.time()
|
||||
with log_path.open("a", buffering=1) as log:
|
||||
log.write(f"# watch start {time.strftime('%Y-%m-%dT%H:%M:%S')} "
|
||||
f"budget={PAGE_BUDGET_MS:.0f} ms interval={INTERVAL_SECONDS:.0f} s "
|
||||
f"duration={DURATION_SECONDS:.0f} s hosts={hosts}\n")
|
||||
while time.perf_counter() - started < DURATION_SECONDS:
|
||||
row: dict[str, float | int | str] = {
|
||||
"t": round(time.time(), 1),
|
||||
"elapsed_s": round(time.perf_counter() - started, 1),
|
||||
}
|
||||
for name, path in paths.items():
|
||||
ms, code = timed(client, path)
|
||||
row[f"{name}_ms"] = round(ms, 1)
|
||||
row[f"{name}_code"] = code
|
||||
wal = DB_PATH.with_name(DB_PATH.name + "-wal")
|
||||
row["wal_mb"] = round((wal.stat().st_size if wal.exists() else 0) / 1e6, 2)
|
||||
row["db_mb"] = round(DB_PATH.stat().st_size / 1e6, 1)
|
||||
try:
|
||||
row.update(store_evidence(db, started_wall))
|
||||
except sqlite3.Error as exc:
|
||||
row["store_errors_total"] = -1
|
||||
row["store_errors_in_window"] = -1
|
||||
row["last_store_error"] = f"read failed: {exc}"
|
||||
samples.append(row)
|
||||
worst = max(float(row[f"{n}_ms"]) for n in paths)
|
||||
log.write(
|
||||
f"{row['t']} elapsed={row['elapsed_s']:7.1f}s "
|
||||
+ " ".join(f"{n}={row[f'{n}_ms']:7.1f}ms" for n in paths)
|
||||
+ f" worst={worst:7.1f}ms wal={row['wal_mb']}MB db={row['db_mb']}MB"
|
||||
+ f" store-error(total={row['store_errors_total']},"
|
||||
f" in-window={row['store_errors_in_window']})\n"
|
||||
)
|
||||
time.sleep(INTERVAL_SECONDS)
|
||||
|
||||
# ---- summary
|
||||
def stat(name: str, fn) -> float:
|
||||
values = [float(s[f"{name}_ms"]) for s in samples]
|
||||
return round(fn(values), 1)
|
||||
|
||||
summary: dict[str, object] = {
|
||||
"started": time.strftime("%Y-%m-%dT%H:%M:%S", time.localtime(started_wall)),
|
||||
"duration_seconds": round(time.perf_counter() - started, 1),
|
||||
"passes": len(samples),
|
||||
"db": str(DB_PATH),
|
||||
"db_mb_first": samples[0]["db_mb"],
|
||||
"db_mb_last": samples[-1]["db_mb"],
|
||||
"wal_mb_first": samples[0]["wal_mb"],
|
||||
"wal_mb_max": max(float(s["wal_mb"]) for s in samples),
|
||||
"wal_mb_last": samples[-1]["wal_mb"],
|
||||
"store_errors_total": samples[-1]["store_errors_total"],
|
||||
"store_errors_in_window": samples[-1]["store_errors_in_window"],
|
||||
"last_store_error": samples[-1]["last_store_error"],
|
||||
"paths": {
|
||||
name: {
|
||||
"median_ms": stat(name, statistics.median),
|
||||
"p95_ms": stat(name, lambda v: sorted(v)[max(0, int(len(v) * 0.95) - 1)]),
|
||||
"max_ms": stat(name, max),
|
||||
}
|
||||
for name in paths
|
||||
},
|
||||
"budget_ms": PAGE_BUDGET_MS,
|
||||
"passes_over_budget": sum(
|
||||
1 for s in samples if max(float(s[f"{n}_ms"]) for n in paths) > PAGE_BUDGET_MS
|
||||
),
|
||||
"non_200_responses": sum(
|
||||
1 for s in samples for n in paths if int(s[f"{n}_code"]) not in (200, 404)
|
||||
),
|
||||
}
|
||||
json_path.write_text(json.dumps({"summary": summary, "samples": samples}, indent=2) + "\n")
|
||||
with log_path.open("a", buffering=1) as log:
|
||||
log.write("# summary\n")
|
||||
for name, values in summary["paths"].items(): # type: ignore[index]
|
||||
log.write(f"# {name:12s} median={values['median_ms']:8.1f} ms "
|
||||
f"p95={values['p95_ms']:8.1f} ms max={values['max_ms']:8.1f} ms\n")
|
||||
log.write(f"# store-error rows in window: {summary['store_errors_in_window']} "
|
||||
f"(total {summary['store_errors_total']})\n")
|
||||
log.write(f"# WAL first/max/last MB: {summary['wal_mb_first']} / "
|
||||
f"{summary['wal_mb_max']} / {summary['wal_mb_last']}\n")
|
||||
log.write(f"# passes over the {PAGE_BUDGET_MS:.0f} ms budget: "
|
||||
f"{summary['passes_over_budget']} of {summary['passes']}\n")
|
||||
|
||||
header = ["t"] + [f"{n}_ms" for n in paths] + ["wal_mb", "db_mb", "store_errors_in_window"]
|
||||
with tsv_path.open("w") as tsv:
|
||||
tsv.write("\t".join(header) + "\n")
|
||||
for sample in samples:
|
||||
tsv.write("\t".join(str(sample.get(key, "")) for key in header) + "\n")
|
||||
print(json.dumps(summary, indent=2))
|
||||
return 0
|
||||
|
||||
|
||||
if __name__ == "__main__":
|
||||
sys.exit(main())
|
||||
Reference in New Issue
Block a user