From 9693d4198b85d708bec1e569dad102e81e292894 Mon Sep 17 00:00:00 2001 From: kushin25 <42917222+kushin25@users.noreply.github.com> Date: Wed, 22 Jul 2026 03:06:31 +0200 Subject: [PATCH] feat(report): show per-stage durations --- docs/usage.md | 4 +++ src/readme2demo/cli.py | 8 +++-- src/readme2demo/manifest.py | 19 ++++++++++++ src/readme2demo/orchestrator.py | 22 ++++++++++--- tests/test_cli.py | 14 ++++++--- tests/test_orchestrator.py | 55 +++++++++++++++++++++++++++------ 6 files changed, 101 insertions(+), 21 deletions(-) diff --git a/docs/usage.md b/docs/usage.md index 7a6c956..fb26f66 100644 --- a/docs/usage.md +++ b/docs/usage.md @@ -61,6 +61,10 @@ directly instead of parsing output: readme2demo report runs/tool-20260702-... --json && echo "verified" || echo "gate failed" ``` +The human and `--markdown` reports show the final attempt's duration for each +stage. `--json` includes the same value as numeric `duration_seconds` per +stage; it is `null` when either timestamp is unavailable or invalid. + ## Outputs Artifacts land in `runs//`: `tutorial.md`, `step_by_step.md`, diff --git a/src/readme2demo/cli.py b/src/readme2demo/cli.py index 4800c46..9bace3b 100644 --- a/src/readme2demo/cli.py +++ b/src/readme2demo/cli.py @@ -25,7 +25,7 @@ from rich.markup import escape from readme2demo.config import Config -from readme2demo.manifest import STAGES, Manifest +from readme2demo.manifest import STAGES, Manifest, stage_duration from readme2demo.orchestrator import ( Orchestrator, PipelineError, @@ -537,7 +537,11 @@ def report( if json_output: output_data = { "stages": [ - {"name": name, "status": rec.status} + { + "name": name, + "status": rec.status, + "duration_seconds": stage_duration(rec), + } for name, rec in manifest.stages.items() ], "verified": manifest.verified, diff --git a/src/readme2demo/manifest.py b/src/readme2demo/manifest.py index 9a77dd5..636836f 100644 --- a/src/readme2demo/manifest.py +++ b/src/readme2demo/manifest.py @@ -38,6 +38,25 @@ class StageRecord(BaseModel): meta: dict = Field(default_factory=dict) +def stage_duration(record: StageRecord) -> Optional[float]: + """Return a stage's final-attempt duration in seconds, if it is knowable. + + Missing, malformed, or clock-skewed timestamps are deliberately unknown + rather than zero: a skipped or still-running stage did not take zero time. + This remains a plain helper so duration never changes the manifest schema. + """ + if not record.started_at or not record.finished_at: + return None + try: + seconds = ( + datetime.fromisoformat(record.finished_at) + - datetime.fromisoformat(record.started_at) + ).total_seconds() + except ValueError: + return None + return seconds if seconds >= 0 else None + + class Manifest(BaseModel): run_id: str # Empty string == a guide-only run (no repository; the -s/--step-by-step diff --git a/src/readme2demo/orchestrator.py b/src/readme2demo/orchestrator.py index c8fac21..1b8a18b 100644 --- a/src/readme2demo/orchestrator.py +++ b/src/readme2demo/orchestrator.py @@ -23,7 +23,7 @@ from readme2demo.agent import run_agent from readme2demo.config import Config from readme2demo.engines import get_engine -from readme2demo.manifest import Manifest, new_run_id +from readme2demo.manifest import Manifest, stage_duration, new_run_id from readme2demo.types import CommandLog, DistillOutput, Plan, TutorialOutline console = Console() @@ -368,14 +368,25 @@ def summarize(manifest: Manifest) -> str: "stages:", ] for name, rec in manifest.stages.items(): + duration = _format_stage_duration(stage_duration(rec)) extra = f" — {rec.error}" if rec.error else "" meta = "" if rec.meta: meta = " " + json.dumps(rec.meta, default=str) - lines.append(f" {name:<10} {rec.status:<10}{meta}{extra}") + lines.append(f" {name:<10} {rec.status:<10} {duration:>8}{meta}{extra}") return "\n".join(lines) +def _format_stage_duration(seconds: float | None) -> str: + """Render a stage duration for human and Markdown report output.""" + if seconds is None: + return "—" + if seconds < 1: + return "<1s" + minutes, remainder = divmod(round(seconds), 60) + return f"{minutes}m {remainder}s" if minutes else f"{remainder}s" + + def _md_cell(text: str) -> str: """Escape arbitrary text for a single GFM table cell. @@ -409,14 +420,15 @@ def summarize_markdown(manifest: Manifest, artifacts: list[str]) -> str: f"{badge} — {repo_part} — engine `{manifest.engine}` — " f"total cost ${manifest.total_cost_usd:.4f}", "", - "| Stage | Status | Cost (USD) | Notes |", - "|---|---|---|---|", + "| Stage | Status | Duration | Cost (USD) | Notes |", + "|---|---|---|---|---|", ] for name, rec in manifest.stages.items(): # Failed stages carry `error`; skipped stages carry meta["reason"]. note = rec.error or rec.meta.get("reason", "") lines.append( - f"| {name} | {rec.status} | {rec.cost_usd:.4f} | {_md_cell(note)} |" + f"| {name} | {rec.status} | {_format_stage_duration(stage_duration(rec))} | " + f"{rec.cost_usd:.4f} | {_md_cell(note)} |" ) if artifacts: lines += ["", "**Artifacts**", ""] diff --git a/tests/test_cli.py b/tests/test_cli.py index 27e7a62..0f08d03 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -470,8 +470,8 @@ def test_regression_report_json_with_recorded_stages(tmp_path): assert parsed["verified"] is True assert parsed["cost"] == 1.5 assert parsed["commit"] == "abcdef123456" - assert {"name": "ingest", "status": "completed"} in parsed["stages"] - assert {"name": "agent", "status": "failed"} in parsed["stages"] + assert {"name": "ingest", "status": "completed", "duration_seconds": None} in parsed["stages"] + assert {"name": "agent", "status": "failed", "duration_seconds": None} in parsed["stages"] # -- report exit codes (#85) -------------------------------------------------- @@ -579,7 +579,11 @@ def test_report_markdown_emits_gfm_summary_with_present_artifacts(tmp_path): "verified": True, "total_cost_usd": 0.1234, "stages": { - "ingest": {"status": "completed", "cost_usd": 0.0021}, + "ingest": { + "status": "completed", "cost_usd": 0.0021, + "started_at": "2026-07-21T12:00:00+00:00", + "finished_at": "2026-07-21T12:00:02.5+00:00", + }, "verify": {"status": "completed"}, }, } @@ -594,8 +598,8 @@ def test_report_markdown_emits_gfm_summary_with_present_artifacts(tmp_path): out = result.output assert "## readme2demo — glow-20260710-162012-33fc72" in out assert "**Verified: yes**" in out - assert "| Stage | Status | Cost (USD) | Notes |" in out - assert "| ingest | completed | 0.0021 | |" in out + assert "| Stage | Status | Duration | Cost (USD) | Notes |" in out + assert "| ingest | completed | 2s | 0.0021 | |" in out assert "- tutorial.md" in out assert "- demo.mp4" in out assert "- demo.gif" not in out # not on disk → not claimed diff --git a/tests/test_orchestrator.py b/tests/test_orchestrator.py index 7c7a97c..b903d01 100644 --- a/tests/test_orchestrator.py +++ b/tests/test_orchestrator.py @@ -9,7 +9,7 @@ from readme2demo import ingest as ingest_mod from readme2demo.config import Config -from readme2demo.manifest import STAGES, Manifest +from readme2demo.manifest import STAGES, Manifest, StageRecord, stage_duration from readme2demo.orchestrator import Orchestrator, PipelineError, summarize_markdown from readme2demo.types import Plan, SuccessCriteria @@ -70,6 +70,39 @@ def test_manifest_skip_counts_as_done(tmp_path: Path): assert m.next_stage() == "tutorial" +@pytest.mark.parametrize( + ("record", "expected"), + [ + (StageRecord(started_at="2026-07-21T12:00:00+00:00", finished_at="2026-07-21T12:01:25+00:00"), 85.0), + (StageRecord(finished_at="2026-07-21T12:01:25+00:00"), None), + (StageRecord(started_at="2026-07-21T12:00:00+00:00"), None), + (StageRecord(started_at="not-a-date", finished_at="2026-07-21T12:01:25+00:00"), None), + (StageRecord(started_at="2026-07-21T12:01:25+00:00", finished_at="2026-07-21T12:00:00+00:00"), None), + ], +) +def test_regression_stage_duration_handles_unknown_timestamps(record, expected): + """Regression: report must not invent zero-duration stages from bad timestamps.""" + assert stage_duration(record) == expected + + +def test_regression_stage_duration_does_not_change_manifest_schema(): + """Regression: cosmetic report timing must never be persisted in manifest.json.""" + manifest = Manifest.model_validate( + { + "run_id": "schema-test", + "stages": { + "ingest": { + "status": "completed", + "started_at": "2026-07-21T12:00:00+00:00", + "finished_at": "2026-07-21T12:00:01+00:00", + } + }, + } + ) + assert stage_duration(manifest.stages["ingest"]) == 1.0 + assert "duration_seconds" not in manifest.model_dump()["stages"]["ingest"] + + # -- orchestrator control flow --------------------------------------------------- @@ -239,7 +272,11 @@ def make_report_manifest(**overrides) -> Manifest: "total_cost_usd": 0.1234, "stages": { "ingest": {"status": "completed", "cost_usd": 0.0021}, - "agent": {"status": "completed", "cost_usd": 0.098}, + "agent": { + "status": "completed", "cost_usd": 0.098, + "started_at": "2026-07-21T12:00:00+00:00", + "finished_at": "2026-07-21T12:01:25+00:00", + }, "verify": {"status": "completed"}, }, **overrides, @@ -258,10 +295,10 @@ def test_summarize_markdown_verified_run_full_shape(): assert "engine `claude-code`" in badge assert "total cost $0.1234" in badge # Stages table: header + one row per recorded stage, with per-stage cost. - assert "| Stage | Status | Cost (USD) | Notes |" in lines - assert "| ingest | completed | 0.0021 | |" in lines - assert "| agent | completed | 0.0980 | |" in lines - assert "| verify | completed | 0.0000 | |" in lines + assert "| Stage | Status | Duration | Cost (USD) | Notes |" in lines + assert "| ingest | completed | — | 0.0021 | |" in lines + assert "| agent | completed | 1m 25s | 0.0980 | |" in lines + assert "| verify | completed | — | 0.0000 | |" in lines # Artifact list renders exactly what the caller passed. assert "**Artifacts**" in lines assert "- tutorial.md" in lines @@ -289,7 +326,7 @@ def test_summarize_markdown_failed_stage_error_in_notes(): stages={"agent": {"status": "failed", "error": "exit 127: no engine"}}, ) md = summarize_markdown(m, []) - assert "| agent | failed | 0.0000 | exit 127: no engine |" in md.splitlines() + assert "| agent | failed | — | 0.0000 | exit 127: no engine |" in md.splitlines() def test_summarize_markdown_skip_reason_in_notes(): @@ -297,7 +334,7 @@ def test_summarize_markdown_skip_reason_in_notes(): stages={"render": {"status": "skipped", "meta": {"reason": "dry-run stop"}}}, ) md = summarize_markdown(m, []) - assert "| render | skipped | 0.0000 | dry-run stop |" in md.splitlines() + assert "| render | skipped | — | 0.0000 | dry-run stop |" in md.splitlines() def test_summarize_markdown_escapes_table_breaking_error_text(): @@ -318,7 +355,7 @@ def test_summarize_markdown_escapes_table_breaking_error_text(): assert len(rows) == 1 # newlines collapsed — still one table row assert "\\|" in rows[0] # pipe escaped, cell not split assert "[openai]" in rows[0] # brackets survive verbatim - assert rows[0].count(" | ") == 3 # exactly 4 cells + assert rows[0].count(" | ") == 4 # exactly 5 cells def test_summarize_markdown_no_artifacts_omits_section():