Files
workinf_Blender_Wasm/my-tools/wbv2_timing.py
mes123456 f3e21c6b98
Some checks failed
M6 deployable RC / quick (push) Has been cancelled
M6 deployable RC / chromium (push) Has been cancelled
M6 deployable RC / release (push) Has been cancelled
chore: checkpoint web Blender migration source, tools and docs
Accumulated uncommitted work: GHOST Web backend, WebGL/GPU web layer,
web workflow engine and protocol, tooling, docs and task records.
Large generated evidence, user-testing archives, build snapshots and
imported test assets remain untracked.

Co-Authored-By: Claude Code <noreply@anthropic.com>
2026-11-10 11:18:01 +08:00

436 lines
24 KiB
Python

"""Incremental process telemetry and minute-labelled execution reports."""
from __future__ import annotations
import json
import hashlib
import re
import shlex
from collections import defaultdict
from datetime import datetime, timezone
from pathlib import Path
from zoneinfo import ZoneInfo
LOCAL_ZONE = ZoneInfo("Asia/Shanghai")
def minute_label(value):
if not value:
return None
try:
return datetime.fromisoformat(value.replace("Z", "+00:00")).astimezone(LOCAL_ZONE).strftime("%Y-%m-%d %H:%M")
except (ValueError, TypeError):
return value
def display_times(value):
if isinstance(value, list):
return [display_times(item) for item in value]
if not isinstance(value, dict):
return value
return {key: minute_label(item) if key.endswith("At") and isinstance(item, str) else display_times(item) for key, item in value.items()}
def command_phase(argv):
if not argv:
return "other"
if argv[0] == "codex":
return "model_request"
if argv[0] == "git":
return "git_" + (argv[1] if len(argv) > 1 else "other")
if any("task-context" in arg or "context-governance" in arg for arg in argv):
return "context_check"
if argv[0] in {"cmake", "ninja"}:
return "build"
return "command"
def item_phase(item):
kind = item.get("type", "unknown")
if kind == "file_change":
return "editing"
if kind != "command_execution":
return "tool" if kind != "agent_message" else "model_response"
try:
argv = shlex.split(item.get("command", ""))
if len(argv) >= 3 and argv[0].endswith(("bash", "sh")) and argv[1] in {"-lc", "-c"}:
argv = shlex.split(argv[2])
except ValueError:
return "command"
if not argv:
return "command"
if argv[0] in {"cat", "sed", "rg", "ls", "head", "tail", "wc", "find", "stat"} or any("search-wbv2" in arg or "print-task-context" in arg for arg in argv):
return "reading"
if "apply_patch" in argv[0]:
return "editing"
if any("test" in arg or "lint" in arg or "typecheck" in arg for arg in argv):
return "testing"
return command_phase(argv)
def read_only_command(command):
"""A narrow retry allowlist, not the looser display-phase classifier."""
if not isinstance(command, str) or any(c in command for c in "\n\r$`<>"):
return False
try:
argv = shlex.split(command)
if len(argv) == 3 and argv[0] in {"bash", "/bin/bash", "sh", "/bin/sh"} and argv[1] in {"-lc", "-c"}:
command = argv[2]
lexer = shlex.shlex(command, posix=True, punctuation_chars=True)
lexer.whitespace_split = True
lexer.commenters = ""
tokens = list(lexer)
except ValueError:
return False
commands, current = [], []
for token in tokens:
if token in {";", "&&", "|"}:
if not current:
return False
commands.append(current)
current = []
elif token in {"&", "||", "(", ")", ";;"}:
return False
else:
current.append(token)
if not current:
return False
commands.append(current)
for argv in commands:
name = argv[0]
if name in {"cat", "head", "tail", "wc", "ls", "stat"}:
continue
if name == "sed" and len(argv) >= 4 and argv[1] == "-n" and re.fullmatch(r"\d+(,\d+)?p", argv[2]) and all(not arg.startswith("-") for arg in argv[3:]):
continue
if name == "rg" and not any(arg.startswith(("--pre", "--hostname-bin", "--search-zip")) or (arg.startswith("-") and not arg.startswith("--") and "z" in arg) for arg in argv[1:]):
continue
if name == "node" and len(argv) >= 2:
if argv[1:] == ["tools/web/print-task-context.mjs"] or argv[1:] == ["tools/web/check-task-context.mjs"]:
continue
if argv[1] == "tools/web/search-wbv2-batch-source.mjs":
args = iter(argv[2:])
valid = True
for flag in args:
if flag in {"--help", "--list"}:
continue
value = next(args, None)
if flag not in {"--task", "--pattern", "--unit", "--runtime", "--max-hits"} or value is None or value.startswith("-"):
valid = False
break
if valid:
continue
return False
return True
def worker_breakdown(trace, elapsed):
"""Partition observed wall time so concurrent tool calls are counted once."""
items = trace.get("items", []) + trace.get("activeItems", [])
spans = [(max(0, min(elapsed, item["startedSeconds"])), max(0, min(elapsed, item.get("finishedSeconds", elapsed))), item["phase"]) for item in items]
first = min(elapsed, trace.get("firstActionSeconds") if trace.get("firstActionSeconds") is not None else elapsed)
last = max([first] + [end for _, end, _ in spans])
changes = defaultdict(lambda: defaultdict(int))
for start, end, phase in spans:
if end > start:
changes[start][phase] += 1
changes[end][phase] -= 1
points = sorted({0, elapsed, first, last, *changes})
totals = defaultdict(float)
active = defaultdict(int)
for start, end in zip(points, points[1:]):
for phase, change in changes[start].items():
active[phase] += change
phases = {phase for phase, count in active.items() if count > 0}
if phases:
phase = "tool:" + next(iter(phases)) if len(phases) == 1 else "tool:overlapping"
else:
phase = "before_first_action" if end <= first else "after_last_tool" if start >= last else "between_tools"
totals[phase] += end - start
return [{"phase": phase, "seconds": round(seconds, 6)} for phase, seconds in sorted(totals.items(), key=lambda pair: -pair[1])]
class WorkerTrace:
"""Times observed JSONL events; never infers model CPU time from silence."""
def __init__(self, on_event=None):
self.offset = 0
self.pending = b""
self.turn_started = False
self.actions_seen = False
self.unknown_output = False
self.first_event = None
self.first_action = None
self.last_progress = 0.0
self.last_output = 0.0
self.provider_error = None
self.errors = 0
self.active_items = {}
self.items = []
self.counts = defaultdict(int)
self.unsafe_actions = False
self.on_event = on_event
def feed(self, event, elapsed):
kind = event.get("type", "unknown")
if not isinstance(kind, str):
self.unknown_output = True
return
self.counts[kind] += 1
if kind not in {"thread.started", "turn.started", "turn.completed", "turn.failed", "error", "item.started", "item.updated", "item.completed"}:
self.unknown_output = True
self.first_event = elapsed if self.first_event is None else self.first_event
if kind == "turn.started":
self.turn_started = True
if kind in {"error", "turn.failed"}:
self.errors += 1
error = event.get("error")
message = event.get("message") or (error.get("message", "") if isinstance(error, dict) else error) or ""
if not isinstance(message, str):
message = str(message)
if re.search(r"concurrency limit|overload|rate.?limit|too many requests|\b429\b|\b503\b|service unavailable", message, re.I):
self.provider_error = re.sub(r"sk-[A-Za-z0-9_-]+", "[redacted]", message)[:600]
if kind.startswith("item."):
item = event.get("item") or {}
if not isinstance(item, dict):
self.unknown_output = True
return
item_type = item.get("type")
is_side_effect = item_type in {"command_execution", "file_change", "shell_command", "mcp_tool_call"}
# Agent prose and reasoning items do not mutate the workspace and
# must not disable the safe provider retry path.
if not is_side_effect:
if item_type not in {"agent_message", "reasoning", "todo_list"}:
self.unknown_output = True
return
self.actions_seen = True
self.first_action = elapsed if self.first_action is None else self.first_action
self.last_progress = elapsed
key = item.get("id")
if not key:
self.unknown_output = True
return
prior = self.active_items.get(key, {})
read_only = read_only_command(item["command"]) if item_type == "command_execution" and "command" in item else prior.get("readOnly", False)
self.unsafe_actions = self.unsafe_actions or not read_only
command = item.get("command", prior.get("command", ""))
output = item.get("aggregated_output", "")
if not isinstance(command, str) or not isinstance(output, str):
self.unknown_output = True
return
details = {"command": command[:600], "commandSha256": hashlib.sha256(command.encode()).hexdigest(), "readOnly": read_only} if "command" in item else {k: prior[k] for k in ("command", "commandSha256", "readOnly") if k in prior}
if kind == "item.started" and key:
self.active_items[key] = {"id": key, "phase": item_phase(item), "startedSeconds": elapsed, **details}
elif kind == "item.completed":
record = self.active_items.pop(key, {"id": key, "phase": item_phase(item), "startedSeconds": elapsed})
record.update(**details, finishedSeconds=elapsed, durationSeconds=max(0, elapsed - record["startedSeconds"]), status=item.get("status"), exitCode=item.get("exit_code"), outputBytes=len(output.encode()))
self.items.append(record)
if self.on_event and kind in {"item.started", "item.completed"}:
self.on_event(kind, elapsed, dict(self.active_items[key] if kind == "item.started" and key else self.items[-1]))
if kind == "turn.completed":
self.last_progress = elapsed
def read(self, path, elapsed):
with path.open("rb") as stream:
stream.seek(self.offset)
chunk = stream.read()
self.offset = stream.tell()
if not chunk:
return
self.last_output = elapsed
lines = (self.pending + chunk).split(b"\n")
self.pending = lines.pop()
for line in lines:
if not line.strip():
continue
try:
event = json.loads(line)
if not isinstance(event, dict):
raise ValueError("non-object event")
self.feed(event, elapsed)
except (ValueError, UnicodeDecodeError):
self.unknown_output = True
@property
def safe_to_retry(self):
return self.turn_started and not self.unsafe_actions and not self.active_items and not self.unknown_output and not self.pending.strip()
def snapshot(self, elapsed):
result = {
"firstEventSeconds": self.first_event,
"firstActionSeconds": self.first_action,
"providerWaitSeconds": self.first_action if self.first_action is not None else elapsed,
"idleSeconds": max(0, elapsed - self.last_progress),
"actionsSeen": self.actions_seen,
"safeToRetry": self.safe_to_retry,
"providerError": self.provider_error,
"errorCount": self.errors,
"eventCounts": dict(self.counts),
"activeItems": list(self.active_items.values()),
"items": self.items,
"readOnlyActions": self.actions_seen and not self.unsafe_actions,
"timingBasis": "JSONL observation; buffered or sub-poll tool durations may appear as zero, not exact execution time",
}
result["breakdown"] = worker_breakdown(result, elapsed)
return result
def legacy_commands(directory, log, items):
"""Recover labels only; never invent timestamps or rewrite old retry proofs."""
if not items or all("command" in item for item in items):
return items
try:
relative = Path(log).relative_to("tests/golden/WBV2/autopilot")
path = (directory / relative).resolve()
if not path.is_relative_to(directory.resolve()) or path.stat().st_size > 32 * 1024 * 1024:
return items
labels = {}
with path.open(encoding="utf-8") as stream:
for line in stream:
try:
event = json.loads(line)
except ValueError:
continue
if not isinstance(event, dict):
continue
item = event.get("item") or {}
if event.get("type") == "item.completed" and isinstance(item, dict) and isinstance(item.get("command"), str):
command = item["command"]
labels[item.get("id")] = {"command": command[:600], "commandSha256": hashlib.sha256(command.encode()).hexdigest(), "outputBytes": len(item.get("aggregated_output", "").encode())}
return [{**labels.get(item.get("id"), {}), **item} for item in items]
except (ValueError, OSError, TypeError):
return items
def _timing_report(directory, state=None, since=None):
rows, worker_details, seen, intervals, transitions, reused = [], [], set(), [], [], []
path = directory / "events.jsonl"
if path.exists():
with path.open(encoding="utf-8") as stream:
for line in stream:
try:
event = json.loads(line)
except ValueError:
continue
if not isinstance(event, dict):
continue
event_time = event.get("time") or event.get("finishedAt") or event.get("startedAt")
if since and (not event_time or event_time < since):
continue
if event.get("event") == "state.changed":
transitions.append(event)
if event.get("event") == "check.reused":
reused.append({"checkId": event.get("checkId"), "originalLog": event.get("originalLog"), "avoidedSeconds": event.get("avoidedSeconds", 0), "time": event.get("time")})
if event.get("event") not in {"process.finished", "timing.span"}:
continue
key = (event.get("log"), event.get("startedAt"), event.get("phase"))
if key in seen:
continue
seen.add(key)
phase = event.get("phase") or command_phase(event.get("argv", []))
seconds = max(0, event.get("durationSeconds", 0))
try:
intervals.append((datetime.fromisoformat(event["startedAt"]), datetime.fromisoformat(event.get("finishedAt") or event["time"])))
except (KeyError, ValueError):
pass
rows.append({"phase": phase, "startedAt": event.get("startedAt"), "finishedAt": event.get("finishedAt") or event.get("time"), "start": minute_label(event.get("startedAt")), "finish": minute_label(event.get("finishedAt") or event.get("time")), "seconds": seconds, "minutes": round(seconds / 60, 4), "exitCode": event.get("exitCode"), "log": event.get("log"), "providerAbort": event.get("providerAbort"), "interrupted": event.get("interrupted", False)})
rows[-1]["resourceUsage"] = event.get("resourceUsage")
if event.get("workerTrace"):
trace = dict(event["workerTrace"])
trace["items"] = legacy_commands(directory, event.get("log"), trace.get("items", []))
worker_details.append({"log": event.get("log"), "seconds": seconds, **trace, "breakdown": worker_breakdown(trace, seconds)})
totals = defaultdict(lambda: {"count": 0, "seconds": 0.0, "maxSeconds": 0.0})
for row in rows:
total = totals[row["phase"]]
total["count"] += 1
total["seconds"] += row["seconds"]
total["maxSeconds"] = max(total["maxSeconds"], row["seconds"])
measured = sum(row["seconds"] for row in rows)
wall = (max(end for _, end in intervals) - min(start for start, _ in intervals)).total_seconds() if intervals else 0
gaps = []
covered_end = None
for start, end in sorted(intervals):
if covered_end is not None and start > covered_end:
gaps.append({"startedAt": covered_end.isoformat(), "finishedAt": start.isoformat(), "seconds": round((start - covered_end).total_seconds(), 6), "attribution": "unrecorded; no inference of model or CPU work"})
covered_end = max(covered_end, end) if covered_end is not None else end
summary = [{"phase": phase, **{k: round(v, 6) if isinstance(v, float) else v for k, v in total.items()}, "minutes": round(total["seconds"] / 60, 4), "sharePercent": round(total["seconds"] / measured * 100, 2) if measured else 0} for phase, total in totals.items()]
summary.sort(key=lambda row: row["seconds"], reverse=True)
current = dict((state or {}).get("currentProcess") or {})
current["cacheTotals"] = {"hits": len(reused), "avoidedSeconds": round(sum(item["avoidedSeconds"] for item in reused), 6), "reuses": reused}
if current.get("status") == "running" and current.get("startedAt"):
current["elapsedMinutes"] = round(current.get("elapsedSeconds", 0) / 60, 4)
worker_totals = defaultdict(float)
commands = []
for worker in worker_details:
for row in worker["breakdown"]:
worker_totals[row["phase"]] += row["seconds"]
commands.extend({"log": worker["log"], **item} for item in worker.get("items", []))
worker_seconds = sum(worker["seconds"] for worker in worker_details)
worker_summary = [{"phase": phase, "seconds": round(seconds, 6), "sharePercent": round(100 * seconds / worker_seconds, 2) if worker_seconds else 0} for phase, seconds in sorted(worker_totals.items(), key=lambda pair: -pair[1])]
worker_activity = {"itemCount": len(commands), "failedCommands": sum(item.get("exitCode") not in {None, 0} for item in commands), "outputBytes": sum(item.get("outputBytes", 0) for item in commands), "zeroObservedDurationCount": sum(item["durationSeconds"] == 0 for item in commands)}
repeats = defaultdict(list)
for item in commands:
if item.get("commandSha256"):
repeats[item["commandSha256"]].append(item)
repeated = [{"command": items[0]["command"], "count": len(items), "seconds": round(sum(item["durationSeconds"] for item in items), 6)} for items in repeats.values() if len(items) > 1]
state_spans = []
for index, event in enumerate(transitions):
end = transitions[index + 1]["time"] if index + 1 < len(transitions) else (state or {}).get("updatedAt", event["time"])
if index + 1 == len(transitions) and event["state"] in {"paused", "needs_reconcile", "blocked", "provider_blocked", "budget_exhausted", "planning_required", "complete"}:
end = datetime.now(timezone.utc).isoformat()
seconds = max(0, (datetime.fromisoformat(end) - datetime.fromisoformat(event["time"])).total_seconds())
state_spans.append({"state": event["state"], "job": event.get("job"), "startedAt": event["time"], "finishedAt": end, "seconds": round(seconds, 6), "reason": event.get("reason")})
return {"schemaVersion": 2, "observedAt": datetime.now(LOCAL_ZONE).strftime("%Y-%m-%d %H:%M"), "timezone": "Asia/Shanghai", "labelPrecision": "minute", "totalMeasuredMinutes": round(measured / 60, 4), "wallClockMinutes": round(wall / 60, 4), "outsideMeasuredStepsMinutes": round(sum(gap["seconds"] for gap in gaps) / 60, 4), "unmeasuredGaps": gaps, "summary": summary, "steps": rows, "workers": worker_details, "workerSummary": worker_summary, "workerMeasuredSeconds": round(worker_seconds, 6), "workerActivity": worker_activity, "commands": commands, "repeatedCommands": sorted(repeated, key=lambda row: -row["count"]), "stateSpans": state_spans, "current": display_times(current), "accounting": "Top-level completed spans only; current work, state spans and nested worker timings are reported separately and must not be added again. Worker timing measures JSONL observations, not model CPU or exact tool execution; zero durations can mean buffered/sub-poll events. Untraced legacy model requests cannot be subdivided. Outside measured steps includes unrecorded scheduling, pauses and reconciliation; new state transitions attribute these going forward."}
def timing_report(directory, state=None, scope="all"):
if scope not in {"all", "local", "last-run"}:
raise ValueError("invalid timing scope")
since = None
events_path = directory / "events.jsonl"
if scope != "all":
since = "9999-12-31T23:59:59+00:00"
if events_path.is_file():
with events_path.open(encoding="utf-8") as stream:
for line in stream:
try:
event = json.loads(line)
except ValueError:
continue
if not isinstance(event, dict) or not event.get("time"):
continue
if scope == "local" and event.get("event") == "workflow.local":
since = min(since, event["time"])
if scope == "last-run" and event.get("event") == "state.changed" and event.get("state") == "implementing":
since = event["time"]
report = _timing_report(directory, state, since=since)
waiting = sum(row["seconds"] for row in report["summary"] if row["phase"] in {"local_work_wait", "provider_backoff", "retry_backoff"})
total = sum(row["seconds"] for row in report["summary"])
report.update(scope=scope, scopeStart=since, activeMeasuredSeconds=round(total - waiting, 6), waitingMeasuredSeconds=round(waiting, 6))
return report
def format_report(report):
lines = [f"Observed: {report['observedAt']} (Asia/Shanghai)", "Phase | Count | Minutes | Share", "--- | ---: | ---: | ---:"]
lines += [f"{r['phase']} | {r['count']} | {r['minutes']:.4f} | {r['sharePercent']:.2f}%" for r in report["summary"]]
lines += [f"Measured: {report['totalMeasuredMinutes']:.4f} minutes; outside measured steps: {report['outsideMeasuredStepsMinutes']:.4f} minutes."]
lines += [f"Scope: {report.get('scope', 'all')}; active: {report.get('activeMeasuredSeconds', 0):.3f} seconds; waiting: {report.get('waitingMeasuredSeconds', 0):.3f} seconds."]
lines += ["", "Unmeasured Gap Start | Finish | Minutes", "--- | --- | ---:"]
lines += [f"{minute_label(r['startedAt'])} | {minute_label(r['finishedAt'])} | {r['seconds'] / 60:.4f}" for r in report["unmeasuredGaps"] if r["seconds"] >= 1]
lines += ["", "Nested Worker Phase | Seconds | Share", "--- | ---: | ---:"]
lines += [f"{r['phase']} | {r['seconds']:.3f} | {r['sharePercent']:.2f}%" for r in report["workerSummary"]]
activity = report["workerActivity"]
lines += [f"Observed items: {activity['itemCount']}; failed commands: {activity['failedCommands']}; captured output: {activity['outputBytes']} bytes; zero sampled durations: {activity['zeroObservedDurationCount']}."]
lines += ["", "Start | Finish | Phase | Minutes | Exit", "--- | --- | --- | ---: | ---:"]
lines += [f"{r['start']} | {r['finish']} | {r['phase']} | {r['minutes']:.4f} | {r['exitCode']}" for r in report["steps"]]
lines += ["", "Stage | Child CPU (s) | CPU % | Peak RSS (MiB) | Peak Threads | Peak Processes", "--- | ---: | ---: | ---: | ---: | ---:"]
for row in report["steps"]:
usage = row.get("resourceUsage")
if usage:
lines.append(f"{row['phase']} | {usage['reapedChildCpuSeconds']:.3f} | {usage['cpuPercent']:.2f} | {usage['peakSampledRssBytes'] / 1048576:.2f} | {usage['peakSampledThreads']} | {usage['peakSampledProcesses']}")
lines += ["", "State | Start | Finish | Seconds | Reason", "--- | --- | --- | ---: | ---"]
lines += [f"{r['state']} | {minute_label(r['startedAt'])} | {minute_label(r['finishedAt'])} | {r['seconds']:.3f} | {r['reason']}" for r in report["stateSpans"]]
lines += ["", "Worker | Item | Phase | Start Offset (s) | Duration (s) | Exit | Command", "--- | --- | --- | ---: | ---: | ---: | ---"]
lines += [f"{r['log']} | {r['id']} | {r['phase']} | {r['startedSeconds']:.3f} | {r['durationSeconds']:.3f} | {r.get('exitCode')} | {r.get('command', '(legacy command unavailable)').replace('|', '&#124;').replace(chr(10), ' ')}" for r in report["commands"]]
lines += ["", report["accounting"]]
if report["current"]:
lines += ["", "Current: " + json.dumps(report["current"], ensure_ascii=False)]
return "\n".join(lines)