420 lines
27 KiB
Python
420 lines
27 KiB
Python
#!/usr/bin/env python3
|
|
"""Report per-step scheduler timing from streaming cycle logs.
|
|
|
|
This is intentionally generic: it reads only JSONL cycle logs and never
|
|
opens source trees, task cards, inventories, or full validation artifacts.
|
|
"""
|
|
from __future__ import annotations
|
|
|
|
import argparse
|
|
import json
|
|
import re
|
|
import shlex
|
|
from collections import defaultdict
|
|
from datetime import datetime
|
|
from pathlib import Path
|
|
|
|
|
|
ROOT = Path(__file__).resolve().parents[1]
|
|
DEFAULT_LOG_DIR = ROOT / "docs/current/continuation-runs"
|
|
TIMING_SUMMARY = ROOT / "docs/current/freecad-web-scheduler-timing.json"
|
|
|
|
|
|
def phase_for(command: str) -> str:
|
|
value = command.lower()
|
|
try:
|
|
parts = shlex.split(command)
|
|
script = parts[-1].lower() if len(parts) >= 3 and Path(parts[0]).name in {"bash", "sh"} and "-lc" in parts else value
|
|
except ValueError:
|
|
script = value
|
|
has_gate = bool(re.search(r"\b(?:node|python3?)\s+[^;&|\s]*run_p6_[^;&|\s]*(?:gate|smoke)", script))
|
|
has_build = bool(re.search(r"\bcmake\s+--build\b|\bbuild_web_module_artifacts(?:\.py)?\b|(?:^|[;&|]\s*)ninja\b|(?:^|[;&|]\s*)make\b", script))
|
|
has_context = bool(re.search(r"\bpython3?\s+[^;&|\s]*(?:prepare_web_task_context|validate_incremental_context)\.py\b", script))
|
|
has_preflight = bool(re.search(r"\bpython3?\s+[^;&|\s]*check_web_link_closure\.py\b", script))
|
|
has_read = bool(re.search(r"(?:^|[;&|]\s*)(?:rg|sed|cat|nl|ls|stat|sha256sum|git\s+(?:status|diff))\b", script))
|
|
if has_build and has_gate:
|
|
return "build+focused-gate"
|
|
if has_build and has_preflight:
|
|
return "build+preflight"
|
|
if has_gate and has_context:
|
|
return "focused-gate+context"
|
|
if has_read and not any((has_gate, has_build, has_context, has_preflight)):
|
|
return "source/read"
|
|
if "continue_web_task_cycle" in value or "check_continuation_state" in value:
|
|
return "prepare/checkpoint"
|
|
if "prepare_web_task_context" in value or "validate_incremental_context" in value:
|
|
return "context"
|
|
if "prepare_full_parity_module_batch" in value:
|
|
return "batch-planning"
|
|
if has_preflight:
|
|
return "build/preflight"
|
|
if has_build:
|
|
return "build"
|
|
if "sync-assets" in value or "generate_web_release_manifest" in value or "module-preload" in value:
|
|
return "artifact-manifest"
|
|
if has_read or "fast_source_search" in script:
|
|
return "source/read"
|
|
if "prepare_" in value and ("resource" in value or "staging" in value):
|
|
return "resource-staging"
|
|
if has_gate:
|
|
return "focused-gate"
|
|
if any(token in value for token in ("sync_web_task_state", "rotate_web_task_context", "repair_continuation_checkpoint", "compact_continuation_docs")):
|
|
return "checkpoint/rotation"
|
|
return "other"
|
|
|
|
|
|
def log_lines(path: Path):
|
|
try:
|
|
with path.open(encoding="utf-8", errors="replace") as stream:
|
|
yield from stream
|
|
except OSError:
|
|
return
|
|
|
|
|
|
def collect(log_dir: Path, limit: int, *, from_logs: bool = False) -> dict:
|
|
if not from_logs and log_dir.resolve() == DEFAULT_LOG_DIR.resolve() and TIMING_SUMMARY.exists():
|
|
try:
|
|
cached = json.loads(TIMING_SUMMARY.read_text(encoding="utf-8"))
|
|
except (OSError, json.JSONDecodeError):
|
|
cached = {}
|
|
if cached.get("schema") in {"freecad-web-scheduler-timing/v1", "freecad-web-scheduler-timing/v2"} and isinstance(cached.get("cycles"), list):
|
|
return collect_cached(cached, limit)
|
|
paths = sorted(log_dir.glob("cycle-*.log"), key=lambda p: int(re.search(r"(\d+)$", p.stem).group(1)))[-limit:]
|
|
phases: dict[str, dict[str, float | int]] = defaultdict(lambda: {"count": 0, "seconds": 0.0, "maxSeconds": 0.0})
|
|
cycles = []
|
|
unmeasured_commands = 0
|
|
stream_failed_cycles = 0
|
|
budget_exceeded_cycles = 0
|
|
agent_idle_stopped_cycles = 0
|
|
slowest_commands: list[dict[str, object]] = []
|
|
for path in paths:
|
|
match = re.search(r"cycle-(\d+)\.log$", path.name)
|
|
if not match:
|
|
continue
|
|
cycle = int(match.group(1))
|
|
started = completed = None
|
|
cycle_phase: dict[str, float] = defaultdict(float)
|
|
measured_command_seconds = 0.0
|
|
cycle_commands = 0
|
|
cycle_timed_commands = 0
|
|
for line in log_lines(path):
|
|
try:
|
|
event = json.loads(line)
|
|
except json.JSONDecodeError:
|
|
continue
|
|
if event.get("type") == "scheduler.cycle.started":
|
|
started = event.get("startedAt")
|
|
elif event.get("type") == "scheduler.cycle.completed":
|
|
completed = event.get("completedAt")
|
|
stream_failed_cycles += int(bool(event.get("streamFailed")))
|
|
budget_exceeded_cycles += int(bool(event.get("commandBudgetExceeded")))
|
|
agent_idle_stopped_cycles += int(bool(event.get("agentIdleStopped")))
|
|
item = event.get("item") if isinstance(event.get("item"), dict) else {}
|
|
if event.get("type") != "item.completed" or item.get("type") != "command_execution":
|
|
continue
|
|
cycle_commands += 1
|
|
duration = item.get("schedulerDurationSeconds")
|
|
if not isinstance(duration, (int, float)):
|
|
unmeasured_commands += 1
|
|
continue
|
|
cycle_timed_commands += 1
|
|
measured_command_seconds += float(duration)
|
|
phase = str(item.get("schedulerPhase") or phase_for(str(item.get("command") or "")))
|
|
row = phases[phase]
|
|
row["count"] = int(row["count"]) + 1
|
|
row["seconds"] = float(row["seconds"]) + float(duration)
|
|
row["maxSeconds"] = max(float(row["maxSeconds"]), float(duration))
|
|
cycle_phase[phase] += float(duration)
|
|
slowest_commands.append({"cycle": cycle, "phase": phase, "seconds": float(duration), "command": str(item.get("command") or "")[:500]})
|
|
duration = None
|
|
if started and completed:
|
|
try:
|
|
duration = (datetime.fromisoformat(completed.replace("Z", "+00:00")) - datetime.fromisoformat(started.replace("Z", "+00:00"))).total_seconds()
|
|
except ValueError:
|
|
pass
|
|
unaccounted = None
|
|
if duration is not None and measured_command_seconds:
|
|
unaccounted = max(0.0, float(duration) - measured_command_seconds)
|
|
cycles.append({
|
|
"cycle": cycle,
|
|
"durationSeconds": duration,
|
|
"commandSeconds": measured_command_seconds if cycle_timed_commands else None,
|
|
"unaccountedSeconds": unaccounted,
|
|
"commands": cycle_commands,
|
|
"timedCommands": cycle_timed_commands,
|
|
"phaseSeconds": dict(cycle_phase),
|
|
})
|
|
total = sum(float(row["seconds"]) for row in phases.values())
|
|
for row in phases.values():
|
|
row["averageSeconds"] = float(row["seconds"]) / int(row["count"]) if row["count"] else 0.0
|
|
row["share"] = 100.0 * float(row["seconds"]) / total if total else 0.0
|
|
measured_cycles = [item for item in cycles if item["unaccountedSeconds"] is not None]
|
|
unaccounted_total = sum(float(item["unaccountedSeconds"]) for item in measured_cycles)
|
|
return {
|
|
"cycles": cycles,
|
|
"phases": dict(sorted(phases.items(), key=lambda pair: float(pair[1]["seconds"]), reverse=True)),
|
|
"timedCommandSeconds": total,
|
|
"unmeasuredCommands": unmeasured_commands,
|
|
"unaccountedSeconds": unaccounted_total,
|
|
"measuredCycles": len(measured_cycles),
|
|
"streamFailedCycles": stream_failed_cycles,
|
|
"budgetExceededCycles": budget_exceeded_cycles,
|
|
"agentIdleStoppedCycles": agent_idle_stopped_cycles,
|
|
"slowestCommands": sorted(slowest_commands, key=lambda item: float(item["seconds"]), reverse=True)[:10],
|
|
}
|
|
|
|
|
|
def collect_cached(summary: dict, limit: int) -> dict:
|
|
records = [item for item in summary.get("cycles", []) if isinstance(item, dict)][-max(1, limit):]
|
|
phases: dict[str, dict[str, float | int]] = defaultdict(lambda: {"count": 0, "seconds": 0.0, "maxSeconds": 0.0})
|
|
cycles = []
|
|
slowest_commands: list[dict[str, object]] = []
|
|
slowest_agent_gaps: list[dict[str, object]] = []
|
|
redundancy: dict[str, float] = defaultdict(float)
|
|
activity: dict[str, int] = defaultdict(int)
|
|
usage: dict[str, int] = defaultdict(int)
|
|
usage_cycles = 0
|
|
effective_cycle_seconds = 0.0
|
|
active_cycles = 0
|
|
productive_cycles = 0
|
|
seen_batches: set[str] = set()
|
|
recovery_cycles = 0
|
|
recovery_seconds = 0.0
|
|
unaccounted = 0.0
|
|
accounted_total = 0.0
|
|
measured_cycles = 0
|
|
unmeasured_commands = 0
|
|
stream_failed_cycles = 0
|
|
budget_exceeded_cycles = 0
|
|
agent_idle_stopped_cycles = 0
|
|
for record in records:
|
|
cycle = int(record.get("cycle", 0) or 0)
|
|
batch = record.get("batch", {}) if isinstance(record.get("batch"), dict) else {}
|
|
batch_id = str(batch.get("id") or "")
|
|
if batch_id:
|
|
if batch_id in seen_batches:
|
|
recovery_cycles += 1
|
|
recovery_seconds += float(record.get("turnSeconds", 0.0) or 0.0)
|
|
else:
|
|
seen_batches.add(batch_id)
|
|
phase_seconds = dict(record.get("phaseTiming", {}) if isinstance(record.get("phaseTiming"), dict) else {})
|
|
for phase, seconds in (record.get("preparationTiming", {}) if isinstance(record.get("preparationTiming"), dict) else {}).items():
|
|
phase_seconds[f"preparation/{phase}"] = float(phase_seconds.get(f"preparation/{phase}", 0.0)) + float(seconds)
|
|
for phase, seconds in (record.get("postPipelineTiming", {}) if isinstance(record.get("postPipelineTiming"), dict) else {}).items():
|
|
phase_seconds[str(phase)] = float(phase_seconds.get(str(phase), 0.0)) + float(seconds)
|
|
phase_seconds = {phase: seconds for phase, seconds in phase_seconds.items() if str(phase) != "event/stream"}
|
|
waiting = record.get("waitingTiming", {})
|
|
waiting_seconds = sum(float(value) for value in waiting.values())
|
|
phase_seconds.update(waiting)
|
|
fallback_accounted = sum(float(seconds) for seconds in phase_seconds.values())
|
|
step_stats = record.get("stepStats", {}) if isinstance(record.get("stepStats"), dict) else {}
|
|
for phase, seconds in phase_seconds.items():
|
|
row = phases[str(phase)]
|
|
details = step_stats.get(str(phase), {}) if isinstance(step_stats.get(str(phase)), dict) else {}
|
|
row["count"] = int(row["count"]) + int(details.get("count", 1) or 1)
|
|
row["seconds"] = float(row["seconds"]) + float(seconds)
|
|
row["maxSeconds"] = max(float(row["maxSeconds"]), float(details.get("maxSeconds", seconds) or seconds))
|
|
turn_seconds = float(record.get("turnSeconds", 0.0) or 0.0)
|
|
is_idle = "scheduler/no-ready" in phase_seconds
|
|
if not is_idle:
|
|
active_cycles += 1
|
|
effective_cycle_seconds += float(record.get("effectiveCycleSeconds", turn_seconds + float(record.get("preparationSeconds", 0.0) or 0.0) + float(record.get("postPipelineSeconds", 0.0) or 0.0)) or 0.0)
|
|
effective_cycle_seconds += waiting_seconds
|
|
productive_cycles += int(bool(record.get("activity", {}).get("fileChanges") or record.get("postPipelineStatus") in {"pass", "implementation_ready", "implementation_partial"}))
|
|
command_seconds = float(record.get("commandSeconds", 0.0) or 0.0)
|
|
has_legacy_event_stream = isinstance(record.get("phaseTiming"), dict) and "event/stream" in record.get("phaseTiming", {})
|
|
accounted_seconds = fallback_accounted if has_legacy_event_stream else float(record.get("accountedSeconds", fallback_accounted) or fallback_accounted)
|
|
accounted_total += sum(float(value) for value in phase_seconds.values())
|
|
timed = int(record.get("timedCommands", 0) or 0)
|
|
commands = int(record.get("commands", 0) or 0)
|
|
if timed:
|
|
measured_cycles += 1
|
|
unaccounted += max(0.0, turn_seconds - accounted_seconds)
|
|
unmeasured_commands += max(0, commands - timed)
|
|
stream_failed_cycles += int(bool(record.get("streamFailed")))
|
|
budget_exceeded_cycles += int(bool(record.get("commandBudgetExceeded")))
|
|
agent_idle_stopped_cycles += int(bool(record.get("agentIdleStopped")))
|
|
for item in record.get("slowestCommands", []) if isinstance(record.get("slowestCommands"), list) else []:
|
|
if isinstance(item, dict): slowest_commands.append({**item, "cycle": item.get("cycle", cycle)})
|
|
for item in record.get("slowestAgentGaps", []) if isinstance(record.get("slowestAgentGaps"), list) else []:
|
|
if isinstance(item, dict): slowest_agent_gaps.append({**item, "cycle": item.get("cycle", cycle)})
|
|
for name, value in (record.get("redundancy", {}) if isinstance(record.get("redundancy"), dict) else {}).items():
|
|
if isinstance(value, (int, float)): redundancy[str(name)] += float(value)
|
|
for name, value in (record.get("activity", {}) if isinstance(record.get("activity"), dict) else {}).items():
|
|
if isinstance(value, int): activity[str(name)] += value
|
|
for name, value in (record.get("usage", {}) if isinstance(record.get("usage"), dict) else {}).items():
|
|
if isinstance(value, int): usage[str(name)] += value
|
|
if isinstance(record.get("usage"), dict) and record.get("usage"):
|
|
usage_cycles += 1
|
|
cycles.append({"cycle": cycle, "activeTask": record.get("activeTask"), "batch": record.get("batch", {}),
|
|
"durationSeconds": turn_seconds, "commandSeconds": command_seconds if timed else None,
|
|
"accountedSeconds": accounted_seconds if timed else None, "unaccountedSeconds": max(0.0, turn_seconds - accounted_seconds) if timed else None,
|
|
"commands": commands, "timedCommands": timed, "phaseSeconds": phase_seconds,
|
|
"fileChanges": record.get("activity", {}).get("fileChanges", 0),
|
|
"waitingTiming": waiting,
|
|
"preparationTiming": record.get("preparationTiming", {}), "postPipelineTiming": record.get("postPipelineTiming", {})})
|
|
total = sum(float(row["seconds"]) for row in phases.values())
|
|
for row in phases.values():
|
|
row["averageSeconds"] = float(row["seconds"]) / int(row["count"]) if row["count"] else 0.0
|
|
row["share"] = 100.0 * float(row["seconds"]) / total if total else 0.0
|
|
return {"cycles": cycles, "phases": dict(sorted(phases.items(), key=lambda pair: float(pair[1]["seconds"]), reverse=True)), "timedCommandSeconds": sum(float(record.get("commandSeconds", 0.0) or 0.0) for record in records), "accountedSeconds": accounted_total, "unmeasuredCommands": unmeasured_commands, "unaccountedSeconds": unaccounted, "measuredCycles": measured_cycles, "streamFailedCycles": stream_failed_cycles, "budgetExceededCycles": budget_exceeded_cycles, "agentIdleStoppedCycles": agent_idle_stopped_cycles, "slowestCommands": sorted(slowest_commands, key=lambda item: float(item.get("seconds", 0.0)), reverse=True)[:10], "slowestAgentGaps": sorted(slowest_agent_gaps, key=lambda item: float(item.get("seconds", 0.0)), reverse=True)[:10], "redundancy": dict(redundancy), "activity": dict(activity), "usage": dict(usage), "usageCycles": usage_cycles, "activeCycles": active_cycles, "idleCycles": len(records) - active_cycles, "productiveCycles": productive_cycles, "averageEffectiveCycleSeconds": effective_cycle_seconds / active_cycles if active_cycles else None, "batchFlow": {"uniqueBatches": len(seen_batches), "recoveryCycles": recovery_cycles, "recoverySeconds": recovery_seconds}}
|
|
|
|
|
|
def detailed_steps(path: Path) -> dict:
|
|
"""Separate observed gaps from command execution without inferring model internals."""
|
|
commands, gaps = [], []
|
|
active = {}
|
|
previous_time = start_time = None
|
|
previous_event = "start"
|
|
tool_union_seconds = 0.0
|
|
for line in log_lines(path):
|
|
try:
|
|
event = json.loads(line)
|
|
except ValueError:
|
|
continue
|
|
stamp = event.get("schedulerObservedAt") or event.get("completedAt") or event.get("startedAt")
|
|
if not isinstance(stamp, str):
|
|
continue
|
|
try:
|
|
current_time = datetime.fromisoformat(stamp.replace("Z", "+00:00")).timestamp()
|
|
except ValueError:
|
|
continue
|
|
if start_time is None:
|
|
start_time = current_time
|
|
item = event.get("item") if isinstance(event.get("item"), dict) else {}
|
|
wait_before = 0.0
|
|
if previous_time is not None:
|
|
current_time = max(previous_time, current_time)
|
|
delta = current_time - previous_time
|
|
if active:
|
|
tool_union_seconds += delta
|
|
elif delta > 0:
|
|
wait_before = delta
|
|
gaps.append({"offsetSeconds": round(previous_time - start_time, 6), "seconds": round(delta, 6),
|
|
"after": previous_event, "before": item.get("type") or event.get("type"),
|
|
"nextCommand": item.get("command") if event.get("type") == "item.started" else None})
|
|
if item.get("type") == "command_execution":
|
|
identity = item.get("id") or item.get("command")
|
|
if event.get("type") == "item.started":
|
|
active[identity] = {"started": current_time, "waitBeforeSeconds": wait_before, "command": item.get("command", "")}
|
|
elif event.get("type") == "item.completed":
|
|
started = active.pop(identity, None)
|
|
elapsed = item.get("schedulerDurationSeconds")
|
|
if elapsed is None and started:
|
|
elapsed = current_time - started["started"]
|
|
commands.append({"order": len(commands) + 1, "phase": item.get("schedulerPhase") or phase_for(item.get("command", "")),
|
|
"command": item.get("command", ""), "exitCode": item.get("schedulerEffectiveExitCode", item.get("exit_code")),
|
|
"runSeconds": elapsed, "waitBeforeSeconds": round(started["waitBeforeSeconds"], 6) if started else None,
|
|
"startedAtOffsetSeconds": round(started["started"] - start_time, 6) if started else None})
|
|
previous_time = current_time
|
|
previous_event = ("command:" + str(item.get("schedulerPhase") or phase_for(item.get("command", "")))) if item.get("type") == "command_execution" else str(event.get("type"))
|
|
observed = max(0.0, previous_time - start_time) if start_time is not None and previous_time is not None else 0.0
|
|
return {"commands": commands, "waitIntervals": gaps, "observedSeconds": round(observed, 6),
|
|
"startedAtEpoch": start_time, "endedAtEpoch": previous_time,
|
|
"toolUnionSeconds": round(tool_union_seconds, 6), "betweenEventSeconds": round(sum(row["seconds"] for row in gaps), 6),
|
|
"unfinishedCommands": len(active)}
|
|
|
|
|
|
def write_detailed_report(result: dict, log_dir: Path, prefix: Path) -> dict:
|
|
detail = {str(row["cycle"]): detailed_steps(log_dir / f"cycle-{int(row['cycle']):06d}.log") for row in result["cycles"]}
|
|
timeline = wall_timeline(detail)
|
|
output = {**result, "stepDetails": detail, "wallTimeline": timeline, "interpretation": "Between-event time is observed time with no active command; it may include model, service, transport or client waiting. Between-cycle gaps include backoff, preparation, pipeline work and restarts; do not add them again to the phase totals. Historical backoff was not instrumented."}
|
|
json_path, markdown_path = prefix.with_suffix(".json"), prefix.with_suffix(".md")
|
|
json_path.parent.mkdir(parents=True, exist_ok=True)
|
|
json_path.write_text(json.dumps(output, ensure_ascii=False, indent=2) + "\n", encoding="utf-8")
|
|
lines = ["# Unattended Execution Timing", "", output["interpretation"], "",
|
|
f"Cycles: {len(result['cycles'])}; aggregate measured time: {result.get('accountedSeconds', 0):.3f} s.", "",
|
|
"| Phase | Total (s) | Share | Count | Average (s) | Maximum (s) |",
|
|
"|---|---:|---:|---:|---:|---:|"]
|
|
for phase, row in result["phases"].items():
|
|
lines.append(f"| {phase} | {row['seconds']:.3f} | {row['share']:.2f}% | {row['count']} | {row['averageSeconds']:.3f} | {row['maxSeconds']:.3f} |")
|
|
lines.extend(["", "## Wall-Clock Coverage", "", f"First cycle start to last observed event: {timeline['wallSeconds']:.3f} s.",
|
|
f"Inside observed cycles: {timeline['observedCycleSeconds']:.3f} s; between cycles: {timeline['betweenCycleSeconds']:.3f} s.", "",
|
|
"| Previous Cycle | Next Cycle | Gap (s) |", "|---:|---:|---:|"])
|
|
lines.extend(f"| {row['previousCycle']} | {row['nextCycle']} | {row['seconds']:.3f} |" for row in timeline["gaps"])
|
|
def cell(value):
|
|
return str(value).replace("|", "\\|").replace("\n", " ")
|
|
for cycle in result["cycles"]:
|
|
steps = detail[str(cycle["cycle"])]
|
|
lines.extend(["", f"## Cycle {cycle['cycle']}", "", f"Task: {cycle.get('activeTask')}; batch: {cell(cycle.get('batch', {}))}.",
|
|
f"Observed command time (union): {steps['toolUnionSeconds']:.3f} s; between-event time: {steps['betweenEventSeconds']:.3f} s; file changes: {cycle.get('fileChanges', 0)}.", ""])
|
|
for stage in ("preparationTiming", "postPipelineTiming", "waitingTiming"):
|
|
if cycle.get(stage):
|
|
lines.extend([f"### {stage}", "", "| Step | Seconds |", "|---|---:|"])
|
|
lines.extend(f"| {cell(name)} | {float(seconds):.3f} |" for name, seconds in cycle[stage].items())
|
|
lines.append("")
|
|
lines.extend(["### Commands", "", "| # | Phase | Wait Before (s) | Execute (s) | Exit | Command |", "|---:|---|---:|---:|---:|---|"])
|
|
for row in steps["commands"]:
|
|
wait = f"{row['waitBeforeSeconds']:.3f}" if row["waitBeforeSeconds"] is not None else "unknown"
|
|
runtime = f"{row['runSeconds']:.3f}" if row["runSeconds"] is not None else "unknown"
|
|
lines.append(f"| {row['order']} | {row['phase']} | {wait} | {runtime} | {row['exitCode']} | {cell(row['command'])} |")
|
|
lines.extend(["", "### Between-Event Intervals", "", "| Offset (s) | Seconds | After | Before |", "|---:|---:|---|---|"])
|
|
for row in steps["waitIntervals"]:
|
|
if row["seconds"] >= 0.05:
|
|
lines.append(f"| {row['offsetSeconds']:.3f} | {row['seconds']:.3f} | {cell(row['after'])} | {cell(row['before'])} |")
|
|
markdown_path.write_text("\n".join(lines) + "\n", encoding="utf-8")
|
|
return {"json": str(json_path), "markdown": str(markdown_path)}
|
|
|
|
|
|
def wall_timeline(details: dict) -> dict:
|
|
rows = sorted(((cycle, row) for cycle, row in details.items()
|
|
if row.get("startedAtEpoch") is not None and row.get("endedAtEpoch") is not None),
|
|
key=lambda item: item[1]["startedAtEpoch"])
|
|
gaps = []
|
|
end = None
|
|
previous = None
|
|
for cycle, row in rows:
|
|
if end is not None and row["startedAtEpoch"] > end:
|
|
gaps.append({"previousCycle": previous, "nextCycle": cycle, "seconds": row["startedAtEpoch"] - end})
|
|
if end is None or row["endedAtEpoch"] >= end:
|
|
end, previous = row["endedAtEpoch"], cycle
|
|
wall = end - rows[0][1]["startedAtEpoch"] if rows else 0.0
|
|
between = sum(row["seconds"] for row in gaps)
|
|
return {"wallSeconds": wall, "betweenCycleSeconds": between, "observedCycleSeconds": wall - between, "gaps": gaps}
|
|
|
|
|
|
def main() -> int:
|
|
parser = argparse.ArgumentParser(description=__doc__)
|
|
parser.add_argument("--cycles", type=int, default=20)
|
|
parser.add_argument("--log-dir", type=Path, default=DEFAULT_LOG_DIR)
|
|
parser.add_argument("--json", action="store_true")
|
|
parser.add_argument("--from-logs", action="store_true", help="read bounded original cycle logs instead of the rolling cache")
|
|
parser.add_argument("--report-prefix", type=Path, help="write a detailed JSON and Markdown report with this path prefix")
|
|
args = parser.parse_args()
|
|
result = collect(args.log_dir if args.log_dir.is_absolute() else ROOT / args.log_dir, max(1, args.cycles), from_logs=args.from_logs)
|
|
if args.report_prefix:
|
|
result["reportPaths"] = write_detailed_report(result, args.log_dir if args.log_dir.is_absolute() else ROOT / args.log_dir,
|
|
args.report_prefix if args.report_prefix.is_absolute() else ROOT / args.report_prefix)
|
|
if args.json:
|
|
print(json.dumps(result, ensure_ascii=False, indent=2))
|
|
return 0
|
|
print(f"Scheduler timing report: cycles={len(result['cycles'])} measuredCycles={result['measuredCycles']} timedCommandSeconds={result['timedCommandSeconds']:.1f} accountedSeconds={result.get('accountedSeconds', result['timedCommandSeconds']):.1f} unaccountedSeconds={result['unaccountedSeconds']:.1f} unmeasuredCommands={result['unmeasuredCommands']} streamFailedCycles={result.get('streamFailedCycles', 0)} budgetExceededCycles={result.get('budgetExceededCycles', 0)} agentIdleStoppedCycles={result.get('agentIdleStoppedCycles', 0)}")
|
|
if result.get("averageEffectiveCycleSeconds") is not None:
|
|
print(f"activeCycles={result.get('activeCycles', 0)} idleCycles={result.get('idleCycles', 0)} cyclesWithEditsOrPipelinePass={result.get('productiveCycles', 0)} averageActiveCycleSeconds={float(result['averageEffectiveCycleSeconds']):.1f}")
|
|
for phase, row in result["phases"].items():
|
|
print(f"{phase}: total={float(row['seconds']):.1f}s share={float(row['share']):.1f}% count={int(row['count'])} avg={float(row['averageSeconds']):.2f}s max={float(row['maxSeconds']):.2f}s")
|
|
batch_flow = result.get("batchFlow", {})
|
|
if batch_flow:
|
|
print(f"batchFlow unique={int(batch_flow.get('uniqueBatches', 0))} recoveryCycles={int(batch_flow.get('recoveryCycles', 0))} recoverySeconds={float(batch_flow.get('recoverySeconds', 0.0)):.1f}")
|
|
if result.get("activity"):
|
|
print("activity " + " ".join(f"{key}={value}" for key, value in sorted(result["activity"].items())))
|
|
if result.get("redundancy"):
|
|
print("redundancy " + " ".join(f"{key}={value:.3f}" for key, value in sorted(result["redundancy"].items())))
|
|
if result.get("usage"):
|
|
print(f"tokenUsage cycles={int(result.get('usageCycles', 0))} " + " ".join(f"{key}={value}" for key, value in sorted(result["usage"].items())))
|
|
for item in result.get("slowestAgentGaps", [])[:5]:
|
|
print(f"slowestAgentGap cycle={item.get('cycle')} phase={item.get('phase')} seconds={float(item.get('seconds', 0.0)):.2f} after={item.get('after', '-')} before={item.get('before', '-')}")
|
|
for item in result["slowestCommands"][:5]:
|
|
print(f"slowestCommand cycle={item['cycle']} phase={item['phase']} seconds={float(item['seconds']):.2f} command={item['command']}")
|
|
measured = [item for item in result["cycles"] if item["durationSeconds"] is not None]
|
|
if measured:
|
|
slowest = max(measured, key=lambda item: float(item["durationSeconds"]))
|
|
print(f"slowestCycle={slowest['cycle']} duration={float(slowest['durationSeconds']):.1f}s")
|
|
if result.get("reportPaths"):
|
|
print("reports=" + json.dumps(result["reportPaths"], ensure_ascii=False))
|
|
return 0
|
|
|
|
|
|
if __name__ == "__main__":
|
|
raise SystemExit(main())
|