From 2304980c40292ad7d94dabd42252287520853a64 Mon Sep 17 00:00:00 2001 From: Adarsh Prashar Date: Mon, 15 Jun 2026 00:47:11 +0530 Subject: [PATCH] feat(benchmark): timed kill -9 recovery with exact-once spend MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add a recovery-time benchmark alongside the cost benchmark. It interrupts a governed, checkpointing run with a hard kill -9 of the daemon mid-run, restarts on the same durable data dir, and times how long until the daemon is healthy with the run reloaded. It then proves the cost meter continues from where it was — no reset, no double-count — and still halts at the original budget, i.e. exact-once spend across the crash. Key-free and deterministic like the cost benchmark: the same mock provider, a dummy key, spend read from RiskKernel's own ledger (GET /v1/runs/{id}). Numbers are merged into results.json under a recovery key without touching the existing cost object; the benchmark README gains a Recovery time section. --- CHANGELOG.md | 11 ++ benchmark/README.md | 72 +++++++++- benchmark/recovery.py | 313 ++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 392 insertions(+), 4 deletions(-) create mode 100644 benchmark/recovery.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 9ec1e0c..f664f72 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,17 @@ surface is governed by [`COMPATIBILITY.md`](COMPATIBILITY.md). ## [Unreleased] ### Added +- **Recovery-time benchmark — timed `kill -9` resume with exact-once spend.** + [`benchmark/recovery.py`](benchmark/recovery.py) adds the crash-recovery dimension + to the cost benchmark: a governed, checkpointing run is interrupted by a hard + `kill -9` of the daemon mid-run, the daemon is restarted on the same durable data + dir, and the harness times how long until it's healthy with the run reloaded + (**recovery time**) and proves the cost meter continues from where it was — no + reset, no double-count — and still halts at the original budget. Deterministic and + key-free (the existing mock provider, dummy key, spend read from RiskKernel's own + ledger); it merges its numbers into `results.json` under a `recovery` key without + touching the existing cost object. The benchmark README gains a "Recovery time" + section with the methodology. - **One-command docker-compose quickstart.** [`examples/quickstart-compose`](examples/quickstart-compose) brings up the daemon, a stand-in mock LLM, and a tiny looping agent with a single `docker compose up` — so a newcomer watches the deterministic loop budget hard-stop diff --git a/benchmark/README.md b/benchmark/README.md index 38a662a..cbf4aeb 100644 --- a/benchmark/README.md +++ b/benchmark/README.md @@ -64,12 +64,76 @@ runaway would have continued.** The baseline grows without bound: So "dollars saved" is a function of how far the loop would have run before a human noticed — and RiskKernel's guarantee is the **flat ceiling**, not a fixed percentage. +## Recovery time — `kill -9` mid-run, resume without re-spending + +The second dimension. [`recovery.py`](recovery.py) measures **crash recovery**: a +governed, checkpointing run is interrupted by a hard `kill -9` of the daemon +mid-run, the daemon is restarted on the same durable data dir, and we time how long +until it's healthy with the run reloaded — then prove the run finishes **without +re-spending**. + +```bash +python3 benchmark/recovery.py +``` + +``` + RiskKernel recovery benchmark — kill -9 mid-run, resume without re-spending + ------------------------------------------------------------------ + dollar budget $0.25 + per-call cost $0.0125 (gpt-4o, from RiskKernel's ledger) + calls before crash 8 + ------------------------------------------------------------------ + RECOVERY TIME 53 ms (kill -9 -> healthy + run reloaded) + daemon log "resumed runs from store" count=1 + ------------------------------------------------------------------ + spend (ledger) dollars tokens loops + before crash $0.1000 16000 8 + after restart (reloaded) $0.1000 16000 8 + final (budget halt) $0.2500 40000 20 + ------------------------------------------------------------------ + meter NOT reset by crash yes (after-restart spend >= before) + meter NOT double-counted yes (after-restart spend == before) + halted at original budget yes (dollar_budget_exceeded) + EXACT-ONCE across crash PASS +``` + +Tunable via env: `BUDGET`, `PRE_CRASH_CALLS` (calls before the crash), `N` (safety +cap on the loop), `RK_BIN`. + +### Methodology (the exact-once guarantee) + +Same key-free, deterministic setup as the cost benchmark — the mock provider, a +dummy key, spend read from RiskKernel's own ledger. The sequence: + +1. **Spend, then checkpoint.** The run makes several governed calls through + RiskKernel (grouped by a run-id header) and checkpoints between them. The spend so + far is read from the ledger (`GET /v1/runs/{id}` → `usage.dollars / tokens / + loops`) — *before crash* in the table. +2. **Hard crash.** The daemon is `SIGKILL`'d — no graceful shutdown, no chance to + flush. Everything that survives is what was already durable in SQLite. +3. **Timed recovery.** The daemon is restarted on the **same data dir**. The clock + runs until `/healthz` is up *and* `GET /v1/runs/{id}` shows the run reloaded and + still `running` with its prior spend — that interval is the **recovery time**. The + `resumed runs from store` startup line is the daemon's own confirmation it + restored runs from the store. +4. **Continue to the budget.** The run keeps calling on the same run-id until it + halts. The proof is three-way: the *after-restart* spend equals the *before-crash* + spend (no reset, no double-count), and the *final* spend lands on exactly the + budget with `dollar_budget_exceeded` — i.e. each call is charged **exactly once** + across the crash. If the meter had reset to `$0`, the run would have spent the + budget *plus* the pre-crash calls re-paid (the counterfactual the harness prints). + +Recovery is sub-100 ms on a laptop here because the work is reloading rows from a +local SQLite file, not replaying a log. The number scales with how many runs and how +much ledger history the store holds, not with how long the killed run had been +spending. + ## Scope & honesty -- This measures the **cost-ceiling** dimension. The **crash-recovery** dimension — - `kill -9` mid-run, resume without re-spending — is demonstrated end-to-end in - [`examples/kill-9-resume`](../examples/kill-9-resume); a *timed* recovery - benchmark is a planned addition here. +- Two dimensions are measured here: the **cost ceiling** ([`benchmark.py`](benchmark.py)) + and **crash recovery** ([`recovery.py`](recovery.py), above). The crash-resume + mechanism is also demonstrated interactively in + [`examples/kill-9-resume`](../examples/kill-9-resume). - It deliberately removes provider latency/variance to isolate the governance effect. The enforcement overhead RiskKernel itself adds is small and measured separately; this harness is about dollars, not milliseconds. diff --git a/benchmark/recovery.py b/benchmark/recovery.py new file mode 100644 index 0000000..ba265fb --- /dev/null +++ b/benchmark/recovery.py @@ -0,0 +1,313 @@ +#!/usr/bin/env python3 +"""RiskKernel recovery benchmark — timed crash-resume with exact-once spend. + +The companion to benchmark.py (the cost dimension). This measures the *recovery* +dimension: a governed, checkpointing run is interrupted by a hard `kill -9` of the +daemon mid-run, the daemon is restarted on the same durable data dir, and we prove +the run finishes WITHOUT re-spending — the cost counter continues from where it was +(no reset, no double-count) and the run still halts at its original budget. That's +exact-once spend across a crash. + +What it measures: + + 1. A checkpointing run makes several governed calls through RiskKernel (run-id + header groups them; a checkpoint is saved between steps). Spend is read from + RiskKernel's own ledger (GET /v1/runs/{id} -> usage.dollars / tokens / loops). + 2. The daemon is SIGKILL'd (no graceful shutdown) mid-run. + 3. The daemon is restarted on the SAME data dir; we time how long until it is + healthy AND the run has been reloaded with the spend it already had + (RECOVERY TIME). + 4. The run continues calling until the dollar budget halts; we confirm the meter + resumed from the pre-crash spend (not 0, not doubled) and the total halted + spend equals exactly the budget. + +Everything is deterministic and key-free: the same mock_provider.py the cost +benchmark uses, reached via RISKKERNEL_OPENAI_BASE_URL with a dummy OPENAI_API_KEY, +models routed to openai ("gpt-4o"). No network, no real money. + +Run: python3 benchmark/recovery.py +Env: RK_BIN (default "riskkernel"), N, BUDGET, PRE_CRASH_CALLS, PORT, MOCK_PORT +""" +import json +import os +import shutil +import signal +import subprocess +import sys +import time +import urllib.error +import urllib.request + +HERE = os.path.dirname(os.path.abspath(__file__)) +RK_BIN = os.environ.get("RK_BIN", "riskkernel") +N = int(os.environ.get("N", "50")) # max calls (safety cap on the loop) +BUDGET = float(os.environ.get("BUDGET", "0.25")) # dollar ceiling for the run +PRE_CRASH_CALLS = int(os.environ.get("PRE_CRASH_CALLS", "8")) # calls to make before the kill -9 +PORT = int(os.environ.get("PORT", "7070")) +MOCK_PORT = int(os.environ.get("MOCK_PORT", "9099")) +MODEL = "gpt-4o" +RUN_ID = "bench-recovery" +RK_URL = f"http://127.0.0.1:{PORT}" +MOCK_URL = f"http://127.0.0.1:{MOCK_PORT}" +RUN_URL = f"{RK_URL}/v1/runs/{RUN_ID}" +CHAT_URL = f"{RK_URL}/v1/chat/completions" +RUN_HEADERS = {"X-RiskKernel-Run-Id": RUN_ID} +CHAT_BODY = json.dumps({"model": MODEL, "messages": [{"role": "user", "content": "continue"}]}).encode() + + +def post(url, body=CHAT_BODY, headers=None, timeout=15): + req = urllib.request.Request(url, data=body, method="POST", + headers={"Content-Type": "application/json", **(headers or {})}) + try: + with urllib.request.urlopen(req, timeout=timeout) as r: + return r.status, b"" + except urllib.error.HTTPError as e: + return e.code, e.read() + except Exception: + return 0, b"" # connection refused while a server is still starting/down + + +def get_json(url, timeout=5): + with urllib.request.urlopen(url, timeout=timeout) as r: + return json.loads(r.read()) + + +def wait_get(url, timeout=25): + deadline = time.time() + timeout + while time.time() < deadline: + try: + urllib.request.urlopen(url, timeout=1) + return True + except Exception: + time.sleep(0.05) + return False + + +def wait_post(url, timeout=10): + deadline = time.time() + timeout + while time.time() < deadline: + if post(url, timeout=1)[0] == 200: + return True + time.sleep(0.1) + return False + + +def usage_of(run): + u = run.get("usage", {}) + return { + "dollars": float(u.get("dollars", 0.0)), + "tokens": int(u.get("tokens", 0)), + "loops": int(u.get("loops", 0)), + } + + +def serve_env(data_dir): + return dict(os.environ, + RISKKERNEL_PORT=str(PORT), + RISKKERNEL_DATA_DIR=data_dir, + RISKKERNEL_DEFAULT_PROVIDER="openai", + OPENAI_API_KEY="bench-dummy-key", + RISKKERNEL_OPENAI_BASE_URL=MOCK_URL, + RISKKERNEL_DEFAULT_DOLLARS=str(BUDGET), + RISKKERNEL_DEFAULT_LOOPS="0", # only the dollar budget halts the loop + RISKKERNEL_DEFAULT_SECONDS="0", + RISKKERNEL_PRICING_FILE=os.path.join(HERE, "pricing.json")) + + +def start_daemon(data_dir, log_path): + """Start `riskkernel serve` on data_dir, logging to log_path. Returns the Popen.""" + log = open(log_path, "ab") + return subprocess.Popen([RK_BIN, "serve"], env=serve_env(data_dir), + stdout=log, stderr=log) + + +def make_calls(n): + """Make up to n governed calls on RUN_ID; stop early on the first non-200 (a + budget halt). Returns (calls_made, halt_reason).""" + calls, halt = 0, "" + for _ in range(n): + code, body = post(CHAT_URL, headers=RUN_HEADERS) + if code != 200: + try: + halt = json.loads(body).get("code") or f"http {code}" + except Exception: + halt = f"http {code}" + break + calls += 1 + return calls, halt + + +def checkpoint(cursor): + body = json.dumps({"name": "progress", "payload": {"cursor": cursor}}).encode() + post(f"{RUN_URL}/checkpoints", body=body, headers=None) + + +def wait_recovered(deadline_s=25): + """Time from now until the daemon is healthy AND the crashed run has been + reloaded with its prior spend. Returns (recovery_seconds, reloaded_run).""" + start = time.time() + if not wait_get(f"{RK_URL}/healthz", timeout=deadline_s): + sys.exit("riskkernel did not come back up after the crash") + # Healthy isn't enough: confirm the run itself is reloaded and still 'running' + # with the usage it had before the crash (Reload restores non-terminal runs). + deadline = time.time() + deadline_s + while time.time() < deadline: + try: + run = get_json(RUN_URL) + if run.get("status") == "running" and usage_of(run)["loops"] > 0: + return time.time() - start, run + except Exception: + pass + time.sleep(0.02) + sys.exit("the crashed run was not reloaded after restart") + + +def grep_resumed(log_path): + """Return the 'resumed runs from store' startup line, if present (proof the + daemon restored runs from the durable store on restart).""" + try: + with open(log_path, "r", errors="ignore") as f: + for line in reversed(f.readlines()): + if "resumed runs from store" in line: + return line.strip() + except Exception: + pass + return "" + + +def main(): + data_dir = os.path.join(HERE, ".recovery-data") + log_path = os.path.join(HERE, ".recovery-serve.log") + shutil.rmtree(data_dir, ignore_errors=True) + if os.path.exists(log_path): + os.remove(log_path) + + mock = subprocess.Popen([sys.executable, os.path.join(HERE, "mock_provider.py"), str(MOCK_PORT)]) + rk = start_daemon(data_dir, log_path) + rk2 = None + try: + if not wait_post(f"{MOCK_URL}/v1/chat/completions"): + sys.exit("mock provider did not come up") + if not wait_get(f"{RK_URL}/healthz"): + sys.exit("riskkernel did not come up") + + # 1. A checkpointing run makes several governed calls (under the budget). + before_calls = 0 + for i in range(min(PRE_CRASH_CALLS, N)): + code, _ = post(CHAT_URL, headers=RUN_HEADERS) + if code != 200: + break + before_calls += 1 + checkpoint(before_calls) # save WHERE we are between steps, durably + + before = usage_of(get_json(RUN_URL)) + if before["loops"] == 0: + sys.exit("no spend recorded before the crash — cannot test resume") + + # 2. kill -9 the daemon mid-run — a hard crash, no graceful shutdown. + rk.send_signal(signal.SIGKILL) + rk.wait(5) + + # 3. Restart on the SAME data dir; time recovery (healthy + run reloaded). + rk2 = start_daemon(data_dir, log_path) + recovery_s, reloaded = wait_recovered() + after_restart = usage_of(reloaded) + resumed_line = grep_resumed(log_path) + + # 4. Continue the run to completion; it must halt at the ORIGINAL budget. + remaining_calls = N - before_calls + post_calls, halt = make_calls(remaining_calls) + final = usage_of(get_json(RUN_URL)) + + # --- exact-once checks --- + per_call = before["dollars"] / before["loops"] if before["loops"] else 0.0 + no_reset = after_restart["dollars"] >= before["dollars"] - 1e-9 + no_double = abs(after_restart["dollars"] - before["dollars"]) < 1e-9 + # The run's final loop count must equal the budget ceiling — one charge per + # call, never re-charging the pre-crash calls. If the meter had reset, it + # would take ~before_calls MORE calls (and total loops > ceiling) to halt. + ceiling_loops = int(round(BUDGET / per_call)) if per_call else 0 + exact_once = ( + no_double + and final["loops"] == ceiling_loops + and abs(final["dollars"] - BUDGET) < per_call / 2 + and halt == "dollar_budget_exceeded" + ) + + # Counterfactual: if the crash had RESET the meter to $0, the post-crash + # phase would have run a FULL budget's worth of calls again (ceiling_loops) + # before halting — so the run would have spent the pre-crash calls plus a + # whole second ceiling. That's the double-spend exact-once prevents. + reset_would_have_spent = (before_calls + ceiling_loops) * per_call + + print("\n RiskKernel recovery benchmark — kill -9 mid-run, resume without re-spending") + print(" " + "-" * 66) + print(f" dollar budget ${BUDGET:.2f}") + print(f" per-call cost ${per_call:.4f} ({MODEL}, from RiskKernel's ledger)") + print(f" calls before crash {before_calls}") + print(" " + "-" * 66) + print(f" RECOVERY TIME {recovery_s * 1000:.0f} ms (kill -9 -> healthy + run reloaded)") + if resumed_line: + msg = resumed_line.split("msg=", 1)[-1] if "msg=" in resumed_line else resumed_line + print(f" daemon log {msg}") + print(" " + "-" * 66) + print(f" {'spend (ledger)':28}{'dollars':>10}{'tokens':>9}{'loops':>7}") + print(f" {'before crash':28}{'$'+format(before['dollars'], '.4f'):>10}{before['tokens']:>9}{before['loops']:>7}") + print(f" {'after restart (reloaded)':28}{'$'+format(after_restart['dollars'], '.4f'):>10}{after_restart['tokens']:>9}{after_restart['loops']:>7}") + print(f" {'final (budget halt)':28}{'$'+format(final['dollars'], '.4f'):>10}{final['tokens']:>9}{final['loops']:>7}") + print(" " + "-" * 66) + print(f" meter NOT reset by crash {'yes' if no_reset else 'NO'} (after-restart spend >= before)") + print(f" meter NOT double-counted {'yes' if no_double else 'NO'} (after-restart spend == before)") + print(f" halted at original budget {'yes' if exact_once else 'NO'} ({halt or 'did not halt'})") + print(f" EXACT-ONCE across crash {'PASS' if exact_once else 'FAIL'}") + print(f" (a crash that reset the meter would have spent ${reset_would_have_spent:.4f} " + f"— the ${final['dollars']:.4f} ceiling plus the {before_calls} pre-crash calls re-paid)") + print() + + # Append a structured record alongside the cost benchmark's results.json, + # without clobbering it: results.json stays the cost object; recovery lives + # under a "recovery" key (back-compatible — readers of the old shape still work). + results_path = os.path.join(HERE, "results.json") + results = {} + if os.path.exists(results_path): + try: + with open(results_path) as f: + results = json.load(f) + except Exception: + results = {} + results["recovery"] = { + "budget_dollars": BUDGET, + "per_call_dollars": round(per_call, 6), + "calls_before_crash": before_calls, + "recovery_ms": round(recovery_s * 1000, 1), + "before_crash": {k: round(v, 6) if k == "dollars" else v for k, v in before.items()}, + "after_restart": {k: round(v, 6) if k == "dollars" else v for k, v in after_restart.items()}, + "final": {k: round(v, 6) if k == "dollars" else v for k, v in final.items()}, + "halt_reason": halt, + "meter_not_reset": no_reset, + "meter_not_doubled": no_double, + "exact_once": exact_once, + "reset_would_have_spent_dollars": round(reset_would_have_spent, 6), + } + with open(results_path, "w") as f: + json.dump(results, f, indent=2) + f.write("\n") + + if not exact_once: + sys.exit("EXACT-ONCE check FAILED — see the table above") + finally: + for p in (rk2, rk, mock): + if p is None: + continue + p.terminate() + try: + p.wait(5) + except Exception: + p.kill() + shutil.rmtree(data_dir, ignore_errors=True) + if os.path.exists(log_path): + os.remove(log_path) + + +if __name__ == "__main__": + main()