|
| 1 | +#!/usr/bin/env python3 |
| 2 | +"""Post-hoc per-trial token/latency accounting from the gateway request log. |
| 3 | +
|
| 4 | +Reads a VeRO session directory (extracted ``session.tar.gz``, a salvage copy, |
| 5 | +or the admin volume) and attributes the gateway's request-log records to the |
| 6 | +Harbor trials they served, without any harness cooperation: |
| 7 | +
|
| 8 | +1. Trials are inventoried from ``evaluations/*/artifacts/harbor/**/result.json`` |
| 9 | + (task name, wall-clock window, agent-reported tokens) together with their |
| 10 | + agent trace files, which serve as per-trial content ground truth. |
| 11 | +2. Records are grouped into conversation threads — by the gateway's stamped |
| 12 | + ``thread_id`` when present (``request_log.attribution`` builds), otherwise |
| 13 | + by a first-user-message snippet recovered from the truncated body. |
| 14 | +3. Threads map to trials by snippet containment in the trial's own traces or |
| 15 | + (with --tasks-dir) task instruction files, falling back to a unique trial |
| 16 | + time-window overlap. Anything else is an explicit unattributed residual — |
| 17 | + per-trial numbers are lower bounds; the gateway per-evaluation totals are |
| 18 | + the envelope. |
| 19 | +
|
| 20 | +Coverage note: on **stamped** logs (``request_log.attribution: true``) every |
| 21 | +turn inherits its conversation's thread_id, so stateful APIs (OpenAI |
| 22 | +responses' ``previous_response_id``) attribute fully. On **legacy** logs the |
| 23 | +fallback recovers only each conversation's root turn — chained follow-ups |
| 24 | +with empty bodies are unrecoverable and land in the residual. Enable |
| 25 | +attribution at build time for complete coverage. |
| 26 | +
|
| 27 | +Usage: per_trial_tokens.py SESSION_DIR [--requests-dir DIR] [--tasks-dir DIR] |
| 28 | + [--json] |
| 29 | +""" |
| 30 | + |
| 31 | +from __future__ import annotations |
| 32 | + |
| 33 | +import argparse |
| 34 | +import json |
| 35 | +import re |
| 36 | +import sys |
| 37 | +from collections import defaultdict |
| 38 | +from datetime import datetime, timedelta |
| 39 | +from pathlib import Path |
| 40 | + |
| 41 | +TOKEN_KEYS = ("input_tokens", "cached_input_tokens", "output_tokens", "total_tokens") |
| 42 | +_INPUT_PATTERN = re.compile(r'"input"\s*:\s*"((?:[^"\\]|\\.){20,600})') |
| 43 | +_USER_CONTENT_PATTERN = re.compile( |
| 44 | + r'"role"\s*:\s*"user"[^{}\[\]]*?"(?:content|text)"\s*:\s*"((?:[^"\\]|\\.){20,600})' |
| 45 | +) |
| 46 | +_ESCAPES = [("\\n", " "), ("\\t", " "), ('\\"', '"'), ("\\\\", "\\")] |
| 47 | + |
| 48 | + |
| 49 | +def normalize(text: str) -> str: |
| 50 | + return "".join(character for character in text.lower() if character.isalnum()) |
| 51 | + |
| 52 | + |
| 53 | +def parse_time(value: str | None) -> datetime | None: |
| 54 | + if not isinstance(value, str): |
| 55 | + return None |
| 56 | + try: |
| 57 | + return datetime.fromisoformat(value.replace("Z", "+00:00")) |
| 58 | + except ValueError: |
| 59 | + return None |
| 60 | + |
| 61 | + |
| 62 | +def load_trials(session: Path) -> dict[str, list[dict]]: |
| 63 | + """Per evaluation id: trials with window, tokens, and normalized trace.""" |
| 64 | + by_evaluation: dict[str, list[dict]] = defaultdict(list) |
| 65 | + for result_path in session.glob("evaluations/*/artifacts/harbor/**/result.json"): |
| 66 | + try: |
| 67 | + value = json.loads(result_path.read_text(encoding="utf-8")) |
| 68 | + except (OSError, json.JSONDecodeError): |
| 69 | + continue |
| 70 | + if not isinstance(value, dict) or "task_name" not in value: |
| 71 | + continue |
| 72 | + evaluation_id = result_path.relative_to(session / "evaluations").parts[0] |
| 73 | + trace_chunks = [] |
| 74 | + agent_dir = result_path.parent / "agent" |
| 75 | + if agent_dir.is_dir(): |
| 76 | + for path in sorted(agent_dir.rglob("*")): |
| 77 | + if path.is_file() and path.stat().st_size < 20_000_000: |
| 78 | + try: |
| 79 | + trace_chunks.append( |
| 80 | + path.read_text(encoding="utf-8", errors="replace") |
| 81 | + ) |
| 82 | + except OSError: |
| 83 | + continue |
| 84 | + agent_result = value.get("agent_result") or {} |
| 85 | + by_evaluation[evaluation_id].append( |
| 86 | + { |
| 87 | + "task_name": value.get("task_name"), |
| 88 | + "trial_name": value.get("trial_name"), |
| 89 | + "started": parse_time(value.get("started_at")), |
| 90 | + "finished": parse_time(value.get("finished_at")), |
| 91 | + "agent_reported": { |
| 92 | + key: agent_result.get(key) |
| 93 | + for key in ("n_input_tokens", "n_cache_tokens", "n_output_tokens") |
| 94 | + if isinstance(agent_result.get(key), (int, float)) |
| 95 | + }, |
| 96 | + "trace": normalize("\n".join(trace_chunks)), |
| 97 | + } |
| 98 | + ) |
| 99 | + return by_evaluation |
| 100 | + |
| 101 | + |
| 102 | +def recover_snippet(record: dict) -> str | None: |
| 103 | + """First-user-message snippet for legacy (unstamped) records.""" |
| 104 | + text = (record.get("request") or {}).get("text") or "" |
| 105 | + match = _INPUT_PATTERN.search(text) or _USER_CONTENT_PATTERN.search(text) |
| 106 | + if not match: |
| 107 | + return None |
| 108 | + snippet = match.group(1) |
| 109 | + for escaped, plain in _ESCAPES: |
| 110 | + snippet = snippet.replace(escaped, plain) |
| 111 | + return snippet[:200] |
| 112 | + |
| 113 | + |
| 114 | +def load_threads(requests_dir: Path) -> dict[str, dict[str, dict]]: |
| 115 | + """Per evaluation id: threads with summed usage, snippet, and time span.""" |
| 116 | + per_evaluation: dict[str, dict[str, dict]] = defaultdict(dict) |
| 117 | + for log_path in sorted(requests_dir.glob("requests-*.jsonl")): |
| 118 | + with open(log_path, encoding="utf-8") as handle: |
| 119 | + for line in handle: |
| 120 | + try: |
| 121 | + record = json.loads(line) |
| 122 | + except json.JSONDecodeError: |
| 123 | + continue |
| 124 | + if record.get("scope") not in ("evaluation", "finalization"): |
| 125 | + continue |
| 126 | + evaluation_id = record.get("attribution") |
| 127 | + snippet = record.get("root_snippet") or recover_snippet(record) |
| 128 | + thread_key = record.get("thread_id") or ( |
| 129 | + "snippet:" + normalize(snippet or "")[:160] or "unattributed" |
| 130 | + ) |
| 131 | + thread = per_evaluation[evaluation_id].setdefault( |
| 132 | + thread_key, |
| 133 | + { |
| 134 | + "requests": 0, |
| 135 | + "latency_ms": 0.0, |
| 136 | + "snippet": None, |
| 137 | + "first": None, |
| 138 | + "last": None, |
| 139 | + **{key: 0 for key in TOKEN_KEYS}, |
| 140 | + }, |
| 141 | + ) |
| 142 | + thread["requests"] += 1 |
| 143 | + thread["latency_ms"] += record.get("latency_ms") or 0.0 |
| 144 | + for key in TOKEN_KEYS: |
| 145 | + value = record.get(key) |
| 146 | + if isinstance(value, (int, float)): |
| 147 | + thread[key] += int(value) |
| 148 | + if snippet and not thread["snippet"]: |
| 149 | + thread["snippet"] = snippet |
| 150 | + timestamp = parse_time(record.get("ts")) |
| 151 | + if timestamp is not None: |
| 152 | + if thread["first"] is None or timestamp < thread["first"]: |
| 153 | + thread["first"] = timestamp |
| 154 | + if thread["last"] is None or timestamp > thread["last"]: |
| 155 | + thread["last"] = timestamp |
| 156 | + return per_evaluation |
| 157 | + |
| 158 | + |
| 159 | +def load_task_texts(tasks_dir: Path | None) -> list[tuple[str, str]]: |
| 160 | + """(task_name, normalized instruction) for snippet→task labeling.""" |
| 161 | + if tasks_dir is None: |
| 162 | + return [] |
| 163 | + texts = [] |
| 164 | + for task_dir in sorted(tasks_dir.glob("*")): |
| 165 | + if not task_dir.is_dir(): |
| 166 | + continue |
| 167 | + chunks = [] |
| 168 | + for name in ("tests/prompt.txt", "instruction.md", "task.toml"): |
| 169 | + path = task_dir / name |
| 170 | + if path.is_file(): |
| 171 | + try: |
| 172 | + chunks.append(path.read_text(encoding="utf-8", errors="replace")) |
| 173 | + except OSError: |
| 174 | + continue |
| 175 | + if chunks: |
| 176 | + texts.append((task_dir.name, normalize("\n".join(chunks)))) |
| 177 | + return texts |
| 178 | + |
| 179 | + |
| 180 | +def assign_thread( |
| 181 | + thread: dict, trials: list[dict], task_texts: list[tuple[str, str]] |
| 182 | +) -> dict | None: |
| 183 | + snippet = normalize(thread["snippet"] or "") |
| 184 | + if len(snippet) >= 24: |
| 185 | + matches = [trial for trial in trials if snippet in trial["trace"]] |
| 186 | + if len(matches) == 1: |
| 187 | + return matches[0] |
| 188 | + # Label via task instruction files, then resolve to the trial(s) that |
| 189 | + # ran that task (>1 with repeated passes → tokens split evenly). |
| 190 | + labeled = [name for name, text in task_texts if snippet[:120] in text] |
| 191 | + if len(labeled) == 1: |
| 192 | + by_task = [t for t in trials if str(t["task_name"]).endswith(labeled[0])] |
| 193 | + if by_task: |
| 194 | + return by_task[0] |
| 195 | + if thread["first"] is not None and thread["last"] is not None: |
| 196 | + slack = timedelta(seconds=10) |
| 197 | + covering = [ |
| 198 | + trial |
| 199 | + for trial in trials |
| 200 | + if trial["started"] is not None |
| 201 | + and trial["finished"] is not None |
| 202 | + and trial["started"] - slack <= thread["first"] |
| 203 | + and thread["last"] <= trial["finished"] + slack |
| 204 | + ] |
| 205 | + if len(covering) == 1: |
| 206 | + return covering[0] |
| 207 | + return None |
| 208 | + |
| 209 | + |
| 210 | +def main() -> int: |
| 211 | + parser = argparse.ArgumentParser(description=__doc__) |
| 212 | + parser.add_argument("session", type=Path) |
| 213 | + parser.add_argument("--requests-dir", type=Path, default=None) |
| 214 | + parser.add_argument("--tasks-dir", type=Path, default=None) |
| 215 | + parser.add_argument("--json", action="store_true", dest="as_json") |
| 216 | + arguments = parser.parse_args() |
| 217 | + |
| 218 | + session = arguments.session |
| 219 | + requests_dir = ( |
| 220 | + arguments.requests_dir or session / "artifacts" / "inference" / "requests" |
| 221 | + ) |
| 222 | + if not requests_dir.is_dir(): |
| 223 | + print(f"no request log at {requests_dir}", file=sys.stderr) |
| 224 | + return 1 |
| 225 | + |
| 226 | + trials_by_evaluation = load_trials(session) |
| 227 | + threads_by_evaluation = load_threads(requests_dir) |
| 228 | + task_texts = load_task_texts(arguments.tasks_dir) |
| 229 | + |
| 230 | + report = {} |
| 231 | + for evaluation_id, threads in sorted(threads_by_evaluation.items()): |
| 232 | + trials = trials_by_evaluation.get(evaluation_id, []) |
| 233 | + per_trial: dict[str, dict] = {} |
| 234 | + residual = {"requests": 0, **{key: 0 for key in TOKEN_KEYS}} |
| 235 | + for thread in threads.values(): |
| 236 | + trial = assign_thread(thread, trials, task_texts) |
| 237 | + if trial is None: |
| 238 | + residual["requests"] += thread["requests"] |
| 239 | + for key in TOKEN_KEYS: |
| 240 | + residual[key] += thread[key] |
| 241 | + continue |
| 242 | + entry = per_trial.setdefault( |
| 243 | + trial["task_name"], |
| 244 | + { |
| 245 | + "requests": 0, |
| 246 | + "latency_ms": 0.0, |
| 247 | + "agent_reported": trial["agent_reported"], |
| 248 | + **{key: 0 for key in TOKEN_KEYS}, |
| 249 | + }, |
| 250 | + ) |
| 251 | + entry["requests"] += thread["requests"] |
| 252 | + entry["latency_ms"] += thread["latency_ms"] |
| 253 | + for key in TOKEN_KEYS: |
| 254 | + entry[key] += thread[key] |
| 255 | + total = { |
| 256 | + key: sum(thread[key] for thread in threads.values()) for key in TOKEN_KEYS |
| 257 | + } |
| 258 | + attributed = { |
| 259 | + key: sum(entry[key] for entry in per_trial.values()) for key in TOKEN_KEYS |
| 260 | + } |
| 261 | + report[evaluation_id] = { |
| 262 | + "trials": per_trial, |
| 263 | + "gateway_total": total, |
| 264 | + "attributed": attributed, |
| 265 | + "residual": residual, |
| 266 | + "coverage_pct": ( |
| 267 | + round(100.0 * attributed["total_tokens"] / total["total_tokens"], 1) |
| 268 | + if total["total_tokens"] |
| 269 | + else None |
| 270 | + ), |
| 271 | + } |
| 272 | + |
| 273 | + if arguments.as_json: |
| 274 | + print(json.dumps(report, indent=1, default=str)) |
| 275 | + return 0 |
| 276 | + |
| 277 | + for evaluation_id, data in report.items(): |
| 278 | + print(f"\n=== evaluation {evaluation_id} ===") |
| 279 | + header = f"{'task':<44} {'req':>5} {'input':>10} {'cached':>10} {'output':>8} {'agent-reported in/cache/out':>28}" |
| 280 | + print(header) |
| 281 | + for task_name, entry in sorted(data["trials"].items()): |
| 282 | + reported = entry["agent_reported"] |
| 283 | + reported_text = "/".join( |
| 284 | + str(reported.get(key, "-")) |
| 285 | + for key in ("n_input_tokens", "n_cache_tokens", "n_output_tokens") |
| 286 | + ) |
| 287 | + print( |
| 288 | + f"{str(task_name)[:44]:<44} {entry['requests']:>5} " |
| 289 | + f"{entry['input_tokens']:>10} {entry['cached_input_tokens']:>10} " |
| 290 | + f"{entry['output_tokens']:>8} {reported_text:>28}" |
| 291 | + ) |
| 292 | + residual = data["residual"] |
| 293 | + print( |
| 294 | + f"{'(unattributed)':<44} {residual['requests']:>5} " |
| 295 | + f"{residual['input_tokens']:>10} {residual['cached_input_tokens']:>10} " |
| 296 | + f"{residual['output_tokens']:>8}" |
| 297 | + ) |
| 298 | + print( |
| 299 | + f"coverage: {data['coverage_pct']}% of " |
| 300 | + f"{data['gateway_total']['total_tokens']} gateway-metered tokens attributed" |
| 301 | + ) |
| 302 | + return 0 |
| 303 | + |
| 304 | + |
| 305 | +if __name__ == "__main__": |
| 306 | + raise SystemExit(main()) |
0 commit comments