Gate calls take 45 s; per-step wall time is not recorded

jared commented

2026-09-03 20:22:42 +00:00

Owner

Context

On 2026-09-03, implementation 4 of ticket 524 ran dispatches 27 and 30 through the os-sdlc-runner gate. Each os-sdlc-runner gate call took 44 to 46 seconds. The first call took 408 seconds.

Observed

Component timings measured separately do not add up to the observed gate wall time.

diff-test: ~1 s
rubocop --format json <file>: 0.67 s (cold)
runner boot: <0.5 s
full suite: 16 s

Sum of measured components is far below the observed 44-46 s per gate call.

step_results holds only a created_at column. It has no started_at/finished_at pair, so per-step duration cannot be read from the database for a completed run.

Reproduce

os-sdlc-runner gate <ticket>
# repeat in a fresh worktree; query step_results for the run and compare durations to the 45 s total

Expected

def test_step_results_records_per_step_duration
  # arrange: run GateEvaluator against a ticket with multiple steps
  # act: read step_results for the run
  # assert: each row has started_at and finished_at (or duration_ms), and the durations sum close to observed wall time
end

Origin

Trigger: os-sdlc-runner gate calls during implementation 4 of ticket 524 (dispatches 27, 30)
Improvised this session: none
Chain: unexplained 45 s gate wall time ← step_results lacks started_at/finished_at ← DESIGN (GateEvaluator/GateVerdict only record created_at)
Root candidate: this ticket
Where: plugins/os-sdlc/lib/os_sdlc/runner/gate_evaluator.rb, plugins/os-sdlc/lib/os_sdlc/runner/gate_verdict.rb
Session: ae931982-f255-4800-b06a-0d845d6b1df7
Transcript: n/a

## Context On 2026-09-03, implementation 4 of ticket 524 ran dispatches 27 and 30 through the os-sdlc-runner gate. Each `os-sdlc-runner gate` call took 44 to 46 seconds. The first call took 408 seconds. ## Observed Component timings measured separately do not add up to the observed gate wall time. ``` diff-test: ~1 s rubocop --format json <file>: 0.67 s (cold) runner boot: <0.5 s full suite: 16 s ``` ``` Sum of measured components is far below the observed 44-46 s per gate call. ``` step_results holds only a created_at column. It has no started_at/finished_at pair, so per-step duration cannot be read from the database for a completed run. ## Reproduce ``` os-sdlc-runner gate <ticket> # repeat in a fresh worktree; query step_results for the run and compare durations to the 45 s total ``` ## Expected ```ruby def test_step_results_records_per_step_duration # arrange: run GateEvaluator against a ticket with multiple steps # act: read step_results for the run # assert: each row has started_at and finished_at (or duration_ms), and the durations sum close to observed wall time end ``` ## Origin - Trigger: os-sdlc-runner gate calls during implementation 4 of ticket 524 (dispatches 27, 30) - Improvised this session: none - Chain: unexplained 45 s gate wall time ← step_results lacks started_at/finished_at ← DESIGN (GateEvaluator/GateVerdict only record created_at) - Root candidate: this ticket - Where: plugins/os-sdlc/lib/os_sdlc/runner/gate_evaluator.rb, plugins/os-sdlc/lib/os_sdlc/runner/gate_verdict.rb - Session: ae931982-f255-4800-b06a-0d845d6b1df7 - Transcript: n/a

jared added the

plugin/os-sdlc

filed-by/agent

labels

2026-09-03 20:22:42 +00:00

jared referenced this issue from a commit

2026-09-03 20:24:17 +00:00

feat(os-sdlc): implement-speed fixes — richer briefs, rubocop server, stall detection

jared commented

2026-09-09 22:00:46 +00:00

Author

Owner

Work started via /os-sdlc:implement on branch ticket-528 (session 83ad9fea-87af-476e-8a40-e8c253061473). First run through the rewired map (audit tail once per ticket, change-auditor).

jared commented

2026-09-10 12:53:14 +00:00

Author

