[eric] browser: persist the wall/llm/tools/ours latency split, so a speed claim has evidence

This commit is contained in:
ciregenz
2026-08-01 00:35:11 -07:00
parent 5799b3b62a
commit 2489cc3971
3 changed files with 31 additions and 2 deletions
+3 -1
View File
@@ -1654,6 +1654,7 @@ async def run_browser_agent(
session_id, browser_id, task, "completed", metrics_started_at,
turns_spent, rlog, session.tokens,
path="replay", task_sig=browser_skills.compute_sig(skill_key_task),
tools_ms=browser_ms_used(),
)
logger.info(f"[browser-skills] REPLAY SUCCEEDED in {summary['total_ms']}ms ({turns_spent} LLM turn(s))")
try:
@@ -3132,7 +3133,8 @@ async def run_browser_agent(
metrics_started_at, turn + 1, action_log, session.tokens,
path="llm_fallback" if replay_attempted else "llm",
task_sig=browser_skills.compute_sig(skill_key_task),
playbook_seeded=pb_seeded)
playbook_seeded=pb_seeded,
llm_ms=llm_ms_total, tools_ms=p_tools_ms_total)
# Learn this task ONLY from a genuinely successful run whose deliverable a deterministic replay can actually reproduce. We skip recording when the run was dishonest (ghost) OR when its answer was gathered/judged content (a list/report): replay can redo the clicks but not regenerate the judgment, so recording it would create a thin shortcut that later ghosts.
informational = deliverable_is_informational(summary, skill_key_task)
# A removal run is NOT a recordable skill: the actual delete is a one-shot destructive
@@ -144,7 +144,8 @@ def record_skill_event(kind, host, task_sig, rev=0, state="", extra=None) -> Non
def record_task(session_id, browser_id, task, status, started_at, turns,
action_log, tokens, path="llm", task_sig="", playbook_seeded=False) -> dict:
action_log, tokens, path="llm", task_sig="", playbook_seeded=False,
llm_ms: int = 0, tools_ms: int = 0) -> dict:
"""One summary line per finished task: completion, total time, per-tier
latency, token cost, and the recurring-error rollup. `path` records HOW the
task finished (replay = no-LLM fast path, llm = full agent, llm_fallback =
@@ -176,6 +177,12 @@ def record_task(session_id, browser_id, task, status, started_at, turns,
"status": status,
"completed": status == "completed",
"total_ms": total_ms,
# The wall clock alone cannot tell "our code got faster" from "the model took fewer turns",
# and on live sites the turn roulette is 5-12x, which buries every change we actually make.
# other_ms is the part we own, so a latency claim has something to stand on.
"llm_ms": llm_ms,
"tools_ms": tools_ms,
"other_ms": max(0, total_ms - llm_ms - tools_ms),
"turns": turns,
"tool_calls": len(action_log),
"tokens_in": (tokens or {}).get("input", 0),
+20
View File
@@ -78,6 +78,26 @@ def test_record_task_summary_and_rollups(metrics):
assert len(tasks) == 1 and tasks[0]["status"] == "completed"
def test_the_latency_split_is_persisted_not_just_logged(metrics):
"""wall = llm + tools + ours, and only the last term is ours to improve. The split existed as a
log line nobody could analyse later, so every latency claim was measured on the wall clock, and
the wall clock on live sites swings 5-12x on model turn count alone. Persist it or it is not
evidence."""
bm, d = metrics
summary = bm.record_task("s1", "b1", "t", "completed", __import__("time").time() - 10.0,
4, [], {}, llm_ms=6000, tools_ms=2500)
assert summary["llm_ms"] == 6000 and summary["tools_ms"] == 2500
assert 1000 <= summary["other_ms"] <= 2000, summary["other_ms"]
assert p_read(d, "tasks.jsonl")[0]["other_ms"] == summary["other_ms"]
def test_a_run_that_reported_no_split_never_shows_negative_time(metrics):
"""Default 0s (the stopped/error paths) must read as "unknown", never as a bogus fast run."""
bm, _ = metrics
s = bm.record_task("s1", "b1", "t", "stopped", __import__("time").time() - 1.0, 1, [], {})
assert s["llm_ms"] == 0 and s["other_ms"] == s["total_ms"] >= 0
def test_metrics_never_raises_on_bad_dir(monkeypatch):
# An unwritable dir must not throw into the agent loop.
monkeypatch.setenv("OPENSWARM_BROWSER_METRICS_DIR", "/proc/cannot/write/here")