**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`.
1697 lines
84 KiB
Python
1697 lines
84 KiB
Python
r"""The production-shaped store phase 14 measures, and the measurements of its hot paths.
|
|
|
|
`TODO.md:7` is a complaint about speed, and a speed claim needs a "before" that is measured
|
|
rather than remembered. This module is that "before": it seeds a SQLite file with the **shape
|
|
and retention semantics of the deployed store** and times every hot read and write path of
|
|
`store.py`/`api.py` against it, so tasks 02-04 change a number they can point at.
|
|
|
|
Why a synthetic seed and not the dev DB
|
|
---------------------------------------
|
|
`AGENTS.md`'s testing policy keeps `uv run pytest` hermetic: no test opens
|
|
`data/dashboards.sqlite3`, because a test that reads the operator's live history changes
|
|
behaviour when the operator's live history changes (and a fixture assertion that passes
|
|
today and fails next month is not a test). The honest substitute is a file of the same
|
|
*shape*: the same `SampleStore` defaults for retention (`raw_keep_hours=48`,
|
|
`minute_keep_days=30`, `hour_keep_days=400` — i.e. what a 90 d chart actually reads, 1m/1h,
|
|
never raw beyond 48 h), the fleet's real metric names, the real 10 s cadence, and the same
|
|
`meta`/`event` rows the app writes.
|
|
|
|
The seeded numbers are recorded in `data/logs/NOTES-store-perf.md` together with the
|
|
dev DB's real inventory, so a reader can see where the reproduction is faithful and where it
|
|
is a deliberate subset (per-core `cpu.usage_pct@coreN` series and the `llm`/`ups`/`disks`
|
|
families are excluded — see `HOST_SERIES`).
|
|
|
|
Where the file lives
|
|
--------------------
|
|
`cache_path()` (default `data/perf/`, overridable with `DASH_PERF_STORE_DIR`) rather than a
|
|
pytest tmp dir, for two reasons that are both about the *measurement*, not convenience:
|
|
|
|
* the same physical file has to be timed before task 02 and after task 04, or the two numbers
|
|
describe two different databases; and
|
|
* the repo filesystem is a real block device, while pytest's `tmp_path` here is `tmpfs` —
|
|
RAM. Timing a store on RAM is a flattering number nobody deploys.
|
|
|
|
Write-side measurements (`measure_maintain`, the two-connection races) run against a
|
|
`scratch_copy()` of that file rather than the file itself: a catch-up rollup really does roll ten
|
|
more minutes of buckets and the pre-fix control rewrites 330 000 rows, and a baseline that moves
|
|
under the next task is not a baseline. The copy is in the same directory, so it is the same device.
|
|
|
|
The file is a cache, keyed by `SEED_VERSION` and by its own age (`MAX_CACHE_AGE_HOURS`): the
|
|
deep 1m/1h history is anchored to the time it was built, so a cache older than half a day no
|
|
longer covers "the last 90 days" and gets rebuilt. Builds are serialised with `flock` and
|
|
publish atomically, so two sessions never read a half-written store.
|
|
|
|
Nothing here is a production module: `src/dashboards` must stay free of benchmark furniture,
|
|
and coverage counts `src/dashboards` only.
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
import fcntl
|
|
import json
|
|
import math
|
|
import os
|
|
import platform
|
|
import shutil
|
|
import sqlite3
|
|
import statistics
|
|
import sys
|
|
import threading
|
|
import time
|
|
from collections.abc import Callable, Iterator
|
|
from contextlib import contextmanager
|
|
from dataclasses import asdict, dataclass, field, replace
|
|
from pathlib import Path
|
|
from typing import Any
|
|
|
|
from dashboards.store import (
|
|
HOUR,
|
|
JOURNAL_SIZE_LIMIT_BYTES,
|
|
LAST_MAINTAIN_KEY,
|
|
MAINTAIN_SLACK_SECONDS,
|
|
MINUTE,
|
|
RES_COUNT_BRANCH,
|
|
RES_HOUR,
|
|
RES_MIN,
|
|
RES_RAW,
|
|
ROLLUP_INSERT,
|
|
Event,
|
|
Sample,
|
|
SampleStore,
|
|
)
|
|
|
|
ROOT = Path(__file__).resolve().parents[1]
|
|
|
|
#: Bump when the shape below changes: the cached file is named after it, so an old cache can
|
|
#: never be mistaken for the new shape.
|
|
SEED_VERSION = "phase14-v1"
|
|
|
|
#: The seed's clock, aligned to a minute so every rollup bucket boundary is exact. Stored in
|
|
#: `meta` (`perf.seed_now`) and re-read by the verifier.
|
|
MAX_CACHE_AGE_HOURS = 12.0
|
|
|
|
#: The store's own retention defaults, restated here so the fixture cannot silently seed a
|
|
#: shape the app does not keep (`test_the_seed_uses_the_stores_own_retention` asserts it).
|
|
RAW_KEEP_HOURS, MINUTE_KEEP_DAYS, HOUR_KEEP_DAYS = 48.0, 30.0, 400.0
|
|
|
|
#: The `system` poll cadence (`HOST_INTERVAL_SECONDS` default) — the raw window's spacing.
|
|
CADENCE_SECONDS = 10.0
|
|
|
|
#: Event rows: the dev DB held ~2 800 after a few days of transitions and logins; 2 000 is
|
|
#: the same order and keeps `event` big enough for `stats()` to notice it.
|
|
EVENT_ROWS = 2000
|
|
|
|
#: Samples written by the measurements themselves (`race_*`) use this source so they can never
|
|
#: be confused with the seeded fleet, and one `delete_series` cleans them up.
|
|
RACE_SOURCE, RACE_HOST = "perf", "race-target"
|
|
|
|
#: The pass line for "did this insert wait": one poll of 30 samples costs ~1 ms, so anything
|
|
#: past this is a wait behind someone else's transaction, not the cost of the insert.
|
|
WAIT_THRESHOLD_MS = 100.0
|
|
|
|
#: `busy_timeout` in `store.py`. Production value; the race reports waits against it.
|
|
BUSY_TIMEOUT_MS = 5000
|
|
|
|
#: Wall-clock budget per race pass. One `stats()` on this store costs seconds, so "100 inserts"
|
|
#: is minutes of deliberate waiting; the report always says how many were attempted.
|
|
MAX_RACE_SECONDS = 30.0
|
|
|
|
#: Spacing between the raced inserts. The app does not insert 100 polls back to back: the hub
|
|
#: has ~9 sources writing every 2-300 s. Un-paced, the inserts finish before the contending
|
|
#: transaction even opens, and a race that never happened reports "no lock errors".
|
|
RACE_PACE_SECONDS = 0.1
|
|
|
|
#: Idle time between the maintainer's passes in the cadence-shaped race. The app maintains once
|
|
#: every 60 s, so its write transaction holds the WAL lock for a couple of seconds per minute at
|
|
#: the very most; the race compresses that minute to this. The saturated variant (`gap=0`, which is
|
|
#: what task 01 ran and what its numbers stay comparable to) holds the lock ~100% of the wall
|
|
#: clock, because the loop restarts the transaction the instant it commits — no window fixes that,
|
|
#: so it answers "can a writer starve forever", not "what does a poller wait during a rollup".
|
|
RACE_MAINTAIN_GAP_SECONDS = 1.5
|
|
|
|
META_SEED_NOW = "perf.seed_now"
|
|
META_SEED_VERSION = "perf.seed_version"
|
|
|
|
|
|
# --------------------------------------------------------------------------- #
|
|
# The shape: real hosts, real metric names, real cadence
|
|
# --------------------------------------------------------------------------- #
|
|
#: The `host`-family series one agent publishes, minus the per-core fan-out.
|
|
#:
|
|
#: Every name here is a name the deployed store actually holds (`SELECT DISTINCT metric FROM
|
|
#: sample WHERE source='host'` on the dev DB), because `series_names()`/`history()` cost
|
|
#: depends on the number of distinct names and on row width. Deliberately excluded, with the
|
|
#: consequence recorded in the NOTES rather than hidden:
|
|
#:
|
|
#: * `cpu.usage_pct@coreN` — 48 more series on driveripper. `system` stopped plotting them in
|
|
#: phase 03 (a locked decision), so no hot path of this phase reads them; including them
|
|
#: would double the raw window for the family the phase optimises.
|
|
#: * the `llm`/`ups`/`disks` families — a *mature* store holds them too (17 + 24 + 4 series at
|
|
#: 2 s / 5 s / 300 s), and the extrapolation is in the NOTES. They are out of the seed
|
|
#: because the prescribed 90-series x 48 h x 30 d x 400 d shape already lands in the dev
|
|
#: DB's order of magnitude, and a bigger fixture buys nothing this phase must decide.
|
|
BASE_SERIES: tuple[str, ...] = (
|
|
"cpu.context_switches_per_s",
|
|
"cpu.freq_mhz",
|
|
"cpu.iowait_pct",
|
|
"cpu.load1",
|
|
"cpu.load15",
|
|
"cpu.load5",
|
|
"cpu.system_pct",
|
|
"cpu.usage_pct",
|
|
"cpu.user_pct",
|
|
"disk.read_bytes_per_s",
|
|
"disk.reads_per_s",
|
|
"disk.used_bytes@/",
|
|
"disk.used_pct",
|
|
"disk.used_pct@/",
|
|
"disk.util_pct",
|
|
"disk.write_bytes_per_s",
|
|
"disk.writes_per_s",
|
|
"host.processes",
|
|
"host.uptime_seconds",
|
|
"mem.available_bytes",
|
|
"mem.cached_bytes",
|
|
"mem.swap_used_bytes",
|
|
"mem.total_bytes",
|
|
"mem.used_bytes",
|
|
"mem.used_pct",
|
|
"net.rx_bytes_per_s",
|
|
"net.rx_bytes_per_s@enp3s0",
|
|
"net.tx_bytes_per_s",
|
|
)
|
|
|
|
#: The four GPU series, on the two hosts that have a card (`gateway` has none — the shape the
|
|
#: `/system` contract calls "no GPU at all", so a plan that assumes every host has a stream
|
|
#: fails here rather than in a browser).
|
|
GPU_SERIES: tuple[str, ...] = (
|
|
"gpu.busy_pct@0",
|
|
"gpu.mem_used_pct@0",
|
|
"gpu.power_watts@0",
|
|
"gpu.temp_c@0",
|
|
)
|
|
|
|
#: host -> its series. Names are the fleet's; the values are synthetic (`_value`).
|
|
HOST_SERIES: dict[str, tuple[str, ...]] = {
|
|
"deskwork": (*BASE_SERIES, *GPU_SERIES),
|
|
"driveripper": (*BASE_SERIES, *GPU_SERIES),
|
|
"gateway": BASE_SERIES,
|
|
}
|
|
|
|
#: The nine metrics the task-01 `/api/system/history` request asks for, per host: the three
|
|
#: the utilisation chart plots, the two network rates, the worst mount, the CPU temp, and the
|
|
#: GPU stream. 3 hosts x 9 = the 27 `_history` calls the endpoint makes for one page load.
|
|
HISTORY_METRICS: tuple[str, ...] = (
|
|
"cpu.usage_pct",
|
|
"mem.used_pct",
|
|
"disk.used_pct",
|
|
"net.rx_bytes_per_s",
|
|
"net.tx_bytes_per_s",
|
|
"disk.used_pct@/",
|
|
"cpu.temp_c",
|
|
"gpu.busy_pct@0",
|
|
"gpu.temp_c@0",
|
|
)
|
|
|
|
#: The metrics `/system` actually asks a *page* for (UTIL_SERIES + NET_SERIES + one GPU), i.e.
|
|
#: the request shape `page-system.js` really makes, one per host per refresh.
|
|
PAGE_HISTORY_METRICS: tuple[str, ...] = (
|
|
"cpu.usage_pct",
|
|
"mem.used_pct",
|
|
"disk.used_pct",
|
|
"net.rx_bytes_per_s",
|
|
"net.tx_bytes_per_s",
|
|
"gpu.busy_pct@0",
|
|
)
|
|
|
|
|
|
def seed_value(metric: str, index: int) -> float:
|
|
"""Deterministic pseudo-signal for one sample: finite, plausible, never random.
|
|
|
|
Determinism is the point (`test_the_seed_is_deterministic_and_the_rollups_are_idempotent`
|
|
recomputes a rollup from this function), so there is no RNG: a phase of the row index plus
|
|
a per-metric offset. Values are plausible rather than realistic — a percentage between 0
|
|
and 100, a byte counter that grows — because a chart of them is never read; only the row
|
|
count, the row width, and the arithmetic of the rollups matter.
|
|
|
|
Public because `tests/test_store.py` recomputes stored rows from it: that is how the fixture
|
|
proves a rebuild is byte-identical to the store it measured.
|
|
"""
|
|
offset = (len(metric) * 31 + sum(ord(ch) for ch in metric[:6])) % 997
|
|
wave = math.sin((index + offset) / 360.0)
|
|
if metric.startswith(("mem.", "disk.used_bytes", "net.")):
|
|
# byte counters: hundreds of MB to tens of GB, and monotonic for the ones that are
|
|
# odometers
|
|
base = 1e8 + (offset % 40) * 5e8
|
|
return base + wave * 5e7 + index * 128.0
|
|
if metric.endswith("_bytes") or metric.endswith("_bytes_per_s"):
|
|
return 1e6 + wave * 5e5 + index * 4.0
|
|
if "temp_c" in metric:
|
|
return 45.0 + wave * 12.0
|
|
if metric.startswith("gpu.power"):
|
|
return 90.0 + wave * 40.0
|
|
if metric.startswith(("cpu.load",)):
|
|
return 2.0 + wave * 2.0
|
|
if metric.endswith("_pct") or metric.endswith("_percent"):
|
|
return 40.0 + wave * 30.0
|
|
if metric.endswith("_per_s"):
|
|
return 5_000.0 + wave * 2_000.0
|
|
if metric == "host.uptime_seconds":
|
|
return index * CADENCE_SECONDS
|
|
return 10.0 + wave * 5.0
|
|
|
|
|
|
@dataclass(frozen=True)
|
|
class SeedPlan:
|
|
"""What a build *should* contain, computed before (and independently of) the insert.
|
|
|
|
`*_steps` are rows **per series** (what the insert loops count); `*_rows` are the totals
|
|
the verifier compares against `COUNT(*)`. Confusing the two once already made this fixture
|
|
try to seed 75 million rows, which is why both are spelled out instead of derived at the
|
|
call site.
|
|
"""
|
|
|
|
now: float
|
|
hosts: tuple[str, ...]
|
|
series_total: int
|
|
raw_steps: int
|
|
minute_steps: int
|
|
hour_steps: int
|
|
events: int
|
|
|
|
@property
|
|
def raw_rows(self) -> int:
|
|
return self.series_total * self.raw_steps
|
|
|
|
@property
|
|
def minute_rows_seeded(self) -> int:
|
|
return self.series_total * self.minute_steps
|
|
|
|
@property
|
|
def hour_rows_seeded(self) -> int:
|
|
return self.series_total * self.hour_steps
|
|
|
|
@property
|
|
def sample_rows_seeded(self) -> int:
|
|
return self.raw_rows + self.minute_rows_seeded + self.hour_rows_seeded
|
|
|
|
def as_dict(self) -> dict[str, Any]:
|
|
"""The plan plus its derived totals — `dataclasses.asdict` alone would drop them."""
|
|
return {**asdict(self), "raw_rows": self.raw_rows,
|
|
"minute_rows_seeded": self.minute_rows_seeded,
|
|
"hour_rows_seeded": self.hour_rows_seeded,
|
|
"sample_rows_seeded": self.sample_rows_seeded}
|
|
|
|
|
|
def plan(now: float) -> SeedPlan:
|
|
"""The row counts a build of this shape produces, from the shape alone.
|
|
|
|
The deep 1m history starts where the raw window ends (that is what a store with 48 h of
|
|
raw retention looks like: anything older than 48 h exists only as a rollup) and the deep
|
|
1h history starts where the 1m window ends, for the same reason. The rows inside those
|
|
windows are produced by the real `maintain()`, so the rollup path is exercised rather
|
|
than faked.
|
|
|
|
Every count is in *its own* unit: a step is one row of that resolution, so the deep window
|
|
is `retention - the window the finer resolution already covers`, both converted to that
|
|
resolution's period.
|
|
"""
|
|
raw_steps = int(RAW_KEEP_HOURS * HOUR // CADENCE_SECONDS)
|
|
minute_steps = int((MINUTE_KEEP_DAYS * 24 * HOUR - RAW_KEEP_HOURS * HOUR) // MINUTE)
|
|
hour_steps = int((HOUR_KEEP_DAYS * 24 * HOUR - MINUTE_KEEP_DAYS * 24 * HOUR) // HOUR)
|
|
series = sum(len(metrics) for metrics in HOST_SERIES.values())
|
|
return SeedPlan(
|
|
now=now,
|
|
hosts=tuple(sorted(HOST_SERIES)),
|
|
series_total=series,
|
|
raw_steps=raw_steps,
|
|
minute_steps=minute_steps,
|
|
hour_steps=hour_steps,
|
|
events=EVENT_ROWS,
|
|
)
|
|
|
|
|
|
# --------------------------------------------------------------------------- #
|
|
# building
|
|
# --------------------------------------------------------------------------- #
|
|
def open_store(path: str | Path, *, extra_retention_hours: float = 0.0) -> SampleStore:
|
|
"""A `SampleStore` on `path` with the retention the seed promises.
|
|
|
|
`extra_retention_hours` is for handles that must **not** prune: the seeded store is anchored
|
|
to the time it was built, so a `maintain()` at the wall clock while the cache is six hours
|
|
old prunes six hours of raw rows, and the next session would rebuild the whole thing over a
|
|
measurement artefact. The cache's own age is the only thing past the window, and the read
|
|
paths this phase optimises (`history`, `pick_res`, `series_names`, `stats`) do not read
|
|
retention at all — so widening it for a measurement handle changes no number and keeps the
|
|
baseline byte-stable. The store under test is still opened with the real defaults.
|
|
"""
|
|
margin = extra_retention_hours
|
|
return SampleStore(path, raw_keep_hours=RAW_KEEP_HOURS + margin,
|
|
minute_keep_days=MINUTE_KEEP_DAYS + margin / 24.0,
|
|
hour_keep_days=HOUR_KEEP_DAYS + margin / 24.0)
|
|
|
|
|
|
def build(path: str | Path, *, now: float | None = None,
|
|
log: Callable[[str], None] | None = None) -> dict[str, Any]:
|
|
"""Seed `path` production-shaped and return a build report.
|
|
|
|
Insert order is `(source, host, metric, res, ts)` ascending — the primary key, and
|
|
`"1h" < "1m" < "raw"` sorts the resolutions the same way) — so the writes append instead
|
|
of splitting index pages. That is not a trick to hide cost: it is how the app itself writes
|
|
(a series' samples always arrive in time order), and the rollup inserts of `maintain()` are
|
|
the ones that scatter, which is what task 03 times.
|
|
"""
|
|
say = log or (lambda _line: None)
|
|
now = float(now if now is not None else math.floor(time.time() / MINUTE) * MINUTE)
|
|
path = Path(path)
|
|
path.parent.mkdir(parents=True, exist_ok=True)
|
|
expected = plan(now)
|
|
store = open_store(path)
|
|
started = time.perf_counter()
|
|
try:
|
|
buffer: list[tuple[str, str, str, str, float, float]] = []
|
|
|
|
def flush() -> None:
|
|
if not buffer:
|
|
return
|
|
with store._lock, store._db:
|
|
store._db.executemany("INSERT OR REPLACE INTO sample VALUES (?,?,?,?,?,?)", buffer)
|
|
buffer.clear()
|
|
|
|
def emit(source: str, host: str, metric: str, res: str, ts: float, value: float) -> None:
|
|
buffer.append((source, host, metric, res, ts, value))
|
|
if len(buffer) >= 100_000:
|
|
flush()
|
|
|
|
# One pass per series, deepest resolution first: that is primary-key order, and it is
|
|
# the only order in which a 6-million-row load does not rewrite the index behind itself.
|
|
t0 = time.perf_counter()
|
|
hour_start = now - HOUR_KEEP_DAYS * 24 * HOUR
|
|
minute_start = now - MINUTE_KEEP_DAYS * 24 * HOUR
|
|
raw_start = now - RAW_KEEP_HOURS * HOUR
|
|
window = ((RES_HOUR, hour_start, HOUR, expected.hour_steps),
|
|
(RES_MIN, minute_start, MINUTE, expected.minute_steps),
|
|
(RES_RAW, raw_start, CADENCE_SECONDS, expected.raw_steps))
|
|
for host in sorted(HOST_SERIES):
|
|
for metric in sorted(HOST_SERIES[host]):
|
|
for res, start, step, steps in window:
|
|
for index in range(steps):
|
|
emit("host", host, metric, res, start + index * step, seed_value(metric, index))
|
|
flush()
|
|
inserted_seconds = time.perf_counter() - t0
|
|
# Row counts by resolution are re-read after the fact (`counts` below); the per-
|
|
# resolution totals the NOTES quotes come from `expected`, and the verifier compares
|
|
# the two, so this one loop cannot drift from the shape it claims to seed.
|
|
|
|
# events + the meta rows the app writes (`last_maintain` comes from maintain below).
|
|
t0 = time.perf_counter()
|
|
for index in range(EVENT_ROWS):
|
|
store.log_event(Event(ts=now - (index + 1) * 600.0, source="system",
|
|
host=expected.hosts[index % len(expected.hosts)],
|
|
kind="recording" if index % 7 else "reachable",
|
|
severity="info" if index % 7 else "warn",
|
|
message=f"seeded event {index}"))
|
|
store.set_meta(META_SEED_VERSION, SEED_VERSION)
|
|
store.set_meta(META_SEED_NOW, str(now))
|
|
event_seconds = time.perf_counter() - t0
|
|
|
|
# the rollups inside the retention windows, from the real maintenance path.
|
|
t0 = time.perf_counter()
|
|
first = store.maintain(now=now)
|
|
maintain_seconds = time.perf_counter() - t0
|
|
|
|
say(f"seeded {path.name}: {expected.sample_rows_seeded:,} sample rows in "
|
|
f"{inserted_seconds:.1f}s · events {event_seconds:.1f}s · "
|
|
f"maintain {maintain_seconds:.1f}s {first}")
|
|
report = {
|
|
"path": str(path),
|
|
"now": now,
|
|
"expected": expected.as_dict(),
|
|
"maintain": first,
|
|
"seconds": {
|
|
"sample_rows": round(inserted_seconds, 3),
|
|
"events": round(event_seconds, 3),
|
|
"first_maintain": round(maintain_seconds, 3),
|
|
"total": round(time.perf_counter() - started, 3),
|
|
},
|
|
}
|
|
report["counts"] = counts(store)
|
|
return report
|
|
finally:
|
|
store.close()
|
|
|
|
|
|
def seed_now(store: SampleStore) -> float:
|
|
"""The seed's own clock, read back out of `meta`.
|
|
|
|
Every window in this module is relative to it rather than to `time.time()`: the deep history
|
|
is anchored to the moment the file was built, so a test or a pass that used the wall clock
|
|
would measure a different slice of the store on every run (and prune the baseline). Lives
|
|
here rather than in `tests/test_store.py` because the HTTP budget pass in
|
|
`tests/test_api.py` needs it too, and two copies of "what time is this store" is how a
|
|
before/after stops being a before/after.
|
|
"""
|
|
raw = store.get_meta(META_SEED_NOW)
|
|
assert raw is not None, "the seeded store lost its clock row"
|
|
return float(raw)
|
|
|
|
|
|
def counts(store: SampleStore) -> dict[str, int]:
|
|
"""Row counts by resolution, plus series and event totals."""
|
|
with store._lock, store._db:
|
|
by_res = {row[0]: int(row[1]) for row in store._db.execute(
|
|
"SELECT res, COUNT(*) FROM sample WHERE source='host' GROUP BY res")}
|
|
series = int(store._db.execute(
|
|
"SELECT COUNT(*) FROM (SELECT DISTINCT source, host, metric FROM sample"
|
|
" WHERE source='host')").fetchone()[0])
|
|
events = int(store._db.execute("SELECT COUNT(*) FROM event").fetchone()[0])
|
|
return {"raw": by_res.get(RES_RAW, 0), "1m": by_res.get(RES_MIN, 0),
|
|
"1h": by_res.get(RES_HOUR, 0), "series": series, "events": events}
|
|
|
|
|
|
# --------------------------------------------------------------------------- #
|
|
# the cached store: one file, built once, verified on reuse
|
|
# --------------------------------------------------------------------------- #
|
|
def cache_dir(explicit: str | Path | None = None) -> Path:
|
|
"""Where the cached seeded store lives: `DASH_PERF_STORE_DIR`, else `data/perf`.
|
|
|
|
A directory inside the repo (and inside the gitignored `data/`) on purpose: it is the same
|
|
*kind* of filesystem the container gets, unlike pytest's `tmp_path` on this box, which is
|
|
`tmpfs`. Set `DASH_PERF_STORE_DIR=/tmp/…` to measure on RAM instead, and know that you
|
|
then measured the faster machine.
|
|
"""
|
|
if explicit is not None:
|
|
return Path(explicit)
|
|
env = os.environ.get("DASH_PERF_STORE_DIR", "").strip()
|
|
return Path(env) if env else ROOT / "data" / "perf"
|
|
|
|
|
|
def cache_path(directory: str | Path | None = None) -> Path:
|
|
return cache_dir(directory) / f"seeded-{SEED_VERSION}.sqlite3"
|
|
|
|
|
|
def _close_and_remove(path: Path) -> None:
|
|
for suffix in ("", "-wal", "-shm", "-journal"):
|
|
candidate = Path(str(path) + suffix)
|
|
if candidate.exists():
|
|
candidate.unlink()
|
|
|
|
|
|
@contextmanager
|
|
def scratch_copy(path: Path, *, name: str = "scratch") -> Iterator[Path]:
|
|
"""A private copy of the seeded store, for the measurements that **write**.
|
|
|
|
The write-side passes this phase times are not all idempotent-at-a-clock: a rollup run at
|
|
`seed_now + 600` really does roll ten more minutes of buckets and prune ten minutes of raw, and
|
|
the pre-fix whole-window rollup rewrites 330 000 rows. Doing that to the cached file would move
|
|
the baseline every later task compares against, so it happens here instead — same directory
|
|
(same device, same page-cache behaviour), same rows, deleted afterwards. `Connection.backup`
|
|
rather than `copyfile` because the seed has a WAL of its own and a byte copy would miss it; the
|
|
copy is 720 MB in ~1.3 s on the probe's machine, which is cheap next to the passes it buys.
|
|
"""
|
|
dest = path.with_name(f"{path.stem}.{name}-{os.getpid()}.sqlite3")
|
|
# A run killed mid-pass leaves a 720 MB copy behind; sweep the old ones (never a live one:
|
|
# an hour of mtime is several passes) before adding to the pile.
|
|
for stale in path.parent.glob(f"{path.stem}.{name}-*.sqlite3"):
|
|
if time.time() - stale.stat().st_mtime > 3_600:
|
|
_close_and_remove(stale)
|
|
source = sqlite3.connect(str(path))
|
|
try:
|
|
target = sqlite3.connect(str(dest))
|
|
try:
|
|
source.backup(target)
|
|
finally:
|
|
target.close()
|
|
finally:
|
|
source.close()
|
|
try:
|
|
yield dest
|
|
finally:
|
|
_close_and_remove(dest)
|
|
|
|
|
|
def wal_bytes(path: Path) -> int:
|
|
"""Public spelling of `_wal_bytes`, for the notes and the live watch."""
|
|
return _wal_bytes(path)
|
|
|
|
|
|
def _verify(path: Path) -> str | None:
|
|
"""`None` when the cached file matches the shape, else the reason it does not."""
|
|
if not path.exists():
|
|
return "not built yet"
|
|
store = open_store(path)
|
|
try:
|
|
version = store.get_meta(META_SEED_VERSION)
|
|
if version != SEED_VERSION:
|
|
return f"seed version {version!r} != {SEED_VERSION!r}"
|
|
now = float(store.get_meta(META_SEED_NOW) or "0")
|
|
if not now:
|
|
return "no seed clock recorded"
|
|
age_hours = (time.time() - now) / 3600.0
|
|
if age_hours > MAX_CACHE_AGE_HOURS:
|
|
return f"seeded {age_hours:.1f} h ago (max {MAX_CACHE_AGE_HOURS:.0f} h)"
|
|
if age_hours < -1.0:
|
|
return "seeded in the future (the clock moved backwards)"
|
|
expected = plan(now)
|
|
got = counts(store)
|
|
if got["raw"] != expected.raw_rows:
|
|
return f"raw rows {got['raw']} != {expected.raw_rows}"
|
|
for res, label in ((RES_MIN, "1m"), (RES_HOUR, "1h")):
|
|
seeded = {"1m": expected.minute_rows_seeded, "1h": expected.hour_rows_seeded}[label]
|
|
if got[res] < seeded:
|
|
return f"{label} rows {got[res]} < the {seeded} the shape seeds"
|
|
if got["events"] < expected.events:
|
|
return f"{got['events']} events < {expected.events}"
|
|
if got["series"] != expected.series_total:
|
|
return f"{got['series']} series != {expected.series_total}"
|
|
return None
|
|
finally:
|
|
store.close()
|
|
|
|
|
|
def ensure_seeded(directory: str | Path | None = None, *, force: bool = False,
|
|
log: Callable[[str], None] | None = None) -> Path:
|
|
"""The cached seeded store's path, building (or rebuilding) it when needed.
|
|
|
|
`flock` because a half-built store is worse than a slow one: a session that read a partial
|
|
file would report timings for a database nobody has. The build writes to a sibling
|
|
`.building` path and renames, so readers only ever see a finished store.
|
|
"""
|
|
target = cache_path(directory)
|
|
target.parent.mkdir(parents=True, exist_ok=True)
|
|
reason = None if force else _verify(target)
|
|
if reason is None:
|
|
if log:
|
|
log(f"reusing seeded store {target}")
|
|
return target
|
|
say = log or (lambda _line: None)
|
|
say(f"building seeded store ({reason}) — this takes a minute or two")
|
|
lock_path = Path(str(target) + ".lock")
|
|
with open(lock_path, "w") as handle:
|
|
fcntl.flock(handle, fcntl.LOCK_EX)
|
|
try:
|
|
# re-check: another session may have finished the same build while we waited
|
|
reason = None if force else _verify(target)
|
|
if reason is not None:
|
|
_close_and_remove(target)
|
|
staging = Path(str(target) + ".building")
|
|
_close_and_remove(staging)
|
|
build(staging, log=log)
|
|
staging.replace(target)
|
|
for suffix in ("-wal", "-shm"):
|
|
leftover = Path(str(staging) + suffix)
|
|
if leftover.exists():
|
|
leftover.replace(Path(str(target) + suffix))
|
|
finally:
|
|
fcntl.flock(handle, fcntl.LOCK_UN)
|
|
return target
|
|
|
|
|
|
# --------------------------------------------------------------------------- #
|
|
# measurement
|
|
# --------------------------------------------------------------------------- #
|
|
def timed(fn: Callable[[], Any], *, runs: int = 3) -> dict[str, float]:
|
|
"""Wall-clock seconds for `fn`, run `runs` times: mean/median/max of the individual runs."""
|
|
samples: list[float] = []
|
|
for _ in range(runs):
|
|
started = time.perf_counter()
|
|
fn()
|
|
samples.append(time.perf_counter() - started)
|
|
return {"mean": statistics.fmean(samples), "median": statistics.median(samples),
|
|
"max": max(samples), "min": min(samples), "runs": len(samples)}
|
|
|
|
|
|
def explain(store: SampleStore, sql: str, args: tuple[Any, ...] = ()) -> list[str]:
|
|
"""`EXPLAIN QUERY PLAN` for one statement, as the one-line shapes the NOTES quote."""
|
|
with store._lock, store._db:
|
|
rows = store._db.execute(f"EXPLAIN QUERY PLAN {sql}", args).fetchall()
|
|
return [str(row[3]) for row in rows]
|
|
|
|
|
|
def _machine() -> dict[str, Any]:
|
|
cpu = platform.uname()
|
|
model = "unknown"
|
|
try:
|
|
for line in Path("/proc/cpuinfo").read_text().splitlines():
|
|
if line.lower().startswith("model name"):
|
|
model = line.split(":", 1)[1].strip()
|
|
break
|
|
except OSError: # pragma: no cover - /proc is always there on Linux
|
|
pass
|
|
usage = shutil.disk_usage(str(cache_dir()))
|
|
return {
|
|
"cpu": model,
|
|
"cores": os.cpu_count(),
|
|
"machine": cpu.machine,
|
|
"kernel": cpu.release,
|
|
"python": platform.python_version(),
|
|
"sqlite": sqlite3.sqlite_version,
|
|
"store_dir": str(cache_dir()),
|
|
"store_dir_free_gb": round(usage.free / 1e9, 1),
|
|
"store_dir_on_tmpfs": _is_tmpfs(str(cache_dir())),
|
|
}
|
|
|
|
|
|
def _is_tmpfs(path: str) -> bool:
|
|
"""Is the store's directory RAM? A caveat that changes every number in this report."""
|
|
try:
|
|
lines = Path("/proc/mounts").read_text()
|
|
except OSError: # pragma: no cover
|
|
return False
|
|
best, best_len, best_type = "", 0, "unknown"
|
|
for line in lines.splitlines():
|
|
parts = line.split()
|
|
if len(parts) < 3:
|
|
continue
|
|
mount, kind = parts[1], parts[2]
|
|
if path.startswith(mount) and len(mount) > best_len:
|
|
best, best_len, best_type = mount, len(mount), kind
|
|
del best
|
|
return best_type == "tmpfs"
|
|
|
|
|
|
def _main_bytes(path: Path) -> int:
|
|
"""The database file alone — the WAL is reported separately, because *that* is the number
|
|
task 03 tunes and folding the two together hides which one moved."""
|
|
return path.stat().st_size if path.exists() else 0
|
|
|
|
|
|
def _size_bytes(path: Path) -> int:
|
|
total = 0
|
|
for suffix in ("", "-wal", "-shm"):
|
|
candidate = Path(str(path) + suffix)
|
|
if candidate.exists():
|
|
total += candidate.stat().st_size
|
|
return total
|
|
|
|
|
|
def _wal_bytes(path: Path) -> int:
|
|
wal = Path(str(path) + "-wal")
|
|
return wal.stat().st_size if wal.exists() else 0
|
|
|
|
|
|
@dataclass
|
|
class RaceResult:
|
|
"""One round of "the poller writes while a page reads" — the known-gap-4 race, as numbers."""
|
|
|
|
target: int = 0 # inserts asked for
|
|
attempted: int = 0 # inserts actually run (a deadline can stop it early — see MAX_RACE_SECONDS)
|
|
inserts: int = 0 # inserts that succeeded
|
|
seconds: float = 0.0
|
|
waiters: int = 0 # inserts slower than WAIT_THRESHOLD_MS
|
|
max_wait_ms: float = 0.0
|
|
median_wait_ms: float = 0.0
|
|
busy_errors: int = 0 # OperationalError "database is locked" — outlived busy_timeout
|
|
notes: list[str] = field(default_factory=list)
|
|
|
|
def as_dict(self) -> dict[str, Any]:
|
|
return {**asdict(self), "busy_timeout_ms": BUSY_TIMEOUT_MS,
|
|
"wait_threshold_ms": WAIT_THRESHOLD_MS}
|
|
|
|
|
|
def _record_waits(result: RaceResult, waits: list[float]) -> None:
|
|
if not waits:
|
|
return
|
|
result.waiters = sum(1 for wait in waits if wait > WAIT_THRESHOLD_MS)
|
|
result.max_wait_ms = max(waits)
|
|
result.median_wait_ms = statistics.median(waits)
|
|
|
|
|
|
def race_single_connection(store: SampleStore, *, iterations: int = 100,
|
|
max_seconds: float = MAX_RACE_SECONDS) -> RaceResult:
|
|
"""The one-process race: the poller's `add_many` while a page runs `stats()`.
|
|
|
|
Everything in the app shares `SampleStore._lock`, so this cannot produce a SQLite lock
|
|
error — it produces the *other* half of the complaint, a poll that waits behind a read (and
|
|
a page that waits behind a poll). The number that matters is how long an insert waits for the
|
|
mutex, because on today's store that is the read's own full-table cost: one `/api/health`
|
|
poll can hold every writer out for as long as it takes to count the table.
|
|
|
|
The loop stops at `max_seconds` rather than running all 100 inserts, because a read here
|
|
costs seconds and 100 of them would be a five-minute benchmark; the report says how many
|
|
were attempted, so the sample size is part of the number.
|
|
"""
|
|
result = RaceResult(target=iterations)
|
|
stop = threading.Event()
|
|
reads: list[float] = []
|
|
|
|
def reader() -> None:
|
|
while not stop.is_set():
|
|
started = time.perf_counter()
|
|
store.stats()
|
|
store.series_names("host")
|
|
reads.append(time.perf_counter() - started)
|
|
|
|
thread = threading.Thread(target=reader, name="perf-reader", daemon=True)
|
|
thread.start()
|
|
waits: list[float] = []
|
|
started_at = time.perf_counter()
|
|
deadline = started_at + max_seconds
|
|
try:
|
|
while result.attempted < iterations and time.perf_counter() < deadline:
|
|
index = result.attempted
|
|
result.attempted += 1
|
|
ts = time.time()
|
|
samples = [Sample(RACE_SOURCE, RACE_HOST, f"race.metric{column}", float(index), ts)
|
|
for column in range(30)]
|
|
started = time.perf_counter()
|
|
try:
|
|
store.add_many(samples)
|
|
result.inserts += 1
|
|
except sqlite3.OperationalError as exc: # pragma: no cover - the mutex prevents it
|
|
result.busy_errors += 1
|
|
result.notes.append(f"add_many raised {exc}")
|
|
waits.append((time.perf_counter() - started) * 1000.0)
|
|
finally:
|
|
stop.set()
|
|
thread.join(timeout=120.0)
|
|
store.delete_series(RACE_SOURCE, RACE_HOST)
|
|
result.seconds = time.perf_counter() - started_at
|
|
_record_waits(result, waits)
|
|
if reads:
|
|
result.notes.append(
|
|
f"{len(reads)} `stats()`+`series_names()` passes in {result.seconds:.1f} s, median "
|
|
f"{statistics.median(reads) * 1000:,.0f} ms — the store mutex serialises them, so an "
|
|
f"insert above {WAIT_THRESHOLD_MS:.0f} ms waited behind a read, not behind a SQLite "
|
|
"lock (one process cannot get one)")
|
|
return result
|
|
|
|
|
|
def race_two_connections(path: Path, *, iterations: int = 100, busy_timeout_ms: int | None = None,
|
|
now: float | None = None,
|
|
max_seconds: float = MAX_RACE_SECONDS,
|
|
pace_seconds: float = RACE_PACE_SECONDS,
|
|
reset_window: bool = False,
|
|
maintain_gap_seconds: float = 0.0) -> RaceResult:
|
|
"""The two-process race: an insert losing to `maintain()`'s write transaction.
|
|
|
|
A second `SampleStore` on the same file is the cheapest faithful stand-in for the case
|
|
`AGENTS.md` gap 4 proved for this repo — *two servers on one database* — because one
|
|
process's mutex hides the SQLite-level contention entirely. `busy_timeout_ms=0` counts raw
|
|
`SQLITE_BUSY` replies (what the poller would see with no timeout at all, and the measure of
|
|
how much of the window the write lock was held); the production 5 000 ms answers the question
|
|
the gap actually asks: does an insert ever outlive the timeout and surface as `store-error`?
|
|
|
|
`max_seconds` bounds the pass for the same reason as the other race: with a timeout of five
|
|
seconds and a `maintain()` of several, "100 inserts" would be minutes of waiting on purpose.
|
|
|
|
`reset_window=True` deletes `last_maintain` before every pass, which puts the maintainer back
|
|
into the shape task 01 measured — a whole-retention rollup on every tick — and it is run as the
|
|
**control**. A windowed `maintain()` writes almost nothing per minute, so "zero `database is
|
|
locked`" would also be what a race that never contended reports; the control is the number that
|
|
says this race can still see the failure, and therefore that the zero means the fix.
|
|
|
|
`maintain_gap_seconds` is the app's 60 s cadence, compressed: the maintainer idles between
|
|
passes instead of restarting the transaction the instant it commits. `measure()` runs both, and
|
|
the gap is where the honest pass line lives — see `RACE_MAINTAIN_GAP_SECONDS`.
|
|
"""
|
|
timeout = BUSY_TIMEOUT_MS if busy_timeout_ms is None else busy_timeout_ms
|
|
# prune-safe: the point of this race is the lock, not the retention sweep (see open_store)
|
|
writer = open_store(path, extra_retention_hours=2 * MAX_CACHE_AGE_HOURS)
|
|
maintainer = open_store(path, extra_retention_hours=2 * MAX_CACHE_AGE_HOURS)
|
|
writer._db.execute(f"PRAGMA busy_timeout={timeout}")
|
|
result = RaceResult(target=iterations)
|
|
stop = threading.Event()
|
|
writing = threading.Event()
|
|
maintains: list[float] = []
|
|
|
|
def maintainer_loop() -> None:
|
|
while not stop.is_set():
|
|
if reset_window:
|
|
# outside `writing` on purpose: this is not part of the transaction being raced
|
|
maintainer.delete_meta(LAST_MAINTAIN_KEY)
|
|
started = time.perf_counter()
|
|
writing.set()
|
|
try:
|
|
# the seed's own clock, so the loop repeats the same write instead of ageing the
|
|
# store it is measuring
|
|
maintainer.maintain(now=now)
|
|
finally:
|
|
maintains.append(time.perf_counter() - started)
|
|
writing.clear()
|
|
if maintain_gap_seconds:
|
|
time.sleep(maintain_gap_seconds)
|
|
|
|
thread = threading.Thread(target=maintainer_loop, name="perf-maintain", daemon=True)
|
|
thread.start()
|
|
# Don't start inserting until a write transaction is actually open: un-paced, 100 inserts
|
|
# finish in ~50 ms, before the maintainer's first `BEGIN`, and the pass reports "no
|
|
# contention" for a race that never happened. `writing` is set just before `maintain()`.
|
|
if not writing.wait(timeout=max_seconds): # pragma: no cover - a dead maintainer thread
|
|
result.notes.append("the maintainer thread never started a transaction")
|
|
time.sleep(0.05) # the flag is set just before `BEGIN`; give the transaction a moment
|
|
waits: list[float] = []
|
|
started_at = time.perf_counter()
|
|
deadline = started_at + max_seconds
|
|
try:
|
|
while result.attempted < iterations and time.perf_counter() < deadline:
|
|
index = result.attempted
|
|
result.attempted += 1
|
|
ts = time.time()
|
|
samples = [Sample(RACE_SOURCE, RACE_HOST, f"race.metric{column}", float(index), ts)
|
|
for column in range(30)]
|
|
started = time.perf_counter()
|
|
try:
|
|
writer.add_many(samples)
|
|
result.inserts += 1
|
|
except sqlite3.OperationalError as exc:
|
|
result.busy_errors += 1
|
|
if len(result.notes) < 2:
|
|
result.notes.append(f"add_many raised: {exc}")
|
|
waits.append((time.perf_counter() - started) * 1000.0)
|
|
# pace it: this is the poller's cadence, not a tight loop — 9 sources writing every
|
|
# few seconds, so inserts land at every offset inside the write transaction
|
|
time.sleep(pace_seconds)
|
|
finally:
|
|
stop.set()
|
|
thread.join(timeout=180.0)
|
|
try:
|
|
writer.delete_series(RACE_SOURCE, RACE_HOST)
|
|
except sqlite3.OperationalError as exc: # pragma: no cover - cleanup only
|
|
result.notes.append(f"cleanup skipped: {exc}")
|
|
writer.close()
|
|
maintainer.close()
|
|
result.seconds = time.perf_counter() - started_at
|
|
_record_waits(result, waits)
|
|
result.notes.insert(0, (
|
|
f"busy_timeout={timeout} ms · {'whole-window (pre-fix control) ' if reset_window else ''}"
|
|
f"{'cadence ' + format(maintain_gap_seconds, '.1f') + ' s gap' if maintain_gap_seconds else 'saturated (no gap between passes)'}"
|
|
f" · {len(maintains)} `maintain()` write transactions "
|
|
f"(median {statistics.median(maintains) * 1000:,.0f} ms) held the WAL write lock across "
|
|
f"{result.seconds:.1f} s · {result.busy_errors} of {result.attempted} inserts answered "
|
|
f"`database is locked`"))
|
|
return result
|
|
|
|
|
|
#: The write-side passes, as `(label, seconds after the seed clock, drop `last_maintain` first)`.
|
|
#: All three run on the same copy of the same rows, so they differ only in the window:
|
|
#:
|
|
#: * `steady` is the shape of nearly every real tick — the previous pass recorded the same clock,
|
|
#: so each step re-reads its overlap and writes the buckets that filled since;
|
|
#: * `catch_up_10m` is the restart-after-a-quiet-interval case, ten minutes of buckets due;
|
|
#: * `full_window` is the **pre-fix control**: with no `last_maintain` row the steps scan their whole
|
|
#: retention, which is the transaction task 01 measured at 5.4 s. Reproducing it in the same run
|
|
#: on the same file is what turns "the race is clean now" into a measurement instead of a hope.
|
|
MAINTAIN_PASSES: tuple[tuple[str, float, bool], ...] = (
|
|
("steady", 0.0, False),
|
|
("catch_up_10m", 600.0, False),
|
|
("full_window", 1_200.0, True),
|
|
)
|
|
|
|
#: The SELECT half of `store.ROLLUP_INSERT`, derived rather than retyped so the `EXPLAIN QUERY PLAN`
|
|
#: the NOTES record is the plan the rollup actually runs (the same reason the count branch is a
|
|
#: constant). `SELECT` occurs once in that statement.
|
|
ROLLUP_SELECT = "SELECT" + ROLLUP_INSERT.split("SELECT", 1)[1]
|
|
|
|
|
|
def measure_maintain(path: Path, *, now: float, log: Callable[[str], None] | None = None) -> dict[str, Any]:
|
|
"""The write transaction, per window, on a scratch copy — with the WAL around each pass.
|
|
|
|
`now` is the seed's own clock. Offsets from it are the only way to ask "what did the next ten
|
|
minutes cost?" of a store whose history is anchored to when it was seeded, and the copy keeps
|
|
those writes away from the file every later measurement in the phase compares against.
|
|
"""
|
|
say = log or (lambda _line: None)
|
|
out: dict[str, Any] = {
|
|
"journal_size_limit_bytes": JOURNAL_SIZE_LIMIT_BYTES,
|
|
"seed_now": now,
|
|
"passes": {},
|
|
}
|
|
with scratch_copy(path) as copy:
|
|
out["scratch_bytes"] = _main_bytes(copy)
|
|
store = open_store(copy)
|
|
try:
|
|
for label, offset, reset in MAINTAIN_PASSES:
|
|
if reset:
|
|
store.delete_meta(LAST_MAINTAIN_KEY)
|
|
written: dict[str, int] = {}
|
|
|
|
def run_pass(_offset: float = offset, _into: dict[str, int] = written) -> None:
|
|
_into.update(store.maintain(now=now + _offset))
|
|
|
|
wal_before = _wal_bytes(copy)
|
|
run = timed(run_pass, runs=1)
|
|
wal_after = _wal_bytes(copy)
|
|
out["passes"][label] = {
|
|
"seconds": run["mean"],
|
|
"clock": now + offset,
|
|
"counts": written,
|
|
"rows_written": written["to_minute"] + written["to_hour"],
|
|
"wal_before_bytes": wal_before,
|
|
"wal_after_bytes": wal_after,
|
|
}
|
|
say(f" {label}: {run['mean'] * 1000:,.0f} ms, "
|
|
f"{written} -> WAL {wal_after / 1e6:,.1f} MB")
|
|
# Two more ticks for the WAL criterion: the cap is what the file must stay under, and
|
|
# the steady-state growth per tick is what the 140 MB in AGENTS.md gap 4 adds up from.
|
|
cycles: list[dict[str, int]] = []
|
|
for _ in range(2):
|
|
before = _wal_bytes(copy)
|
|
store.maintain(now=now + 1_260.0)
|
|
after = _wal_bytes(copy)
|
|
cycles.append({"wal_before_bytes": before, "wal_after_bytes": after})
|
|
out["two_steady_cycles"] = cycles
|
|
out["wal_within_cap"] = all(
|
|
cycle["wal_after_bytes"] <= JOURNAL_SIZE_LIMIT_BYTES for cycle in cycles)
|
|
out["store_bytes_after"] = _main_bytes(copy)
|
|
# The plans, from the copy, after the first pass put statistics in the file and against
|
|
# the windows just timed. The SELECT half of a rollup is what costs and the DELETE half
|
|
# is what a planner gets wrong: `SCAN sample` here means the window bought nothing, no
|
|
# matter how few rows are inside it.
|
|
out["plans"] = {
|
|
"rollup_minute_steady": explain(store, ROLLUP_SELECT, (
|
|
RES_MIN, MINUTE, MINUTE, RES_RAW, now - MINUTE - MAINTAIN_SLACK_SECONDS,
|
|
now - MINUTE - MAINTAIN_SLACK_SECONDS, MINUTE)),
|
|
"rollup_minute_catch_up": explain(store, ROLLUP_SELECT, (
|
|
RES_MIN, MINUTE, MINUTE, RES_RAW, now - MINUTE - MAINTAIN_SLACK_SECONDS,
|
|
now - MINUTE - MAINTAIN_SLACK_SECONDS - 600.0, MINUTE)),
|
|
"rollup_hour_steady": explain(store, ROLLUP_SELECT, (
|
|
RES_HOUR, HOUR, HOUR, RES_MIN, now - HOUR - MAINTAIN_SLACK_SECONDS,
|
|
now - HOUR - MAINTAIN_SLACK_SECONDS, HOUR)),
|
|
"prune_raw": explain(store, "DELETE FROM sample WHERE res = ? AND ts < ?",
|
|
(RES_RAW, now - RAW_KEEP_HOURS * HOUR)),
|
|
}
|
|
finally:
|
|
store.close()
|
|
return out
|
|
|
|
|
|
def measure_http(path: Path, *, hosts: tuple[str, ...],
|
|
metrics: tuple[str, ...]) -> dict[str, Any]:
|
|
"""The browser's own numbers, through the real ASGI gate (a session is required).
|
|
|
|
`TestClient` is in-process, so this is the handler's cost plus the store's, with no network
|
|
— which is the half the operator feels as "the page took forever" once the response is big.
|
|
"""
|
|
sys_path_fixup()
|
|
from fastapi.testclient import TestClient # noqa: PLC0415 - only the HTTP numbers need it
|
|
|
|
# tests/ is on sys.path via sys_path_fixup(); these two are the suite's own door in.
|
|
from auth_client import ADMIN_PASSWORD, sign_in # noqa: PLC0415
|
|
from auth_contract import FAST_PBKDF2 # noqa: PLC0415
|
|
from dashboards.app import create_app # noqa: PLC0415
|
|
from dashboards.config import Settings # noqa: PLC0415
|
|
|
|
settings = Settings(db_path=str(path), admin_password=ADMIN_PASSWORD,
|
|
pbkdf2_iterations=FAST_PBKDF2)
|
|
# The lifespan starts the hub's maintenance loop, and that loop calls `maintain()` at the
|
|
# wall clock the moment it starts — so this handle gets the prune-safe margin, or booting a
|
|
# server to time a read would prune the baseline it is timing.
|
|
store = open_store(path, extra_retention_hours=2 * MAX_CACHE_AGE_HOURS)
|
|
out: dict[str, Any] = {}
|
|
with TestClient(create_app(settings, store)) as client:
|
|
sign_in(client)
|
|
joined_hosts = ",".join(hosts)
|
|
joined_metrics = ",".join(metrics)
|
|
page = ",".join(PAGE_HISTORY_METRICS)
|
|
out["health"] = timed(lambda: client.get("/api/health"), runs=5)
|
|
out["metrics_list"] = timed(lambda: client.get("/api/metrics?source=host"), runs=3)
|
|
out["system_history_9x3_1h"] = timed(
|
|
lambda: client.get(f"/api/system/history?hosts={joined_hosts}"
|
|
f"&metrics={joined_metrics}&range=1h"), runs=5)
|
|
out["system_history_9x3_24h"] = timed(
|
|
lambda: client.get(f"/api/system/history?hosts={joined_hosts}"
|
|
f"&metrics={joined_metrics}&range=24h"), runs=3)
|
|
out["system_history_9x3_90d"] = timed(
|
|
lambda: client.get(f"/api/system/history?hosts={joined_hosts}"
|
|
f"&metrics={joined_metrics}&range=90d"), runs=3)
|
|
out["system_history_page_shape_1h"] = timed(
|
|
lambda: client.get(f"/api/system/history?hosts={hosts[0]}"
|
|
f"&metrics={page}&range=1h"), runs=5)
|
|
out["summary"] = timed(lambda: client.get("/api/summary"), runs=3)
|
|
store.close()
|
|
return out
|
|
|
|
|
|
def sys_path_fixup() -> None:
|
|
"""Make `tests/` importable from a bare script (pytest does it for free via conftest)."""
|
|
here = str(Path(__file__).resolve().parent)
|
|
if here not in sys.path:
|
|
sys.path.insert(0, here)
|
|
|
|
|
|
def measure(store: SampleStore, *, race_iterations: int = 100, with_http: bool = True,
|
|
race_max_seconds: float = MAX_RACE_SECONDS,
|
|
log: Callable[[str], None] | None = None) -> dict[str, Any]:
|
|
"""Every number task 01 asks for, in one dict.
|
|
|
|
Read-only except the two race helpers, which clean up after themselves (the seeded store is
|
|
reused by later tasks, so a measurement that leaves 3 000 rows behind would move the next
|
|
one's baseline).
|
|
"""
|
|
say = log or (lambda _line: None)
|
|
path = Path(store.path)
|
|
now = float(store.get_meta(META_SEED_NOW) or time.time())
|
|
expected = plan(now)
|
|
report: dict[str, Any] = {
|
|
"generated_at": time.time(),
|
|
"seed_version": SEED_VERSION,
|
|
"machine": _machine(),
|
|
"store": {
|
|
"path": str(path),
|
|
"bytes": _size_bytes(path),
|
|
"wal_bytes": _wal_bytes(path),
|
|
"seed_now": now,
|
|
"expected": expected.as_dict(),
|
|
"counts": counts(store),
|
|
},
|
|
"paths": {},
|
|
"plans": {},
|
|
"race": {},
|
|
}
|
|
|
|
def cold(fn: Callable[[], Any]) -> Callable[[], Any]:
|
|
"""Time the *uncached* answer, whatever the short-TTL read caches are holding.
|
|
|
|
Task 02 put a cache in front of the two scanned answers, so a report that timed them
|
|
naively would compare a cache hit against the baseline's full scan and call it a 1 000x
|
|
win. Both numbers belong in the NOTES: the cold one is what the first poll after a process
|
|
start pays, the warm one is what the browser's next poll pays.
|
|
"""
|
|
def run() -> Any:
|
|
store.invalidate_read_caches()
|
|
return fn()
|
|
return run
|
|
|
|
say("series_names() — cold (cache invalidated) and cached")
|
|
report["paths"]["series_names_all"] = timed(cold(lambda: store.series_names()), runs=3)
|
|
report["paths"]["series_names_all_cached"] = timed(lambda: store.series_names(), runs=5)
|
|
report["paths"]["series_names_host"] = timed(cold(lambda: store.series_names("host")), runs=3)
|
|
report["paths"]["series_names_host_cached"] = timed(lambda: store.series_names("host"), runs=5)
|
|
report["paths"]["series_names_host_driveripper"] = timed(
|
|
lambda: store.series_names("host", "driveripper"), runs=3)
|
|
report["plans"]["series_names_all"] = explain(store, "SELECT DISTINCT metric FROM sample"
|
|
" ORDER BY metric")
|
|
report["plans"]["series_names_host"] = explain(
|
|
store, "SELECT DISTINCT metric FROM sample WHERE source=? ORDER BY metric", ("host",))
|
|
|
|
say("stats() — what the browser-polled /api/health runs, cold and cached")
|
|
report["paths"]["stats"] = timed(cold(store.stats), runs=5)
|
|
report["paths"]["stats_cached"] = timed(store.stats, runs=5)
|
|
report["plans"]["stats_by_res"] = explain(
|
|
store, "SELECT res, COUNT(*) FROM sample GROUP BY res")
|
|
report["plans"]["stats_events"] = explain(store, "SELECT COUNT(*) FROM event")
|
|
|
|
say("pick_res() + history() over 90 d")
|
|
host, metric = "driveripper", "cpu.usage_pct"
|
|
report["paths"]["pick_res_90d"] = timed(
|
|
lambda: [store.pick_res("host", host, metric, span, 600)
|
|
for span in (3600.0, 24 * 3600.0, 90 * 24 * 3600.0)], runs=3)
|
|
report["paths"]["history_90d"] = timed(
|
|
lambda: store.history("host", host, metric, span=90 * 24 * 3600.0, max_points=600),
|
|
runs=3)
|
|
report["paths"]["history_24h"] = timed(
|
|
lambda: store.history("host", host, metric, span=24 * 3600.0, max_points=600), runs=3)
|
|
report["paths"]["history_5m"] = timed(
|
|
lambda: store.history("host", host, metric, span=300.0, max_points=600), runs=3)
|
|
# The statement behind `pick_res` since task 02: three capped counts in one compound, one
|
|
# index seek each. EXPLAINed here rather than the old per-`res` COUNT because the NOTES
|
|
# compare shapes across the phase, and the shape that runs is the one worth recording.
|
|
res_count = " UNION ALL ".join([RES_COUNT_BRANCH] * 3)
|
|
res_args: list[object] = []
|
|
for res in (RES_RAW, RES_MIN, RES_HOUR):
|
|
# the branch's own parameter order: three label columns, then the seek itself
|
|
res_args += [host, metric, res, "host", host, metric, res, now - 90 * 24 * 3600.0, 601]
|
|
report["plans"]["pick_res_count"] = explain(store, res_count, tuple(res_args))
|
|
|
|
say("the N x M batch (27 series, the /system page's request) — grouped vs per-series")
|
|
pair_hosts = list(HOST_SERIES)
|
|
pair_metrics = list(HISTORY_METRICS)
|
|
for label, span in (("24h", 24 * 3600.0), ("90d", 90 * 24 * 3600.0)):
|
|
report["paths"][f"pick_res_x27_{label}"] = timed(
|
|
lambda hs=pair_hosts, ms=pair_metrics, s=span: [
|
|
store.pick_res("host", h, m, s, 600) for h in hs for m in ms], runs=3)
|
|
report["paths"][f"pick_res_many_x27_{label}"] = timed(
|
|
lambda hs=pair_hosts, ms=pair_metrics, s=span: store.pick_res_many(
|
|
"host", hs, ms, s, 600), runs=3)
|
|
report["paths"][f"history_x27_{label}"] = timed(
|
|
lambda hs=pair_hosts, ms=pair_metrics, s=span: [
|
|
store.history("host", h, m, span=s, max_points=600)
|
|
for h in hs for m in ms], runs=3)
|
|
report["paths"][f"history_many_x27_{label}"] = timed(
|
|
lambda hs=pair_hosts, ms=pair_metrics, s=span: store.history_many(
|
|
"host", hs, ms, span=s, max_points=600), runs=3)
|
|
# The batched statement is that same branch repeated per `(series, res)` and chunked at
|
|
# `COMPOUND_CHUNK`; EXPLAINing three of them is the shape without a 300-line plan in the NOTES.
|
|
grouped_args: list[object] = []
|
|
for (h, m), res in zip((("driveripper", "cpu.usage_pct"), ("deskwork", "mem.used_pct"),
|
|
("gateway", "disk.used_pct")), (RES_RAW, RES_MIN, RES_HOUR),
|
|
strict=True):
|
|
grouped_args += [h, m, res, "host", h, m, res, now - 90 * 24 * 3600.0, 601]
|
|
report["plans"]["pick_res_many_branch"] = explain(
|
|
store, " UNION ALL ".join([RES_COUNT_BRANCH] * 3), tuple(grouped_args))
|
|
report["plans"]["history_tail"] = explain(
|
|
store, "SELECT ts, value FROM (SELECT ts, value FROM sample WHERE source=? AND host=?"
|
|
" AND metric=? AND res=? AND ts>=? AND ts<=? ORDER BY ts DESC LIMIT ?)"
|
|
" ORDER BY ts ASC",
|
|
("host", host, metric, RES_MIN, now - 90 * 24 * 3600.0, now, 2400))
|
|
|
|
say("maintain() — the write transaction per window, and the WAL around each pass")
|
|
# Seeded-clock maintenance on a scratch copy: the store's newest row is at `now`, so timing a
|
|
# rollup at the wall clock would measure a slightly different job (and prune the baseline) every
|
|
# time the probe runs. The copy is where the passes that *write* belong — a catch-up pass rolls
|
|
# ten more minutes of buckets, and the pre-fix whole-window control rewrites 330 000 rows.
|
|
report["maintain"] = measure_maintain(path, now=now, log=say)
|
|
# The write-side plans (`maintain.plans`) are explained inside `measure_maintain`, on the copy:
|
|
# a plan is only worth recording next to the timings that produced it, and only after that
|
|
# pass has put query statistics in the file — without statistics the planner reads the table for
|
|
# every window, so explaining it beforehand would record a shape production no longer runs.
|
|
|
|
say(f"the race: a 30-sample add_many against {race_iterations} concurrent readers/maintains")
|
|
single = race_single_connection(store, iterations=race_iterations,
|
|
max_seconds=race_max_seconds)
|
|
report["race"]["single_connection"] = single.as_dict()
|
|
# The two-connection races write (rollups on the maintainer's side, 3 000 raced samples on the
|
|
# writer's), so they run against one scratch copy of the same rows: the seed the next task
|
|
# measures has to come back exactly as it went in.
|
|
with scratch_copy(path, name="race") as arena:
|
|
# (1) the saturated harness, unchanged from task 01 so its numbers stay comparable, and
|
|
# (2) the same race at the app's cadence, which is the one with a pass line: a poller's
|
|
# insert landing inside a rollup waits that rollup out, and windowing is what made the
|
|
# wait short enough to never reach `busy_timeout`.
|
|
report["race"]["two_connections_prod_timeout"] = race_two_connections(
|
|
arena, iterations=race_iterations, now=now, max_seconds=race_max_seconds).as_dict()
|
|
report["race"]["two_connections_no_timeout"] = race_two_connections(
|
|
arena, iterations=race_iterations, busy_timeout_ms=0, now=now,
|
|
max_seconds=race_max_seconds).as_dict()
|
|
report["race"]["poller_during_windowed_maintain"] = race_two_connections(
|
|
arena, iterations=race_iterations, now=now, max_seconds=race_max_seconds,
|
|
maintain_gap_seconds=RACE_MAINTAIN_GAP_SECONDS).as_dict()
|
|
report["race"]["poller_during_full_window_maintain"] = race_two_connections(
|
|
arena, iterations=race_iterations, now=now, max_seconds=race_max_seconds,
|
|
reset_window=True, maintain_gap_seconds=RACE_MAINTAIN_GAP_SECONDS).as_dict()
|
|
for key in ("two_connections_prod_timeout", "two_connections_no_timeout"):
|
|
report["race"][key]["notes"].append(
|
|
"saturated harness (task 01's shape): the maintainer restarts `maintain()` the instant "
|
|
"it commits, so the WAL write lock is held ~100% of the wall clock and a writer can be "
|
|
"starved however short each pass is. The app maintains once per 60 s — the "
|
|
"`poller_during_*` rows are that shape, and they are the ones with a pass line.")
|
|
|
|
if with_http:
|
|
say("through the app (signed in, TestClient, no network)")
|
|
report["http"] = measure_http(path, hosts=expected.hosts, metrics=HISTORY_METRICS)
|
|
|
|
# Task 04's budgets, priced against everything above. Computed last on purpose: a budget row
|
|
# whose path was never measured is a failing row, so it has to see the finished report.
|
|
rows = budget_rows(report)
|
|
report["budgets"] = [row.as_dict() for row in rows]
|
|
report["budgets_ok"] = all(row.ok for row in rows)
|
|
|
|
# `_verify` is cheap and proves the measurements left the seeded shape alone
|
|
problem = _verify(path)
|
|
report["store_after"] = {"counts": counts(store), "integrity": problem or "unchanged"}
|
|
return report
|
|
|
|
|
|
# --------------------------------------------------------------------------- #
|
|
# the budgets (task 04): the measured "after", promoted to a red test
|
|
# --------------------------------------------------------------------------- #
|
|
#: Why a table and not `assert elapsed < 0.05` sprinkled through the tests: the same numbers have
|
|
#: to appear in three places — the pytest budgets, the probe's report, and
|
|
#: `data/logs/NOTES-store-perf.md` — and three copies of a budget drift the moment one is relaxed.
|
|
#: One table, one verdict function, and the notes are rendered from it.
|
|
#:
|
|
#: Every limit is **2-3x the measured "after"** on the seeded store (`AGENTS.md`: a budget asserted
|
|
#: on first writing is a number fitted to the machine it was written on), and each row records that
|
|
#: measured figure in `basis` so a reader can see the margin instead of trusting it. They are cost
|
|
#: *ceilings*, not targets: a path that used to cost a whole-table pass and now costs 1 ms still
|
|
#: gets a 10 ms ceiling, because the claim under test is "bounded", not "1 ms".
|
|
@dataclass(frozen=True)
|
|
class Budget:
|
|
"""One pinned cost: a report path, the ceiling it may not cross, and where the ceiling came from."""
|
|
|
|
#: which section of a `measure()` report to read: `paths`, `http`, `maintain`, `race`
|
|
section: str
|
|
#: the key inside that section
|
|
key: str
|
|
#: the ceiling, in `unit`
|
|
limit: float
|
|
#: what the limit is compared against: a `timed()` field (`mean`/`median`/`max`) for the
|
|
#: `paths`/`http` sections, `seconds` for a `maintain` pass, and the `RaceResult` field name
|
|
#: (`max_wait_ms`, `busy_errors`) for a race
|
|
statistic: str = "median"
|
|
unit: str = "ms"
|
|
#: prose: the measured "after" this ceiling was set from, and the margin on it
|
|
basis: str = ""
|
|
#: an optional *relative* claim — this path must also cost at most `ratio_limit` of the named
|
|
#: key in the same section. That is the assertion a cache needs: "0.0 ms" on a machine that
|
|
#: got faster for an unrelated reason is uninteresting, "50x cheaper than the scan it replaced"
|
|
#: is the scan being gone.
|
|
ratio_key: str | None = None
|
|
ratio_limit: float | None = None
|
|
|
|
def label(self) -> str:
|
|
return f"{self.section}.{self.key}[{self.statistic}]"
|
|
|
|
def as_dict(self) -> dict[str, Any]:
|
|
return asdict(self)
|
|
|
|
|
|
#: The budgets themselves, in the order the NOTES table prints them. Keys are report keys, so
|
|
#: `test_every_pinned_budget_names_a_path_the_probe_measures` can fail a budget that points at a
|
|
#: measurement nobody takes any more.
|
|
BUDGETS: tuple[Budget, ...] = (
|
|
# --- the two reads that used to be a scan per request -------------------------------
|
|
Budget("paths", "series_names_host_cached", 10.0, ratio_key="series_names_host",
|
|
ratio_limit=0.02, basis="measured ~0.0 ms cached vs 1,440 ms cold (task 03); the claim "
|
|
"is 'the scan is gone', so the ceiling comes with a 50x-relative claim beside it"),
|
|
Budget("paths", "stats_cached", 10.0, ratio_key="stats", ratio_limit=0.02,
|
|
basis="measured ~0.0 ms cached vs 1,336 ms cold (task 03); `/api/health` runs this "
|
|
"every 15 s per tab, which is why both halves are pinned"),
|
|
Budget("paths", "history_90d", 25.0, basis="measured 1.9-2.6 ms; task 01's 'do not regress it' "
|
|
"line, 10x the after and 6x under the 4.1 ms baseline"),
|
|
Budget("paths", "pick_res_many_x27_90d", 50.0, basis="measured 2.7-3.0 ms for 27 series; "
|
|
"one grouped statement, 16x headroom"),
|
|
Budget("paths", "history_many_x27_90d", 150.0, basis="measured ~30 ms for 27 series at the "
|
|
"widest window; 5x headroom on the slowest request the pages can make"),
|
|
# --- the same paths over HTTP, gate included -----------------------------------------
|
|
Budget("http", "health", 150.0, basis="measured 0.8-1.4 ms median (task 01: 1,272 ms); "
|
|
"task 01's own suggested ceiling, kept because a deployment disk is slower than "
|
|
"the dev box"),
|
|
Budget("http", "metrics_list", 150.0, basis="measured 1.6-2.0 ms median (task 01: 1,415 ms)"),
|
|
Budget("http", "system_history_9x3_1h", 100.0, basis="the raw-resolution case: measured ~6 ms"),
|
|
Budget("http", "system_history_9x3_90d", 200.0, basis="measured ~50 ms mean (task 01: 100 ms); "
|
|
"4x the after, and under the baseline the phase started from"),
|
|
Budget("http", "summary", 150.0, basis="measured ~1 ms; the overview's single call"),
|
|
# --- the write side: the transaction that held the WAL write lock --------------------
|
|
Budget("maintain", "steady", 1_000.0, statistic="seconds", basis="measured 2.7 ms steady "
|
|
"(task 01: 5,368 ms); task 01's ceiling, 5x under the baseline's *mean* so a "
|
|
"catch-up tick cannot cross it either"),
|
|
Budget("maintain", "catch_up_10m", 2_000.0, statistic="seconds",
|
|
basis="measured 48 ms after ten quiet minutes; the ceiling is the promise that a "
|
|
"restart after a quiet spell is still well inside a poller's 5 s busy_timeout"),
|
|
Budget("race", "poller_during_windowed_maintain", 1_000.0, statistic="max_wait_ms",
|
|
basis="measured 21 ms worst wait (task 01: 5,005 ms median); the wait that matters "
|
|
"is the worst one, since that is the one that raises"),
|
|
Budget("race", "poller_during_windowed_maintain", 0.0, statistic="busy_errors", unit="count",
|
|
basis="measured 0 of 100 (task 01: 5 of 9) — AGENTS.md known gap 4's failure mode, "
|
|
"pinned at zero"),
|
|
)
|
|
|
|
#: Which budgets the *default* test run can price without the seeded store (see
|
|
#: `measure_budget_reads`): the cheap-store pass produces these sections and no others.
|
|
BUDGET_SECTIONS = ("paths", "http", "maintain", "race")
|
|
|
|
#: The keys the two cheap measurement passes produce, pinned by tests against the reports they
|
|
#: build. A budget (or the ratio partner of one) has to name a key from the right one of these,
|
|
#: because the failure mode of a budget table is a row that quietly stops being priced: rename the
|
|
#: measurement, and the ceiling still "passes".
|
|
READ_MEASURED_KEYS: tuple[str, ...] = (
|
|
"series_names_host", "series_names_host_cached", "stats", "stats_cached", "history_90d",
|
|
"pick_res_many_x27_90d", "history_many_x27_90d",
|
|
)
|
|
HTTP_MEASURED_KEYS: tuple[str, ...] = (
|
|
"health", "metrics_list", "system_history_9x3_1h", "system_history_9x3_24h",
|
|
"system_history_9x3_90d", "system_history_page_shape_1h", "summary",
|
|
)
|
|
#: The report keys the write-side passes produce, for the same reason. `full_window` is the
|
|
#: pre-fix control and deliberately has no budget: a thing is only a control if it is slow.
|
|
MAINTAIN_MEASURED_KEYS: tuple[str, ...] = tuple(label for label, _o, _r in MAINTAIN_PASSES)
|
|
|
|
|
|
@dataclass(frozen=True)
|
|
class BudgetRow:
|
|
"""One budget, the number it was priced against, and the verdict."""
|
|
|
|
budget: Budget
|
|
measured: float | None # in the budget's unit; `None` = the report did not measure it
|
|
ok: bool
|
|
detail: str = ""
|
|
|
|
@property
|
|
def margin(self) -> float | None:
|
|
"""How many times inside the ceiling the measurement is (`None` when unpricables make that
|
|
meaningless: a 0.0 ms measurement against a 10 ms ceiling has no finite margin)."""
|
|
if self.measured is None or self.measured <= 0.0 or self.budget.limit <= 0.0:
|
|
return None
|
|
return self.budget.limit / self.measured
|
|
|
|
def as_dict(self) -> dict[str, Any]:
|
|
return {**self.budget.as_dict(), "measured": self.measured, "ok": self.ok,
|
|
"margin": self.margin, "detail": self.detail}
|
|
|
|
|
|
def _budget_value(report: dict[str, Any], budget: Budget) -> float | None:
|
|
"""The measured value for one budget, in its unit, or `None` when the report lacks it."""
|
|
section = report.get(budget.section) or {}
|
|
if budget.section == "maintain":
|
|
entry = (section.get("passes") or {}).get(budget.key)
|
|
return None if entry is None else float(entry["seconds"]) * 1000.0
|
|
entry = section.get(budget.key)
|
|
if entry is None:
|
|
return None
|
|
if budget.section == "race":
|
|
# a RaceResult: the fields are already ms / counts, no unit conversion
|
|
return None if entry.get(budget.statistic) is None else float(entry[budget.statistic])
|
|
value = entry.get(budget.statistic)
|
|
return None if value is None else float(value) * 1000.0
|
|
|
|
|
|
def budget_rows(report: dict[str, Any],
|
|
sections: tuple[str, ...] | None = None) -> list[BudgetRow]:
|
|
"""Price every pinned budget against `report` — the table the NOTES print and the tests assert.
|
|
|
|
`sections` narrows the pass to the parts a given report actually contains (the cheap read-only
|
|
pass prices `paths` alone, the HTTP pass `http` alone); without it a partial report would report
|
|
every other budget as unmeasured, which is true but not what that caller is claiming.
|
|
|
|
A budget whose path the report does not measure comes back as a failing row rather than a
|
|
missing one: a budget that silently stops being checked is the same failure as a budget that
|
|
is crossed, and it is the one a refactor causes.
|
|
"""
|
|
rows: list[BudgetRow] = []
|
|
for budget in BUDGETS:
|
|
if sections is not None and budget.section not in sections:
|
|
continue
|
|
measured = _budget_value(report, budget)
|
|
if measured is None:
|
|
rows.append(BudgetRow(budget, None, False, "not measured by this report"))
|
|
continue
|
|
if measured > budget.limit:
|
|
rows.append(BudgetRow(budget, measured, False,
|
|
f"over the {fmt_budget(budget)} ceiling"))
|
|
continue
|
|
if budget.ratio_key is not None and budget.ratio_limit is not None:
|
|
other = _budget_value(report, replace(budget, key=budget.ratio_key))
|
|
if other is None:
|
|
rows.append(BudgetRow(budget, measured, False,
|
|
f"ratio partner {budget.ratio_key} was not measured"))
|
|
continue
|
|
ratio = (measured / other) if other > 0 else math.inf
|
|
if ratio > budget.ratio_limit:
|
|
rows.append(BudgetRow(budget, measured, False, f"{ratio:.3f} of the {budget.ratio_key} "
|
|
f"cost, must be <= {budget.ratio_limit:.3f}"))
|
|
continue
|
|
rows.append(BudgetRow(budget, measured, True))
|
|
return rows
|
|
|
|
|
|
def budget_violations(report: dict[str, Any],
|
|
sections: tuple[str, ...] | None = None) -> list[str]:
|
|
"""The failing rows as sentences — what a budget test asserts away."""
|
|
return [f"{row.budget.label()} = {fmt_budget_value(row.budget, row.measured)} "
|
|
f"(limit {fmt_budget(row.budget)}): {row.detail}"
|
|
for row in budget_rows(report, sections) if not row.ok]
|
|
|
|
|
|
def missing_budget_keys(report: dict[str, Any],
|
|
sections: tuple[str, ...] | None = None) -> list[str]:
|
|
"""Budgets this report cannot price at all — the stale-pointer check, not the cost check.
|
|
|
|
The default suite runs this against a *small* store, where a budget may legitimately be
|
|
crossed (a ratio against a 20 us scan is luck) but must never be unmeasurable.
|
|
"""
|
|
return [row.budget.label() for row in budget_rows(report, sections)
|
|
if row.measured is None]
|
|
|
|
|
|
def fmt_budget_value(budget: Budget, value: float | None) -> str:
|
|
if value is None:
|
|
return "n/a"
|
|
return _ms(value / 1000.0) if budget.unit == "ms" else f"{value:,.0f}"
|
|
|
|
|
|
def fmt_budget(budget: Budget) -> str:
|
|
return _ms(budget.limit / 1000.0) if budget.unit == "ms" else f"<= {budget.limit:,.0f}"
|
|
|
|
|
|
def render_budgets_markdown(rows: list[BudgetRow]) -> str:
|
|
"""The budget table: measured, ceiling, margin, verdict — one row per pinned budget."""
|
|
lines = ["| budget | path | measured | ceiling | margin | verdict |",
|
|
"| --- | --- | --- | --- | --- | --- |"]
|
|
for row in rows:
|
|
margin = "—" if row.margin is None else f"{row.margin:,.0f}x"
|
|
lines.append(f"| `{row.budget.section}` | `{row.budget.key}` "
|
|
f"({row.budget.statistic}) | {fmt_budget_value(row.budget, row.measured)} | "
|
|
f"{fmt_budget(row.budget)} | {margin} | "
|
|
+ ("**inside**" if row.ok else f"**OVER** — {row.detail}") + " |")
|
|
return "\n".join(lines)
|
|
|
|
|
|
def measure_budget_reads(store: SampleStore, *, runs: int = 5) -> dict[str, Any]:
|
|
"""Only the paths with a pinned budget, timed — the cheap half of `measure()`.
|
|
|
|
Task 04's budget tests must not each pay for the races (minutes) or the write passes, so this
|
|
produces the same-shaped `paths` document for the budget keys and nothing else. It is a
|
|
*measurement*, not a baseline: the numbers it prints go in the notes next to the full probe
|
|
report, and both are on the same seeded file.
|
|
"""
|
|
host, metric = "driveripper", "cpu.usage_pct"
|
|
hosts = list(HOST_SERIES)
|
|
metrics = list(HISTORY_METRICS)
|
|
paths: dict[str, Any] = {}
|
|
paths["series_names_host"] = timed(lambda: (store.invalidate_read_caches(),
|
|
store.series_names("host"))[1], runs=runs)
|
|
paths["series_names_host_cached"] = timed(lambda: store.series_names("host"), runs=runs)
|
|
paths["stats"] = timed(lambda: (store.invalidate_read_caches(), store.stats())[1], runs=runs)
|
|
paths["stats_cached"] = timed(store.stats, runs=runs)
|
|
paths["history_90d"] = timed(
|
|
lambda: store.history("host", host, metric, span=90 * 24 * 3600.0, max_points=600),
|
|
runs=runs)
|
|
paths["pick_res_many_x27_90d"] = timed(
|
|
lambda: store.pick_res_many("host", hosts, metrics, 90 * 24 * 3600.0, 600), runs=runs)
|
|
paths["history_many_x27_90d"] = timed(
|
|
lambda: store.history_many("host", hosts, metrics, span=90 * 24 * 3600.0, max_points=600),
|
|
runs=runs)
|
|
return {"budget_runs": runs, "paths": paths}
|
|
|
|
|
|
def measure_budget_http(path: str | Path, *, hosts: tuple[str, ...] | None = None,
|
|
metrics: tuple[str, ...] | None = None) -> dict[str, Any]:
|
|
"""The HTTP half of the budgets, through the same signed-in `TestClient` as `measure()`.
|
|
|
|
Split out so `tests/test_api.py` can price the endpoint budgets without also paying for the
|
|
races and the write passes. `hosts`/`metrics` default to the seeded shape so the request is
|
|
the one `/system` makes; a caller passing them explicitly is pricing a *different* request and
|
|
should say so in the notes rather than reuse these budgets.
|
|
"""
|
|
return {"http": measure_http(Path(path),
|
|
hosts=hosts or tuple(sorted(HOST_SERIES)),
|
|
metrics=metrics or HISTORY_METRICS)}
|
|
|
|
|
|
def measure_dev_db(path: str | Path, *, runs: int = 3) -> dict[str, Any]:
|
|
"""The same three hot reads against a *real* store, opened read-only.
|
|
|
|
The answer to "is your synthetic seed representative?" is better as a measurement than as an
|
|
argument. `mode=ro` and nothing else: no DDL, no PRAGMA that writes, no `SampleStore`
|
|
(constructing one runs the schema and `journal_mode=WAL`, which need write access). Tests
|
|
never pass this path — `AGENTS.md`'s testing policy keeps the suite off the operator's
|
|
history — but the probe is run by a human, exactly like `data/logs/analyze-watch.py` did in
|
|
phase 13, and the numbers it prints belong in the NOTES either way.
|
|
"""
|
|
uri = f"file:{Path(path)}?mode=ro"
|
|
db = sqlite3.connect(uri, uri=True)
|
|
out: dict[str, Any] = {"path": str(path), "bytes": Path(path).stat().st_size}
|
|
try:
|
|
out["counts"] = {row[0]: int(row[1]) for row in db.execute(
|
|
"SELECT res, COUNT(*) FROM sample GROUP BY res")}
|
|
out["events"] = int(db.execute("SELECT COUNT(*) FROM event").fetchone()[0])
|
|
out["series"] = {row[0]: int(row[1]) for row in db.execute(
|
|
"SELECT source, COUNT(*) FROM (SELECT DISTINCT source, host, metric FROM sample)"
|
|
" GROUP BY source")}
|
|
|
|
def run(sql: str, args: tuple[Any, ...] = ()) -> dict[str, float]:
|
|
def call() -> None:
|
|
db.execute(sql, args).fetchall()
|
|
|
|
return timed(call, runs=runs)
|
|
|
|
out["paths"] = {
|
|
"series_names_all": run("SELECT DISTINCT metric FROM sample ORDER BY metric"),
|
|
"series_names_host": run("SELECT DISTINCT metric FROM sample WHERE source=?"
|
|
" ORDER BY metric", ("host",)),
|
|
"stats_by_res": run("SELECT res, COUNT(*) FROM sample GROUP BY res"),
|
|
"stats_events": run("SELECT COUNT(*) FROM event"),
|
|
}
|
|
out["plans"] = {key: [str(row[3]) for row in db.execute(
|
|
f"EXPLAIN QUERY PLAN {sql}", args).fetchall()]
|
|
for key, sql, args in (
|
|
("series_names_all", "SELECT DISTINCT metric FROM sample ORDER BY metric", ()),
|
|
("stats_by_res", "SELECT res, COUNT(*) FROM sample GROUP BY res", ()),
|
|
)}
|
|
finally:
|
|
db.close()
|
|
return out
|
|
|
|
|
|
# --------------------------------------------------------------------------- #
|
|
# rendering
|
|
# --------------------------------------------------------------------------- #
|
|
def _ms(seconds: float) -> str:
|
|
if seconds >= 1.0:
|
|
return f"{seconds * 1000:,.0f} ms"
|
|
return f"{seconds * 1000:.1f} ms"
|
|
|
|
|
|
def _mb(value: float) -> str:
|
|
return f"{value / 1e6:,.1f} MB"
|
|
|
|
|
|
def render_markdown(report: dict[str, Any]) -> str:
|
|
"""The NOTES tables, as markdown, from one report.
|
|
|
|
Machine-written so the "before" and the "after" of this phase are the same tables with
|
|
different numbers, which is the only form of the comparison that survives a week.
|
|
"""
|
|
machine = report["machine"]
|
|
store = report["store"]
|
|
counts_ = store["counts"]
|
|
lines: list[str] = []
|
|
push = lines.append
|
|
push(f"- seed version: `{report['seed_version']}` · generated "
|
|
f"{time.strftime('%Y-%m-%d %H:%M:%S', time.localtime(report['generated_at']))}")
|
|
push(f"- cpu: {machine['cpu']} ({machine['cores']} cores, {machine['machine']}, "
|
|
f"kernel {machine['kernel']})")
|
|
push(f"- python {machine['python']} · sqlite {machine['sqlite']}")
|
|
push(f"- store directory: `{machine['store_dir']}` "
|
|
f"({'tmpfs — RAM, the faster machine' if machine['store_dir_on_tmpfs'] else 'a real block device'})")
|
|
push("")
|
|
push("| seeded store | rows | bytes |")
|
|
push("| --- | --- | --- |")
|
|
push(f"| `{Path(store['path']).name}` | raw {counts_['raw']:,} · 1m {counts_['1m']:,} · "
|
|
f"1h {counts_['1h']:,} · events {counts_['events']:,} · "
|
|
f"{counts_['series']} series | {_mb(store['bytes'])} (+{_mb(store['wal_bytes'])} WAL) |")
|
|
push("")
|
|
push("| hot path | mean | median | max |")
|
|
push("| --- | --- | --- | --- |")
|
|
labels = {
|
|
"series_names_all": "`series_names()` — no filter, **cold**",
|
|
"series_names_all_cached": "`series_names()` — cached",
|
|
"series_names_host": "`series_names('host')` — `/api/metrics?source=host`, **cold**",
|
|
"series_names_host_cached": "`series_names('host')` — cached",
|
|
"series_names_host_driveripper": "`series_names('host','driveripper')`",
|
|
"stats": "`stats()` — `/api/health`, **cold**",
|
|
"stats_cached": "`stats()` — cached (what the next `/api/health` poll pays)",
|
|
"pick_res_90d": "`pick_res()` x 3 (1 h, 24 h, 90 d) — one series",
|
|
"pick_res_x27_24h": "`pick_res()` x 27, one call per series — 24 h",
|
|
"pick_res_many_x27_24h": "`pick_res_many()` — the same 27 in one grouped call — 24 h",
|
|
"pick_res_x27_90d": "`pick_res()` x 27, one call per series — 90 d",
|
|
"pick_res_many_x27_90d": "`pick_res_many()` — the same 27 in one grouped call — 90 d",
|
|
"history_x27_24h": "`history()` x 27, one call per series — 24 h",
|
|
"history_many_x27_24h": "`history_many()` — the same 27 batched — 24 h",
|
|
"history_x27_90d": "`history()` x 27, one call per series — 90 d",
|
|
"history_many_x27_90d": "`history_many()` — the same 27 batched — 90 d",
|
|
"history_5m": "`history()` — 5 m window",
|
|
"history_24h": "`history()` — 24 h window",
|
|
"history_90d": "`history()` — 90 d window",
|
|
}
|
|
for key, label in labels.items():
|
|
entry = report["paths"].get(key)
|
|
if entry is None:
|
|
continue
|
|
push(f"| {label} | {_ms(entry['mean'])} | {_ms(entry['median'])} | {_ms(entry['max'])} |")
|
|
maintain = report["maintain"]
|
|
for label, entry in maintain["passes"].items():
|
|
push(f"| `maintain()` — {label} | {_ms(entry['seconds'])} | — | — |")
|
|
for key, entry in report.get("http", {}).items():
|
|
push(f"| HTTP `{key}` | {_ms(entry['mean'])} | {_ms(entry['median'])} | "
|
|
f"{_ms(entry['max'])} |")
|
|
push("")
|
|
push("`maintain()` passes on a scratch copy of the seeded store — same rows, same device, and "
|
|
"the writes kept off the file every later measurement compares against:")
|
|
push("")
|
|
push("| pass | write transaction | rows written | WAL before → after |")
|
|
push("| --- | --- | --- | --- |")
|
|
for label, entry in maintain["passes"].items():
|
|
counts_ = entry["counts"]
|
|
push(f"| `{label}` | {_ms(entry['seconds'])} | {entry['rows_written']:,} "
|
|
f"(1m {counts_['to_minute']:,} · 1h {counts_['to_hour']:,}) | "
|
|
f"{_mb(entry['wal_before_bytes'])} → {_mb(entry['wal_after_bytes'])} |")
|
|
cycles = maintain["two_steady_cycles"]
|
|
push("")
|
|
push("Two more steady ticks, WAL after each: "
|
|
+ " → ".join(_mb(cycle["wal_after_bytes"]) for cycle in cycles)
|
|
+ f", against the {_mb(maintain['journal_size_limit_bytes'])} `journal_size_limit` cap: "
|
|
+ ("inside it" if maintain["wal_within_cap"] else "OVER IT")
|
|
+ f". Scratch file {_mb(maintain['scratch_bytes'])} → "
|
|
f"{_mb(maintain['store_bytes_after'])} (the main file does not move; the WAL is the "
|
|
"number that grows between checkpoints).")
|
|
push("")
|
|
push("| race | inserts | waited > "
|
|
f"{WAIT_THRESHOLD_MS:.0f} ms | median | max | `database is locked` |")
|
|
push("| --- | --- | --- | --- | --- | --- |")
|
|
for key, label in (("single_connection", "one connection, `stats()`+`series_names()` looping"),
|
|
("two_connections_prod_timeout",
|
|
f"two connections, windowed `maintain()` looping, "
|
|
f"busy_timeout={BUSY_TIMEOUT_MS}"),
|
|
("two_connections_no_timeout",
|
|
"two connections, windowed `maintain()` looping, busy_timeout=0"),
|
|
("poller_during_windowed_maintain",
|
|
f"two connections, windowed `maintain()` at a "
|
|
f"{RACE_MAINTAIN_GAP_SECONDS:.1f} s cadence, "
|
|
f"busy_timeout={BUSY_TIMEOUT_MS} — **the pass line**"),
|
|
("poller_during_full_window_maintain",
|
|
"CONTROL: two connections, whole-window (pre-fix) `maintain()` at the same "
|
|
f"cadence, busy_timeout={BUSY_TIMEOUT_MS}")):
|
|
entry = report["race"].get(key)
|
|
if entry is None:
|
|
continue
|
|
push(f"| {label} | {entry['inserts']} of {entry['attempted']} attempted "
|
|
f"(target {entry['target']}, {entry['seconds']:.1f} s) | {entry['waiters']} | "
|
|
f"{entry['median_wait_ms']:,.1f} ms | {entry['max_wait_ms']:,.0f} ms | "
|
|
f"{entry['busy_errors']} |")
|
|
for note in entry.get("notes", []):
|
|
push(f"| ↳ | {note} | | | | |")
|
|
push("")
|
|
rows = budget_rows(report)
|
|
if any(row.measured is not None for row in rows):
|
|
push("The task-04 budgets, priced against the run above. Each ceiling is 2-3x the measured "
|
|
"\"after\" (and the `basis` column of `store_perf.BUDGETS` says which figure and how "
|
|
"much margin), so this table is the regression gate: a path that drifts back toward "
|
|
"its baseline turns red here instead of just feeling slow.")
|
|
push("")
|
|
push(render_budgets_markdown(rows))
|
|
push("")
|
|
verdict = "all inside" if all(row.ok for row in rows) else "OVER"
|
|
push(f"Budget verdict: **{verdict}** "
|
|
f"({sum(1 for row in rows if row.ok)} of {len(rows)} inside).")
|
|
push("")
|
|
push("EXPLAIN QUERY PLAN shapes (read paths):")
|
|
push("")
|
|
for key, plan_rows in report["plans"].items():
|
|
push(f"- `{key}`: " + " · ".join(f"`{row}`" for row in plan_rows))
|
|
push("")
|
|
push("EXPLAIN QUERY PLAN shapes (`maintain()`, on the copy, after its own statistics landed):")
|
|
push("")
|
|
for key, plan_rows in maintain.get("plans", {}).items():
|
|
push(f"- `{key}`: " + " · ".join(f"`{row}`" for row in plan_rows))
|
|
push("")
|
|
dev = report.get("dev_db")
|
|
if dev:
|
|
dev_counts = dev["counts"]
|
|
dev_total = sum(dev_counts.values())
|
|
dev_series = sum(dev["series"].values())
|
|
dev_by_res = " ".join(f"{key}={value:,}" for key, value in sorted(dev_counts.items()))
|
|
push(f"The same reads against the operator's **real** store "
|
|
f"(`{dev['path']}`, {_mb(dev['bytes'])}, opened read-only, no test ever does this):")
|
|
push("")
|
|
push("| read | what is in that store | mean |")
|
|
push("| --- | --- | --- |")
|
|
push(f"| `series_names()` | {dev_total:,} samples · {dev_series:,} distinct series · "
|
|
f"{dev['events']:,} events | {_ms(dev['paths']['series_names_all']['mean'])} |")
|
|
host_series = dev["series"].get("host", 0)
|
|
push(f"| `series_names('host')` | {host_series:,} host series | "
|
|
f"{_ms(dev['paths']['series_names_host']['mean'])} |")
|
|
push(f"| `stats()` counts | `{dev_by_res}` | "
|
|
f"{_ms(dev['paths']['stats_by_res']['mean'])} + "
|
|
f"{_ms(dev['paths']['stats_events']['mean'])} |")
|
|
push("")
|
|
for key, plan_rows in dev["plans"].items():
|
|
push(f"- `{key}`: " + " · ".join(f"`{row}`" for row in plan_rows))
|
|
push("")
|
|
integrity = report.get("store_after", {}).get("integrity", "?")
|
|
push(f"Seeded shape after the measurements: `{integrity}` "
|
|
f"(raw {report['store_after']['counts']['raw']:,}).")
|
|
return "\n".join(lines)
|
|
|
|
|
|
def write_report(report: dict[str, Any], out_prefix: Path) -> dict[str, str]:
|
|
"""Write `<prefix>.json` and `<prefix>.md` so the numbers survive the terminal."""
|
|
out_prefix.parent.mkdir(parents=True, exist_ok=True)
|
|
json_path = out_prefix.with_suffix(".json")
|
|
md_path = out_prefix.with_suffix(".md")
|
|
json_path.write_text(json.dumps(report, indent=2, sort_keys=True) + "\n")
|
|
md_path.write_text(render_markdown(report) + "\n")
|
|
return {"json": str(json_path), "md": str(md_path)}
|