Owner

Work resumed on branch ticket-528 via /os-sdlc:implement (session a29eac7b). Pipeline run continues from the worktree.

jared commented

2026-09-10 12:56:24 +00:00

Author

Owner

Pipeline run blocked (implementation 8, session a29eac7b). Failed step: change-auditor, dispatch 136, verdict error (stopped_without_handoff). Cause: the change-auditor's sandbox guard blocked every write of its handoff payload (heredocs, redirects, and quoted '->' text are refused for the read-only role); an empty subagent-stop payload was submitted, which closed the implementation. Not a ticket defect. Recovery: fix the handoff write path for read-only agents, then a fresh implementation-open.

jared added the

waiting

label

2026-09-10 12:56:24 +00:00

jared referenced this issue

2026-09-10 14:42:06 +00:00

Add dispatch duration report derived from dispatch timestamps #549

jared referenced this issue

2026-09-10 15:48:46 +00:00

Make hooks dumb pipes: runner parses the raw hook event from stdin via Hook::Event #550

jared referenced this issue

2026-09-10 16:19:44 +00:00

Read-only guard rejects subagent-stop handoff with pipe chars; Runner records error #543

jared commented

2026-09-10 16:19:48 +00:00

Author

Owner

Blocked by #543 (judge guard vs handoff transport). The correction plan is on #543. Rerun implement from a fresh implementation-open after #543 closes.

jared commented

2026-09-10 17:49:13 +00:00

Author

Owner

Unblocked 2026-09-10: #543 closed (main 93f1595, guard quote-aware + single-pipe charters). Also on main: #550 hooks-as-pipes (ADR-0172). Rerun /os-sdlc:implement #528 from a fresh implementation-open in a new session; the worktree ticket-528 still exists at main's tip.

Unblocked 2026-09-10: #543 closed (main 93f1595, guard quote-aware + single-pipe charters). Also on main: #550 hooks-as-pipes (ADR-0172). Rerun /os-sdlc:implement #528 from a fresh implementation-open in a new session; the worktree ticket-528 still exists at main's tip.

jared removed the

waiting

label

2026-09-10 17:49:25 +00:00

jared referenced this issue

2026-09-10 17:55:43 +00:00

Make hooks dumb pipes: runner parses the raw hook event from stdin via Hook::Event #550

jared commented

2026-09-10 17:57:34 +00:00

Author

Owner

