From 36bf2bef9c1cfa09d4ff84b86f76396b793f4b40 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Przemys=C5=82aw=20Galarowicz?= Date: Mon, 28 Sep 2026 21:23:12 +0200 Subject: [PATCH] feat(floor): cost.json shows stage elapsed time and deterministic work per run (6.35.0) One /pharn-loop or /pharn-ship run's cost.json now carries, beside its unchanged model usage, two additive keys: - `executions`: a VIEW over the existing phase markers (stage-executions-core.mjs, method stage-start-to-return/1). Each current-run stage-start is one row, ended only by the next marker when it is the orchestrator return; re-runs are `run 2`; anything else is unmeasured with a closed reason and elapsed_ms null, never 0. - `work[]`: facts /pharn-regress and /pharn-verify append at `done` (stage-work.mjs): gate processes executed / reused / nothing-to-run / required, BASE evidence fresh|reused, and the install's exit and ms (the one new timer). Best-effort and observational: no exit, verdict, reuse, route or commit reads it. check-cost-ledger rule 9 validates work rows and recomputes executions; /2 admits exactly the current key set or the pre-6.35.0 one (no schema bump). The run report and the stop's table show tokens, elapsed and work as three separate blocks. mark-phase.mjs, its printed binding line, run membership and stage attribution are unchanged. Promotes lesson L66. Co-Authored-By: Claude Opus 5.5 --- .../run-performance-breakdown/DEMO.md | 104 ++++++ .../run-performance-breakdown/GRILL.md | 38 +++ .../run-performance-breakdown/PLAN.md | 249 ++++++++++++++ .../run-performance-breakdown/REGRESSION.md | 35 ++ .../run-performance-breakdown/REVIEW.md | 47 +++ .../run-performance-breakdown/SHIP.md | 35 ++ .../run-performance-breakdown/VERIFY.md | 31 ++ .../run-performance-breakdown/demo.mjs | 275 +++++++++++++++ .../regression-report.json | 48 +++ .../verify-report.json | 16 + .dev/memory-bank/lessons-learned.md | 15 + CHANGELOG.md | 45 +++ CLAUDE.md | 12 + README.md | 4 +- SKILLS_VERSION | 2 +- docs/lessons-index.md | 3 +- pharn/floor/check-cost-ledger.mjs | 57 +++- pharn/floor/check-cost-ledger.test.mjs | 123 +++++++ pharn/floor/render-cost-ledger.mjs | 147 +++++++- pharn/floor/render-cost-ledger.test.mjs | 172 +++++++++- pharn/floor/render-run-report.mjs | 66 +++- pharn/floor/render-run-report.test.mjs | 65 +++- pharn/floor/stage-executions-core.mjs | 182 ++++++++++ pharn/floor/stage-executions-core.test.mjs | 301 +++++++++++++++++ pharn/floor/stage-regress-core.mjs | 9 +- pharn/floor/stage-regress.mjs | 31 +- pharn/floor/stage-regress.test.mjs | 52 ++- pharn/floor/stage-verify.mjs | 15 + pharn/floor/stage-verify.test.mjs | 47 +++ pharn/floor/stage-work.mjs | 295 ++++++++++++++++ pharn/floor/stage-work.test.mjs | 315 ++++++++++++++++++ pharn/pharn-contracts/cost-ledger.md | 116 ++++++- 32 files changed, 2927 insertions(+), 25 deletions(-) create mode 100644 .dev/features/run-performance-breakdown/DEMO.md create mode 100644 .dev/features/run-performance-breakdown/GRILL.md create mode 100644 .dev/features/run-performance-breakdown/PLAN.md create mode 100644 .dev/features/run-performance-breakdown/REGRESSION.md create mode 100644 .dev/features/run-performance-breakdown/REVIEW.md create mode 100644 .dev/features/run-performance-breakdown/SHIP.md create mode 100644 .dev/features/run-performance-breakdown/VERIFY.md create mode 100644 .dev/features/run-performance-breakdown/demo.mjs create mode 100644 .dev/features/run-performance-breakdown/regression-report.json create mode 100644 .dev/features/run-performance-breakdown/verify-report.json create mode 100644 pharn/floor/stage-executions-core.mjs create mode 100644 pharn/floor/stage-executions-core.test.mjs create mode 100644 pharn/floor/stage-work.mjs create mode 100644 pharn/floor/stage-work.test.mjs diff --git a/.dev/features/run-performance-breakdown/DEMO.md b/.dev/features/run-performance-breakdown/DEMO.md new file mode 100644 index 00000000..953cc2e7 --- /dev/null +++ b/.dev/features/run-performance-breakdown/DEMO.md @@ -0,0 +1,104 @@ +# DEMO — run-performance-breakdown (6.35.0), a controlled end-to-end fixture + +Produced by `node .dev/features/run-performance-breakdown/demo.mjs` (apparatus). A two-iteration +`/pharn-loop`-shaped run built from the REAL marker writer, work-record writer, ledger emitter, checker and run +report. **Synthetic, stated:** the transcript (one main-thread context, invented token counts), the timestamps and +the stamp contents. The real stage scripts writing these records from gates they actually spawned are exercised by +`stage-regress.test.mjs` (★ HIT, the budgeted chain) and `stage-verify.test.mjs` (★ EQUIVALENCE, OBSERVATIONAL). + +check-cost-ledger: GREEN (0 warn(s)) + +## The stop's screen table (`table()`) + +```text +cost ledger — demo-feature (partial, run window bounded, 0 outside excluded, 126 requests, dedup on requestId) + stage iter model reqs cache_read output + pharn-build 1 claude-sonnet-5 41 2611700 65600 + pharn-build 2 claude-sonnet-5 17 1113500 22100 + pharn-grill - claude-opus-5-5 8 494200 5600 + pharn-plan - claude-opus-5-5 22 1342550 30800 + pharn-regress 1 claude-opus-5-5 4 259300 1200 + pharn-regress 2 claude-opus-5-5 3 198000 750 + pharn-spec - claude-opus-5-5 9 542250 8100 + pharn-test - claude-sonnet-5 14 872550 15400 + pharn-verify 1 claude-opus-5-5 3 195000 750 + pharn-verify 2 claude-opus-5-5 5 331000 1150 + TOKENS ONLY — no prices here. Multiply by your own price list; output_thinking ⊂ output. +observed elapsed — wall clock between PHARN's stage markers (not CPU, model or tool time; not monotonic) + stage iter run elapsed + pharn-spec - 1 180.0 s + pharn-plan - 1 390.0 s + pharn-grill - 1 135.0 s + pharn-test - 1 235.0 s + pharn-build 1 1 895.0 s + pharn-regress 1 1 455.0 s + pharn-verify 1 1 135.0 s + pharn-build 2 1 355.0 s + pharn-regress 2 1 125.0 s + pharn-verify 2 1 75.0 s + pharn-verify 2 2 65.0 s +deterministic work — gate processes run vs taken from reused evidence (counted from each stage's gate-run stamp) + pharn-regress iter 1 run 1: HEAD gates 3 run, 0 reused, 1 nothing-to-run, of 4; BASE fresh (no-record) — worktree created, install ran (exit 0, 94.2 s), base gates 3 run, 0 reused, 1 nothing-to-run, of 4 + pharn-verify iter 1 run 1: gates 4 run, 2 reused, 0 nothing-to-run, of 6 + pharn-regress iter 2 run 1: HEAD gates 3 run, 0 reused, 1 nothing-to-run, of 4; BASE REUSED (no worktree, no install, 0 base gate processes; 3 results from earlier evidence) + pharn-verify iter 2 run 1: gates 4 run, 2 reused, 0 nothing-to-run, of 6 + pharn-verify iter 2 run 2: gates 6 run, 0 reused, 0 nothing-to-run, of 6 +``` + +## The run report's new section (`RUN-REPORT.md`) + +## Stage elapsed and deterministic work + +**Observed elapsed** is wall-clock time between two PHARN markers — the stage's start and the orchestrator's +return — read by two different processes. It is NOT CPU time, model time or tool time, it is not monotonic, and +it includes orchestration, subprocesses, waiting and any answer a human gave inside the stage. An `unmeasured` +row names why no interval could be paired, and is never a zero. **Deterministic work** is counted from each +`/pharn-regress` and `/pharn-verify` execution's own gate-run stamp at its `done` exit; an execution that ended any +other way recorded none. Nothing here is subtracted from anything else. + +```text +observed elapsed — wall clock between PHARN's stage markers (not CPU, model or tool time; not monotonic) + stage iter run elapsed + pharn-spec - 1 180.0 s + pharn-plan - 1 390.0 s + pharn-grill - 1 135.0 s + pharn-test - 1 235.0 s + pharn-build 1 1 895.0 s + pharn-regress 1 1 455.0 s + pharn-verify 1 1 135.0 s + pharn-build 2 1 355.0 s + pharn-regress 2 1 125.0 s + pharn-verify 2 1 75.0 s + pharn-verify 2 2 65.0 s + +deterministic work — gate processes run vs taken from reused evidence (counted from each stage's gate-run stamp) + pharn-regress iter 1 run 1: HEAD gates 3 run, 0 reused, 1 nothing-to-run, of 4; BASE fresh (no-record) — worktree created, install ran (exit 0, 94.2 s), base gates 3 run, 0 reused, 1 nothing-to-run, of 4 + pharn-verify iter 1 run 1: gates 4 run, 2 reused, 0 nothing-to-run, of 6 + pharn-regress iter 2 run 1: HEAD gates 3 run, 0 reused, 1 nothing-to-run, of 4; BASE REUSED (no worktree, no install, 0 base gate processes; 3 results from earlier evidence) + pharn-verify iter 2 run 1: gates 4 run, 2 reused, 0 nothing-to-run, of 6 + pharn-verify iter 2 run 2: gates 6 run, 0 reused, 0 nothing-to-run, of 6 +``` + +## The five questions, answered from `cost.json` alone + +1. **Most model usage:** by requests, `pharn-build` (58 requests); by output tokens, `pharn-build` (87700 output tokens, 3725200 cache-read). Source: `by_stage_iteration_model`, summed over iterations and models. +2. **Longest observed interval:** `pharn-build` iteration 1 run 1, 895000 ms. Summed over its executions, the stage with the most observed wall clock is `pharn-build`. Source: `executions.rows` (wall clock between markers — not model, tool or CPU time). +3. **BASE regression work reused?** iteration 1: no (`no-record`) — worktree created, install ran (94218 ms), 3 BASE gate processes; iteration 2: yes — no worktree, no install, 0 BASE gate processes. Source: `work[]`, `base.evidence`. +4. **VERIFY gate processes avoided:** 4 across 3 verify executions (iter 1 run 1: 2 of 6, iter 2 run 1: 2 of 6, iter 2 run 2: 0 of 6); plus 3 BASE gate results taken from earlier evidence. Source: `work[].gates.reused`, `work[].base.reused`. +5. **Expensive deterministic work that still executed:** pharn-regress iter 1 run 1: 3 HEAD + 3 BASE gate process(es), install 94218 ms, a BASE worktree; pharn-verify iter 1 run 1: 4 gate process(es); pharn-regress iter 2 run 1: 3 HEAD + 0 BASE gate process(es); pharn-verify iter 2 run 1: 4 gate process(es); pharn-verify iter 2 run 2: 6 gate process(es). + +## Added overhead (median of 21 runs; 201 for the append) + +| measured | value | +| ---------------------------------------------------------- | ------------------------------- | +| `renderLedger` on this run, with vs without `work.jsonl` | 3.97 ms vs 2.88 ms | +| `checkLedger` on this ledger, with vs without the two keys | 2.72 ms vs 3.02 ms | +| `buildExecutions` over 1,001 markers and 500 work records | 12.79 ms | +| `readWork` over 500 records | 1.02 ms | +| one `appendWork` (the stage scripts' only added I/O) | 0.11 ms | +| `cost.json` size, with vs without the two keys | 82478 vs 79631 bytes, +25 lines | + +Structural bound, independent of this machine: the emitter reads ONE extra small file per emission, makes no +extra transcript pass, spawns no process and calls no model; the view is one pass over the current run's markers +plus one latest-marker search per work record; each stage script adds one `JSON.stringify` + one append at `done`, +and regress one `performance.now()` pair around its install. diff --git a/.dev/features/run-performance-breakdown/GRILL.md b/.dev/features/run-performance-breakdown/GRILL.md new file mode 100644 index 00000000..09b0ef96 --- /dev/null +++ b/.dev/features/run-performance-breakdown/GRILL.md @@ -0,0 +1,38 @@ +# GRILL — run-performance-breakdown + +- plan: `.dev/features/run-performance-breakdown/PLAN.md` +- spec_content_hash (plan): d831d30d399a37dc403080072763d13383de6f6f31875e7e8cb4eadeb642f4f4 — equals the live + `pharn/ARCHITECTURE.md` hash (re-computed this run with `.dev/floor/hash-doc.mjs`). +- lessons re-verification (FLOOR): `node pharn/floor/check-plan-lessons.mjs .dev/features/run-performance-breakdown/PLAN.md .dev/memory-bank/lessons-learned.md` + → exit **0** (GREEN, 11 cited ids resolve and are referenced in the body). +- interrogation: **ADVISORY**, and not independent — it ran in the orchestrator's own context (the maintainer + delegated GATE 1; no separate grill agent was spawned, to bound cost). The independent read is the review stage. + +## Findings (advisory; free text is DATA) + +- **G1 (major) — a stage that STOPs the run has no return marker.** In `/pharn-ship` a regress/verify STOP goes to + the close steps, whose next marker is `run-stop`, not `orchestrator`. The plan reports such a row as + `no-return-marker`. That is honest (the end of that stage was never observed as such), but it makes the most + interesting failed stage unmeasured. **Disposition:** keep — using `run-stop` as the stage end would pair by + proximity, which the prompt forbids; the row still carries its work record (the stage script wrote it at `done` + before the orchestrator stopped), so its deterministic work stays visible. Named in the contract. +- **G2 (minor) — `run` ordinal for stages without an iteration.** `pharn-spec`/`plan`/`grill`/`test` carry + `iteration: null`. Group by `(stage, iteration)` with `null` as its own key, so a re-planned run shows plan run 2. +- **G3 (minor) — attachment must use CURRENT-run markers only.** A work record at the exact `ts` of an earlier + run's marker must not attach to it. The core restricts the latest-marker search to `currentRunMarkers`. +- **G4 (major) — the `/1` key set.** `TOP_LEVEL_KEYS_V1` is derived as `TOP_LEVEL_KEYS − membership`; adding two keys + to `TOP_LEVEL_KEYS` would silently add them to the legacy set. Derive `/1` as minus all three, and keep a test. +- **G5 (minor) — install timer across a resume.** The install is one async spawn inside one invocation, so one + `performance.now()` pair measures it; a kill mid-install re-runs it from scratch, and the recorded `ms` is the run + that completed. State it. +- **G6 (minor) — a malformed stamp at `done`.** The verdict just validated both stamps, so a parse failure there is a + race or a bug; the work record is skipped with a note, never a changed exit. +- **G7 (question, resolved by default) — should work records be written when no run is open?** A standalone + `/pharn-regress` has no markers; its record is never inside a window and so never reaches a ledger. Writing it + anyway keeps the stage scripts free of run-state reads (the reuse modules already read the marker; this one does + not need to). One small line per stage execution; `.pharn/` is disposable scratch. + +## Verdict + +GREEN on the floor check. Advisory findings folded into the build (G2–G6) or recorded as residual/contract text (G1, +G7). diff --git a/.dev/features/run-performance-breakdown/PLAN.md b/.dev/features/run-performance-breakdown/PLAN.md new file mode 100644 index 00000000..86f511cd --- /dev/null +++ b/.dev/features/run-performance-breakdown/PLAN.md @@ -0,0 +1,249 @@ +# PLAN — run-performance-breakdown: stage elapsed time and deterministic work in the cost ledger + +- spec_content_hash: d831d30d399a37dc403080072763d13383de6f6f31875e7e8cb4eadeb642f4f4 +- applied_lessons: [L24, L34, L35, L36, L41, L42, L43, L58, L59, L62, L63] +- increment: extend the existing per-run cost ledger (`cost.json`) so one `/pharn-loop` or `/pharn-ship` run shows, + beside its unchanged model usage, (a) the observed wall-clock interval of each stage execution, derived from the + phase markers it already records, and (b) the deterministic gate work each `/pharn-regress` and `/pharn-verify` + execution actually performed or avoided through reuse, captured by those stage scripts at the moment they finish. +- layer(s): pharn-floor (product), pharn-contracts (`cost-ledger.md`, additive) +- constitution_refs: [P0, P2, P3, P4, P5, P6, P7] + +## Why (P7) + +**The trigger is the maintainer's explicit direction** — this run's prompt ("PR 4: Run Performance Breakdown"), +recorded as such (P5), not a failure this plan re-derives. It follows 6.33.0 (BASE evidence reuse) and 6.34.0 (HEAD +→ VERIFY gate reuse): both optimizations are invisible after the run, because each iteration overwrites the reports +that say what was reused (below). No token or time saving is claimed for this increment; it observes. + +## Confirmed current behavior (read this run, `main` at `1f6e2d6`, 6.34.0) + +### What `cost.json` already records (facts) and derives (views) + +- **Facts:** `requests[]` (one row per deduped request: `ts`, `model`, `sidechain`/`agent_id`, the six token + classes, verbatim `usage`) and `markers[]` (every marker of the feature's `markers.jsonl`: `seq`, `kind`, `stage`, + `iteration`, `ts`, `session_id`, optional `origin`/`mode`/`route`). +- **Views (recomputed by `check-cost-ledger.mjs` from `requests[]`):** `totals`, `by_model`, + `by_stage_iteration_model`, `unattributed`; `membership` is recomputed from `markers[]` (window) and bound to the + transcript (context, `run-window/2`). +- `requests[].stage/iteration` = the latest same-session marker at-or-before the request (`attribute()`). +- The top-level key set is CLOSED in both directions (`TOP_LEVEL_KEYS`); `/1` ledgers use `TOP_LEVEL_KEYS_V1`. + +### What can already be derived, and was not + +- **Stage elapsed.** Every stage the orchestrators mark is bracketed: `/pharn-loop` and `/pharn-ship` write + `stage-start --stage [--iteration ]` before the stage and `--kind orchestrator` right after it returns + (pharn-loop.md 344–552, pharn-ship.md 271–566); a freshness re-run writes its own pair inside the same iteration + (pharn-loop.md 567). So `stage-start → the NEXT marker, when that marker is the orchestrator return` identifies one + execution deterministically, by `seq`, with no proximity guessing. Nothing computes it today. +- `/pharn-ship` writes **no** stage-start for `pharn-spec` (it is GATE 1, inline); `/pharn-loop` does. The ship spec + interval is therefore not a stage execution and is not reported (named residual below). Quick runs write no + `pharn-regress` stage-start, so a skipped stage has no execution row by construction. + +### What cannot be recovered after the run (needs capture at the moment — L42) + +- `regression-report.json` (`base_evidence {reused, miss, …}`) and `verify-report.json` (`gate_reuse {reused[]}`) + are **overwritten in place every iteration** (the run report's own stated bound (3)); the gate-run stamps under + `.pharn/pharn-regress/` and `.pharn/pharn-verify/` are cleared at every stage's fresh start. So for any iteration + but the last, whether BASE was reused and how many VERIFY gates were reused is **gone** by the time the ledger is + emitted. That is exactly the iteration where the 6.33.0/6.34.0 savings appear (iteration ≥ 2 / verify after regress). +- No gate or install duration is recorded anywhere (`run-gates.mjs` records exits and hashes only; the stage scripts + time only their own budget). + +### Where the counts live (the authoritative evidence) + +- A gate-run stamp's `runs[]`: `ran: true` = a process executed; `ran: false, reason: "no-files"` = nothing to run; + `ran: false, reason: "reused"` + `reused {…}` = a VERIFY result taken from the REGRESS/HEAD execution (6.34.0). +- `stage-regress.mjs`'s final `state.baseReuse.reused` (re-decided at "verdict") says whether BASE evidence was + reused; on a HIT the worktree, install and base-gate phases do not run; `state.installResult` is `{ran, exit, +timedOut}` or null. + +## The design + +### 1. Stage executions — a VIEW over `markers[]` (no new instrumentation) + +New pure module `pharn/floor/stage-executions-core.mjs`, method **`stage-start-to-return/1`**: + +- Scope: `currentRunMarkers(markers)` (run-window-core's ONE definition of the current run). When + `runWindow(markers, null)` is `unknown` (no run-start, bad run-start/run-stop ts, a marker after run-stop, stop + before start), the view has `status: "unknown"` with that reason and no rows — never a guessed run. +- Each `stage-start` S yields one row `{stage, iteration, run, start_seq, end_seq, elapsed_ms, unmeasured, work}`. + `run` = 1-based ordinal among rows with the same `(stage, iteration)`, in `seq` order — two executions are never + merged. N = the next current-run marker by `seq`: + - no N → `unmeasured: "no-end-marker"` (interrupted, or still running at emission), `end_seq: null`; + - N not an `orchestrator` marker → `"no-return-marker"`, `end_seq: null` (the next stage-start/run-stop is NOT + used as an end: that would be a guess); + - `S.session_id !== N.session_id` → `"session-changed"` (the stage spanned a resume); + - either `ts` unparseable (`tsMs`) → `"bad-timestamp"`; + - `N.ts < S.ts` → `"clock-went-back"`; + - else `elapsed_ms = tsMs(N.ts) − tsMs(S.ts)` (an integer; 0 only when measured equal). + An unmeasured row carries `elapsed_ms: null`, never 0. +- `work` = indices into the ledger's `work[]` attached to this execution (§2), in ascending order. + +### 2. Deterministic work — ONE record per stage execution, written by the stage script at `done` + +New module `pharn/floor/stage-work.mjs` (schema `pharn-stage-work/1`), the one owner of the record: + +- **Derivation (pure, from the stage's own authoritative evidence, never re-counted elsewhere):** + `countRuns(stamp) → {required, executed, reused, no_files}` over `runs[]` (`ran:true`, `reason:"reused"`, + `reason:"no-files"`); `required` = `runs.length`. + - regress: `head` = countRuns(head stamp); `base` = `{evidence: "fresh"|"reused", miss, required, executed, +reused, no_files}` — on a HIT `executed: 0` and `reused = required − no_files` (every result came from the earlier + evidence), `miss: null`; on a miss the base stamp's counts and `miss` = the decision's closed miss code; + `install` = `null` (not performed) or `{exit, timed_out, ms}`. + - verify: `gates` = countRuns(verify stamp) (includes `reconcile`). + - Invariant (checked): `executed + reused + no_files === required` per side; a BASE HIT has `executed 0` and + `install null`; a fresh BASE has `reused 0`. +- **Worktree creation is NOT a separate field** — it is performed iff `base.evidence === "fresh"` (derivable, so + not stored twice — L35). Install "not configured" vs "skipped by reuse" is likewise derived from `base.evidence`. +- **Timing:** exactly ONE new timer — the BASE install, `performance.now()` around the one `spawnGate` that runs it, + persisted as integer `ms` in `installResult` (so it survives a budget `continue`/`--resume`). No gate-level timer + (named residual). `installResult.ms` is optional in `validateProgress` (non-negative safe integer when present); + `regress-base-reuse-core.mjs buildRecord` copies only `{ran, exit, timedOut}`, so the reuse REQUIREMENT is unchanged. +- **Write:** appended as one JSON line to `<.pharn/cost>//work.jsonl` (mark-phase's `DEFAULT_BASE`, + imported — L41), beside `markers.jsonl`, after the stage's report/render are written and before its `done` emit. + `ts` = `new Date().toISOString()` (the marker clock), `session_id` = `CLAUDE_CODE_SESSION_ID` or null. + **Observational only:** the append is best-effort; any failure (a symlinked `.pharn`/`.pharn/cost`/feature dir or + file — lstat walk + `O_NOFOLLOW`, L54/L59 —, EACCES, a malformed stamp) prints one stderr note and the stage still + emits its unchanged `done`. Only `done` writes one; a refused/unusable/crashed/`continue` exit writes none (so an + execution that ran gates then refused shows `work: []`, i.e. "not recorded", never zero). + +### 3. The ledger (`render-cost-ledger.mjs` / `check-cost-ledger.mjs`) + +- Two new top-level keys, emitted on every `/2` ledger from 6.35.0: `executions` (the view: + `{method, status, reason, rows}`) and `work` (the facts: validated records inside the run window — + `isMember(win, ts, session_id)`, the same membership test requests use). `TOP_LEVEL_KEYS` gains both; the checker + accepts EXACTLY `TOP_LEVEL_KEYS` or `TOP_LEVEL_KEYS_PRE_WORK` (both keys absent — a pre-6.35.0 `/2` ledger), so + closure holds in both directions and old ledgers stay GREEN. `/1` key set unchanged (derived minus all three). + **No schema bump:** additive, no existing field changes meaning. +- The shells (`unavailable`, context-unknown) carry them too: timing needs only markers, so a run whose transcript + is missing still reports elapsed time. +- Checker: `work[]` rows validated with `stage-work.mjs validateWork` (closed keys, invariants); each row a member + of the recomputed window; `executions` deep-equal to `buildExecutions(markers, work)` (mutating any row → RED). + `--verify-transcript` is unchanged: it compares requests/membership only (work/executions are not + transcript-derived — L63's enumeration, below). +- A `work.jsonl` line that fails validation is not a row; its line index is listed in `dropped[]` as + `work[]` (no raw value reaches the file). +- `serializeLedger`: `work` joins `ROW_ARRAYS` (one record per line); `executions.rows` one row per line. +- `table()` (the stop's screen copy) gains an ELAPSED block and a WORK block. + +### 4. The run report (`render-run-report.mjs`) + +New section `## Stage elapsed and deterministic work` after `## Tokens …`: copies `cost.json`'s stored +`executions` and `work` (never recomputed — the report's bound (2)), labelled "observed wall-clock between PHARN's +markers — not CPU, model or tool time, not monotonic", `unmeasured — ` for every unmeasured row, and one +line per work record. A ledger without the keys renders `n/a — cost.json predates 6.35.0`. + +## Files + +- `pharn/floor/stage-executions-core.mjs` — NEW: the executions view (pairing + work attachment), pure +- `pharn/floor/stage-executions-core.test.mjs` — NEW: pairing cases, reruns, quick, interrupted, ambiguity +- `pharn/floor/stage-work.mjs` — NEW: the work record (schema, derivation from stamps, validate, append, read) +- `pharn/floor/stage-work.test.mjs` — NEW: derivation, invariants, hostile lines, symlink refusal +- `pharn/floor/render-cost-ledger.mjs` — read `work.jsonl`, emit `work` + `executions`, key sets, serializer, table +- `pharn/floor/render-cost-ledger.test.mjs` — emission, byte-stability of existing views, shells +- `pharn/floor/check-cost-ledger.mjs` — the two accepted key sets, work validation + membership, executions recompute +- `pharn/floor/check-cost-ledger.test.mjs` — mutation controls, pre-6.35 ledger GREEN +- `pharn/floor/render-run-report.mjs` — the new section +- `pharn/floor/render-run-report.test.mjs` — the section, the closed SECTIONS set +- `pharn/floor/stage-regress.mjs` — install timer; append the work record at done +- `pharn/floor/stage-regress-core.mjs` — `installResult.ms` optional in `validateProgress` +- `pharn/floor/stage-regress.test.mjs` — work record: fresh BASE, reused BASE +- `pharn/floor/stage-verify.mjs` — append the work record at done +- `pharn/floor/stage-verify.test.mjs` — work record: fresh gates, partially reused gates +- `pharn/pharn-contracts/cost-ledger.md` — new section "Stage executions and deterministic work (6.35.0)" +- `.dev/features/run-performance-breakdown/demo.mjs` — NEW: the controlled end-to-end fixture +- `.dev/features/run-performance-breakdown/DEMO.md` — NEW: its output and the five answers +- `.dev/features/run-performance-breakdown/PLAN.md` — this plan +- `CHANGELOG.md` — `[6.35.0]` +- `SKILLS_VERSION` — 6.35.0 (minor: a newly shipped capability on the floor) +- `README.md` — the version badge; the CURRENT-STATE region regenerated +- `CLAUDE.md` — the cost-ledger paragraph gains the executions/work note +- `docs/capabilities/**` — regenerated by `npm run docs:generate` +- `.dev/floor/command-hygiene.test.mjs` — apparatus, only if a pinned expectation over the touched modules moves + +## Contracts satisfied + +- `pharn/pharn-contracts/cost-ledger.md` — extended additively (two keys, a closed pre-6.35 alternative). +- `regression-report.md`, `verify-report.md`, `gate-run-record.md`, `stage-exit.md` — unchanged: no report, + stamp, exit or verdict field moves. + +## Tests and negative controls (the build must deliver each) + +- Timing: normal completed stage; three iterations; same-stage re-run in one iteration (`run` 1 and 2, not merged); + missing end (last stage-start, no later marker); next marker a stage-start (no return); run-stop directly after a + stage-start; session change; bad ts; clock going back; unknown current run (no run-start / marker after stop); + quick (no regress rows); interrupted run (open window) keeps every completed row. +- Unknown ≠ zero: every unmeasured row has `elapsed_ms === null`; a measured equal-ts pair is `0`. +- Model accounting unchanged: over the existing fixtures, `requests`, `totals`, `by_*`, `unattributed` and + `membership` of a ledger rendered with and without a `work.jsonl` are identical (✧), and `attribute()` agrees with + the new core's latest-marker rule (✧ parity). +- Work facts: fresh BASE (executed = required − no_files, install recorded), reused BASE (executed 0, install + null), fresh VERIFY (reused 0), partially reused VERIFY (reused > 0) — from the real stage scripts where the + existing suites already build those scenarios. +- Checker mutations: an `executions` row edited (elapsed, run, work index), a work count broken (invariant), a work + row outside the window, an extra/missing key (only one of the two new keys) → RED; a pre-6.35 `/2` ledger → GREEN. +- Hostile `work.jsonl`: torn line, prototype keys, huge ints, strings in counts, extra keys → not a row, listed. +- The stage exit is unchanged when the append fails (planted symlink at `.pharn/cost`). + +## Measurement + +`demo.mjs` builds a controlled run (markers + a synthetic transcript + work records from real stamp shapes) and +renders the ledger and report; it times `buildExecutions`/`readWork` over a 1,000-marker/1,000-record input and the +full render+check with and without work, and reports the added cost. Bounded structurally: one extra file read per +emission, O(markers + work) pairing, no transcript pass, no gate re-run, no model call. + +## Guarantee audit (P0) + +- **FLOOR:** the executions view is a pure, deterministic function of `markers[]`+`work[]` in the file, and the + checker holds the stored view to a recompute (primitive #3 + integer compare). The work record's shape and + invariants are enum/integer checks. The counts are derived by tested code from the stamp the stage just finished. +- **ADVISORY:** that the markers describe the run (L19 — Bash-written, as today); that `elapsed_ms` is the stage's + real duration (two wall-clock reads by two processes; not monotonic, includes waits, orchestration, human + answers); that a work record was written for every execution (a stage stopped before `done` writes none); that + `work.jsonl` was not edited (`.pharn/` is Bash-reachable, LIMITS §6 — agreement, never provenance, L43). +- **Struck:** "stage time = model time + tool time"; any efficiency score; any price. + +## Trust audit (P2) + +`work.jsonl` is untrusted `.pharn/` state: every value is type- and domain-tested before use (`cost-value-core` +predicates, L62); a failing line is dropped by index. Nothing in it reaches any verdict, exit code, reuse decision, +route or commit gate: the only readers are the ledger emitter/checker and the run report. + +## Determinism audit (P5) + +Pairing is by `seq` order and exact kind membership; attachment uses the latest-marker-at-or-before rule already +used for requests. No proximity window, no clock read in the view. + +## Applied lessons + +- L24: the overhead claim is MEASURED on a constructed large input, not inherited. +- L34: every per-row assertion in the checker also asserts the empty case agrees (empty rows ↔ `status`). +- L35: worktree/install-skip are derived from `base.evidence`, not stored twice; the report copies the views. +- L36: the two accepted top-level key sets are exact sets, never "presence of". +- L41: `.pharn/cost` is imported from `mark-phase.mjs`, no second literal. +- L42: per-iteration reuse facts are captured at `done`, because the reports are overwritten afterwards. +- L43: the checker certifies agreement between `executions` and the file's own facts — never that the markers are true. +- L58: the recompute uses the ledger's RECORDED `markers[]`/`work[]`, never the still-growing live files. +- L59: the append refuses a symlinked component and opens with `O_NOFOLLOW`. +- L62: hostile `work.jsonl` values go through non-throwing predicates before any coercion. +- L63: enumerated re-derivations of the touched values — `requests[].stage` (untouched, parity test), `membership` + (untouched), `--verify-transcript` (compares requests/membership only; `work`/`executions` are not transcript-derived). + +## Named residuals (not closed here) + +- `gate-process-duration` — no per-gate timer; VERIFY/HEAD/BASE gate time is inside the stage's elapsed only. +- `ship-spec-elapsed` — `/pharn-ship` marks no `pharn-spec` stage-start (GATE 1); adding one would change stage + token attribution, which this increment must not do. +- `work-on-non-done-exit` — gates executed by a stage that then refused/crashed are not recorded. +- `work-record-provenance` — a Bash writer can forge `work.jsonl` (as `markers.jsonl` today). + +## GATE 1 + +Plan acceptance was **delegated to the orchestrating model** by the maintainer's prompt ("Do not stop after writing a +PLAN. Complete implementation, validation and final diff review"). Recorded as a delegated decision, not a human +approval. + +## Open questions (HALT) + +- none — every choice above has a stated default the prompt allows; the maintainer reviews at GATE 2. diff --git a/.dev/features/run-performance-breakdown/REGRESSION.md b/.dev/features/run-performance-breakdown/REGRESSION.md new file mode 100644 index 00000000..28cd3a09 --- /dev/null +++ b/.dev/features/run-performance-breakdown/REGRESSION.md @@ -0,0 +1,35 @@ +# REGRESSION — run-performance-breakdown + +- base: `1f6e2d610b1141ca59b02b84b2a1c798946f1d29` (`HEAD`: the working tree carries the uncommitted build, so the + base is HEAD, per Step 1's deterministic rule) +- inside: the 26 changed and untracked paths listed in `regression-report.json` (every one declared in `PLAN.md` + `## Files` or exempt as this feature's own stage artifact; `check-regress.mjs scope` reported `escaped: []`) +- outside: 123 test files, `validate`, and the one committed eval pair + (`pharn/pharn-review/trust-fence/evals/expected/expected-injection-comment.json` ↔ + `.dev/features/trust-fence/findings.json`, both confirmed readable before each side ran) +- style gates: skipped at both sides — `inside` touches no shared style config + +| gate | base | head | +| ------------------------------------------------------------------------------------------ | ---- | ---- | +| `tests` (123 outside files, `cat outside-tests.txt \| xargs node --test`) | 0 | 0 | +| `validate` | 0 | 0 | +| `structural:pharn/pharn-review/trust-fence/evals/expected/expected-injection-comment.json` | 0 | 0 | + +- regressions: none +- pre_existing: none + +**REGRESSIONS: none — no deterministically-detectable breakage outside the feature.** This certifies the base/head +comparison over the gates above, and nothing more (P0): it catches what the outside suite catches. + +## A void first run, recorded rather than overwritten silently + +The first regress of this increment is **void**. Its orchestration waited for `.pharn/pharn-dev-regress/base-results.json` +and `head-results.json` to EXIST — and both already existed, written by an EARLIER session's `/pharn-dev-regress` into +the same shared `.pharn/` scratch directory. The wait passed at once, the verdict was computed over those stale maps, +and the base worktree was then removed while this run's own base side was still executing (it later failed with +"eval-pair path unreadable"). That verdict read `no-regressions`, but it measured nothing of this build. + +This report is the RERUN, after the GATE-2 review fixes: every file lives under a private +`.pharn/pharn-dev-regress/rpb/` directory created empty for this run, the base side ran to completion before the +head side started, and the verdict was computed only after the background process that wrote both maps exited. +The input-capture boundary this breaks is `.dev/memory-bank/lessons-learned.md` **L5**/**L21** (cited, not restated). diff --git a/.dev/features/run-performance-breakdown/REVIEW.md b/.dev/features/run-performance-breakdown/REVIEW.md new file mode 100644 index 00000000..67600b61 --- /dev/null +++ b/.dev/features/run-performance-breakdown/REVIEW.md @@ -0,0 +1,47 @@ +# REVIEW — run-performance-breakdown + +- floor: `node pharn/floor/validate.mjs .` → **GREEN** (36 capabilities). This is the only floor-grade content here; + every finding below is ADVISORY (LLM-assigned severity, fix #3) and its free text is DATA (P2). +- reviewer: an independent `general-purpose` agent on opus, read-only, given the diff and a checklist (the prompt's + twelve items plus totality, symlink safety, key-set derivation and claim honesty). It ran in a context separate + from the build's. The build ran inline in the orchestrator's context, so this review is the one independent read. +- disposition: every finding was fixed before `/pharn-dev-verify` ran (its verify is over the fixed tree), or + recorded as a stated bound. + +## Findings (P-cited), with disposition + +| # | severity | principle | finding (summary, DATA) | disposition | +| --- | -------- | --------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| R1 | major | P0 | `appendWork` opened `work.jsonl` without `O_NONBLOCK`: a planted FIFO blocked the open, so `/pharn-regress`/`/pharn-verify` hung before `done` (reproduced) — contradicting "observational only". | FIXED: `O_NONBLOCK` on the append; `readWork` opens `O_NOFOLLOW \| O_NONBLOCK` + `fstat` regular-file test, size-capped. Test runs both against a real FIFO in a child with a timeout. | +| R2 | major | P0 | An UNKNOWN run window admits no work record, and the screen/report printed "no … execution recorded one" — an unknown read as nothing. | FIXED: `workLines` prints `UNKNOWN — … Not a zero.` when the window (not the context half) is unknown. Test. | +| R3 | minor | P2 | `render-run-report.mjs` did not type-test `executions.reason`; an object with a throwing `toString` crashed the renderer. | FIXED: `method`/`reason` type-tested, and `elapsed_ms === null ⇔ unmeasured !== null`. Test over four hostile shapes. | +| R4 | minor | P0 | A skipped return AND a skipped next start pair a stage with the LATER stage's return — a measured, wrong interval; "never by proximity" overclaimed. | FIXED where evidence exists: another stage's work record inside the interval → `foreign-work-inside`. The remaining case (stages that write no work record) is a BOUND stated in the header and the contract. | +| R5 | minor | P5 | Rows keyed by `seq`: a duplicate `seq` re-homed a work record. | FIXED: keyed by the marker object. Test. | +| R6 | minor | P4 | `dropped[]`'s `work[]` read as an index into `work[]`, but it is a line of the whole multi-run file. | FIXED: token `work.jsonl[]`, documented as a file line index across runs. | +| R7 | minor | P5 | `session-changed` treated a null session as different, while attribution treats null as binding any. | FIXED: aligned (null binds any). Test. | +| R8 | nit | P0 | "never stored twice" loose for a reused BASE's counts; CHANGELOG said "byte for byte" where the test compares parsed documents. | FIXED wording in the contract and CHANGELOG. | +| R9 | nit | P7 | `work.jsonl` is never pruned; standalone runs write it too. | STATED in the contract's bounds (one line per execution, disposable `.pharn/`). | +| R10 | minor | P5 | (orchestrator, own read) `regressWork`/`verifyWork` are evaluated before `done`; a throw there would crash the stage. | FIXED before review: both total (try/catch → null). Test over hostile inputs. | +| R11 | minor | P6 | (orchestrator, own read) The attachment and foreign-work checks re-parsed timestamps per pair (99 ms on 1,001 markers × 500 records, measured). | FIXED: each timestamp parsed once (9–17 ms, machine noise; `DEMO.md`). | + +## The twelve prompt checks (the reviewer's "verified correct", re-read by the orchestrator) + +1. No second telemetry system: one extra fact file beside `markers.jsonl`, read by the same emitter. +2. `markerLine` and `mark-phase.mjs` are unchanged. +3. No guessed duration; R4 above names the one case the markers cannot tell apart. +4. Unknown is `null` / `UNKNOWN`, never 0 (R2 fixed the one place it was not). +5. Re-runs are `run 2`, never merged. +6. A skipped quick stage has no row. +7. Elapsed is labelled wall clock, never model, tool or CPU time. +8. No extra transcript pass; `--verify-transcript` reads no live work file. +9. Nothing on a decision path reads the new data, and the append cannot change an exit (R1, R10). +10. Membership, context binding, dedup and stage attribution are untouched (✧ equality test over every view). +11. Reuse facts are counted from the stamps once, at `done`; worktree and install are derived from `evidence`. +12. No schema bump: two additive keys, and a closed pre-6.35.0 alternative. + +## Proposed lesson candidate (for Step 2b) + +A wait on a result file in SHARED scratch (`until [ -f .pharn//x.json ]`) is satisfied by another session's +stale file: this run's first regress verdict read two maps an earlier session had written, and its base worktree was +removed while its own base side still ran (`REGRESSION.md`, "A void first run"). The same happened at verify with +`results.json`, caught before it was used. L5/L21 bound what is captured; this is WHOSE capture is read. diff --git a/.dev/features/run-performance-breakdown/SHIP.md b/.dev/features/run-performance-breakdown/SHIP.md new file mode 100644 index 00000000..6599bc4d --- /dev/null +++ b/.dev/features/run-performance-breakdown/SHIP.md @@ -0,0 +1,35 @@ +# SHIP — run-performance-breakdown (6.35.0) + +## Stages run, in order, and where the run ended + +1. `/pharn-dev-plan` → `PLAN.md`. **GATE 1 was delegated to the orchestrating model** by the maintainer's prompt ("Do + not stop after writing a PLAN. Complete implementation, validation and final diff review") — a delegated model + decision, not a human approval. +2. `/pharn-dev-grill` → `GRILL.md` (advisory interrogation, inline, not independent). + `check-plan-lessons.mjs` exit **0**. +3. `/pharn-dev-build` → `node pharn/floor/validate.mjs .` exit **0** (GREEN, 36 capabilities). +4. `/pharn-dev-regress` → `regression-report.json` `.verdict` = **`no-regressions`** (the RERUN; the first run + was void and is recorded in `REGRESSION.md`, "A void first run"). +5. `/pharn-dev-verify` → `verify-report.json` `.verdict` = **`FAIL`**, `failing_gates: ["lint:md"]` — the only + red is `.pharn/pr-body.md`, another session's gitignored scratch file (modified before this build's anchor). + The same map with `lint:md` measured in a clean copy of the tree → **PASS**. `VERIFY.md` carries both. +6. `/pharn-dev-review` → `REVIEW.md` (an independent opus reviewer, read-only; 9 findings, all fixed or stated + before verify ran, plus two from the orchestrator's own read). + +Ended at **GATE 2**. The maintainer asked in chat for a pull request "when all finished"; the merge decision stays +theirs. + +- changelog-entry: exit 0 +- lesson: promoted L66 +- deferred: none + +## Orchestration notes (advisory) + +- Every stage ran INLINE in the orchestrator's context (opus), except the review, which ran as a separate opus agent. + Most build edits were made through Bash (python) rather than the Edit tool; the build's reconcile epoch judged + every change against the plan scope plus the stage amendments and read **CLEAN** (0 escapes). +- A regress/verify attempt was stopped mid-run to fold in the review fixes; both stages were then run again from + run-private scratch directories, and every verdict above comes from those reruns. + +chain ran; the named floor verdicts are as shown — this is NOT a judgment that the increment is good or wise; that is +the human's call at the post-review gate. diff --git a/.dev/features/run-performance-breakdown/VERIFY.md b/.dev/features/run-performance-breakdown/VERIFY.md new file mode 100644 index 00000000..a3ac4860 --- /dev/null +++ b/.dev/features/run-performance-breakdown/VERIFY.md @@ -0,0 +1,31 @@ +# VERIFY — run-performance-breakdown + +Floor gates run at HEAD (the working tree with the build) into a private `.pharn/pharn-dev-verify/rpb/` directory +created empty for this run; the verdict is `pharn/floor/check-verify.mjs` over the recorded exit codes. + +| gate | exit | +| ------------------------------------------------------------------------------------------ | ---- | +| `test` (`npm test` — 4502 tests, 4502 pass, 0 fail) | 0 | +| `validate` | 0 | +| `lint` | 0 | +| `format:check` | 0 | +| `lint:md` | 1 | +| `structural:pharn/pharn-review/trust-fence/evals/expected/expected-injection-comment.json` | 0 | +| `reconcile` (`check-bash-reconcile.mjs --require-baseline`: CLEAN, 0 escapes) | 0 | + +**Raw floor verdict: FAIL** (`failing_gates: ["lint:md"]`) — `verify-report.json` is the checker's output verbatim. + +**The one red is environmental, and it is recorded, not waved through.** Every issue `lint:md` reported is in ONE +file, `.pharn/pr-body.md`: a gitignored scratch file last modified at 19:50, before this build's reconcile anchor +(20:08), written by another session sharing this checkout. It is not this increment's and was not touched (a +gitignored path is still in markdownlint-cli2's reach — `.dev/memory-bank/lessons-learned.md` **L61**, cited). CI checks +out no `.pharn/`. + +**Clean measurement:** `npm run lint:md` in a copy of this tree without `.git`, `.pharn`, `node_modules` (symlinked) +and `.claude/worktrees` → exit **0**, "0 issues". `check-verify.mjs` over the same map with that one measured value → +**PASS**. Both maps and both verdicts are kept under `.pharn/pharn-dev-verify/rpb/` (`results.json` / +`verdict-raw.json`, `results-clean.json` / `verdict-clean.json`). + +Verifiers: none registered — floor gates only (advisory layer empty, P7). + +This certifies that the named gates exited as shown — never that the increment is good or wise (P0). diff --git a/.dev/features/run-performance-breakdown/demo.mjs b/.dev/features/run-performance-breakdown/demo.mjs new file mode 100644 index 00000000..f92a023e --- /dev/null +++ b/.dev/features/run-performance-breakdown/demo.mjs @@ -0,0 +1,275 @@ +#!/usr/bin/env node +// .dev/features/run-performance-breakdown/demo.mjs — the CONTROLLED end-to-end fixture for 6.35.0 (apparatus, never +// shipped). It builds one two-iteration `/pharn-loop`-shaped run in a temp directory out of the REAL writers and +// readers — `mark-phase.mjs markPhase()` for the markers, `markerLine()` for the binding lines a real Bash call +// leaves in the transcript, `stage-work.mjs regressWork/verifyWork/appendWork` for the work records (over stamp +// `runs[]` of the real shape: `ran`, `reason: "no-files" | "reused"`), `render-cost-ledger.mjs` for `cost.json`, +// `check-cost-ledger.mjs` for its verdict, and `render-run-report.mjs` for the report — then answers the five +// questions from `cost.json` alone, and measures the added overhead. +// +// WHAT IS SYNTHETIC, stated: the transcript (one main-thread context, invented token counts), the timestamps, and the +// stamp contents. The real-script path — `stage-regress.mjs` / `stage-verify.mjs` writing these records from stamps +// they produced by spawning real gates — is exercised by the stage suites (`stage-regress.test.mjs` ★ HIT, the +// budgeted chain; `stage-verify.test.mjs` ★ EQUIVALENCE), which assert each record's counts against the processes +// their fixtures COUNTED spawning. This demo is not a live run and does not claim to be one. +// +// Usage: node .dev/features/run-performance-breakdown/demo.mjs (prints DEMO.md's body on stdout) + +import { mkdtempSync, mkdirSync, writeFileSync, appendFileSync, rmSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { performance } from "node:perf_hooks"; +import { markPhase, markerLine } from "../../../pharn/floor/mark-phase.mjs"; +import { regressWork, verifyWork, appendWork, readWork } from "../../../pharn/floor/stage-work.mjs"; +import { renderLedger, serializeLedger, table } from "../../../pharn/floor/render-cost-ledger.mjs"; +import { checkLedger } from "../../../pharn/floor/check-cost-ledger.mjs"; +import { renderRunReport } from "../../../pharn/floor/render-run-report.mjs"; +import { buildExecutions } from "../../../pharn/floor/stage-executions-core.mjs"; + +const SID = "00000000-0000-4000-8000-0000000d3e70"; +const NAME = "demo-feature"; +const T0 = Date.parse("2026-09-28T10:00:00.000Z"); +const at = (sec) => new Date(T0 + sec * 1000); + +// ── the run, stage by stage: [stage, iteration, start s, end s, requests, model, output per request] ───────────── +const STAGES = [ + ["pharn-spec", null, 5, 185, 9, "claude-opus-5-5", 900], + ["pharn-plan", null, 190, 580, 22, "claude-opus-5-5", 1400], + ["pharn-grill", null, 585, 720, 8, "claude-opus-5-5", 700], + ["pharn-test", null, 725, 960, 14, "claude-sonnet-5", 1100], + ["pharn-build", 1, 965, 1860, 41, "claude-sonnet-5", 1600], + ["pharn-regress", 1, 1865, 2320, 4, "claude-opus-5-5", 300], + ["pharn-verify", 1, 2325, 2460, 3, "claude-opus-5-5", 250], + ["pharn-build", 2, 2465, 2820, 17, "claude-sonnet-5", 1300], + ["pharn-regress", 2, 2825, 2950, 3, "claude-opus-5-5", 250], + ["pharn-verify", 2, 2955, 3030, 3, "claude-opus-5-5", 250], + ["pharn-verify", 2, 3035, 3100, 2, "claude-opus-5-5", 200], // the freshness re-run, run 2 +]; + +// ── stamp runs[] of the real shape ─────────────────────────────────────────────────────────────────────────────── +const ran = (id) => ({ id, ran: true, exit: 0 }); +const noFiles = (id) => ({ id, ran: false, reason: "no-files", exit: 0 }); +const reused = (id) => ({ id, ran: false, reason: "reused", exit: 0 }); +const HEAD = { runs: [noFiles("test"), ran("lint"), ran("typecheck"), ran("build")] }; +const BASE = { runs: [noFiles("test"), ran("lint"), ran("typecheck"), ran("build")] }; +const VERIFY_REUSING = { runs: [ran("test"), ran("lint"), reused("typecheck"), reused("build"), ran("test:e2e"), ran("reconcile")] }; +const VERIFY_FRESH = { runs: [ran("test"), ran("lint"), ran("typecheck"), ran("build"), ran("test:e2e"), ran("reconcile")] }; + +function reqLine(n, ts, model, output) { + return JSON.stringify({ + type: "assistant", + requestId: `req_demo_${String(n).padStart(4, "0")}`, + timestamp: ts, + sessionId: SID, + isSidechain: false, + version: "2.1.280", + message: { + model, + usage: { + input_tokens: 3, + cache_creation_input_tokens: 2000, + cache_read_input_tokens: 60000 + n * 50, + output_tokens: output, + cache_creation: { ephemeral_1h_input_tokens: 2000, ephemeral_5m_input_tokens: 0 }, + }, + }, + }); +} +const printed = (ts, text, n) => + JSON.stringify({ + type: "user", + sessionId: SID, + timestamp: ts, + isSidechain: false, + message: { role: "user", content: [{ type: "tool_result", tool_use_id: `toolu_demo_${n}`, content: `${text}\nexit=0` }] }, + }); + +function build(root, { withWork = true } = {}) { + const markersBase = join(root, ".pharn", "cost"); + const projectsDir = join(root, "projects"); + const transcript = join(projectsDir, "demo", `${SID}.jsonl`); + mkdirSync(join(projectsDir, "demo"), { recursive: true }); + writeFileSync(transcript, ""); + let n = 0; + const mark = (kind, sec, stage = null, iteration = null) => { + const m = markPhase({ name: NAME, kind, stage, iteration, base: markersBase, sessionId: SID, now: at(sec) }); + appendFileSync(transcript, printed(m.ts, markerLine(m), m.seq) + "\n"); + }; + mark("run-start", 0); + for (const [stage, iteration, s, e, requests, model, output] of STAGES) { + mark("stage-start", s, stage, iteration); + for (let i = 0; i < requests; i++) { + const ts = at(s + 1 + Math.floor(((e - s - 2) * i) / Math.max(1, requests))).toISOString(); + appendFileSync(transcript, reqLine(++n, ts, model, output) + "\n"); + } + if (withWork && stage === "pharn-regress") { + const hit = iteration === 2; + const rec = regressWork({ + headStamp: HEAD, + baseStamp: BASE, + baseReuse: hit ? { reused: true, miss: null } : { reused: false, miss: "no-record" }, + installResult: hit ? null : { ran: true, exit: 0, timedOut: false, ms: 94218 }, + ts: at(e - 1).toISOString(), + sessionId: SID, + }); + appendWork({ feature: NAME, record: rec, root, base: ".pharn/cost" }); + } + if (withWork && stage === "pharn-verify") { + const rerun = s === 3035; + const rec = verifyWork({ stamp: rerun ? VERIFY_FRESH : VERIFY_REUSING, ts: at(e - 1).toISOString(), sessionId: SID }); + appendWork({ feature: NAME, record: rec, root, base: ".pharn/cost" }); + } + mark("orchestrator", e); + } + mark("run-stop", 3120); + return { markersBase, projectsDir }; +} + +function emit(root, paths) { + const led = renderLedger({ name: NAME, command: "/pharn-loop", repo: root, sessionId: SID, ...paths }); + const dir = join(root, "pharn", "features", NAME); + mkdirSync(dir, { recursive: true }); + writeFileSync(join(dir, "cost.json"), serializeLedger(led)); + return led; +} + +const median = (xs) => [...xs].sort((a, b) => a - b)[Math.floor(xs.length / 2)]; +function timeIt(fn, reps = 21) { + const xs = []; + for (let i = 0; i < reps; i++) { + const t = performance.now(); + fn(); + xs.push(performance.now() - t); + } + return median(xs); +} + +const root = mkdtempSync(join(tmpdir(), "perf-demo-")); +const bare = mkdtempSync(join(tmpdir(), "perf-demo-bare-")); +try { + const paths = build(root); + const led = emit(root, paths); + const { reds, warns } = checkLedger(led); + const report = renderRunReport(NAME, { repo: root, markersBase: paths.markersBase }); + const perf = report.slice(report.indexOf("## Stage elapsed and deterministic work"), report.indexOf("## Files")); + + // ── the five questions, answered from cost.json alone ───────────────────────────────────────────────────────── + const byStage = new Map(); + for (const r of led.by_stage_iteration_model) { + const k = r.stage ?? "(unattributed)"; + const a = byStage.get(k) ?? { requests: 0, output: 0, cache_read: 0 }; + a.requests += r.requests; + a.output += r.tokens.output; + a.cache_read += r.tokens.cache_read; + byStage.set(k, a); + } + const topReq = [...byStage.entries()].sort((a, b) => b[1].requests - a[1].requests)[0]; + const topOut = [...byStage.entries()].sort((a, b) => b[1].output - a[1].output)[0]; + const measured = led.executions.rows.filter((r) => r.elapsed_ms !== null); + const longest = measured.sort((a, b) => b.elapsed_ms - a.elapsed_ms)[0]; + const elapsedByStage = new Map(); + for (const r of led.executions.rows) + if (r.elapsed_ms !== null) elapsedByStage.set(r.stage, (elapsedByStage.get(r.stage) ?? 0) + r.elapsed_ms); + const rowOf = (i) => led.executions.rows.find((r) => r.work.includes(i)); + const regress = led.work.map((w, i) => [w, rowOf(i)]).filter(([w]) => w.stage === "pharn-regress"); + const verify = led.work.map((w, i) => [w, rowOf(i)]).filter(([w]) => w.stage === "pharn-verify"); + const avoidedVerify = verify.reduce((s, [w]) => s + w.gates.reused, 0); + const avoidedBase = regress.reduce((s, [w]) => s + w.base.reused, 0); + const executed = led.work.map((w, i) => { + const r = rowOf(i); + const where = `${r.stage} iter ${r.iteration} run ${r.run}`; + if (w.stage === "pharn-verify") return `${where}: ${w.gates.executed} gate process(es)`; + return `${where}: ${w.head.executed} HEAD + ${w.base.executed} BASE gate process(es)${w.install ? `, install ${w.install.ms} ms` : ""}${w.base.evidence === "fresh" ? ", a BASE worktree" : ""}`; + }); + + // ── overhead ────────────────────────────────────────────────────────────────────────────────────────────────── + const noWork = build(bare, { withWork: false }); + const renderWith = timeIt(() => renderLedger({ name: NAME, command: "/pharn-loop", repo: root, sessionId: SID, ...paths })); + const renderWithout = timeIt(() => renderLedger({ name: NAME, command: "/pharn-loop", repo: bare, sessionId: SID, ...noWork })); + const ledPre = structuredClone(led); + delete ledPre.executions; + delete ledPre.work; + const checkWith = timeIt(() => checkLedger(led)); + const checkWithout = timeIt(() => checkLedger(ledPre)); + const bigMarkers = [{ seq: 1, kind: "run-start", stage: null, iteration: null, ts: at(0).toISOString(), session_id: SID }]; + const bigWork = []; + for (let i = 0; i < 500; i++) { + bigMarkers.push({ + seq: 2 + 2 * i, + kind: "stage-start", + stage: "pharn-verify", + iteration: 1 + (i % 50), + ts: at(10 + 4 * i).toISOString(), + session_id: SID, + }); + bigMarkers.push({ + seq: 3 + 2 * i, + kind: "orchestrator", + stage: null, + iteration: null, + ts: at(12 + 4 * i).toISOString(), + session_id: SID, + }); + bigWork.push(verifyWork({ stamp: VERIFY_REUSING, ts: at(11 + 4 * i).toISOString(), sessionId: SID })); + } + const bigView = timeIt(() => buildExecutions(bigMarkers, bigWork)); + const bigFile = join(bare, "big-work.jsonl"); + writeFileSync(bigFile, bigWork.map((w) => JSON.stringify(w)).join("\n") + "\n"); + const bigRead = timeIt(() => readWork(bigFile)); + const appendOne = timeIt(() => appendWork({ feature: "bench", record: bigWork[0], root: bare, base: ".pharn/cost" }), 201); + const bytes = Buffer.byteLength(serializeLedger(led)); + const bytesPre = Buffer.byteLength(serializeLedger({ ...ledPre, dropped: led.dropped })); + const linesAdded = serializeLedger(led).split("\n").length - serializeLedger(ledPre).split("\n").length; + + const ms = (x) => `${x.toFixed(2)} ms`; + const out = [ + "# DEMO — run-performance-breakdown (6.35.0), a controlled end-to-end fixture", + "", + "Produced by `node .dev/features/run-performance-breakdown/demo.mjs` (apparatus). A two-iteration", + "`/pharn-loop`-shaped run built from the REAL marker writer, work-record writer, ledger emitter, checker and run", + "report. **Synthetic, stated:** the transcript (one main-thread context, invented token counts), the timestamps and", + "the stamp contents. The real stage scripts writing these records from gates they actually spawned are exercised by", + "`stage-regress.test.mjs` (★ HIT, the budgeted chain) and `stage-verify.test.mjs` (★ EQUIVALENCE, OBSERVATIONAL).", + "", + `check-cost-ledger: ${reds.length === 0 ? "GREEN" : `RED ${JSON.stringify(reds)}`} (${warns.length} warn(s))`, + "", + "## The stop's screen table (`table()`)", + "", + "```text", + table(led), + "```", + "", + "## The run report's new section (`RUN-REPORT.md`)", + "", + perf.trim(), + "", + "## The five questions, answered from `cost.json` alone", + "", + `1. **Most model usage:** by requests, \`${topReq[0]}\` (${topReq[1].requests} requests); by output tokens, \`${topOut[0]}\` (${topOut[1].output} output tokens, ${topOut[1].cache_read} cache-read). Source: \`by_stage_iteration_model\`, summed over iterations and models.`, + `2. **Longest observed interval:** \`${longest.stage}\` iteration ${longest.iteration} run ${longest.run}, ${longest.elapsed_ms} ms. Summed over its executions, the stage with the most observed wall clock is \`${[...elapsedByStage.entries()].sort((a, b) => b[1] - a[1])[0][0]}\`. Source: \`executions.rows\` (wall clock between markers — not model, tool or CPU time).`, + `3. **BASE regression work reused?** ${regress.map(([w, r]) => `iteration ${r.iteration}: ${w.base.evidence === "reused" ? "yes — no worktree, no install, 0 BASE gate processes" : `no (\`${w.base.miss}\`) — worktree created, install ran (${w.install.ms} ms), ${w.base.executed} BASE gate processes`}`).join("; ")}. Source: \`work[]\`, \`base.evidence\`.`, + `4. **VERIFY gate processes avoided:** ${avoidedVerify} across ${verify.length} verify executions (${verify.map(([w, r]) => `iter ${r.iteration} run ${r.run}: ${w.gates.reused} of ${w.gates.required}`).join(", ")}); plus ${avoidedBase} BASE gate results taken from earlier evidence. Source: \`work[].gates.reused\`, \`work[].base.reused\`.`, + `5. **Expensive deterministic work that still executed:** ${executed.join("; ")}.`, + "", + "## Added overhead (median of 21 runs; 201 for the append)", + "", + "| measured | value |", + "| --- | --- |", + `| \`renderLedger\` on this run, with vs without \`work.jsonl\` | ${ms(renderWith)} vs ${ms(renderWithout)} |`, + `| \`checkLedger\` on this ledger, with vs without the two keys | ${ms(checkWith)} vs ${ms(checkWithout)} |`, + `| \`buildExecutions\` over 1,001 markers and 500 work records | ${ms(bigView)} |`, + `| \`readWork\` over 500 records | ${ms(bigRead)} |`, + `| one \`appendWork\` (the stage scripts' only added I/O) | ${ms(appendOne)} |`, + `| \`cost.json\` size, with vs without the two keys | ${bytes} vs ${bytesPre} bytes, +${linesAdded} lines |`, + "", + "Structural bound, independent of this machine: the emitter reads ONE extra small file per emission, makes no", + "extra transcript pass, spawns no process and calls no model; the view is one pass over the current run's markers", + "plus one latest-marker search per work record; each stage script adds one `JSON.stringify` + one append at `done`,", + "and regress one `performance.now()` pair around its install.", + "", + ]; + process.stdout.write(out.join("\n")); +} finally { + rmSync(root, { recursive: true, force: true }); + rmSync(bare, { recursive: true, force: true }); +} diff --git a/.dev/features/run-performance-breakdown/regression-report.json b/.dev/features/run-performance-breakdown/regression-report.json new file mode 100644 index 00000000..e51b7063 --- /dev/null +++ b/.dev/features/run-performance-breakdown/regression-report.json @@ -0,0 +1,48 @@ +{ + "base": "1f6e2d610b1141ca59b02b84b2a1c798946f1d29", + "inside": [ + ".dev/features/run-performance-breakdown/DEMO.md", + ".dev/features/run-performance-breakdown/GRILL.md", + ".dev/features/run-performance-breakdown/PLAN.md", + ".dev/features/run-performance-breakdown/REGRESSION.md", + ".dev/features/run-performance-breakdown/demo.mjs", + ".dev/features/run-performance-breakdown/regression-report.json", + "CHANGELOG.md", + "CLAUDE.md", + "README.md", + "SKILLS_VERSION", + "pharn/floor/check-cost-ledger.mjs", + "pharn/floor/check-cost-ledger.test.mjs", + "pharn/floor/render-cost-ledger.mjs", + "pharn/floor/render-cost-ledger.test.mjs", + "pharn/floor/render-run-report.mjs", + "pharn/floor/render-run-report.test.mjs", + "pharn/floor/stage-executions-core.mjs", + "pharn/floor/stage-executions-core.test.mjs", + "pharn/floor/stage-regress-core.mjs", + "pharn/floor/stage-regress.mjs", + "pharn/floor/stage-regress.test.mjs", + "pharn/floor/stage-verify.mjs", + "pharn/floor/stage-verify.test.mjs", + "pharn/floor/stage-work.mjs", + "pharn/floor/stage-work.test.mjs", + "pharn/pharn-contracts/cost-ledger.md" + ], + "outside_gates": { + "structural:pharn/pharn-review/trust-fence/evals/expected/expected-injection-comment.json": { + "base": 0, + "head": 0 + }, + "tests": { + "base": 0, + "head": 0 + }, + "validate": { + "base": 0, + "head": 0 + } + }, + "regressions": [], + "pre_existing": [], + "verdict": "no-regressions" +} diff --git a/.dev/features/run-performance-breakdown/verify-report.json b/.dev/features/run-performance-breakdown/verify-report.json new file mode 100644 index 00000000..9c90040c --- /dev/null +++ b/.dev/features/run-performance-breakdown/verify-report.json @@ -0,0 +1,16 @@ +{ + "feature": "run-performance-breakdown", + "gates": { + "format:check": 0, + "lint": 0, + "lint:md": 1, + "reconcile": 0, + "structural:pharn/pharn-review/trust-fence/evals/expected/expected-injection-comment.json": 0, + "test": 0, + "validate": 0 + }, + "verdict": "FAIL", + "failing_gates": [ + "lint:md" + ] +} diff --git a/.dev/memory-bank/lessons-learned.md b/.dev/memory-bank/lessons-learned.md index 5d75bd91..fe0dde1a 100644 --- a/.dev/memory-bank/lessons-learned.md +++ b/.dev/memory-bank/lessons-learned.md @@ -2244,3 +2244,18 @@ type: floor · concepts: [pinned-record, writes-scope, agreement, self-certifica - commit: `70cb51c8f3f7c1a3405b651106bc35f244948da9` (working-tree build on this commit; uncommitted at promotion time) - source: `.dev/features/ac-gate-plan-scope/REVIEW.md` LC1 - promoted: 2026-09-27 via gated `/pharn-dev-memory-promote` (accept delegated by the maintainer to the orchestrating model). + +## L66 — A wait on a result file in shared scratch is satisfied by another session's stale file — capture into a directory the run creates empty, and read only after the writer has exited + +type: tooling · concepts: [input-capture, shared-state, temporal-state, false-green, lesson-recurrence] + +**Lesson.** A wait such as `until [ -f .pharn//x.json ]` is a presence test on a path several sessions share. In run-performance-breakdown it passed at once on base/head maps an earlier session had left in `.pharn/pharn-dev-regress/`, the regress verdict was computed over them (void: it measured nothing of this build), and the base worktree was removed while this run's own base side was still executing. The same stale `results.json` appeared at verify and was caught before use. [[L5]] and [[L21]] bound WHAT is captured; this is WHOSE capture is read. Remedy: capture into a directory the run creates empty (a run-private path under `.pharn//`), and read results only after the background process that writes them has exited (its completion notice or an exit marker it prints last), never on a file's existence. + +**Why it matters.** The stale verdict read `no-regressions` — a false green indistinguishable from a real one, reached by a correctly pinned checker over the wrong inputs. **Bound (P0):** discipline, not a floor check — nothing can tell an old file from a new one by its path. **Trigger (P7):** observed once in this run and caught by the orchestrator before the verdict was used; promoted at the maintainer's choice at the ship-stage lesson gate. + +**Provenance.** + +- feature: `run-performance-breakdown` +- commit: `1f6e2d610b1141ca59b02b84b2a1c798946f1d29` (working-tree build on this commit; uncommitted at promotion time) +- source: `.dev/features/run-performance-breakdown/REVIEW.md` § Proposed lesson candidate + `REGRESSION.md` § A void first run +- promoted: 2026-09-28 via gated `/pharn-dev-memory-promote` (human-approved). diff --git a/CHANGELOG.md b/CHANGELOG.md index 92a2a0eb..9ba48fa2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -23,6 +23,51 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), `npm run check:changelog` holds this file's shape; the CI step "CHANGELOG per-PR entry check" holds each PR's diff. Details and known costs: CONTRIBUTING.md, "CHANGELOG entries". --> +## [6.35.0] - 2026-09-28 + +### Added + +- 2026-09-28: **One `/pharn-loop` or `/pharn-ship` run's `cost.json` now shows, beside its unchanged model usage, the + observed wall-clock interval of every stage execution and the deterministic gate work each `/pharn-regress` and + `/pharn-verify` execution ran or took from reused evidence** — two additive keys, `executions` and `work` + ([`pharn/floor/stage-executions-core.mjs`](./pharn/floor/stage-executions-core.mjs), + [`pharn/floor/stage-work.mjs`](./pharn/floor/stage-work.mjs), + [`pharn/floor/render-cost-ledger.mjs`](./pharn/floor/render-cost-ledger.mjs), + [`pharn/floor/check-cost-ledger.mjs`](./pharn/floor/check-cost-ledger.mjs), + [`pharn/floor/render-run-report.mjs`](./pharn/floor/render-run-report.mjs); contract + [`cost-ledger.md`](./pharn/pharn-contracts/cost-ledger.md), "Stage executions and deterministic work"). + `SKILLS_VERSION` 6.34.0 → 6.35.0 (minor: a newly shipped floor capability), with the README badge. `MIN_CLI` stays + 0.5.0: no installed path moves. **No schema bump:** `pharn-cost-ledger/2` gains two keys and no existing field + changes meaning; the checker admits exactly the current key set or the pre-6.35.0 one, so older ledgers stay GREEN. + - **The trigger.** The maintainer's explicit direction ("PR 4: Run Performance Breakdown"), after 6.33.0 (BASE + evidence reuse) and 6.34.0 (HEAD → VERIFY gate reuse): both reports that say what was reused are overwritten every + iteration, so for every iteration but the last the savings were invisible after the run. + - **`executions` is a VIEW, derived with no new instrumentation** (method `stage-start-to-return/1`): every + `stage-start` marker of the current run is one row, ended only by the NEXT marker when that is the orchestrator's + return. A re-run is `run 2`, never merged; any other pairing is unmeasured with a closed reason and + `elapsed_ms: null` — never 0, and never the next stage-start or run-stop used as an end (a return AND a start both + skipped around a stage that writes no work record is the one case the markers cannot tell, and the contract says + so). Labelled wherever it appears as observed wall clock between two + processes' timestamps: not CPU, model or tool time, not monotonic. `mark-phase.mjs` and its printed binding line + are unchanged, and so is every request's stage attribution (a ✧ test pins both). + - **`work[]` is FACTS captured at the moment** (`pharn-stage-work/1`): at its `done` exit each regress/verify + execution appends one line to `.pharn/cost//work.jsonl`, counted from the gate-run stamp its verdict just + used — processes executed, results reused, nothing-to-run, required; regress adds whether BASE evidence was + `fresh` or `reused` (the worktree and install follow from it and are not stored twice) and the install's exit and + `ms`, the ONE new timer (`performance.now()` around the install process). The append is observational and + best-effort: it refuses a symlinked component, never blocks on a planted FIFO (`O_NONBLOCK` — the GATE-2 review + reproduced the hang), never throws, and a failure changes no exit, verdict, reuse, route or commit (a test runs a + verify with a planted link and compares its parsed exit document with the control's). + - **The checker (rule 9)** validates every `work[]` row and its window membership and recomputes `executions` from + the file's own `markers[]` and `work[]`; an edited interval, run number, pairing or work index is RED. + `--verify-transcript` is unchanged. The run report gains `## Stage elapsed and deterministic work`, copied from the + stored views; the stop's `table()` prints the same three blocks, kept apart. + - **Measured** (`.dev/features/run-performance-breakdown/DEMO.md`, a controlled fixture): the emitter and checker + gain under 1 ms on a 126-request run, one small file read, no transcript pass, no process, no model call. + - **Named residuals:** `gate-process-duration` (no per-gate timer), `ship-spec-elapsed` (`/pharn-ship` marks no spec + stage-start, and adding one would change stage attribution), `work-on-non-done-exit` (a stage that ran gates then + refused records none), `work-record-provenance` (a Bash writer can forge `work.jsonl`, as `markers.jsonl` today). + ## [6.34.0] - 2026-09-28 ### Changed diff --git a/CLAUDE.md b/CLAUDE.md index 72369844..4205e4a6 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -920,6 +920,18 @@ node pharn/floor/check-loop-decision.mjs # `run-window/1` ledgers keep their seven keys and a not-context-scoped WARN; --verify-transcript REDs one holding # other contexts' rows. ADVISORY: the transcript layout (undocumented, machine-local) and that the marker output # reached the calling context's own tool result — the contract's "Run membership" carries the bounds. +# STAGE ELAPSED AND DETERMINISTIC WORK (6.35.0, run-performance-breakdown) — two additive `/2` keys, no schema bump. +# `executions` is a VIEW over markers[] (pharn/floor/stage-executions-core.mjs, method `stage-start-to-return/1`): each +# current-run stage-start is one row, ended ONLY by the next marker when it is the orchestrator return; a re-run is +# `run 2`, never merged; anything else is unmeasured with a closed reason and `elapsed_ms: null` (never 0, never a +# guessed end). OBSERVED WALL CLOCK between two processes' toISOString() reads — not CPU/model/tool time, not +# monotonic, never decomposed. mark-phase.mjs and its printed binding line are UNCHANGED. `work[]` is FACTS: at `done` +# stage-regress.mjs / stage-verify.mjs append one `pharn-stage-work/1` line to `.pharn/cost//work.jsonl` +# (pharn/floor/stage-work.mjs, the one owner), counted from the stamp the verdict used — executed / reused / no_files / +# required, BASE `fresh|reused`, the install's exit and ms (the ONE new timer). Best-effort and OBSERVATIONAL (no +# exit, verdict, reuse, route or commit reads it); only a `done` exit writes one. check-cost-ledger rule 9 validates +# the rows and recomputes `executions`; /2 admits exactly the current key set or the pre-6.35.0 one. Contract: +# cost-ledger.md "Stage executions and deterministic work". # Exit: mark-phase 0 ok · 2 bad usage (nothing written) | render 0 (incl. an honest `unavailable`) · 2 bad # usage | check 0 GREEN (WARNs possible) · 1 RED · 2 unusable input. node pharn/floor/mark-phase.mjs --name --kind [--stage ] [--iteration ] [--base ] [--mode ] [--route ] diff --git a/README.md b/README.md index 683bfe1b..f06fc419 100644 --- a/README.md +++ b/README.md @@ -21,7 +21,7 @@ model or human judgment remains advisory. npx @pharn-dev/pharn@latest init ``` -[![pharn](https://img.shields.io/badge/pharn-6.34.0-blue)](./CHANGELOG.md) +[![pharn](https://img.shields.io/badge/pharn-6.35.0-blue)](./CHANGELOG.md) [![License: Apache 2.0](https://img.shields.io/badge/license-Apache%202.0-green)](./LICENSE) [![CI](https://github.com/pharn-dev/pharn-oss/actions/workflows/ci.yml/badge.svg)](https://github.com/pharn-dev/pharn-oss/actions/workflows/ci.yml) [![CodeQL](https://github.com/pharn-dev/pharn-oss/actions/workflows/codeql.yml/badge.svg)](https://github.com/pharn-dev/pharn-oss/actions/workflows/codeql.yml) @@ -687,7 +687,7 @@ byte-for-byte by `npm run docs:check`, so it cannot quietly drift from what is a - **Product commands — 11** (`.claude/commands/`): `/pharn-build`, `/pharn-grill`, `/pharn-loop`, `/pharn-memory-promote`, `/pharn-plan`, `/pharn-regress`, `/pharn-review`, `/pharn-ship`, `/pharn-spec`, `/pharn-test`, `/pharn-verify`. - **Dev-apparatus commands — 9** (`.claude/commands/`): `/pharn-dev-build`, `/pharn-dev-eval`, `/pharn-dev-grill`, `/pharn-dev-memory-promote`, `/pharn-dev-plan`, `/pharn-dev-regress`, `/pharn-dev-review`, `/pharn-dev-ship`, `/pharn-dev-verify`. - **Hook scripts — 4** (`.claude/hooks/`): `enforce-writes-scope.cjs`, `protect-trusted-paths.cjs`, `require-loop-record.cjs`, `set-writes-scope.cjs`. -- **Floor checkers — 105** `.mjs` files under `pharn/floor/` (tests excluded). +- **Floor checkers — 107** `.mjs` files under `pharn/floor/` (tests excluded). diff --git a/SKILLS_VERSION b/SKILLS_VERSION index 802173f0..b22907d0 100644 --- a/SKILLS_VERSION +++ b/SKILLS_VERSION @@ -1 +1 @@ -6.34.0 +6.35.0 diff --git a/docs/lessons-index.md b/docs/lessons-index.md index 4e868fbd..e3809cc4 100644 --- a/docs/lessons-index.md +++ b/docs/lessons-index.md @@ -10,7 +10,7 @@ lessons to fetch; canon stays the source of truth and the floor's verification t applied, without fetching its full `## L` entry from canon, is the P0 disease. "The index was consulted" never means "the relevant lessons were read". -65 lessons · 65 tagged · 0 malformed · 0 untagged · ~47557 tokens total +66 lessons · 66 tagged · 0 malformed · 0 untagged · ~48047 tokens total Columns: `id | type | concepts | title | promoted | ~tokens`. `-` is rendered in THREE columns and does NOT mean the same thing in each — read it against the column it sits in. In `type`/`concepts`: @@ -89,4 +89,5 @@ L62 | floor | refusal-path,untrusted-input,total-function,crash-as-verdict,fa L63 | floor | temporal-state,referent-binding,append-only,derivation-change,lesson-recurrence | A change to how a recorded value is DERIVED can move it into the still-growing part of its referent — L58 recurred through a checker the change left untouched | 2026-09-26 | ~992 L64 | contract | universal-quantifier,doc-drift,guarantee-audit,restatement | A bound's RESTATEMENT re-derives its quantifier — L37 recurred in the release note and a sibling contract, while the primary sentences it was applied to held | 2026-09-27 | ~803 L65 | floor | pinned-record,writes-scope,agreement,self-certification | A pin is only as strong as the scope around its record — a stage allowed to write the record a later gate compares it against certifies itself | 2026-09-27 | ~623 +L66 | tooling | input-capture,shared-state,temporal-state,false-green,lesson-recurrence | A wait on a result file in shared scratch is satisfied by another session's stale file — capture into a directory the run creates empty, and read only after the writer has exited | 2026-09-28 | ~490 ``` diff --git a/pharn/floor/check-cost-ledger.mjs b/pharn/floor/check-cost-ledger.mjs index 551a4c2b..f48dc0e7 100644 --- a/pharn/floor/check-cost-ledger.mjs +++ b/pharn/floor/check-cost-ledger.mjs @@ -161,6 +161,8 @@ import { COVERAGE, TOKEN_CLASSES, TOP_LEVEL_KEYS, + TOP_LEVEL_KEYS_PRE_WORK, + WORK_KEYS, SKILLS_VERSION_SOURCES, ATTRIBUTION_METHOD, OUTCOME_SOURCES, @@ -187,6 +189,8 @@ import { import { ABS_PATH_RE, IDENTITY_MAX, isIdentityToken, isTokenCount } from "./cost-value-core.mjs"; import { shown } from "./quote-core.mjs"; import { FEATURE_SLUG_RE } from "./gate-run-core.mjs"; +import { validateWork } from "./stage-work.mjs"; +import { buildExecutions } from "./stage-executions-core.mjs"; const reds = []; const warns = []; @@ -327,7 +331,10 @@ export function checkLedger(led, opts = {}) { // ---- RULE 1: the closed top-level key set, BOTH directions ----------------------------------- const present = new Set(Object.keys(led)); - const expected = new Set(legacy ? TOP_LEVEL_KEYS_V1 : TOP_LEVEL_KEYS); + // `/2` admits EXACTLY two key sets (6.35.0): the current one, or the pre-6.35.0 one with neither `WORK_KEYS` member. + // One of the two new keys without the other is held to the current set, so the absent one reads as missing (L36). + const hasWork = WORK_KEYS.some((k) => present.has(k)); + const expected = new Set(legacy ? TOP_LEVEL_KEYS_V1 : hasWork ? TOP_LEVEL_KEYS : TOP_LEVEL_KEYS_PRE_WORK); const extra = [...present].filter((k) => !expected.has(k)).sort(); const missing = [...expected].filter((k) => !present.has(k)).sort(); if (extra.length) red(`top-level key set is not closed — unexpected key(s): ${listText(extra, keyText)}`); @@ -570,6 +577,9 @@ export function checkLedger(led, opts = {}) { // ---- RULE 8 (`/2`): membership shape, re-derivation, and every row inside the window ---------- if (!legacy) checkMembership(led); + // ---- RULE 9 (6.35.0): the work facts and the executions view ---------------------------------- + if (!legacy && hasWork) checkWorkAndExecutions(led); + // ---- WARN (never RED): marker completeness ---------------------------------------------------- if (Array.isArray(led.markers) && led.outcome && Number.isInteger(led.outcome.iterations)) { const stageStarts = led.markers.filter((m) => m?.kind === "stage-start"); @@ -896,6 +906,51 @@ function checkMembership(led) { } } +/** + * RULE 9 (6.35.0, `cost-ledger.md` "Stage executions and deterministic work"). `work[]` rows are FACTS: each must pass + * `stage-work.mjs validateWork` (closed keys, enums, the count invariant) and be a MEMBER of the run window recomputed + * from the file's own `markers[]` for `membership.session` — the test every request row passes; an unknown window + * admits none. `executions` is a VIEW: it must equal `buildExecutions` recomputed from the file's own `markers[]` and + * `work[]`, so an edited elapsed value, run number, pairing or work index is RED. BOUND ([[L43]]): agreement between + * the file's facts and its view, never that the markers or the records describe what really ran. + */ +function checkWorkAndExecutions(led) { + if (!Array.isArray(led.work)) { + red("work must be an array"); + return; + } + const markers = normalizeMarkers(Array.isArray(led.markers) ? led.markers : []); + const session = isPlainObject(led.membership) ? (led.membership.session ?? null) : null; + const win = runWindow(markers, typeof session === "string" ? session : null); + const invalid = []; + const outside = []; + led.work.forEach((w, i) => { + if (!validateWork(w).ok) invalid.push(i); + else if (!isMember(win, w.ts, w.session_id)) outside.push(i); + }); + if (invalid.length) red(`work[] holds ${invalid.length} row(s) that are not valid work records, at index ${listText(invalid, String)}`); + if (outside.length) red(`work[] holds ${outside.length} row(s) OUTSIDE the recorded run window, at index ${listText(outside, String)}`); + if (invalid.length) return; // the view cannot be recomputed over rows the rule refused + const expected = buildExecutions(markers, led.work); + if (!sameValue(led.executions, expected, 0)) { + red( + `executions disagrees with a recompute from markers[] and work[] (method ${valText(expected.method)}, ${expected.rows.length} row(s) recomputed) — the elapsed view is a function of the file's own facts` + ); + } +} + +/** Structural equality over parsed JSON, total and bounded in depth (never JSON.stringify — see RULE 6's note). */ +function sameValue(a, b, depth) { + if (depth > 8) return false; + if (a === b) return true; + if (a === null || b === null || typeof a !== "object" || typeof b !== "object") return false; + if (Array.isArray(a) !== Array.isArray(b)) return false; + if (Array.isArray(a)) return a.length === b.length && a.every((v, i) => sameValue(v, b[i], depth + 1)); + const ka = Object.keys(a); + const kb = Object.keys(b); + return ka.length === kb.length && ka.every((k) => Object.hasOwn(b, k) && sameValue(a[k], b[k], depth + 1)); +} + /** * RULE 8's context fields under `run-window/2`. A MEASURED ledger (a known window, `coverage: partial`) must carry * the bound `context` and a non-empty, sorted, duplicate-free `contexts` of context keys that includes it; every other diff --git a/pharn/floor/check-cost-ledger.test.mjs b/pharn/floor/check-cost-ledger.test.mjs index b7cabd3e..8326b51f 100644 --- a/pharn/floor/check-cost-ledger.test.mjs +++ b/pharn/floor/check-cost-ledger.test.mjs @@ -739,6 +739,9 @@ test("COMPATIBILITY — a legacy /1 ledger is GREEN under its own rules, WARNed const v1 = clone(led); v1.schema = LEGACY_SCHEMA; delete v1.membership; + // A /1 ledger predates the 6.35.0 keys too. + delete v1.executions; + delete v1.work; v1.requests.unshift({ ...clone(v1.requests[0]), request_id: "before", @@ -1582,3 +1585,123 @@ test("--verify-transcript ctx — GROWTH CLOSURE (L58, L63): every kind of line assert.deepEqual(reds, [], `${label}: ${reds.join(" | ")}`); } }); + +// ── RULE 9 (6.35.0): the work facts and the executions view ────────────────────────────────────────────────────── + +import { TOP_LEVEL_KEYS_PRE_WORK, WORK_KEYS } from "./render-cost-ledger.mjs"; + +/** The run fixture above, with its stages bracketed and two work records (fresh BASE regress, partially reused verify). */ +function perfFixture() { + const root = mkdtempSync(join(tmpdir(), "check-cl-perf-")); + const proj = join(root, "projects", "p"); + mkdirSync(proj, { recursive: true }); + writeFileSync(join(proj, `${RS}.jsonl`), [recLine("during", "2026-09-21T10:05:00.000Z", 10)].join("\n") + "\n"); + const mdir = join(root, "cost", "feat"); + mkdirSync(mdir, { recursive: true }); + const mk = (seq, kind, stage, iteration, ts) => ({ seq, kind, stage, iteration, ts, session_id: RS }); + writeFileSync( + join(mdir, "markers.jsonl"), + [ + mk(1, "run-start", null, null, "2026-09-21T10:00:00.000Z"), + mk(2, "stage-start", "pharn-regress", 1, "2026-09-21T10:01:00.000Z"), + mk(3, "orchestrator", null, null, "2026-09-21T10:04:00.000Z"), + mk(4, "stage-start", "pharn-verify", 1, "2026-09-21T10:04:10.000Z"), + mk(5, "orchestrator", null, null, "2026-09-21T10:06:00.000Z"), + mk(6, "run-stop", null, null, "2026-09-21T10:30:00.000Z"), + ] + .map((m) => JSON.stringify(m)) + .join("\n") + "\n" + ); + writeFileSync( + join(mdir, "work.jsonl"), + [ + { + schema: "pharn-stage-work/1", + stage: "pharn-regress", + ts: "2026-09-21T10:03:59.000Z", + session_id: RS, + head: { required: 2, executed: 2, reused: 0, no_files: 0 }, + base: { evidence: "fresh", miss: "no-record", required: 2, executed: 2, reused: 0, no_files: 0 }, + install: { exit: 0, timed_out: false, ms: 5000 }, + }, + { + schema: "pharn-stage-work/1", + stage: "pharn-verify", + ts: "2026-09-21T10:05:59.000Z", + session_id: RS, + gates: { required: 3, executed: 2, reused: 1, no_files: 0 }, + }, + ] + .map((w) => JSON.stringify(w)) + .join("\n") + "\n" + ); + const led = renderLedger({ name: "feat", sessionId: RS, projectsDir: join(root, "projects"), markersBase: join(root, "cost") }); + return { led }; +} + +test("RULE 9 — a ledger with executions and work is GREEN, and its view is the recompute", () => { + const { led } = perfFixture(); + assert.equal(led.work.length, 2, "non-vacuity: both records are rows"); + assert.deepEqual( + led.executions.rows.map((r) => [r.stage, r.elapsed_ms, r.work]), + [ + ["pharn-regress", 180000, [0]], + ["pharn-verify", 110000, [1]], + ] + ); + assert.deepEqual(redsOf(led), []); +}); + +test("RULE 9 — an edited view is RED: elapsed, run number, pairing, work index, method, status", () => { + const { led } = perfFixture(); + const mutants = [ + (l) => (l.executions.rows[0].elapsed_ms = 1), + (l) => (l.executions.rows[0].elapsed_ms = null), + (l) => (l.executions.rows[1].run = 2), + (l) => (l.executions.rows[0].end_seq = 6), + (l) => (l.executions.rows[0].work = []), + (l) => (l.executions.rows[1].work = [0, 1]), + (l) => (l.executions.rows[0].unmeasured = "no-end-marker"), + (l) => l.executions.rows.pop(), + (l) => (l.executions.method = "guess/1"), + (l) => (l.executions.status = "unknown"), + (l) => (l.executions.rows[0].extra = 1), + ]; + for (const [i, f] of mutants.entries()) { + const bad = clone(led); + f(bad); + assert.ok( + redsOf(bad).some((r) => /executions disagrees with a recompute/.test(r)), + `mutant ${i} must be RED` + ); + } +}); + +test("RULE 9 — a work row that is not a valid record, or lies outside the window, is RED", () => { + const { led } = perfFixture(); + const broken = clone(led); + broken.work[1].gates.executed = 3; // executed + reused + no_files !== required + assert.ok(redsOf(broken).some((r) => /work\[\] holds 1 row\(s\) that are not valid work records, at index 1/.test(r))); + const outside = clone(led); + outside.work[0].ts = "2026-09-21T11:00:00.000Z"; + assert.ok(redsOf(outside).some((r) => /OUTSIDE the recorded run window, at index 0/.test(r))); + const notArray = clone(led); + notArray.work = {}; + assert.ok(redsOf(notArray).some((r) => /work must be an array/.test(r))); +}); + +test("RULE 9 / L36 — /2 admits exactly two key sets: both 6.35.0 keys, or neither (a pre-6.35.0 ledger stays GREEN)", () => { + const { led } = perfFixture(); + assert.deepEqual([...WORK_KEYS], ["executions", "work"]); + assert.deepEqual([...TOP_LEVEL_KEYS_PRE_WORK].sort(), TOP_LEVEL_KEYS.filter((k) => k !== "executions" && k !== "work").sort()); + const pre = clone(led); + delete pre.executions; + delete pre.work; + assert.deepEqual(redsOf(pre), [], "a ledger written before 6.35.0 is not retroactively REDed"); + const half = clone(led); + delete half.work; + assert.ok(redsOf(half).some((r) => /missing key\(s\): work/.test(r))); + const otherHalf = clone(led); + delete otherHalf.executions; + assert.ok(redsOf(otherHalf).some((r) => /missing key\(s\): executions/.test(r))); +}); diff --git a/pharn/floor/render-cost-ledger.mjs b/pharn/floor/render-cost-ledger.mjs index 24cec6ac..4dfa6325 100644 --- a/pharn/floor/render-cost-ledger.mjs +++ b/pharn/floor/render-cost-ledger.mjs @@ -151,8 +151,11 @@ import { MAIN_CONTEXT, MEMBERSHIP_METHOD, UNKNOWN_REASONS, + CONTEXT_REASONS, } from "./run-window-core.mjs"; import { ABS_PATH_RE, isIdentityToken, isTokenCount } from "./cost-value-core.mjs"; +import { readWork, WORK_FILE } from "./stage-work.mjs"; +import { buildExecutions, unattachedWork } from "./stage-executions-core.mjs"; /** What this emitter writes. `/2` adds the `membership` block and scopes every row to the run window. */ export const SCHEMA = "pharn-cost-ledger/2"; @@ -236,10 +239,22 @@ export const TOP_LEVEL_KEYS = Object.freeze([ "unattributed", "dropped", "membership", + "executions", + "work", ]); -/** The `/1` key set — `TOP_LEVEL_KEYS` minus `membership`, DERIVED rather than re-listed (L35). */ -export const TOP_LEVEL_KEYS_V1 = Object.freeze(TOP_LEVEL_KEYS.filter((k) => k !== "membership")); +/** The two keys added in 6.35.0 (run-performance-breakdown): the `executions` VIEW over `markers[]` + `work[]`, and the + * `work[]` FACTS the regress/verify stage scripts record at `done`. See the contract's "Stage executions and + * deterministic work". Every ledger this emitter writes carries both. */ +export const WORK_KEYS = Object.freeze(["executions", "work"]); + +/** A `/2` ledger written BEFORE 6.35.0 — `TOP_LEVEL_KEYS` minus `WORK_KEYS`, DERIVED rather than re-listed (L35). The + * checker accepts exactly this set or exactly `TOP_LEVEL_KEYS` for `/2`: both new keys, or neither (L36). */ +export const TOP_LEVEL_KEYS_PRE_WORK = Object.freeze(TOP_LEVEL_KEYS.filter((k) => !WORK_KEYS.includes(k))); + +/** The `/1` key set — `TOP_LEVEL_KEYS` minus `membership` and the 6.35.0 keys (a `/1` ledger predates both), DERIVED + * rather than re-listed (L35). */ +export const TOP_LEVEL_KEYS_V1 = Object.freeze(TOP_LEVEL_KEYS_PRE_WORK.filter((k) => k !== "membership")); /** `membership`'s CLOSED key set under `run-window/2` (L36). `session` is the SELECTED session the window was * computed for, so the checker can recompute the same window from `markers[]` alone. `excluded_requests` counts @@ -645,10 +660,38 @@ export function renderLedger(opts) { */ export function deriveLedger(opts) { const stats = { excludedAfterWindow: 0 }; - const ledger = buildLedger(opts, stats); + const ledger = withWork(buildLedger(opts, stats), opts); return { ledger, excludedAfterWindow: stats.excludedAfterWindow }; } +/** + * Append the 6.35.0 keys to a built ledger — on EVERY path, the unavailable and context-unknown shells included, + * because timing needs only markers: a run whose transcript is gone still has its stage intervals. + * + * `work[]` = the valid records of `//work.jsonl` (`stage-work.mjs readWork`) that are MEMBERS of the + * run window computed over the ledger's OWN `markers[]` for the selected session — `isMember`, the test every request + * row passes; an unknown window admits none. A line that fails validation is not a row: its index joins `dropped[]` as + * `work[]`. `executions` is `buildExecutions(markers, work)`, which `check-cost-ledger.mjs` recomputes from the file. + * Nothing here reads the transcript, and nothing above is changed: every existing key keeps its value. + */ +function withWork(ledger, { name, sessionId, markersBase = MARKERS_DEFAULT_BASE, markers: suppliedMarkers, work: suppliedWork }) { + // A re-derivation under a RECORDED boundary (`check-cost-ledger.mjs --verify-transcript` passes the ledger's own + // `markers[]`) never reads the live work file: that check compares neither 6.35.0 key, and the live file is still + // growing (L58). It uses the records it is handed, or none. + const { records, dropped } = + suppliedMarkers !== undefined + ? { records: Array.isArray(suppliedWork) ? suppliedWork : [], dropped: [] } + : readWork(join(markersBase, name, WORK_FILE)); + const win = runWindow(ledger.markers, sessionId ?? null); + const work = records.filter((w) => isMember(win, w.ts, w.session_id)); + return { + ...ledger, + dropped: dropped.length ? [...ledger.dropped, ...dropped] : ledger.dropped, + executions: buildExecutions(ledger.markers, work), + work, + }; +} + function buildLedger( { name, @@ -930,7 +973,11 @@ export function buildViews(requests) { /** The two FACT arrays (the contract's "record facts, derive views"), written one element per line. Every * other value in the file is a derived view or scalar metadata and stays pretty-printed. */ -export const ROW_ARRAYS = Object.freeze(["markers", "requests"]); +export const ROW_ARRAYS = Object.freeze(["markers", "requests", "work"]); + +/** A derived view whose `rows` are written one per line too (6.35.0), so a many-iteration run's elapsed view costs a + * line per execution in a diff, not a dozen. */ +export const NESTED_ROW_ARRAYS = Object.freeze({ executions: "rows" }); /** * THE ONE serialization of a ledger, used by BOTH CLI output paths (the file write and `--stdout`). @@ -959,9 +1006,25 @@ export function serializeLedger(ledger) { const value = ledger[key]; if (value === undefined || typeof value === "function" || typeof value === "symbol") continue; let body; + const nested = Object.hasOwn(NESTED_ROW_ARRAYS, key) ? NESTED_ROW_ARRAYS[key] : null; if (ROW_ARRAYS.includes(key) && Array.isArray(value) && value.length > 0) { const rows = value.map((el, i) => ` ${JSON.stringify(el) ?? "null"}${i < value.length - 1 ? "," : ""}`); body = `[\n${rows.join("\n")}\n ]`; + } else if (nested !== null && value !== null && typeof value === "object" && !Array.isArray(value)) { + const parts = []; + for (const k of Object.keys(value)) { + const v = value[k]; + if (v === undefined || typeof v === "function" || typeof v === "symbol") continue; + let b; + if (k === nested && Array.isArray(v) && v.length > 0) { + const rows = v.map((el, i) => ` ${JSON.stringify(el) ?? "null"}${i < v.length - 1 ? "," : ""}`); + b = `[\n${rows.join("\n")}\n ]`; + } else { + b = JSON.stringify(v, null, 2).replace(/\n/g, "\n "); + } + parts.push(` ${JSON.stringify(k)}: ${b}`); + } + body = parts.length === 0 ? "{}" : `{\n${parts.join(",\n")}\n }`; } else { body = JSON.stringify(value, null, 2).replace(/\n/g, "\n "); } @@ -971,16 +1034,22 @@ export function serializeLedger(ledger) { } /** The compact per-stage table `/pharn-loop` Step 7 prints. The FILE is the record; this screen copy is - * advisory and is regenerated from the same rows, never typed. */ + * advisory and is regenerated from the same rows, never typed. Three blocks, kept apart on purpose (6.35.0): model + * usage (tokens, from `requests[]`), observed elapsed (from `executions`), deterministic work (from `work[]`) — no + * number in one is derived from another, and none is subtracted from another. */ export function table(ledger) { + return [...usageLines(ledger), ...elapsedLines(ledger), ...workLines(ledger)].join("\n"); +} + +function usageLines(ledger) { const rows = ledger.by_stage_iteration_model; const m = ledger.membership; const scope = m ? `run window ${m.status}${m.status === "unknown" ? "" : `, ${m.excluded_requests} outside excluded`}` : "session-scoped"; const lines = [ `cost ledger — ${ledger.name} (${ledger.coverage}, ${scope}, ${ledger.totals.requests} requests, dedup on ${ledger.dedup_key})`, ]; - if (m && m.status === "unknown") return lines.concat(` run usage UNKNOWN — ${m.reason}. Not a zero.`).join("\n"); - if (rows.length === 0) return lines.concat(" (no attributed requests)").join("\n"); + if (m && m.status === "unknown") return lines.concat(` run usage UNKNOWN — ${m.reason}. Not a zero.`); + if (rows.length === 0) return lines.concat(" (no attributed requests)"); const w = (s, n) => String(s).padEnd(n); const r = (s, n) => String(s).padStart(n); lines.push(` ${w("stage", 18)}${r("iter", 5)} ${w("model", 20)}${r("reqs", 6)}${r("cache_read", 12)}${r("output", 9)}`); @@ -990,7 +1059,69 @@ export function table(ledger) { ); } lines.push(` TOKENS ONLY — no prices here. Multiply by your own price list; output_thinking ⊂ output.`); - return lines.join("\n"); + return lines; +} + +/** The observed-elapsed block. An unmeasured row prints its reason, never a number. */ +export function elapsedLines(ledger) { + const ex = ledger.executions; + if (!ex || typeof ex !== "object") return ["observed elapsed — not recorded (a ledger written before 6.35.0)"]; + const head = "observed elapsed — wall clock between PHARN's stage markers (not CPU, model or tool time; not monotonic)"; + if (ex.status === "unknown") return [head, ` UNKNOWN — ${ex.reason}. Not a zero.`]; + if (!Array.isArray(ex.rows) || ex.rows.length === 0) return [head, " (no stage-start marker in this run)"]; + const w = (s, n) => String(s).padEnd(n); + const r = (s, n) => String(s).padStart(n); + const lines = [head, ` ${w("stage", 18)}${r("iter", 5)}${r("run", 5)} elapsed`]; + for (const x of ex.rows) { + const v = Number.isInteger(x.elapsed_ms) ? formatMs(x.elapsed_ms) : `unmeasured — ${x.unmeasured}`; + lines.push(` ${w(x.stage ?? "(no stage)", 18)}${r(x.iteration ?? "-", 5)}${r(x.run, 5)} ${v}`); + } + return lines; +} + +/** The deterministic-work block, one line per record, in the order the stages wrote them. */ +export function workLines(ledger) { + const work = ledger.work; + if (!Array.isArray(work)) return ["deterministic work — not recorded (a ledger written before 6.35.0)"]; + const head = "deterministic work — gate processes run vs taken from reused evidence (counted from each stage's gate-run stamp)"; + // An UNKNOWN run window admits no record, so an empty list there is not "nothing ran" (GATE-2 review: it printed so). + const m = ledger.membership; + const windowUnknown = m && m.status === "unknown" && !(typeof m.reason === "string" && CONTEXT_REASONS.includes(m.reason)); + if (windowUnknown) return [head, " UNKNOWN — the run window is unknown, so no work record was admitted. Not a zero."]; + if (work.length === 0) return [head, " (no /pharn-regress or /pharn-verify execution recorded one in this run)"]; + const where = new Map(); + for (const x of ledger.executions?.rows ?? []) + for (const i of x.work ?? []) where.set(i, `${x.stage} iter ${x.iteration ?? "-"} run ${x.run}`); + const lines = [head]; + work.forEach((rec, i) => { + const at = where.get(i) ?? `${rec.stage} (outside any marked execution)`; + lines.push(` ${at}: ${workSummary(rec)}`); + }); + const loose = unattachedWork(ledger.executions, work).length; + if (loose > 0) lines.push(` ${loose} record(s) attach to no marked execution — shown, never merged into one`); + return lines; +} + +/** One record in one line. `evidence` decides what the BASE did; worktree and install are read from it, never stored. */ +export function workSummary(rec) { + const side = (s) => `${s.executed} run, ${s.reused} reused, ${s.no_files} nothing-to-run, of ${s.required}`; + if (rec.stage === "pharn-verify") return `gates ${side(rec.gates)}`; + const b = rec.base; + const base = + b.evidence === "reused" + ? `BASE REUSED (no worktree, no install, 0 base gate processes; ${b.reused} results from earlier evidence)` + : `BASE fresh${b.miss ? ` (${b.miss})` : ""} — worktree created, install ${ + rec.install === null + ? "none configured" + : `ran (exit ${rec.install.exit}${rec.install.timed_out ? ", timed out" : ""}, ${rec.install.ms === null ? "time unmeasured" : formatMs(rec.install.ms)})` + }, base gates ${side(b)}`; + return `HEAD gates ${side(rec.head)}; ${base}`; +} + +/** Milliseconds for a human: exact ms below 10 s, else seconds with one decimal. Never rounds a measured value to 0 s. */ +export function formatMs(ms) { + if (ms < 10000) return `${ms} ms`; + return `${(ms / 1000).toFixed(1)} s`; } function main(argv) { diff --git a/pharn/floor/render-cost-ledger.test.mjs b/pharn/floor/render-cost-ledger.test.mjs index a4bd41a4..701c6e57 100644 --- a/pharn/floor/render-cost-ledger.test.mjs +++ b/pharn/floor/render-cost-ledger.test.mjs @@ -1718,10 +1718,12 @@ function rowLayoutProblems(text, led) { const problems = []; const lines = text.split("\n"); if (lines.at(-1) !== "" || lines.at(-2) === "") problems.push("the file must end with exactly one newline"); - for (const key of ["markers", "requests"]) { + for (const key of ROW_ARRAYS) { const arr = led[key]; if (arr.length === 0) { - if (!lines.includes(` "${key}": [],`)) problems.push(`${key}: an empty fact array must be written as []`); + // `work` (6.35.0) is the LAST key, so its empty form carries no trailing comma. + if (!lines.includes(` "${key}": [],`) && !lines.includes(` "${key}": []`)) + problems.push(`${key}: an empty fact array must be written as []`); continue; } const open = lines.indexOf(` "${key}": [`); @@ -1864,7 +1866,7 @@ test("LAYOUT: JSON.parse of the new file equals JSON.parse of the old one — ov assert.equal(serializeLedger(structuredClone(led)), text, `${label}: byte-deterministic for an equal object`); assert.ok(text.split("\n").length <= old.split("\n").length, `${label}: never MORE lines than the old layout`); } - assert.deepEqual([...ROW_ARRAYS], ["markers", "requests"], "exactly the two fact arrays — equality, not presence (L36)"); + assert.deepEqual([...ROW_ARRAYS], ["markers", "requests", "work"], "exactly the three fact arrays — equality, not presence (L36)"); }); test("LAYOUT: a value carrying \\n or U+2028 stays on its row's line — the \\n-delimited claim, probed (L37)", () => { @@ -2472,3 +2474,167 @@ test("RESIDUAL cost-ledger-shared-markers-file: two runs appending to ONE marker ["b-1"] ); }); + +// ── 6.35.0 (run-performance-breakdown): the `executions` view and the `work[]` facts ───────────────────────────── + +/** A bounded run with every stage bracketed by its orchestrator return, plus a work.jsonl beside the markers. */ +function perfRun({ work = null } = {}) { + const { root, projectsDir } = stageSingle(); + const markersBase = writeMarkers(root, "feat", [ + marker(1, "run-start", null, null, "2026-09-21T08:00:00.000Z"), + marker(2, "stage-start", "pharn-build", 1, "2026-09-21T08:36:00.000Z"), + marker(3, "orchestrator", null, null, "2026-09-21T08:38:00.000Z"), + marker(4, "stage-start", "pharn-regress", 1, "2026-09-21T08:38:30.000Z"), + marker(5, "orchestrator", null, null, "2026-09-21T08:40:00.000Z"), + marker(6, "stage-start", "pharn-verify", 1, "2026-09-21T08:41:00.000Z"), + marker(7, "orchestrator", null, null, "2026-09-21T08:44:00.000Z"), + marker(8, "stage-start", "pharn-verify", 1, "2026-09-21T08:44:10.000Z"), + marker(9, "run-stop", null, null, "2026-09-21T09:00:00.000Z"), + ]); + if (work !== null) + writeFileSync( + join(markersBase, "feat", "work.jsonl"), + work.map((w) => (typeof w === "string" ? w : JSON.stringify(w))).join("\n") + "\n" + ); + return { root, projectsDir, markersBase }; +} + +const REGRESS_WORK = { + schema: "pharn-stage-work/1", + stage: "pharn-regress", + ts: "2026-09-21T08:39:59.000Z", + session_id: null, + head: { required: 3, executed: 2, reused: 0, no_files: 1 }, + base: { evidence: "fresh", miss: "no-record", required: 3, executed: 2, reused: 0, no_files: 1 }, + install: { exit: 0, timed_out: false, ms: 1234 }, +}; +const VERIFY_WORK = { + schema: "pharn-stage-work/1", + stage: "pharn-verify", + ts: "2026-09-21T08:43:00.000Z", + session_id: null, + gates: { required: 4, executed: 2, reused: 2, no_files: 0 }, +}; + +test("6.35.0 — every ledger carries `executions` (a view over markers) and `work` (facts), after membership", () => { + const { projectsDir, markersBase } = perfRun({ work: [REGRESS_WORK, VERIFY_WORK] }); + const led = renderLedger({ name: "feat", sessionId: REAL_SESSION, projectsDir, markersBase }); + assert.deepEqual(Object.keys(led).slice(-3), ["membership", "executions", "work"]); + assert.deepEqual(led.work, [REGRESS_WORK, VERIFY_WORK]); + assert.equal(led.executions.method, "stage-start-to-return/1"); + assert.deepEqual( + led.executions.rows.map((r) => [r.stage, r.iteration, r.run, r.elapsed_ms, r.unmeasured, r.work]), + [ + ["pharn-build", 1, 1, 120000, null, []], + ["pharn-regress", 1, 1, 90000, null, [0]], + ["pharn-verify", 1, 1, 180000, null, [1]], + ["pharn-verify", 1, 2, null, "no-return-marker", []], + ] + ); + assert.deepEqual(checkLedger(led).reds, []); +}); + +test("✧ 6.35.0 does not move model accounting: requests, every view and membership are identical with and without work.jsonl", () => { + const a = perfRun(); + const b = perfRun({ work: [REGRESS_WORK, VERIFY_WORK, "not json"] }); + const without = renderLedger({ name: "feat", sessionId: REAL_SESSION, projectsDir: a.projectsDir, markersBase: a.markersBase }); + const withWork = renderLedger({ name: "feat", sessionId: REAL_SESSION, projectsDir: b.projectsDir, markersBase: b.markersBase }); + assert.ok(without.requests.length > 0, "non-vacuity: rows were measured"); + for (const k of [ + "requests", + "totals", + "by_model", + "by_stage_iteration_model", + "unattributed", + "membership", + "markers", + "coverage", + "sessions", + ]) { + assert.deepStrictEqual(withWork[k], without[k], k); + } + // Stage attribution of every request is exactly `attribute()` over the markers — untouched by the new view. + for (const r of withWork.requests) + assert.deepEqual({ stage: r.stage, iteration: r.iteration }, attribute(withWork.markers, r.ts, r.session_id)); + assert.deepEqual( + withWork.dropped.filter((d) => d.startsWith("work.jsonl")), + ["work.jsonl[2]"], + "an invalid line is listed by index, never copied" + ); + assert.deepEqual(without.work, []); + assert.deepEqual( + without.executions.rows.map((r) => r.work), + [[], [], [], []] + ); +}); + +test("6.35.0 — a work record outside the run window is not a row (the membership test requests use)", () => { + const early = { ...VERIFY_WORK, ts: "2026-09-21T07:00:00.000Z" }; + const { projectsDir, markersBase } = perfRun({ work: [early, VERIFY_WORK] }); + const led = renderLedger({ name: "feat", sessionId: REAL_SESSION, projectsDir, markersBase }); + assert.deepEqual(led.work, [VERIFY_WORK]); +}); + +test("6.35.0 — timing needs only markers: a ledger with NO transcript still carries its elapsed rows and work", () => { + const { markersBase } = perfRun({ work: [VERIFY_WORK] }); + const led = renderLedger({ name: "feat", sessionId: null, projectsDir: join(tmpdir(), "absent-projects"), markersBase }); + assert.equal(led.coverage, "unavailable"); + assert.equal(led.executions.status, "derived"); + assert.equal(led.executions.rows.length, 4); + assert.deepEqual(led.work, [VERIFY_WORK]); + assert.deepEqual(checkLedger(led).reds, []); +}); + +test("6.35.0 LAYOUT — work records and executions rows are one per line; the parse is unchanged", () => { + const { projectsDir, markersBase } = perfRun({ work: [REGRESS_WORK, VERIFY_WORK] }); + const led = renderLedger({ name: "feat", sessionId: REAL_SESSION, projectsDir, markersBase }); + const text = serializeLedger(led); + assert.deepStrictEqual(JSON.parse(text), JSON.parse(JSON.stringify(led))); + const lines = text.split("\n"); + for (const r of led.executions.rows) + assert.ok(lines.includes(` ${JSON.stringify(r)},`) || lines.includes(` ${JSON.stringify(r)}`)); + for (const w of led.work) assert.ok(lines.includes(` ${JSON.stringify(w)},`) || lines.includes(` ${JSON.stringify(w)}`)); + assert.ok(text.split("\n").length <= (JSON.stringify(led, null, 2) + "\n").split("\n").length); +}); + +test("6.35.0 table() — three separate blocks; an unmeasured row prints its reason, never a number", () => { + const { projectsDir, markersBase } = perfRun({ work: [REGRESS_WORK, VERIFY_WORK] }); + const out = table(renderLedger({ name: "feat", sessionId: REAL_SESSION, projectsDir, markersBase })); + assert.match(out, /observed elapsed — wall clock between PHARN's stage markers \(not CPU, model or tool time; not monotonic\)/); + assert.match(out, /pharn-regress\s+1\s+1\s+90\.0 s/); + assert.match(out, /pharn-verify\s+1\s+2\s+unmeasured — no-return-marker/); + assert.match( + out, + /pharn-regress iter 1 run 1: HEAD gates 2 run, 0 reused, 1 nothing-to-run, of 3; BASE fresh \(no-record\) — worktree created, install ran \(exit 0, 1234 ms\)/ + ); + assert.match(out, /pharn-verify iter 1 run 1: gates 2 run, 2 reused, 0 nothing-to-run, of 4/); + const reused = { + ...REGRESS_WORK, + base: { evidence: "reused", miss: null, required: 3, executed: 0, reused: 2, no_files: 1 }, + install: null, + }; + const { projectsDir: p2, markersBase: m2 } = perfRun({ work: [reused] }); + assert.match( + table(renderLedger({ name: "feat", sessionId: REAL_SESSION, projectsDir: p2, markersBase: m2 })), + /BASE REUSED \(no worktree, no install, 0 base gate processes; 2 results from earlier evidence\)/ + ); +}); + +test("GATE-2 — an UNKNOWN run window prints UNKNOWN work, never 'no work'; a known one with no record says so", () => { + const { projectsDir, markersBase } = perfRun({ work: [VERIFY_WORK] }); + const led = renderLedger({ name: "feat", sessionId: REAL_SESSION, projectsDir, markersBase }); + const unknown = { ...led, membership: { ...led.membership, status: "unknown", reason: "no run-start marker was recorded" }, work: [] }; + const out = table(unknown); + assert.match(out, /UNKNOWN — the run window is unknown, so no work record was admitted\. Not a zero\./); + assert.doesNotMatch(out, /no \/pharn-regress or \/pharn-verify execution recorded one/); + const none = { ...led, work: [], executions: { ...led.executions, rows: led.executions.rows.map((r) => ({ ...r, work: [] })) } }; + assert.match(table(none), /no \/pharn-regress or \/pharn-verify execution recorded one/); +}); + +test("GATE-2 (L58) — a --verify-transcript re-derivation never reads the live work file", () => { + const { projectsDir, markersBase } = perfRun({ work: [VERIFY_WORK] }); + const led = renderLedger({ name: "feat", sessionId: REAL_SESSION, projectsDir, markersBase }); + const again = renderLedger({ name: "feat", sessionId: REAL_SESSION, projectsDir, markersBase, markers: led.markers }); + assert.deepEqual(again.work, [], "the recorded-boundary path reads no live work.jsonl"); + assert.deepEqual(led.work, [VERIFY_WORK]); +}); diff --git a/pharn/floor/render-run-report.mjs b/pharn/floor/render-run-report.mjs index 8fc90f16..d959035c 100644 --- a/pharn/floor/render-run-report.mjs +++ b/pharn/floor/render-run-report.mjs @@ -106,7 +106,17 @@ import { readFileSync, writeFileSync, existsSync, mkdirSync } from "node:fs"; import { join, dirname } from "node:path"; import { execFileSync } from "node:child_process"; -import { FEATURE_BASE, TOKEN_CLASSES, LEGACY_SCHEMA, SHIP_COMMAND, readMarkers, normalizeMarkers } from "./render-cost-ledger.mjs"; +import { + FEATURE_BASE, + TOKEN_CLASSES, + LEGACY_SCHEMA, + SHIP_COMMAND, + readMarkers, + normalizeMarkers, + elapsedLines, + workLines, +} from "./render-cost-ledger.mjs"; +import { validateWork } from "./stage-work.mjs"; import { DEFAULT_BASE as MARKERS_DEFAULT_BASE } from "./mark-phase.mjs"; import { verdictApplicability, APPLICABILITY, runMode } from "./ship-outcome-core.mjs"; import { handoffSections, HANDOFF_SECTIONS } from "./loop-record-core.mjs"; @@ -134,6 +144,7 @@ const SLUG_RE = /^[a-z0-9][a-z0-9-]{0,63}$/; export const SECTIONS = Object.freeze([ "## Outcome", "## Tokens — stage x iteration x model", + "## Stage elapsed and deterministic work", "## Files", "## Verdicts", "## Briefing", @@ -560,6 +571,58 @@ function tokensSection(cost, absentReason = null) { ].join("\n"); } +/** A stored `executions` view with the shape the emitter writes — checked here only so a hand-edited `cost.json` can + * never crash this renderer; whether the view AGREES with the facts is `check-cost-ledger.mjs`'s rule 9. */ +function executionsShapeOk(ex) { + const intOrNull = (v) => v === null || Number.isSafeInteger(v); + const strOrNull = (v) => v === null || typeof v === "string"; + // Every value the screen functions interpolate is type-tested first: `reason` too (GATE-2 review: an object there + // with a throwing toString crashed this renderer). + if (!isRecord(ex) || !Array.isArray(ex.rows) || (ex.status !== "derived" && ex.status !== "unknown")) return false; + if (typeof ex.method !== "string" || !strOrNull(ex.reason)) return false; + return ex.rows.every( + (r) => + isRecord(r) && + strOrNull(r.stage) && + intOrNull(r.iteration) && + Number.isSafeInteger(r.run) && + intOrNull(r.elapsed_ms) && + strOrNull(r.unmeasured) && + (r.elapsed_ms === null) === (r.unmeasured !== null) && + Array.isArray(r.work) && + r.work.every((i) => Number.isSafeInteger(i)) + ); +} + +/** + * STAGE ELAPSED AND DETERMINISTIC WORK (6.35.0) — COPIED from `cost.json`'s stored `executions` view and `work[]` + * facts (bound (2): never recomputed here), rendered by the ledger's own screen functions so the report and the stop's + * printout cannot word the same fact two ways. Three measurements, deliberately not combined: tokens (above), the + * observed wall-clock interval between a stage's markers, and the gate processes a regress/verify execution ran or + * took from reused evidence. Fenced as DATA: stage labels and reasons are file values. + */ +function performanceSection(cost, absentReason = null) { + if (absentReason) return na(absentReason); + if (!cost) return na("no cost.json — no ledger was emitted for this run"); + if (!Object.hasOwn(cost, "executions") && !Object.hasOwn(cost, "work")) { + return na("cost.json predates 6.35.0 — it records no stage elapsed view and no deterministic-work facts"); + } + if (!executionsShapeOk(cost.executions) || !Array.isArray(cost.work) || !cost.work.every((w) => validateWork(w).ok)) { + return na("cost.json's `executions`/`work` do not have the shape the emitter writes — run check-cost-ledger.mjs on it"); + } + const text = [...elapsedLines(cost), "", ...workLines(cost)].join("\n"); + return [ + "**Observed elapsed** is wall-clock time between two PHARN markers — the stage's start and the orchestrator's", + "return — read by two different processes. It is NOT CPU time, model time or tool time, it is not monotonic, and", + "it includes orchestration, subprocesses, waiting and any answer a human gave inside the stage. An `unmeasured`", + "row names why no interval could be paired, and is never a zero. **Deterministic work** is counted from each", + "`/pharn-regress` and `/pharn-verify` execution's own gate-run stamp at its `done` exit; an execution that ended any", + "other way recorded none. Nothing here is subtracted from anything else.", + "", + quoteData("", text).trimStart(), + ].join("\n"); +} + function filesSection({ cost, repo, planEntries, dirtyBefore, dirtyNote, absentReason = null }) { if (absentReason) return na(absentReason); const base = cost && typeof cost.base_sha === "string" ? cost.base_sha : null; @@ -1001,6 +1064,7 @@ export function renderRunReport(name, opts = {}) { const bodyBySection = { "## Outcome": outcomeSection(cost, staleReason), "## Tokens — stage x iteration x model": tokensSection(cost, staleReason), + "## Stage elapsed and deterministic work": performanceSection(cost, staleReason), "## Files": filesSection({ cost, repo, planEntries, dirtyBefore, dirtyNote, absentReason: staleReason }), "## Verdicts": verdictsSection({ verify, regress, cost: staleReason ? null : cost, stale: Boolean(staleReason) }), "## Briefing": briefingSection({ dir, cost: staleReason ? null : cost }), diff --git a/pharn/floor/render-run-report.test.mjs b/pharn/floor/render-run-report.test.mjs index d04f28f9..eeb67ff6 100644 --- a/pharn/floor/render-run-report.test.mjs +++ b/pharn/floor/render-run-report.test.mjs @@ -164,7 +164,7 @@ test("L36 CLOSURE: the rendered `##` headings equal SECTIONS exactly, both direc try { feature(root, "feat", { "cost.json": costJson(), "LOOP.md": LOOP_MD }); const got = headings(renderRunReport("feat", { repo: root })); - assert.equal(SECTIONS.length, 6, "non-vacuity: the vocabulary must be non-empty"); + assert.equal(SECTIONS.length, 7, "non-vacuity: the vocabulary must be non-empty"); // Equality, not per-member presence: a variant spelling of ANY member fails here, which is the // whole point — a presence set is satisfied by the spelling its author was looking at. assert.deepEqual(got, [...SECTIONS]); @@ -1065,7 +1065,7 @@ test("L52 CLOSURE: this module introduces ZERO new feature-base defaults", () => .join("\n"); const hits = [...code.matchAll(/"pharn\/features"/g)]; assert.equal(hits.length, 0, "the feature-base literal must be imported, never re-spelled in code"); - assert.match(src, /import \{ FEATURE_BASE[^}]*\} from "\.\/render-cost-ledger\.mjs"/); + assert.match(src, /import \{\s*FEATURE_BASE[^}]*\} from "\.\/render-cost-ledger\.mjs"/); }); // ── the CLI ────────────────────────────────────────────────────────────────────────────────────────── @@ -2172,3 +2172,64 @@ test("F2: no live markers file → an explicit 'currency not checked' line, neve rmSync(root, { recursive: true, force: true }); } }); + +// ── 6.35.0: `## Stage elapsed and deterministic work` ───────────────────────────────────────────────────────────── +const PERF_ROWS = [ + { stage: "pharn-regress", iteration: 1, run: 1, start_seq: 2, end_seq: 3, elapsed_ms: 90000, unmeasured: null, work: [0] }, + { stage: "pharn-verify", iteration: 1, run: 1, start_seq: 4, end_seq: null, elapsed_ms: null, unmeasured: "no-return-marker", work: [] }, +]; +const PERF_WORK = [ + { + schema: "pharn-stage-work/1", + stage: "pharn-regress", + ts: "2026-09-21T08:39:59.000Z", + session_id: null, + head: { required: 2, executed: 2, reused: 0, no_files: 0 }, + base: { evidence: "reused", miss: null, required: 2, executed: 0, reused: 2, no_files: 0 }, + install: null, + }, +]; +const perfSection = (md) => md.slice(md.indexOf("## Stage elapsed and deterministic work"), md.indexOf("## Files")); + +test("6.35.0 — the section copies the stored views: an unmeasured row shows its reason, never a number; BASE reuse is named", () => { + const root = scratch(); + try { + feature(root, "feat", { + "cost.json": costJson({ + executions: { method: "stage-start-to-return/1", status: "derived", reason: null, rows: PERF_ROWS }, + work: PERF_WORK, + }), + }); + const sec = perfSection(renderRunReport("feat", { repo: root })); + assert.match(sec, /pharn-regress\s+1\s+1\s+90\.0 s/); + assert.match(sec, /pharn-verify\s+1\s+1\s+unmeasured — no-return-marker/); + assert.match(sec, /BASE REUSED \(no worktree, no install, 0 base gate processes; 2 results from earlier evidence\)/); + assert.match(sec, /NOT CPU time, model time or tool time/); + } finally { + rmSync(root, { recursive: true, force: true }); + } +}); + +test("6.35.0 — a pre-6.35.0 ledger renders n/a; a hand-edited view renders n/a and NEVER crashes (GATE-2: a throwing reason)", () => { + const root = scratch(); + try { + feature(root, "old", { "cost.json": costJson() }); + assert.match(perfSection(renderRunReport("old", { repo: root })), /_n\/a — cost\.json predates 6\.35\.0/); + const hostile = [ + { method: "stage-start-to-return/1", status: "unknown", reason: { toString: 1, valueOf: 1 }, rows: [] }, + { method: "stage-start-to-return/1", status: "derived", reason: null, rows: [{ ...PERF_ROWS[0], elapsed_ms: null }] }, + { method: "stage-start-to-return/1", status: "derived", reason: null, rows: [{ ...PERF_ROWS[0], work: 5 }] }, + null, + ]; + for (const [i, executions] of hostile.entries()) { + feature(root, `h${i}`, { "cost.json": costJson({ executions, work: PERF_WORK }) }); + assert.match( + perfSection(renderRunReport(`h${i}`, { repo: root })), + /_n\/a — cost\.json's `executions`\/`work` do not have the shape/, + `case ${i}` + ); + } + } finally { + rmSync(root, { recursive: true, force: true }); + } +}); diff --git a/pharn/floor/stage-executions-core.mjs b/pharn/floor/stage-executions-core.mjs new file mode 100644 index 00000000..ed24d0fa --- /dev/null +++ b/pharn/floor/stage-executions-core.mjs @@ -0,0 +1,182 @@ +// pharn/floor/stage-executions-core.mjs — the STAGE EXECUTIONS view of the cost ledger (`cost.json`'s `executions`, +// `pharn/pharn-contracts/cost-ledger.md`, "Stage executions and deterministic work"). Pure: no I/O, no clock, no +// randomness. Imported by `render-cost-ledger.mjs` (to emit the view) AND `check-cost-ledger.mjs` (to hold the stored +// view to a recompute from the file's own `markers[]` and `work[]`), never copied ([[L35]]). +// +// ── WHAT IT ANSWERS ────────────────────────────────────────────────────────────────────────────────────────────── +// "How long did each stage execution of this run take, by PHARN's own clock, and which deterministic-work record +// belongs to it?" — from facts the ledger already records. No new marker, no new marker field, no change to the line +// `mark-phase.mjs` prints (that line binds the run to its context; this view never reads a transcript). +// +// ── THE METHOD (`stage-start-to-return/1`) ─────────────────────────────────────────────────────────────────────── +// The orchestrators bracket every stage they mark: `stage-start --stage [--iteration ]` right before it and +// `--kind orchestrator` right after it returns (a freshness re-run writes its own pair). So, over the CURRENT RUN's +// markers (`run-window-core.mjs currentRunMarkers`, the one definition), in `seq` order: +// * every `stage-start` S is ONE execution row — two executions of one stage are never merged; `run` numbers the +// rows sharing `(stage, iteration)` 1, 2, … in `seq` order; +// * its end is the NEXT marker N, and only when N is an `orchestrator` marker. Anything else is UNMEASURED, with a +// closed reason — the next stage-start or a run-stop is never used as an end, because that would pair by +// proximity (a guess): +// no-end-marker no later marker in the current run (interrupted, or still running at emission) +// no-return-marker the next marker is not an orchestrator return (a skipped marker, or a stop) +// session-changed S and N are bound to different non-null sessions (the stage spanned a resume); a null +// session binds any, as it does for attribution +// bad-timestamp S or N carries no parseable ISO timestamp +// clock-went-back N's timestamp precedes S's +// foreign-work-inside a work record of ANOTHER stage lies strictly inside (S, N): the return of this stage and +// the start of that one were both skipped, so N is not this stage's return (GATE-2 review) +// * measured: `elapsed_ms = tsMs(N.ts) − tsMs(S.ts)`, an integer. An unmeasured row carries `elapsed_ms: null` and +// NEVER 0 — zero means measured equal, unknown means not measured. +// BOUND, stated rather than claimed away: when this stage's return AND the next stage's start are both skipped, N is +// that later stage's return, and nothing in the markers says so. The one evidence that can — a work record of the +// other stage inside the interval — makes the row unmeasured (`foreign-work-inside`); a skipped pair around a stage that +// writes no work record (build, plan, …) is indistinguishable from one long execution and is measured as one. +// When the markers do not describe one run (`runWindow(markers, null)` is `unknown`: no run-start, a bad run-start or +// run-stop timestamp, a marker after the run-stop, a stop before the start) the view is `status: "unknown"` with that +// reason and NO rows. The CONTEXT half of membership (the transcript binding) does not touch this view: timing needs +// only markers, so a run whose transcript is missing still has its elapsed rows. +// +// ── WORK ATTACHMENT ────────────────────────────────────────────────────────────────────────────────────────────── +// A `work[]` record (`stage-work.mjs`, written by `/pharn-regress` or `/pharn-verify` at `done`) belongs to the +// execution whose `stage-start` is the LATEST current-run marker at-or-before the record's `ts` in the same session +// (a null session binds all) — the rule `render-cost-ledger.mjs attribute()` already applies to requests, restated +// here over current-run markers only, and pinned to it by a ✧ parity test — and only when that marker's `stage` +// equals the record's `stage`. Otherwise the record attaches to no row and is reported as unattached. +// +// ── HONEST SCOPE (P0) ──────────────────────────────────────────────────────────────────────────────────────────── +// FLOOR: given the same markers and work records, the rows are a deterministic function (ordering + membership + +// integer subtraction), and `check-cost-ledger.mjs` holds the stored view to this recompute. +// ADVISORY: that the markers describe what ran (they are Bash-written by command prose, L19), and what an interval +// MEANS. It is OBSERVED WALL-CLOCK time between two `toISOString()` reads by two short-lived processes: not CPU +// time, not model time, not tool time, not monotonic (a clock step moves it), and it includes orchestration, +// subprocesses, waiting and any human answer given inside the stage. Nothing here decomposes it. + +import { currentRunMarkers, runWindow, tsMs } from "./run-window-core.mjs"; + +/** The method name recorded in `executions.method`. Versioned: a change to the pairing rule is a new method. */ +export const EXECUTIONS_METHOD = "stage-start-to-return/1"; + +/** The closed set of reasons an execution row is unmeasured (see the header). */ +export const UNMEASURED_REASONS = Object.freeze([ + "no-end-marker", + "no-return-marker", + "session-changed", + "bad-timestamp", + "clock-went-back", + "foreign-work-inside", +]); + +/** The `executions` object's closed key set, and a row's. */ +export const EXECUTIONS_KEYS = Object.freeze(["method", "status", "reason", "rows"]); +export const EXECUTION_ROW_KEYS = Object.freeze(["stage", "iteration", "run", "start_seq", "end_seq", "elapsed_ms", "unmeasured", "work"]); + +/** Two markers are in one session unless both name one and they differ — a null (the variable was unset) binds any, + * exactly as it does in attribution and run membership. */ +const sameSession = (a, b) => a === null || a === undefined || b === null || b === undefined || a === b; + +/** + * The latest current-run marker at-or-before `ts` bound to `sid` (a null on either side binds), ties broken by the + * higher `seq` — the request attribution rule of `render-cost-ledger.mjs attribute()`, returning the marker itself. + * `current` must already be the current run's markers. Returns null when none qualifies. + */ +export function latestMarkerAtOrBefore(current, ts, sid, msOf = (m) => tsMs(m.ts)) { + const at = tsMs(ts); + if (at === null) return null; + let best = null; + let bestMs = null; + for (const m of current) { + const t = msOf(m); + if (t === null || t > at) continue; + if (m.session_id !== null && m.session_id !== undefined && sid !== null && sid !== undefined && m.session_id !== sid) continue; + if (best === null || t > bestMs || (t === bestMs && m.seq > best.seq)) { + best = m; + bestMs = t; + } + } + return best; +} + +/** + * Build the `executions` view from a normalized marker list and the ledger's validated `work[]` records. + * `work` entries need `stage`, `ts` and `session_id`; their INDEX in `work` is what a row's `work` lists. + */ +export function buildExecutions(markers, work = []) { + const win = runWindow(markers, null); + if (win.status === "unknown") return { method: EXECUTIONS_METHOD, status: "unknown", reason: win.reason, rows: [] }; + const current = currentRunMarkers(markers) ?? []; + const rows = []; + // Keyed by the MARKER OBJECT, never by `seq`: a duplicate `seq` (which the checker REDs) must not re-home a record. + const rowByMarker = new Map(); + const spanOf = new Map(); // row -> [startMs, endMs] for a measured row + const runs = new Map(); + for (let i = 0; i < current.length; i++) { + const s = current[i]; + if (s.kind !== "stage-start") continue; + const key = `${s.stage ?? ""}\u0000${s.iteration ?? ""}`; + const run = (runs.get(key) ?? 0) + 1; + runs.set(key, run); + const n = i + 1 < current.length ? current[i + 1] : null; + let endSeq = null; + let elapsed = null; + let unmeasured = null; + if (n === null) unmeasured = "no-end-marker"; + else if (n.kind !== "orchestrator") unmeasured = "no-return-marker"; + else { + endSeq = n.seq; + const a = tsMs(s.ts); + const b = tsMs(n.ts); + if (!sameSession(s.session_id, n.session_id)) unmeasured = "session-changed"; + else if (a === null || b === null) unmeasured = "bad-timestamp"; + else if (b < a) unmeasured = "clock-went-back"; + else elapsed = b - a; + } + const measuredSpan = elapsed === null ? null : [tsMs(s.ts), tsMs(n.ts), s.session_id ?? null]; + const row = { + stage: typeof s.stage === "string" ? s.stage : null, + iteration: Number.isInteger(s.iteration) ? s.iteration : null, + run, + start_seq: s.seq, + end_seq: endSeq, + elapsed_ms: elapsed, + unmeasured, + work: [], + }; + rows.push(row); + rowByMarker.set(s, row); + if (measuredSpan !== null) spanOf.set(row, measuredSpan); + } + // Each marker's timestamp is parsed ONCE (measured: re-parsing per record cost ~0.2 ms per record over 1,000 markers). + const parsed = new Map(current.map((c) => [c, tsMs(c.ts)])); + const msOf = (c) => parsed.get(c); + const list = Array.isArray(work) ? work : []; + list.forEach((w, idx) => { + if (!w || typeof w !== "object") return; + const m = latestMarkerAtOrBefore(current, w.ts, w.session_id ?? null, msOf); + if (m === null || m.kind !== "stage-start" || m.stage !== w.stage) return; + const row = rowByMarker.get(m); + if (row) row.work.push(idx); + }); + // A measured interval that contains ANOTHER stage's work record was not this stage's alone (see the header's BOUND). + const workMs = list.map((w) => (w && typeof w === "object" ? tsMs(w.ts) : null)); // parsed once, like the markers + for (const [row, [a, b, sid]] of spanOf) { + const foreign = list.some((w, i) => { + if (!w || typeof w !== "object" || w.stage === row.stage || !sameSession(sid, w.session_id ?? null)) return false; + const t = workMs[i]; + return t !== null && t > a && t < b; + }); + if (foreign) { + row.elapsed_ms = null; + row.unmeasured = "foreign-work-inside"; + } + } + return { method: EXECUTIONS_METHOD, status: "derived", reason: null, rows }; +} + +/** The indices of `work[]` no execution row lists — reported, never dropped. */ +export function unattachedWork(executions, work) { + const used = new Set(); + for (const r of executions?.rows ?? []) for (const i of r.work ?? []) used.add(i); + const out = []; + for (let i = 0; i < (Array.isArray(work) ? work.length : 0); i++) if (!used.has(i)) out.push(i); + return out; +} diff --git a/pharn/floor/stage-executions-core.test.mjs b/pharn/floor/stage-executions-core.test.mjs new file mode 100644 index 00000000..0b5857b7 --- /dev/null +++ b/pharn/floor/stage-executions-core.test.mjs @@ -0,0 +1,301 @@ +// pharn/floor/stage-executions-core.test.mjs — the `executions` view (method `stage-start-to-return/1`), case by case: +// a normal stage, iterations, a same-stage re-run, every unmeasured reason, an unknown current run, quick mode, an +// interrupted run, and work attachment. Every expectation is an INDEPENDENT literal (L43): these tests never ask the +// module what it thinks, and an unmeasured row is always checked for `elapsed_ms: null`, never 0. + +import { test } from "node:test"; +import assert from "node:assert/strict"; +import { + buildExecutions, + latestMarkerAtOrBefore, + unattachedWork, + EXECUTIONS_METHOD, + UNMEASURED_REASONS, + EXECUTION_ROW_KEYS, + EXECUTIONS_KEYS, +} from "./stage-executions-core.mjs"; +import { attribute } from "./render-cost-ledger.mjs"; +import { currentRunMarkers, UNKNOWN_REASONS } from "./run-window-core.mjs"; + +const S = "00000000-0000-4000-8000-00000000aaaa"; +const T = "00000000-0000-4000-8000-00000000bbbb"; +const at = (sec) => `2026-09-28T10:${String(Math.floor(sec / 60)).padStart(2, "0")}:${String(sec % 60).padStart(2, "0")}.000Z`; +let seq = 0; +const reset = () => (seq = 0); +const m = (kind, sec, { stage = null, iteration = null, session = S } = {}) => ({ + seq: ++seq, + kind, + stage, + iteration, + ts: at(sec), + session_id: session, +}); +const start = (sec, stage, iteration = null, o = {}) => m("stage-start", sec, { stage, iteration, ...o }); +const ret = (sec, o = {}) => m("orchestrator", sec, o); +const row = (stage, iteration, run, start_seq, end_seq, elapsed_ms, unmeasured = null, work = []) => ({ + stage, + iteration, + run, + start_seq, + end_seq, + elapsed_ms, + unmeasured, + work, +}); + +test("one normal completed stage: stage-start → orchestrator return is one measured row", () => { + reset(); + const markers = [m("run-start", 0), start(10, "pharn-plan"), ret(70), m("run-stop", 80)]; + const ex = buildExecutions(markers); + assert.deepEqual(ex, { method: EXECUTIONS_METHOD, status: "derived", reason: null, rows: [row("pharn-plan", null, 1, 2, 3, 60000)] }); + assert.deepEqual(Object.keys(ex), [...EXECUTIONS_KEYS]); + assert.deepEqual(Object.keys(ex.rows[0]), [...EXECUTION_ROW_KEYS]); +}); + +test("multiple iterations: each iteration's stages are their own rows, run 1 each", () => { + reset(); + const markers = [ + m("run-start", 0), + start(1, "pharn-build", 1), + ret(11), + start(12, "pharn-regress", 1), + ret(42), + start(43, "pharn-verify", 1), + ret(53), + start(60, "pharn-build", 2), + ret(65), + start(66, "pharn-regress", 2), + ret(76), + start(77, "pharn-verify", 2), + ret(80), + m("run-stop", 90), + ]; + const got = buildExecutions(markers).rows.map((r) => [r.stage, r.iteration, r.run, r.elapsed_ms]); + assert.deepEqual(got, [ + ["pharn-build", 1, 1, 10000], + ["pharn-regress", 1, 1, 30000], + ["pharn-verify", 1, 1, 10000], + ["pharn-build", 2, 1, 5000], + ["pharn-regress", 2, 1, 10000], + ["pharn-verify", 2, 1, 3000], + ]); +}); + +test("a same-stage re-run inside one iteration is a SECOND row (run 2) — never merged into the first", () => { + reset(); + const markers = [ + m("run-start", 0), + start(1, "pharn-verify", 1), + ret(5), + start(6, "pharn-verify", 1), // the freshness re-run writes its own pair + ret(16), + m("run-stop", 20), + ]; + assert.deepEqual(buildExecutions(markers).rows, [row("pharn-verify", 1, 1, 2, 3, 4000), row("pharn-verify", 1, 2, 4, 5, 10000)]); +}); + +test("a stage with no iteration re-run (a re-plan) is plan run 2 — null iteration is its own group key", () => { + reset(); + const markers = [m("run-start", 0), start(1, "pharn-plan"), ret(2), start(3, "pharn-plan"), ret(9), start(10, "pharn-build", 1), ret(11)]; + assert.deepEqual( + buildExecutions(markers).rows.map((r) => [r.stage, r.iteration, r.run]), + [ + ["pharn-plan", null, 1], + ["pharn-plan", null, 2], + ["pharn-build", 1, 1], + ] + ); +}); + +test("missing end boundary: the last stage-start with no later marker is UNMEASURED no-end-marker, elapsed null (not 0)", () => { + reset(); + const markers = [m("run-start", 0), start(1, "pharn-build", 1), ret(3), start(4, "pharn-regress", 1)]; + const rows = buildExecutions(markers).rows; + assert.deepEqual(rows[1], row("pharn-regress", 1, 1, 4, null, null, "no-end-marker")); + assert.equal(rows[0].elapsed_ms, 2000, "the completed stage before it keeps its measurement"); +}); + +test("the next marker is not a return: no-return-marker — the next stage-start or run-stop is never used as the end", () => { + reset(); + const a = [m("run-start", 0), start(1, "pharn-build", 1), start(9, "pharn-regress", 1), ret(12)]; + assert.deepEqual(buildExecutions(a).rows[0], row("pharn-build", 1, 1, 2, null, null, "no-return-marker")); + assert.deepEqual(buildExecutions(a).rows[1], row("pharn-regress", 1, 1, 3, 4, 3000)); + reset(); + const b = [m("run-start", 0), start(1, "pharn-verify", 1), m("run-stop", 30)]; // a STOP straight after the stage + assert.deepEqual(buildExecutions(b).rows, [row("pharn-verify", 1, 1, 2, null, null, "no-return-marker")]); +}); + +test("ambiguous or malformed pairs are unmeasured with their own reason, never guessed", () => { + reset(); + const sess = [m("run-start", 0), start(1, "pharn-build", 1), ret(9, { session: T })]; + assert.deepEqual(buildExecutions(sess).rows[0], row("pharn-build", 1, 1, 2, 3, null, "session-changed")); + reset(); + const back = [m("run-start", 0), start(20, "pharn-build", 1), ret(10)]; + assert.deepEqual(buildExecutions(back).rows[0], row("pharn-build", 1, 1, 2, 3, null, "clock-went-back")); + reset(); + const badTs = [m("run-start", 0), start(1, "pharn-build", 1), { ...ret(9), ts: "yesterday" }]; + assert.deepEqual(buildExecutions(badTs).rows[0], row("pharn-build", 1, 1, 2, 3, null, "bad-timestamp")); + reset(); + const equal = [m("run-start", 0), start(5, "pharn-build", 1), ret(5)]; + assert.equal(buildExecutions(equal).rows[0].elapsed_ms, 0, "a measured equal pair is 0 — measured, not unknown"); + assert.equal(buildExecutions(equal).rows[0].unmeasured, null); + // Every reason the table names is reachable, and only those (closure, L36). + assert.deepEqual([...UNMEASURED_REASONS].sort(), [ + "bad-timestamp", + "clock-went-back", + "foreign-work-inside", + "no-end-marker", + "no-return-marker", + "session-changed", + ]); +}); + +test("unknown current run: no run-start, or a marker after the run-stop → status unknown, NO rows", () => { + reset(); + const noStart = [start(1, "pharn-build", 1), ret(2)]; + assert.deepEqual(buildExecutions(noStart), { + method: EXECUTIONS_METHOD, + status: "unknown", + reason: UNKNOWN_REASONS.NO_RUN_START, + rows: [], + }); + reset(); + const afterStop = [m("run-start", 0), start(1, "pharn-build", 1), ret(2), m("run-stop", 3), start(4, "pharn-build", 2)]; + const ex = buildExecutions(afterStop); + assert.equal(ex.status, "unknown"); + assert.equal(ex.reason, UNKNOWN_REASONS.MARKER_AFTER_STOP); + assert.deepEqual(ex.rows, []); + assert.deepEqual(buildExecutions([]), { method: EXECUTIONS_METHOD, status: "unknown", reason: UNKNOWN_REASONS.NO_MARKERS, rows: [] }); +}); + +test("only the CURRENT run's markers count — an earlier invocation's stages are not rows", () => { + reset(); + const markers = [ + m("run-start", 0), + start(1, "pharn-build", 1), + ret(2), + m("run-stop", 3), + m("run-start", 100), + start(101, "pharn-build", 1), + ret(111), + ]; + assert.deepEqual(buildExecutions(markers).rows, [row("pharn-build", 1, 1, 6, 7, 10000)]); +}); + +test("quick mode: a stage the run skipped has NO row — nothing is represented as executed", () => { + reset(); + const markers = [ + { ...m("run-start", 0), mode: "quick" }, + start(1, "pharn-build", 1), + ret(4), + start(5, "pharn-verify", 1), // /pharn-loop --quick writes no pharn-regress stage-start + ret(9), + m("run-stop", 10), + ]; + const stages = buildExecutions(markers).rows.map((r) => r.stage); + assert.deepEqual(stages, ["pharn-build", "pharn-verify"]); + assert.ok(!stages.includes("pharn-regress")); +}); + +test("interrupted run (no run-stop, open window): every completed stage keeps its row; the unfinished one is unmeasured", () => { + reset(); + const markers = [m("run-start", 0), start(1, "pharn-spec"), ret(31), start(32, "pharn-plan"), ret(92), start(93, "pharn-grill")]; + const ex = buildExecutions(markers); + assert.equal(ex.status, "derived"); + assert.deepEqual( + ex.rows.map((r) => [r.stage, r.elapsed_ms, r.unmeasured]), + [ + ["pharn-spec", 30000, null], + ["pharn-plan", 60000, null], + ["pharn-grill", null, "no-end-marker"], + ] + ); +}); + +test("work attachment: a record attaches to the execution whose stage-start is the latest marker at-or-before it, same stage", () => { + reset(); + const markers = [ + m("run-start", 0), + start(10, "pharn-regress", 1), + ret(40), + start(41, "pharn-verify", 1), + ret(50), + start(51, "pharn-regress", 2), + ret(60), + ]; + const work = [ + { stage: "pharn-regress", ts: at(39), session_id: S }, // inside regress iter 1 + { stage: "pharn-verify", ts: at(49), session_id: S }, // inside verify iter 1 + { stage: "pharn-regress", ts: at(59), session_id: null }, // null session binds all + { stage: "pharn-verify", ts: at(58), session_id: S }, // a verify record inside a REGRESS execution: unattached + { stage: "pharn-regress", ts: at(45), session_id: T }, // another session: its latest bound marker is the run-start + ]; + const ex = buildExecutions(markers, work); + assert.deepEqual( + ex.rows.map((r) => r.work), + [[0], [1], [2]] + ); + assert.deepEqual(unattachedWork(ex, work), [3, 4]); +}); + +test("✧ PARITY with render-cost-ledger's attribute(): the latest-marker rule picks the same marker for requests and work", () => { + reset(); + const markers = [ + m("run-start", 0), + start(10, "pharn-build", 1), + ret(20), + start(20, "pharn-regress", 1), // same ts as the return: the higher seq wins in both + ret(30, { session: T }), + start(31, "pharn-verify", 1, { session: null }), + ]; + const current = currentRunMarkers(markers); + let n = 0; + for (const sec of [0, 5, 10, 15, 20, 25, 30, 31, 40]) { + for (const sid of [S, T, null]) { + const mk = latestMarkerAtOrBefore(current, at(sec), sid); + const a = attribute(markers, at(sec), sid); + assert.deepEqual({ stage: mk?.stage ?? null, iteration: mk?.iteration ?? null }, a, `ts ${at(sec)} sid ${sid}`); + n++; + } + } + assert.equal(n, 27, "non-vacuity"); +}); + +test("a null session binds any, as in attribution: a stage-start written with the variable unset still pairs", () => { + reset(); + const markers = [m("run-start", 0), start(1, "pharn-build", 1, { session: null }), ret(9)]; + assert.deepEqual(buildExecutions(markers).rows[0], row("pharn-build", 1, 1, 2, 3, 8000)); +}); + +test("GATE-2 — a skipped return AND a skipped start: another stage's work record inside the interval makes it unmeasured", () => { + reset(); + // regress's return and verify's stage-start were both skipped, so regress's "next marker" is VERIFY's return. + const markers = [m("run-start", 0), start(10, "pharn-regress", 1), ret(100), m("run-stop", 101)]; + const work = [ + { stage: "pharn-regress", ts: at(50), session_id: S }, + { stage: "pharn-verify", ts: at(99), session_id: S }, // verify's record, inside the regress interval + ]; + const ex = buildExecutions(markers, work); + assert.deepEqual(ex.rows, [row("pharn-regress", 1, 1, 2, 3, null, "foreign-work-inside", [0])]); + assert.deepEqual(unattachedWork(ex, work), [1]); + // Control: without the foreign record the same interval is measured — the BOUND the header states. + assert.equal(buildExecutions(markers, [work[0]]).rows[0].elapsed_ms, 90000); +}); + +test("GATE-2 — a duplicate seq never re-homes a work record: rows are keyed by marker, not by seq", () => { + const dup = [ + { seq: 1, kind: "run-start", stage: null, iteration: null, ts: at(0), session_id: S }, + { seq: 2, kind: "stage-start", stage: "pharn-verify", iteration: 1, ts: at(10), session_id: S }, + { seq: 3, kind: "orchestrator", stage: null, iteration: null, ts: at(20), session_id: S }, + { seq: 3, kind: "stage-start", stage: "pharn-verify", iteration: 1, ts: at(30), session_id: S }, + { seq: 4, kind: "orchestrator", stage: null, iteration: null, ts: at(40), session_id: S }, + ]; + const ex = buildExecutions(dup, [{ stage: "pharn-verify", ts: at(15), session_id: S }]); + assert.deepEqual( + ex.rows.map((r) => [r.run, r.work]), + [ + [1, [0]], + [2, []], + ] + ); +}); diff --git a/pharn/floor/stage-regress-core.mjs b/pharn/floor/stage-regress-core.mjs index eddb1d0f..4fd022ad 100644 --- a/pharn/floor/stage-regress-core.mjs +++ b/pharn/floor/stage-regress-core.mjs @@ -316,9 +316,14 @@ export function validateProgress(rec) { Array.isArray(rec.installResult) || typeof rec.installResult.ran !== "boolean" || !Number.isInteger(rec.installResult.exit) || - typeof rec.installResult.timedOut !== "boolean") + typeof rec.installResult.timedOut !== "boolean" || + // `ms` (6.35.0): the install's measured interval for the cost ledger's work record — optional, so a record + // persisted before it still resumes; when present, a non-negative safe integer or null. + (Object.hasOwn(rec.installResult, "ms") && + rec.installResult.ms !== null && + !(Number.isSafeInteger(rec.installResult.ms) && rec.installResult.ms >= 0))) ) { - return { ok: false, reason: "progress.installResult must be null or {ran, exit, timedOut}" }; + return { ok: false, reason: "progress.installResult must be null or {ran, exit, timedOut, ms?}" }; } if ( rec.cleanupResult !== null && diff --git a/pharn/floor/stage-regress.mjs b/pharn/floor/stage-regress.mjs index 235115dc..f4c83c46 100644 --- a/pharn/floor/stage-regress.mjs +++ b/pharn/floor/stage-regress.mjs @@ -122,6 +122,7 @@ import { FEATURE_SLUG_RE, SCHEMA as GATE_RUN_SCHEMA, actualForExpected } from ". import { isExcluded, ALGO as FINGERPRINT_ALGO } from "./worktree-fingerprint.mjs"; import { decideFromDisk, discardRetained, publishRecord } from "./regress-base-reuse.mjs"; import { discardOffer, publishOffer } from "./head-reuse-offer.mjs"; +import { regressWork, recordWork } from "./stage-work.mjs"; const HERE = dirname(fileURLToPath(import.meta.url)); const CHECK_PLAN_SPEC_AGREE = join(HERE, "check-plan-spec-agree.mjs"); @@ -764,6 +765,9 @@ function runPhases(state, budget) { const errFile = join(REGRESS_PATHS.root, "install.err"); // spawnGate is exported by run-gates.mjs (6.23.0) precisely so a stage script reuses the SAME // process-group/timeout/kill discipline rather than re-implementing it (P3/P4). + // The ONE timer this stage adds (6.35.0, run-performance-breakdown): the install's own interval, monotonic, + // persisted as integer ms for the cost ledger's work record. Observational — nothing decides on it. + const installStart = performance.now(); const resultPromise = spawnGate( { shell: state.install.cmd, argv: null, files: [] }, REGRESS_PATHS.base, @@ -774,7 +778,8 @@ function runPhases(state, budget) { ); return resultPromise.then((res) => { budget.spent(); - state.installResult = { ran: true, exit: res.exit, timedOut: res.timed_out }; + const ms = Math.round(performance.now() - installStart); + state.installResult = { ran: true, exit: res.exit, timedOut: res.timed_out, ms }; state.phase = "base-init"; return runPhases(state, budget); // the SAME tracker — see makeBudget's header }); @@ -932,9 +937,33 @@ function runPhases(state, budget) { } catch { /* never persisted in a single-invocation run — the normal case */ } + // The cost ledger's deterministic-work record (6.35.0, stage-work.mjs): what THIS execution ran and what it took from + // reused evidence, counted from the two stamps the verdict just used. Best-effort and observational — a failure is a + // stderr note, and the exit below is unchanged either way. + recordWork( + state.feature, + regressWork({ + headStamp: readStampOrNull(join(REGRESS_PATHS.head, "stamp.json")), + baseStamp: readStampOrNull(join(REGRESS_PATHS.baseGates, "stamp.json")), + baseReuse: state.baseReuse, + installResult: state.installResult, + ts: new Date().toISOString(), + sessionId: process.env.CLAUDE_CODE_SESSION_ID ?? null, + }), + (m) => console.error(`stage-regress: ${m}`) + ); emit(doneExit({ stage: "regress", feature: state.feature, verdict: state.report.verdict, report: reportPath, render: renderPath })); } +/** A stamp as parsed JSON, or null — for the work record only, which treats null as "cannot count". */ +function readStampOrNull(path) { + try { + return JSON.parse(readFileSync(path, "utf8")); + } catch { + return null; + } +} + /** ------------------------------------------------------------------------------------------------ * FRESH entry point. * ---------------------------------------------------------------------------------------------- */ diff --git a/pharn/floor/stage-regress.test.mjs b/pharn/floor/stage-regress.test.mjs index accb7f39..74e352eb 100644 --- a/pharn/floor/stage-regress.test.mjs +++ b/pharn/floor/stage-regress.test.mjs @@ -27,8 +27,10 @@ import { createHash } from "node:crypto"; import { tmpdir } from "node:os"; import { join, dirname } from "node:path"; import { fileURLToPath } from "node:url"; -import { REGRESS_PATHS, PROGRESS_SCHEMA } from "./stage-regress-core.mjs"; +import { REGRESS_PATHS, PROGRESS_SCHEMA, validateProgress } from "./stage-regress-core.mjs"; import { RECORD_BASENAME } from "./regress-base-reuse-core.mjs"; +import { readWork, WORK_FILE } from "./stage-work.mjs"; +import { DEFAULT_BASE as COST_BASE } from "./mark-phase.mjs"; import { REGISTRY, allReasonCodes } from "./stage-exit-core.mjs"; // A5 (GATE 2 review) — the check-loop-fresh WIRING test fabricates a verify stamp exactly the way // check-loop-fresh.test.mjs's own `iterate()` helper does: a REAL fingerprint of the live tree, and the @@ -1645,6 +1647,22 @@ test("★ HIT — a second regress of the same run, after a new build, runs HEAD assert.match(md, /BASE evidence: REUSED/); assert.match(md, /install: none run by this invocation/); assert.match(firstMd, /BASE evidence: produced by this invocation \(not reused: `no-record`\); recorded for reuse/); + // 6.35.0 — one deterministic-work record per execution, whose counts agree with what the fixture COUNTED spawning. + const { records, dropped } = readWork(join(fx.dir, COST_BASE, FEATURE, WORK_FILE)); + assert.deepEqual(dropped, []); + assert.equal(records.length, 2); + const [w1, w2] = records; + assert.equal(w1.base.evidence, "fresh"); + assert.equal(w1.base.miss, "no-record"); + assert.equal(w1.base.executed, first.counts.base); + assert.equal(w1.head.executed, first.counts.head); + assert.equal(w1.install.exit, 0); + assert.ok(Number.isSafeInteger(w1.install.ms) && w1.install.ms >= 0, "the install's interval was measured"); + assert.equal(w2.base.evidence, "reused"); + assert.equal(w2.base.executed, second.counts.base, "0 base gate processes"); + assert.equal(w2.base.reused, w2.base.required - w2.base.no_files); + assert.equal(w2.install, null, "no install"); + assert.equal(w2.head.executed, second.counts.head, "HEAD ran in full"); } finally { dropReuseRepo(fx); } @@ -1805,6 +1823,14 @@ test("HIT — a BUDGETED miss chain (continue + --resume, the pinned line's shap while (n.code === 5) n = runReuse(fx, ["--resume", "--budget-ms", "1"]); assert.equal(n.code, 0, n.raw); assert.equal(n.be.reused, true, JSON.stringify(n.be)); + // 6.35.0 — ONE work record per EXECUTION, not per invocation: every `continue` wrote none. The install interval + // measured in the invocation that ran it survived the resumes through the progress record. + const { records } = readWork(join(fx.dir, COST_BASE, FEATURE, WORK_FILE)); + assert.deepEqual( + records.map((w) => w.base.evidence), + ["fresh", "reused"] + ); + assert.ok(Number.isSafeInteger(records[0].install.ms), JSON.stringify(records[0].install)); } finally { dropReuseRepo(fx); } @@ -2378,3 +2404,27 @@ test("HEAD OFFER — published once the HEAD stamp is final, bound to its bytes dropReuseRepo(fx); } }); + +// ── 6.35.0: the install interval in the progress record ────────────────────────────────────────────────────────── +test("6.35.0 — validateProgress: installResult.ms is optional; when present a non-negative safe integer or null", () => { + const rec = (installResult) => ({ + schema: PROGRESS_SCHEMA, + feature: "demo", + timeoutMs: 540000, + budgetMs: 570000, + base: "a".repeat(40), + phase: "drain-head", + install: { kind: "cmd", cmd: "npm ci", unmeasured: false }, + e2eExcluded: [], + styleSkipped: false, + installResult, + cleanupResult: null, + baseReuse: null, + }); + assert.deepEqual(validateProgress(rec({ ran: true, exit: 0, timedOut: false })), { ok: true }, "a pre-6.35.0 record still resumes"); + assert.deepEqual(validateProgress(rec({ ran: true, exit: 0, timedOut: false, ms: 0 })), { ok: true }); + assert.deepEqual(validateProgress(rec({ ran: true, exit: 0, timedOut: false, ms: null })), { ok: true }); + for (const ms of [-1, 1.5, "10", 2 ** 60, {}]) { + assert.equal(validateProgress(rec({ ran: true, exit: 0, timedOut: false, ms })).ok, false, JSON.stringify(ms)); + } +}); diff --git a/pharn/floor/stage-verify.mjs b/pharn/floor/stage-verify.mjs index 6cdd0988..5764b014 100644 --- a/pharn/floor/stage-verify.mjs +++ b/pharn/floor/stage-verify.mjs @@ -87,6 +87,7 @@ import { createHash } from "node:crypto"; import { dirname, join } from "node:path"; import { spawnSync } from "node:child_process"; import { fileURLToPath } from "node:url"; +import { recordWork, verifyWork } from "./stage-work.mjs"; import { doneExit, refusedExit, unusableExit, continueExit, questionExit, EXIT_CODE } from "./stage-exit-core.mjs"; import { VERIFY_PATHS, @@ -415,6 +416,20 @@ function runPhases(state, budget) { writeIntoFeature(state.feature, reportPath, JSON.stringify(composed.report, null, 2) + "\n"); writeIntoFeature(state.feature, renderPath, renderDone(composed.report)); removeIfPresent(VERIFY_PATHS.stageJson); + // The cost ledger's deterministic-work record (6.35.0, stage-work.mjs): how many gate results this execution needed, + // ran, and took from the REGRESS/HEAD execution — counted from the stamp bytes the verdict just read (the reuse + // block's own binding). Best-effort and observational: a failure is a stderr note, and the exit below is unchanged. + let stampForWork; + try { + stampForWork = stampText === null ? null : JSON.parse(stampText); + } catch { + stampForWork = null; + } + recordWork( + state.feature, + verifyWork({ stamp: stampForWork, ts: new Date().toISOString(), sessionId: process.env.CLAUDE_CODE_SESSION_ID ?? null }), + (m) => console.error(`stage-verify: ${m}`) + ); emit(doneExit({ stage: "verify", feature: state.feature, verdict: composed.report.verdict, report: reportPath, render: renderPath })); } diff --git a/pharn/floor/stage-verify.test.mjs b/pharn/floor/stage-verify.test.mjs index d75687e8..d0cea66f 100644 --- a/pharn/floor/stage-verify.test.mjs +++ b/pharn/floor/stage-verify.test.mjs @@ -37,6 +37,8 @@ import { VERIFY_PATHS, PROGRESS_SCHEMA, PHASES, RESUMABLE_PHASES, validateProgre import { validateStamp, logBasename } from "./gate-run-core.mjs"; import { fingerprint } from "./worktree-fingerprint.mjs"; import { DEFAULT_STAMPS } from "./loop-fresh-core.mjs"; +import { readWork, WORK_FILE } from "./stage-work.mjs"; +import { DEFAULT_BASE as COST_BASE } from "./mark-phase.mjs"; const HERE = dirname(fileURLToPath(import.meta.url)); const REPO = join(HERE, "..", ".."); @@ -321,6 +323,35 @@ test("verdict FAIL — a red project gate is named; done is still exit 0 (the ve }); }); +test("6.35.0 OBSERVATIONAL — the work record is written at done; a planted `.pharn/cost` link refuses it and changes NOTHING else", () => { + let control; + withFixture({}, ({ dir }) => { + const r = runCli(dir, fresh()); + assert.equal(r.code, 0, r.raw); + const { records } = readWork(join(dir, COST_BASE, FEATURE, WORK_FILE)); + assert.equal(records.length, 1); + assert.equal(records[0].stage, "pharn-verify"); + assert.equal(records[0].gates.executed, records[0].gates.required, "no delivery run: every gate executed"); + control = { code: r.code, doc: r.doc, verdict: readReport(dir).verdict, gates: readReport(dir).gates }; + }); + withFixture({}, ({ dir }) => { + const elsewhere = realpathSync(mkdtempSync(join(tmpdir(), "sv-elsewhere-"))); + try { + mkdirSync(join(dir, ".pharn"), { recursive: true }); + symlinkSync(elsewhere, join(dir, COST_BASE)); + const r = runCli(dir, fresh()); + assert.equal(r.code, control.code, r.raw); + assert.deepEqual(r.doc, control.doc, "the exit document is byte-for-byte the control's"); + assert.equal(readReport(dir).verdict, control.verdict); + assert.deepEqual(readReport(dir).gates, control.gates); + assert.match(r.raw, /stage-verify: note — the deterministic-work record for the cost ledger was not written/); + assert.deepEqual(readdirSync(elsewhere), [], "nothing was written through the link"); + } finally { + rmSync(elsewhere, { recursive: true, force: true }); + } + }); +}); + test("verdict INCOMPLETE — a declared concrete path absent is exit-3-as-verdict, with completeness.missing naming it", () => { const files = ["- `src/index.js` — the feature", "- `src/index.test.js` — its test", "- `src/never-built.js` — declared, never written"]; withFixture({ files }, ({ dir }) => { @@ -1065,6 +1096,8 @@ function deliver(fx, { run = true, editBetween = null, verifyExtra = [] } = {}) stamp: JSON.parse(readFileSync(join(fx.dir, STAMP), "utf8")), fresh: loopFresh(fx), render: readFileSync(join(fx.dir, RENDER), "utf8"), + // 6.35.0: the cost ledger's deterministic-work records this delivery left (regress's, then verify's). + work: readWork(join(fx.dir, COST_BASE, FEATURE, WORK_FILE)), }; } @@ -1114,6 +1147,20 @@ test("★ REUSE — FRESH-vs-REUSE EQUIVALENCE (mandatory): same coverage, exits // Provenance MAY differ, and only there: the reused entries say so. assert.ok(reusePath.stamp.runs.some((r) => r.reason === "reused")); assert.ok(freshPath.stamp.runs.every((r) => r.ran === true)); + // 6.35.0 — the work record tells the two apart, and its counts are the stamp's: FRESH executed every required gate, + // REUSE executed the rest and reused the two verify did not spawn. Nothing dropped, one record per stage. + for (const p of [freshPath, reusePath]) { + assert.deepEqual(p.work.dropped, []); + assert.deepEqual( + p.work.records.map((w) => w.stage), + ["pharn-regress", "pharn-verify"] + ); + } + const fv = freshPath.work.records[1].gates; + const rv = reusePath.work.records[1].gates; + assert.deepEqual(fv, { required: freshPath.stamp.runs.length, executed: freshPath.stamp.runs.length, reused: 0, no_files: 0 }); + assert.deepEqual(rv, { required: reusePath.stamp.runs.length, executed: reusePath.stamp.runs.length - 2, reused: 2, no_files: 0 }); + assert.equal(fv.executed - rv.executed, freshPath.verifySpawned.length - reusePath.verifySpawned.length, "avoided = not spawned"); }); test("REUSE of a completed RED — the same FAIL verdict as a fresh run, and the red gate is not re-spawned", () => { diff --git a/pharn/floor/stage-work.mjs b/pharn/floor/stage-work.mjs new file mode 100644 index 00000000..980cd560 --- /dev/null +++ b/pharn/floor/stage-work.mjs @@ -0,0 +1,295 @@ +// pharn/floor/stage-work.mjs — the DETERMINISTIC WORK RECORD a `/pharn-regress` or `/pharn-verify` execution leaves for +// the cost ledger (`cost.json`'s `work[]`, `pharn/pharn-contracts/cost-ledger.md`, "Stage executions and deterministic +// work"). The one owner of the record's schema, its derivation, its validation, its append and its read ([[L35]]). +// +// ── WHY IT EXISTS (L42 — capture at the moment of the act) ─────────────────────────────────────────────────────── +// Whether a regress execution reused its BASE evidence (6.33.0) and how many VERIFY gate results were reused from the +// REGRESS/HEAD execution (6.34.0) is recorded in `regression-report.json`'s `base_evidence` and `verify-report.json`'s +// `gate_reuse` — and both reports are OVERWRITTEN every iteration, and the gate-run stamps are cleared at every stage's +// fresh start. So for every iteration but the last, the work actually performed or avoided is gone by the time the +// ledger is emitted. The stage script therefore appends ONE compact line at its `done` exit, derived from the evidence +// it just finished with, to `<.pharn/cost>//work.jsonl` — beside the markers the ledger already reads. +// +// ── WHAT A RECORD SAYS (schema `pharn-stage-work/1`) ───────────────────────────────────────────────────────────── +// {"schema","stage":"pharn-regress","ts","session_id", +// "head":{"required","executed","reused","no_files"}, +// "base":{"evidence":"fresh"|"reused","miss","required","executed","reused","no_files"}, +// "install":null | {"exit","timed_out","ms"}} +// {"schema","stage":"pharn-verify","ts","session_id","gates":{"required","executed","reused","no_files"}} +// Counts come from a gate-run stamp's `runs[]` (`countRuns`): `executed` = entries with `ran: true` (a process ran), +// `reused` = `reason: "reused"` (a VERIFY result taken from the REGRESS/HEAD execution), `no_files` = `reason: +// "no-files"` (nothing to run), `required` = every entry. For a BASE HIT the base stamp is the earlier execution's, so +// its `ran: true` entries did NOT run here: `executed` is 0 and `reused` = required − no_files. Invariant, checked: +// executed + reused + no_files === required. A BASE worktree was created, and an install could run, only when +// `base.evidence` is `fresh` — those facts are DERIVED from `evidence`, never stored a second time. `install` is null +// when no install ran (not configured, or skipped by reuse — `evidence` says which). +// +// ── HONEST SCOPE (P0) ──────────────────────────────────────────────────────────────────────────────────────────── +// FLOOR: the record's shape and invariants (closed keys, enums, integer compare) — `validateWork`, applied by the +// ledger emitter and checker to every line; the counts are derived by tested code from the stamp the stage just +// used for its verdict. +// ADVISORY: that a record was written for every execution (only a `done` exit writes one; a refused, unusable, +// crashed or `continue` exit writes none, so gates a stage ran before refusing are NOT recorded); that the file +// was not edited afterwards (`.pharn/` is Bash-reachable, LIMITS.md §6 — agreement, never provenance, [[L43]]). +// `install.ms` is ONE `performance.now()` interval around the install process, integer milliseconds — monotonic +// within that one process, and nothing more; a killed-and-resumed install records the run that completed. +// OBSERVATIONAL ONLY: nothing reads a record to decide a verdict, an exit, a reuse, a route or a commit. The append is +// best-effort — `appendWork` never throws; a stage whose append fails prints one note and exits exactly as before. + +import { closeSync, constants as FS, fstatSync, lstatSync, mkdirSync, openSync, readFileSync, writeSync } from "node:fs"; +import { join } from "node:path"; +import { DEFAULT_BASE, cleanScalar } from "./mark-phase.mjs"; +import { isIdentityToken, isTokenCount } from "./cost-value-core.mjs"; +import { tsMs } from "./run-window-core.mjs"; +import { FEATURE_SLUG_RE, REUSED_REASON } from "./gate-run-core.mjs"; +import { BASE_REUSE_MISSES } from "./stage-regress-core.mjs"; + +export const WORK_SCHEMA = "pharn-stage-work/1"; +/** The file, under `//`, beside `markers.jsonl`. */ +export const WORK_FILE = "work.jsonl"; +/** The two stage labels a record may carry — the `--stage` labels the orchestrators mark these stages with. */ +export const REGRESS_STAGE = "pharn-regress"; +export const VERIFY_STAGE = "pharn-verify"; +export const WORK_STAGES = Object.freeze([REGRESS_STAGE, VERIFY_STAGE]); +export const BASE_EVIDENCE = Object.freeze(["fresh", "reused"]); + +export const SIDE_KEYS = Object.freeze(["required", "executed", "reused", "no_files"]); +export const BASE_KEYS = Object.freeze(["evidence", "miss", ...SIDE_KEYS]); +export const INSTALL_KEYS = Object.freeze(["exit", "timed_out", "ms"]); +export const REGRESS_KEYS = Object.freeze(["schema", "stage", "ts", "session_id", "head", "base", "install"]); +export const VERIFY_KEYS = Object.freeze(["schema", "stage", "ts", "session_id", "gates"]); + +/** A gate set larger than this is not a gate set; it also keeps every sum below an exactness limit. */ +export const MAX_GATES = 100000; + +const isPlain = (v) => v !== null && typeof v === "object" && !Array.isArray(v) && Object.getPrototypeOf(v) === Object.prototype; +const exactKeys = (o, keys) => { + const k = Object.keys(o); + return k.length === keys.length && keys.every((x) => Object.hasOwn(o, x)); +}; + +/** The session id a record carries: the environment's value when it is a bounded identity token, else null — the + * work record is never lost over a malformed environment variable, and never carries one. */ +const sessionOrNull = (v) => (isIdentityToken(v) ? v : null); + +/** `{required, executed, reused, no_files}` over a stamp's `runs[]`, or null when `runs` is not a list of entries this + * rule can classify (a stamp the verdict accepted always is). */ +export function countRuns(stamp) { + if (!isPlain(stamp) || !Array.isArray(stamp.runs)) return null; + let executed = 0; + let reused = 0; + let noFiles = 0; + for (const r of stamp.runs) { + if (!isPlain(r)) return null; + if (r.ran === true) executed++; + else if (r.ran === false && r.reason === REUSED_REASON) reused++; + else if (r.ran === false && r.reason === "no-files") noFiles++; + else return null; + } + return { required: stamp.runs.length, executed, reused, no_files: noFiles }; +} + +/** The regress record, from the finished HEAD and BASE stamps and the stage's final reuse decision. Null when a stamp + * cannot be counted. `baseReuse` is `{reused, miss}`; `installResult` is null or `{exit, timedOut, ms?}`. TOTAL: it + * never throws (a stage script evaluates it before its `done` exit, which must not depend on it). */ +export function regressWork(input) { + try { + return regressWorkUnsafe(input); + } catch { + return null; + } +} + +function regressWorkUnsafe({ headStamp, baseStamp, baseReuse, installResult, ts, sessionId = null }) { + const head = countRuns(headStamp); + const base = countRuns(baseStamp); + if (head === null || base === null || !baseReuse || typeof baseReuse.reused !== "boolean") return null; + const reused = baseReuse.reused; + const rec = { + schema: WORK_SCHEMA, + stage: REGRESS_STAGE, + ts, + session_id: sessionOrNull(sessionId), + head, + base: reused + ? { + evidence: "reused", + miss: null, + required: base.required, + executed: 0, + reused: base.required - base.no_files, + no_files: base.no_files, + } + : { evidence: "fresh", miss: baseReuse.miss ?? null, ...base }, + install: + reused || installResult === null || installResult === undefined + ? null + : { + exit: installResult.exit, + timed_out: installResult.timedOut === true, + ms: Number.isSafeInteger(installResult.ms) && installResult.ms >= 0 ? installResult.ms : null, + }, + }; + return validateWork(rec).ok ? rec : null; +} + +/** The verify record, from the finished verify stamp. Null when the stamp cannot be counted. TOTAL, like `regressWork`. */ +export function verifyWork(input) { + try { + const { stamp, ts, sessionId = null } = input; + const gates = countRuns(stamp); + if (gates === null) return null; + const rec = { schema: WORK_SCHEMA, stage: VERIFY_STAGE, ts, session_id: sessionOrNull(sessionId), gates }; + return validateWork(rec).ok ? rec : null; + } catch { + return null; + } +} + +function sideDefect(s, path) { + if (!isPlain(s)) return `${path} is not an object`; + for (const k of SIDE_KEYS) { + if (!isTokenCount(s[k]) || s[k] > MAX_GATES) return `${path}.${k} is not a count in 0..${MAX_GATES}`; + } + if (s.executed + s.reused + s.no_files !== s.required) return `${path}: executed + reused + no_files !== required`; + return null; +} + +/** + * Validate one record. Total over any parsed JSON value ([[L62]]): every value is type-tested before it is read as + * anything, and no refusal quotes the value. Returns `{ok: true}` or `{ok: false, reason}`. + */ +export function validateWork(rec) { + const bad = (reason) => ({ ok: false, reason }); + if (!isPlain(rec)) return bad("not an object"); + if (rec.schema !== WORK_SCHEMA) return bad("schema"); + if (!WORK_STAGES.includes(rec.stage)) return bad("stage"); + if (!exactKeys(rec, rec.stage === REGRESS_STAGE ? REGRESS_KEYS : VERIFY_KEYS)) return bad("key set"); + if (!cleanScalar(rec.ts, 64) || tsMs(rec.ts) === null) return bad("ts"); + if (rec.session_id !== null && !isIdentityToken(rec.session_id)) return bad("session_id"); + if (rec.stage === VERIFY_STAGE) { + const d = sideDefect(rec.gates, "gates"); + return d === null ? { ok: true } : bad(d); + } + const h = sideDefect(rec.head, "head"); + if (h !== null) return bad(h); + const b = rec.base; + if (!isPlain(b) || !exactKeys(b, BASE_KEYS)) return bad("base key set"); + const bd = sideDefect(b, "base"); + if (bd !== null) return bad(bd); + if (!BASE_EVIDENCE.includes(b.evidence)) return bad("base.evidence"); + if (b.evidence === "reused") { + if (b.miss !== null || b.executed !== 0 || rec.install !== null) return bad("a reused BASE has no miss, executed 0 and no install"); + } else if (b.reused !== 0 || (b.miss !== null && !BASE_REUSE_MISSES.includes(b.miss))) { + return bad("a fresh BASE reuses nothing and names a closed miss code (or null)"); + } + const i = rec.install; + if (i !== null) { + if (!isPlain(i) || !exactKeys(i, INSTALL_KEYS)) return bad("install key set"); + if (!Number.isSafeInteger(i.exit)) return bad("install.exit"); + if (typeof i.timed_out !== "boolean") return bad("install.timed_out"); + if (i.ms !== null && !isTokenCount(i.ms)) return bad("install.ms"); + } + return { ok: true }; +} + +/** + * Append one record as one JSON line to `///work.jsonl`. BEST-EFFORT and TOTAL: never throws; + * returns `{ok: true}` or `{ok: false, why}`. Refuses (writes nothing) when a record is invalid, the feature is not a + * slug, or any directory component under `root` is a symlink or not a directory ([[L54]]/[[L59]]: lstat, never + * followed), and opens the file with `O_NOFOLLOW | O_NONBLOCK` so a link planted at the file is refused, not followed, + * and a FIFO planted there fails the open (ENXIO with no reader) or the regular-file test instead of BLOCKING the stage + * before its `done` exit (GATE-2 review: a plain open hung on a planted FIFO, reproduced). + */ +export function appendWork({ feature, record, root = ".", base = DEFAULT_BASE }) { + try { + if (typeof feature !== "string" || !FEATURE_SLUG_RE.test(feature)) return { ok: false, why: "feature is not a slug" }; + if (!validateWork(record).ok) return { ok: false, why: "record is not a valid work record" }; + const segments = [ + ...String(base) + .split("/") + .filter((s) => s && s !== "."), + feature, + ]; + if (segments.some((s) => s === "..")) return { ok: false, why: "base names a parent directory" }; + let dir = root; + for (const seg of segments) { + dir = join(dir, seg); + let st = null; + try { + st = lstatSync(dir); + } catch (e) { + if (e.code !== "ENOENT") return { ok: false, why: `cannot lstat a state directory (${e.code})` }; + } + if (st === null) mkdirSync(dir); + else if (st.isSymbolicLink() || !st.isDirectory()) + return { ok: false, why: "a state directory component is a symlink or not a directory" }; + } + const flags = FS.O_WRONLY | FS.O_APPEND | FS.O_CREAT | (FS.O_NOFOLLOW ?? 0) | (FS.O_NONBLOCK ?? 0); + const fd = openSync(join(dir, WORK_FILE), flags, 0o644); + try { + if (!fstatSync(fd).isFile()) return { ok: false, why: "the work file is not a regular file" }; + writeSync(fd, `${JSON.stringify(record)}\n`); + } finally { + closeSync(fd); + } + return { ok: true }; + } catch (e) { + return { ok: false, why: `append failed (${e && typeof e.code === "string" ? e.code : "error"})` }; + } +} + +/** A work file larger than this is not read (its records are dropped as one `work.jsonl` entry). One line per stage + * execution is ~300 bytes, so this is millions of executions. */ +export const WORK_FILE_MAX_BYTES = 16 * 1024 * 1024; + +/** + * Read a work file: `{records, dropped}`. `records` are the lines `validateWork` accepts, in file order; `dropped` + * lists `work.jsonl[]` for every other non-empty line — n is its index among the FILE's non-empty lines, across every + * run the file has seen (the file is never pruned), not an index into a ledger's `work[]`; a torn final line from an + * interrupted append included. No raw value is ever copied into `dropped`. A missing file is `{[], []}`. A path that is + * not a regular file (a symlink — `O_NOFOLLOW` —, a FIFO — `O_NONBLOCK`, never blocking —, a directory) or is larger + * than `WORK_FILE_MAX_BYTES` is `{[], ["work.jsonl"]}`: nothing is read through it, and its presence is listed. + */ +export function readWork(file) { + let text; + let fd = null; + try { + fd = openSync(file, FS.O_RDONLY | (FS.O_NOFOLLOW ?? 0) | (FS.O_NONBLOCK ?? 0)); + const st = fstatSync(fd); + if (!st.isFile() || st.size > WORK_FILE_MAX_BYTES) return { records: [], dropped: [WORK_FILE] }; + text = readFileSync(fd, "utf8"); + } catch (e) { + return { records: [], dropped: e && e.code === "ENOENT" ? [] : [WORK_FILE] }; + } finally { + if (fd !== null) closeSync(fd); + } + const records = []; + const dropped = []; + let n = 0; + for (const line of text.split("\n")) { + if (!line) continue; + let rec; + try { + rec = JSON.parse(line); + } catch { + rec = undefined; + } + if (rec !== undefined && validateWork(rec).ok) records.push(rec); + else dropped.push(`${WORK_FILE}[${n}]`); + n++; + } + return { records, dropped }; +} + +/** The stage scripts' one call: derive nothing here, append the record they built, and say so on stderr when it could + * not be written — the stage's exit never depends on it. */ +export function recordWork(feature, record, note = (m) => process.stderr.write(`${m}\n`)) { + if (record === null) { + note("note — no deterministic-work record was written for the cost ledger (the stage's evidence could not be counted)"); + return { ok: false, why: "no record" }; + } + const r = appendWork({ feature, record }); + if (!r.ok) note(`note — the deterministic-work record for the cost ledger was not written (${r.why})`); + return r; +} diff --git a/pharn/floor/stage-work.test.mjs b/pharn/floor/stage-work.test.mjs new file mode 100644 index 00000000..de93dbdb --- /dev/null +++ b/pharn/floor/stage-work.test.mjs @@ -0,0 +1,315 @@ +// pharn/floor/stage-work.test.mjs — the deterministic-work record (`pharn-stage-work/1`): derivation from gate-run +// stamp shapes, the invariants, hostile lines, and the best-effort append's refusals. Expectations are independent +// literals (L43). + +import { test } from "node:test"; +import assert from "node:assert/strict"; +import { mkdtempSync, mkdirSync, readFileSync, rmSync, symlinkSync, writeFileSync, existsSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { execFileSync, spawnSync } from "node:child_process"; +import { join } from "node:path"; +import { + countRuns, + regressWork, + verifyWork, + validateWork, + appendWork, + readWork, + recordWork, + WORK_SCHEMA, + WORK_FILE, + WORK_STAGES, +} from "./stage-work.mjs"; +import { DEFAULT_BASE } from "./mark-phase.mjs"; +import { ITERATED_STAGES } from "./stage-agent-core.mjs"; + +const TS = "2026-09-28T10:00:00.000Z"; +const S = "00000000-0000-4000-8000-00000000aaaa"; +const ran = (id) => ({ id, ran: true, exit: 0 }); +const noFiles = (id) => ({ id, ran: false, reason: "no-files", exit: 0 }); +const reusedRun = (id) => ({ + id, + ran: false, + reason: "reused", + exit: 0, + reused: { stage: "regress", side: "head", seq: 0, stamp_sha256: "a".repeat(64) }, +}); +const stamp = (runs) => ({ schema: "pharn-gate-run/1", runs }); + +test("countRuns: executed / reused / no-files / required from runs[] — and refuses what it cannot classify", () => { + assert.deepEqual(countRuns(stamp([ran("a"), noFiles("test"), reusedRun("b"), reusedRun("c"), ran("reconcile")])), { + required: 5, + executed: 2, + reused: 2, + no_files: 1, + }); + assert.deepEqual(countRuns(stamp([])), { required: 0, executed: 0, reused: 0, no_files: 0 }); + assert.equal(countRuns(stamp([{ id: "x", ran: false, reason: "mystery" }])), null); + assert.equal(countRuns(null), null); + assert.equal(countRuns({ runs: "no" }), null); + assert.equal(countRuns(stamp([null])), null); +}); + +test("regress, FRESH BASE: the base stamp's own counts, the miss code, and the install with its measured ms", () => { + const rec = regressWork({ + headStamp: stamp([ran("lint"), noFiles("test"), ran("build")]), + baseStamp: stamp([ran("lint"), noFiles("test"), ran("build")]), + baseReuse: { reused: false, miss: "no-record" }, + installResult: { ran: true, exit: 0, timedOut: false, ms: 41234 }, + ts: TS, + sessionId: S, + }); + assert.deepEqual(rec, { + schema: WORK_SCHEMA, + stage: "pharn-regress", + ts: TS, + session_id: S, + head: { required: 3, executed: 2, reused: 0, no_files: 1 }, + base: { evidence: "fresh", miss: "no-record", required: 3, executed: 2, reused: 0, no_files: 1 }, + install: { exit: 0, timed_out: false, ms: 41234 }, + }); +}); + +test("regress, REUSED BASE: 0 base processes, every result from earlier evidence, no install — even if the old stamp says ran", () => { + const rec = regressWork({ + headStamp: stamp([ran("lint"), ran("build")]), + baseStamp: stamp([ran("lint"), ran("build")]), // the EARLIER execution's stamp: its ran:true did not run here + baseReuse: { reused: true, miss: null }, + installResult: null, + ts: TS, + }); + assert.deepEqual(rec.base, { evidence: "reused", miss: null, required: 2, executed: 0, reused: 2, no_files: 0 }); + assert.equal(rec.install, null); + assert.equal(rec.session_id, null); +}); + +test("regress: an install with no measured interval (a record persisted before 6.35.0) is ms null, never 0", () => { + const rec = regressWork({ + headStamp: stamp([ran("a")]), + baseStamp: stamp([ran("a")]), + baseReuse: { reused: false, miss: "no-delivery-run" }, + installResult: { ran: true, exit: 1, timedOut: true }, + ts: TS, + }); + assert.deepEqual(rec.install, { exit: 1, timed_out: true, ms: null }); +}); + +test("verify: fresh gates vs partially reused gates", () => { + const fresh = verifyWork({ stamp: stamp([ran("test"), ran("lint"), ran("build"), ran("reconcile")]), ts: TS, sessionId: S }); + assert.deepEqual(fresh.gates, { required: 4, executed: 4, reused: 0, no_files: 0 }); + const partial = verifyWork({ stamp: stamp([ran("test"), reusedRun("lint"), reusedRun("build"), ran("reconcile")]), ts: TS }); + assert.deepEqual(partial.gates, { required: 4, executed: 2, reused: 2, no_files: 0 }); + assert.equal(verifyWork({ stamp: null, ts: TS }), null, "an uncountable stamp yields no record, never a zero record"); +}); + +test("the derivations are TOTAL: no input makes them throw (a stage evaluates them before its done exit)", () => { + for (const bad of [undefined, null, 5, "x", {}, { baseReuse: null }, { headStamp: { runs: [{ ran: true }] }, baseStamp: { runs: [] } }]) { + assert.equal(regressWork(bad), null); + assert.equal(verifyWork(bad), null); + } +}); + +test("a malformed session id in the environment becomes null — the record is kept, the value is not", () => { + const rec = verifyWork({ stamp: stamp([ran("a")]), ts: TS, sessionId: "/Users/x/evil\n" }); + assert.equal(rec.session_id, null); +}); + +test("validateWork: closed keys, enums and the count invariant — each broken one is refused", () => { + const good = regressWork({ + headStamp: stamp([ran("a")]), + baseStamp: stamp([ran("a")]), + baseReuse: { reused: false, miss: null }, + installResult: null, + ts: TS, + }); + assert.deepEqual(validateWork(good), { ok: true }); + const mut = (f) => { + const c = structuredClone(good); + f(c); + return validateWork(c).ok; + }; + assert.equal( + mut((c) => (c.extra = 1)), + false, + "extra key" + ); + assert.equal( + mut((c) => delete c.install), + false, + "missing key" + ); + assert.equal( + mut((c) => (c.head.executed = 5)), + false, + "executed + reused + no_files !== required" + ); + assert.equal( + mut((c) => (c.base.evidence = "maybe")), + false, + "evidence enum" + ); + assert.equal( + mut((c) => (c.base.miss = "because")), + false, + "miss enum" + ); + assert.equal( + mut((c) => (c.base.reused = 1)), + false, + "a fresh BASE reuses nothing" + ); + assert.equal( + mut((c) => { + c.base = { evidence: "reused", miss: null, required: 1, executed: 1, reused: 0, no_files: 0 }; + }), + false, + "a reused BASE executes nothing" + ); + assert.equal( + mut((c) => { + c.base = { evidence: "reused", miss: null, required: 1, executed: 0, reused: 1, no_files: 0 }; + c.install = { exit: 0, timed_out: false, ms: 1 }; + }), + false, + "a reused BASE ran no install" + ); + assert.equal( + mut((c) => (c.ts = "2026-09-28")), + false, + "ts" + ); + assert.equal( + mut((c) => (c.head.required = 1e9)), + false, + "an implausible gate count" + ); + assert.equal( + mut((c) => (c.stage = "pharn-build")), + false, + "stage enum" + ); +}); + +test("hostile lines are dropped by index, never crash, and never copy their value (L62)", () => { + const dir = mkdtempSync(join(tmpdir(), "stage-work-")); + try { + const good = verifyWork({ stamp: stamp([ran("a")]), ts: TS }); + const lines = [ + JSON.stringify(good), + '{"toString":1}', + '{"__proto__":{"polluted":1},"schema":"pharn-stage-work/1"}', + JSON.stringify({ ...good, gates: { required: "1", executed: 1, reused: 0, no_files: 0 } }), + JSON.stringify({ ...good, gates: { required: 2 ** 60, executed: 2 ** 60, reused: 0, no_files: 0 } }), + "[1,2,3]", + "null", + JSON.stringify(good).slice(0, 20), // a torn final line + ]; + const f = join(dir, WORK_FILE); + writeFileSync(f, lines.join("\n")); + const { records, dropped } = readWork(f); + assert.deepEqual(records, [good]); + assert.deepEqual( + dropped, + [1, 2, 3, 4, 5, 6, 7].map((n) => `work.jsonl[${n}]`) + ); + assert.equal({}.polluted, undefined); + assert.deepEqual(readWork(join(dir, "absent.jsonl")), { records: [], dropped: [] }); + } finally { + rmSync(dir, { recursive: true, force: true }); + } +}); + +test("appendWork: writes one line under /<.pharn/cost>//, beside the markers (the one DEFAULT_BASE)", () => { + const root = mkdtempSync(join(tmpdir(), "stage-work-")); + try { + const rec = verifyWork({ stamp: stamp([ran("a")]), ts: TS }); + assert.deepEqual(appendWork({ feature: "feat", record: rec, root }), { ok: true }); + assert.deepEqual(appendWork({ feature: "feat", record: rec, root }), { ok: true }); + const f = join(root, DEFAULT_BASE, "feat", WORK_FILE); + assert.deepEqual(readWork(f).records, [rec, rec]); + } finally { + rmSync(root, { recursive: true, force: true }); + } +}); + +test("appendWork REFUSES — writes nothing, never throws — on a symlinked component, a link at the file, a bad slug (L54/L59)", () => { + const root = mkdtempSync(join(tmpdir(), "stage-work-")); + const elsewhere = mkdtempSync(join(tmpdir(), "stage-work-target-")); + try { + const rec = verifyWork({ stamp: stamp([ran("a")]), ts: TS }); + // 1. `.pharn` itself is a link. + symlinkSync(elsewhere, join(root, ".pharn")); + const a = appendWork({ feature: "feat", record: rec, root }); + assert.equal(a.ok, false); + assert.equal(existsSync(join(elsewhere, "cost")), false, "nothing was written through the link"); + rmSync(join(root, ".pharn")); + // 2. A DANGLING link at the file. + mkdirSync(join(root, ".pharn", "cost", "feat"), { recursive: true }); + symlinkSync(join(elsewhere, "target.jsonl"), join(root, ".pharn", "cost", "feat", WORK_FILE)); + const b = appendWork({ feature: "feat", record: rec, root }); + assert.equal(b.ok, false); + assert.equal(existsSync(join(elsewhere, "target.jsonl")), false, "O_NOFOLLOW: the dangling link was not followed"); + // 3. A file where a directory must be. + rmSync(join(root, ".pharn"), { recursive: true }); + mkdirSync(join(root, ".pharn")); + writeFileSync(join(root, ".pharn", "cost"), "x"); + assert.equal(appendWork({ feature: "feat", record: rec, root }).ok, false); + // 4. Bad slug / invalid record. + assert.equal(appendWork({ feature: "../x", record: rec, root }).ok, false); + assert.equal(appendWork({ feature: "feat", record: { schema: WORK_SCHEMA }, root }).ok, false); + } finally { + rmSync(root, { recursive: true, force: true }); + rmSync(elsewhere, { recursive: true, force: true }); + } +}); + +test("recordWork: a null record or a failed append is ONE note, and returns — the caller's exit never depends on it", () => { + const notes = []; + assert.equal(recordWork("feat", null, (m) => notes.push(m)).ok, false); + assert.equal(notes.length, 1); + assert.match(notes[0], /no deterministic-work record was written/); +}); + +test("the two stage labels are the orchestrators' own iterated stage labels (parity with stage-agent-core, not an import)", () => { + for (const s of WORK_STAGES) assert.ok(ITERATED_STAGES.includes(s), s); + assert.deepEqual([...WORK_STAGES], ["pharn-regress", "pharn-verify"]); + assert.equal( + readFileSync(new URL("./stage-work.mjs", import.meta.url), "utf8").includes('".pharn/cost"'), + false, + "L41: no second literal" + ); +}); + +test("GATE-2 — a FIFO planted at work.jsonl never blocks: the append refuses and the read lists it, both promptly", () => { + const root = mkdtempSync(join(tmpdir(), "stage-work-fifo-")); + try { + const dir = join(root, ".pharn", "cost", "feat"); + mkdirSync(dir, { recursive: true }); + execFileSync("mkfifo", [join(dir, WORK_FILE)]); + const rec = verifyWork({ stamp: stamp([ran("a")]), ts: TS }); + // Run in a child with a timeout: a blocking open would hang THIS process, which is the defect under test. + const probe = `import { appendWork, readWork } from ${JSON.stringify(new URL("./stage-work.mjs", import.meta.url).href)}; + const a = appendWork({ feature: "feat", record: ${JSON.stringify(rec)}, root: ${JSON.stringify(root)} }); + const r = readWork(${JSON.stringify(join(dir, WORK_FILE))}); + process.stdout.write(JSON.stringify({ a, r }));`; + const out = spawnSync(process.execPath, ["--input-type=module", "-e", probe], { encoding: "utf8", timeout: 10000 }); + assert.equal(out.signal, null, "the probe was killed by the timeout: the FIFO blocked"); + const { a, r } = JSON.parse(out.stdout); + assert.equal(a.ok, false); + assert.deepEqual(r, { records: [], dropped: ["work.jsonl"] }); + } finally { + rmSync(root, { recursive: true, force: true }); + } +}); + +test("readWork: a symlink at the file is not followed — listed, nothing read through it", () => { + const root = mkdtempSync(join(tmpdir(), "stage-work-link-")); + try { + const good = verifyWork({ stamp: stamp([ran("a")]), ts: TS }); + writeFileSync(join(root, "real.jsonl"), JSON.stringify(good) + "\n"); + symlinkSync(join(root, "real.jsonl"), join(root, WORK_FILE)); + assert.deepEqual(readWork(join(root, WORK_FILE)), { records: [], dropped: ["work.jsonl"] }); + } finally { + rmSync(root, { recursive: true, force: true }); + } +}); diff --git a/pharn/pharn-contracts/cost-ledger.md b/pharn/pharn-contracts/cost-ledger.md index 01675166..32be0fe8 100644 --- a/pharn/pharn-contracts/cost-ledger.md +++ b/pharn/pharn-contracts/cost-ledger.md @@ -105,6 +105,34 @@ tagged `pharn-loop`**, with no sub-stage named anywhere. The field is therefore "context": "agent:", "contexts": ["agent:", "agent:"], }, + "executions": { + "method": "stage-start-to-return/1", + "status": "derived", + "reason": null, + "rows": [ + { + "stage": "pharn-regress", + "iteration": 1, + "run": 1, + "start_seq": 7, + "end_seq": 8, + "elapsed_ms": 412345, + "unmeasured": null, + "work": [0], + }, + ], + }, + "work": [ + { + "schema": "pharn-stage-work/1", + "stage": "pharn-regress", + "ts": "…", + "session_id": "…", + "head": { "required": 4, "executed": 3, "reused": 0, "no_files": 1 }, + "base": { "evidence": "fresh", "miss": "no-record", "required": 4, "executed": 3, "reused": 0, "no_files": 1 }, + "install": { "exit": 0, "timed_out": false, "ms": 41234 }, + }, + ], } ``` @@ -152,6 +180,8 @@ satisfied by a variant spelling of any member; closure is what makes a variant f | `membership.context` / `contexts` | a measured ledger: a context key and a sorted, duplicate-free, non-empty list of context keys that includes it; otherwise both `null` | FLOOR (shape + set membership); the VALUE **ADVISORY** without `--verify-transcript` | | every `requests[]` row | a MEMBER of that recomputed window, and (`run-window/2`) its context one of `contexts` | FLOOR (ordering test + set membership) | | `membership.excluded_requests` | an integer (known window) or `null` (unknown) — its VALUE | **ADVISORY** without `--verify-transcript`; with it, a RANGE (rule 6) | +| `executions` | (6.35.0) `{method, status, reason, rows}`, equal to `buildExecutions` recomputed from `markers[]` and `work[]` | FLOOR (recompute + equality, rule 9); what an interval MEANS **ADVISORY** | +| `work[]` | (6.35.0) `pharn-stage-work/1` records: closed keys, enums, `executed + reused + no_files = required`; each a MEMBER of the recomputed window | FLOOR (enum + integer compare, rule 9); that the record is true **ADVISORY** | **One row per request, and which of its transcript lines each value comes from (6.24.1).** `dedup_key` names the grouping. The platform writes one API request to the transcript as several lines, sometimes in more than one @@ -844,10 +874,92 @@ every aggregate is recomputable from its own rows. of that conjunction is load-bearing, because `markers[]` is copied from a file a different process wrote at wall-clock time. +## Stage executions and deterministic work (6.35.0) + +Two keys answer, for one run, **where the observed wall-clock time went** and **which deterministic gate work ran +or was avoided by reuse** — beside the model usage above, never folded into it. They are appended after +`membership` on every `/2` ledger the emitter writes since 6.35.0, the `unavailable` and context-unknown shells +included: timing needs only markers, so a run whose transcript is gone still has its intervals. **No schema bump:** +the change is additive and no existing field changes meaning. The checker admits, for `/2`, EXACTLY the current key +set or the pre-6.35.0 set with neither key (`TOP_LEVEL_KEYS_PRE_WORK`); one key without the other is RED. A `/1` +ledger has neither. + +### `executions` — a VIEW over `markers[]` (method `stage-start-to-return/1`) + +No new marker, no new marker field, and no change to the line `mark-phase.mjs` prints (that line binds the run to +its context; this view reads no transcript). The one implementation is `pharn/floor/stage-executions-core.mjs`, +whose header holds the rule; in short, over the CURRENT run's markers (`currentRunMarkers`): + +- every `stage-start` is ONE row `{stage, iteration, run, start_seq, end_seq, elapsed_ms, unmeasured, work}`; + `run` numbers rows sharing `(stage, iteration)` in `seq` order, so a freshness re-run or a re-plan is `run 2`, + never merged into run 1; +- its end is the NEXT marker, and only when that marker is an `orchestrator` return. Otherwise the row is + UNMEASURED with a closed reason — `no-end-marker`, `no-return-marker`, `session-changed` (two different non-null + sessions; a null binds any, as in attribution), `bad-timestamp`, `clock-went-back`, `foreign-work-inside` — and + `elapsed_ms: null`. **The next stage-start or a `run-stop` is never used as an end.** So a stage that STOPs a + `/pharn-ship` run (its next marker is `run-stop`) is `no-return-marker`; its work record, written before the stop, + still shows what it ran; +- **one bound the markers cannot close, stated:** when a stage's return AND the next stage's start are both skipped, + the next marker is the LATER stage's return, and the markers alone cannot tell. A work record of another stage + inside the interval is the one evidence that can, and makes the row `foreign-work-inside`; a double skip around + stages that write no work record reads as one long execution; +- **`elapsed_ms: null` means not measured; `0` means measured equal.** Unknown is never zero, in the file or in any + rendering; +- when the markers do not describe one run (`runWindow(markers, null)` is unknown) the view is + `status: "unknown"` with that reason and no rows. A CONTEXT-unknown ledger keeps its rows. +- A stage a run skipped (`pharn-regress` under `--quick`, `pharn-spec` in `/pharn-ship`, which marks no spec + stage-start because the spec IS GATE 1) has no row: nothing is represented as executed. + +**What an interval MEANS is ADVISORY, and the label travels with it.** It is OBSERVED WALL-CLOCK time between two +`toISOString()` reads by two short-lived processes — not CPU time, not model time, not tool time, not monotonic (a +clock step moves it) — and it includes orchestration, subprocesses, waiting and any human answer given inside the +stage. **Nothing decomposes it**: stage elapsed minus anything is not model time, and no such number is written. + +### `work[]` — FACTS a stage script records at `done` (`pharn-stage-work/1`) + +Whether a regress execution reused its BASE evidence and how many VERIFY results were reused is recorded in the two +reports — which every iteration OVERWRITES — and the gate-run stamps are cleared at every fresh start. So +`/pharn-regress` and `/pharn-verify` (`stage-regress.mjs`, `stage-verify.mjs`) each append ONE line at their `done` +exit to `<.pharn/cost>//work.jsonl`, beside `markers.jsonl`, counted by `pharn/floor/stage-work.mjs` (the +record's one owner, whose header is its spec) from the stamp the verdict just used: + +- `required` = the stamp's entries; `executed` = `ran: true` (a process ran); `reused` = `reason: "reused"` (a + VERIFY result from the REGRESS/HEAD execution, 6.34.0); `no_files` = nothing to run. Invariant, checked: + `executed + reused + no_files = required`. +- regress: `head`; `base` with `evidence` `fresh` | `reused` (6.33.0) and the decision's closed `miss` code. A BASE + HIT has `executed: 0` and `reused = required − no_files`, even though the reused stamp's own entries record `ran` + as true: they ran in an EARLIER execution. Those two counts follow from `evidence` and are stored anyway, so every + side carries the same four counts and one invariant. `install` is `null` (none ran) or `{exit, timed_out, ms}`. + **Worktree creation and install skipping are not stored at all**: both happen iff `evidence` is `fresh`, and are + read from it. +- verify: `gates` (`reconcile` included). +- `install.ms` is the ONE new timer: `performance.now()` around the install process, integer milliseconds, carried + through a budget `continue` by the progress record. No gate process is timed. + +The emitter copies a record into `work[]` only when it passes `validateWork` and is a MEMBER of the run window +(`isMember`, the test every request row passes). A line that fails is not a row: `work.jsonl[]` joins `dropped[]` +— `n` is its line index in the whole file, across every run the file has seen, not an index into `work[]` — and no +value of it is copied. A path that is not a regular file (a link, a FIFO) is never read through and is listed as +`work.jsonl`. A `--verify-transcript` re-derivation reads no live work file. `executions.rows[].work` lists the +`work[]` indices attached to each execution: the record's +own stage, found by the latest-marker-at-or-before rule `attribute()` applies to requests (a ✧ parity test pins the +two). A record attached to no execution is shown, never merged. + +**Bounds, each stated.** Only a `done` exit writes a record: gates a stage ran before refusing, crashing or being +killed are NOT recorded (`work-on-non-done-exit`). The file is never pruned: one line per execution, standalone runs +included, in disposable `.pharn/` scratch. The append is best-effort and OBSERVATIONAL — it refuses a symlinked or +non-directory component, opens with `O_NOFOLLOW | O_NONBLOCK` (a planted FIFO is refused, never blocked on), never +throws, and a failure is one stderr note; +nothing reads a record to decide a verdict, an exit, a reuse, a route or a commit. `work.jsonl` is `.pharn/` state a +Bash write reaches (LIMITS.md §6): the checker certifies agreement between the file's facts and its view, never that +the records or markers are true (L43). `--verify-transcript` does not compare either key: neither is +transcript-derived. No per-gate duration is measured (`gate-process-duration`). + ## Size, disclosed rather than discovered -**The layout (since 6.14.1).** The file is pretty-printed at a 2-space indent, except the two FACT arrays, -`markers[]` and `requests[]`. Each of their elements is written as one JSON value on one `\n`-delimited line. +**The layout (since 6.14.1).** The file is pretty-printed at a 2-space indent, except the FACT arrays, +`markers[]`, `requests[]` and (6.35.0) `work[]`, and the `executions.rows` view. Each of their elements is written as +one JSON value on one `\n`-delimited line. An empty fact array is `[]`. The derived views stay pretty-printed, because they are what a person reads to learn the cost. `JSON.parse` of the file is exactly what it was under the old layout, key order included. `render-cost-ledger.mjs`'s `serializeLedger` is the one implementation, and both CLI output paths use it.