Work started (implementation 9, fresh session after #543/#550 merged at 93f1595). Branch: ticket-528, worktree .claude/worktrees/ticket-528.

Work started (implementation 9, fresh session after #543/#550 merged at 93f1595). Branch: ticket-528, worktree .claude/worktrees/ticket-528.

jared commented

2026-09-10 18:08:13 +00:00

Author

Owner

Implementation 9 (session d9e1984d) FAILED at behavior-verifier with verdict:error.

Cause: the verifier brief carried a stale gate record. Programmer dispatch 141 ran the gate three times: two HarnessError runs at 14:03:17 and 14:05:27 (no test file found for gate_step_outcome.rb, before the file existed), then a green run at 14:05:37 (diff-test 38 runs 0 failures, lint clean). The Runner accepted the green run and routed to behavior-verifier, but the verifier's gate block showed the earlier fail, so it refused per its rules and wrote error. Also: verifier brief field was null.

Secondary finding from the verifier: the diff adds a duration_ms column and field, but no producer measures elapsed time yet, so the increment is incomplete. That would have been a normal fail back to test-writer had the brief been correct.

Branch ticket-528 keeps the green partial diff. Recovery = new implementation-open after the brief bug is fixed.

Implementation 9 (session d9e1984d) FAILED at behavior-verifier with verdict:error. Cause: the verifier brief carried a stale gate record. Programmer dispatch 141 ran the gate three times: two HarnessError runs at 14:03:17 and 14:05:27 (no test file found for gate_step_outcome.rb, before the file existed), then a green run at 14:05:37 (diff-test 38 runs 0 failures, lint clean). The Runner accepted the green run and routed to behavior-verifier, but the verifier's gate block showed the earlier fail, so it refused per its rules and wrote error. Also: verifier brief field was null. Secondary finding from the verifier: the diff adds a duration_ms column and field, but no producer measures elapsed time yet, so the increment is incomplete. That would have been a normal fail back to test-writer had the brief been correct. Branch ticket-528 keeps the green partial diff. Recovery = new implementation-open after the brief bug is fixed.

jared added the

waiting

label

2026-09-10 18:08:19 +00:00

jared referenced this issue

2026-09-10 18:09:49 +00:00

Verifier brief carries stale failed gate record instead of dispatch's final green gate run #551

jared removed the

waiting

label

2026-09-10 18:11:34 +00:00

jared commented

2026-09-10 18:11:35 +00:00

Author

Owner

Resuming: reopening as implementation 10 on the same branch ticket-528 (green partial diff kept). #551 filed for the stale-gate brief bug; this run should not trigger it because the test file now exists before the first gate run.

jared commented

2026-09-10 18:39:17 +00:00

Author

Owner

Resolution

Done: GateStepOutcome carries an optional duration_ms (nil default); GateVerdict measures each gate command with a monotonic clock and passes the rounded milliseconds; step_results gains a nullable duration_ms column (schema 22) and StepResult.record persists it. The 45 s latency itself is not diagnosed here; the ticket's ask was to make per-step wall time observable so that diagnosis has data.

Evidence: Branch ticket-528, commits cc348d8 and 6779679 (plus docs row), driven by os-sdlc implementations 9-11 in session d9e1984d. Full os-sdlc suite 1152 runs, 0 failures, 0 errors; rubocop clean on touched files; behavior-verifier pass, suite-check pass, contract-auditor pass (dispatch 158, merge-ready). Implementation 9 died on harness bug #551; implementation 10 died on a required-keyword regression the diff-scoped gate could not see, hand-fixed to a nil default and committed as cc348d8.

Follow-ups: #551 verifier brief carries a stale failed gate row (filed this session, skeptic CREATE). Observed but not ticketed by user choice pending discussion: behavior-verifier chooses terminal error when the full suite is red, pre-empting the suite-check -> programmer-repair route in the map; charter-level fix.

## Resolution **Done:** GateStepOutcome carries an optional duration_ms (nil default); GateVerdict measures each gate command with a monotonic clock and passes the rounded milliseconds; step_results gains a nullable duration_ms column (schema 22) and StepResult.record persists it. The 45 s latency itself is not diagnosed here; the ticket's ask was to make per-step wall time observable so that diagnosis has data. **Evidence:** Branch ticket-528, commits cc348d8 and 6779679 (plus docs row), driven by os-sdlc implementations 9-11 in session d9e1984d. Full os-sdlc suite 1152 runs, 0 failures, 0 errors; rubocop clean on touched files; behavior-verifier pass, suite-check pass, contract-auditor pass (dispatch 158, merge-ready). Implementation 9 died on harness bug #551; implementation 10 died on a required-keyword regression the diff-scoped gate could not see, hand-fixed to a nil default and committed as cc348d8. **Follow-ups:** #551 verifier brief carries a stale failed gate row (filed this session, skeptic CREATE). Observed but not ticketed by user choice pending discussion: behavior-verifier chooses terminal error when the full suite is red, pre-empting the suite-check -> programmer-repair route in the map; charter-level fix.

jared closed this issue

2026-09-10 18:39:17 +00:00

jared referenced this issue from a commit

2026-09-11 13:18:59 +00:00

feat(os-sdlc): settlement timing instrumentation, default-off (#528)

jared referenced this issue from a commit

2026-09-11 13:18:59 +00:00

feat(os-sdlc): GateVerdict measures each gate step's wall time (#528)

jared referenced this issue from a commit

2026-09-11 13:18:59 +00:00

feat(os-sdlc): step_results persists each gate step's duration_ms (#528)

jared referenced this issue from a commit