canary-rollout: gate evaluation ~40% slower since #1238 — 5 of 9 complete scheduled runs now hit the 30-minute timeout

Summary

Since #1238 (ADR-0007 ingress attribution) merged, the scheduled Canary Rollout workflow's two gate-evaluation steps ("Run canary-rollout" and "Sync blocker issues + fleet-status summary") take noticeably longer, and runs that complete both steps now frequently exceed the job's 30-minute timeout-minutes and are cancelled. A cancelled tick promotes nothing (it fails safe), but it also produces no evaluation and no blocker-issue sync.

This is separate from the older problem in #1175 (runs where the first step alone consumes the whole budget), but it compounds it.

Evidence (scheduled runs of `canary-rollout.yml`, 2026-09-27 → 2026-10-07)

Only runs where both gate steps ran to completion are compared (cancelled runs whose first step was still running record no completion time and are excluded; they are the #1175 mode).

	runs	gate evaluation total, median (min–max)	per step, median	reached ≥ 29.5 min (timeout-bound)
Before #1238 (≤ 10-03 22:09Z)	10	21.5 min (15.1–27.2)	run 10.4 / sync 10.8	0 of 10
After #1238 (≥ 10-03 22:09Z)	9	30.8 min (21.8–33.1)	run 15.6 / sync 15.2	5 of 9 (all 5 cancelled by the timeout)

5/9 vs 0/10 would occur by chance ~1% of the time (Fisher exact, one-sided).
The first slow run (10-03 23:16Z, 32.1 min) came right after feat: implement issue #1224 — canary-rollout health gate goes blind on an ADR-0007 collapsed repo: it resolves runs by per-role workflow NAME, which the ingress replaces with jobs #1238 and before fix(canary-rollout): close ingress fail-open gaps — decision-class read failures, run-list cap; pad cut-date line #1250, so fix(canary-rollout): close ingress fail-open gaps — decision-class read failures, run-list cap; pad cut-date line #1250 is not the cause. feat: implement issue #1225 — canary-rollout: tag resolution cannot tell an API error from an absent tag, so a total lookup outage reads as "fully rolled out" #1240 (tag-lookup errors) landed earlier the same day and has not been ruled out.
Caveats: small sample; runtimes also vary with time of day (pre-change runs reached 27 min around 15:00–17:00Z); the two most recent runs (10-06 18:33Z 21.8 min, 10-07 00:00Z 23.3 min) are back inside the old range, so the effect may be intermittent.
Scheduled-run outcomes overall: before the four merges 16 of 38 cancelled (42%, the Canary Rollout times out: 6 of the last 7 scheduled runs hit timeout-minutes: 30 and were cancelled — rings stop advancing silently #1175 baseline); after, 6 of 10 cancelled (60%).

Measured so far (offline, stubbed `gh`)

Resolving a repo that has neither the per-role workflow nor the ingress (the common non-consumer case) costs 10–11 ms per _run_json call before #1238 and 26 ms per _agent_run_json call after (≈ 2.4×): more registry parses (_agent_field, _ingress_workflow, _jq for ingress_job) and a second cache lookup (hashing forks) per call. At that rate the overhead alone would need ~20,000 calls per step to explain +5 min, so it is probably a contributor, not the whole cause. The real call volume per sweep and the network time (extra gh run list for the ingress workflow, any retries on tag lookups after #1240) are not yet measured.

Plan

Instrument (opt-in CANARY_TIMING=1, auto-on for scheduled/dispatched runs): count and time every gh call across subshells and print a per-step summary (total wall vs time in gh, calls by kind, slowest calls), so the next slow run shows where the time goes.
Cut per-call script overhead on the hot path: memoize registry-derived lookups (per-agent run_workflow, ingress_job, the ingress workflow name) so they cost no forks per call, and short-circuit the non-consumer path using the cached "workflow not found" verdict.
Re-measure over the next scheduled runs; keep this issue open until the post-fix medians are known. A temporary timeout-minutes increase is a possible stopgap (workflow change; needs standards/ci-standards.md review) but is not part of this plan.

Refs #1175, #1238, #1240, #1244.

fix(canary): run the timing report for a caller-supplied cache dir; f…

perf(canary): group gh api calls by endpoint in the timing report; gu…

fix(canary): registry preload refuses delimiter-bearing values and dr…

fix(canary): _cache_name stays injective with no hasher installed; qu…

fix(canary): group gh api by resource when the id is the 5th segment;…

chore(canary): drop redundant else-branch trap superseded by the unco…

perf(canary-rollout): cut per-call overhead on the gate's hot path; a…

First scheduled run with the timing instrumentation from #1260: run 37581060882 (2026-10-07 06:21Z, success).

Wall time. Gate steps took 12.4 min ("Run canary-rollout") and 12.8 min (sync-issues), versus 15.6 min median after #1238 and 10.4 min before. Autocut 2.3 min.

Where the time goes: it is gh, not the script.

step	wall	gh time	script time	gh calls	agent_run_json calls
promote-all	745 s	740 s (99%)	6 s	389	107
sync-issues	769 s	763 s (99%)	6 s	444	111

So the per-call script overhead removed by #1260 was real but small; the script is ~1% of each step.

One call kind dominates: gh run list, 58 calls per step, 607 s (promote-all) / 593 s (sync-issues), i.e. ~80% of each step. Average 10.5 s per call, max 31 s. Every other kind is cheap: api repos/git/tags 221 calls / 83 s (0.38 s avg), api repos/git/matching-refs 74 calls / 32 s, everything else under 20 s.

Likely cause (from reading the code, not yet proven). The Agent Ingress run list for each collapsed repo is fetched with -L CANARY_INGRESS_RUN_LIMIT (default 5000), so gh pages through up to ~50 pages of 100 runs per repo. That list was added in #1238 (one read per repo shared by every collapsed role). It matches the shape of the regression (a fixed cost per repo with an ingress, far above per-call overhead).

Proposed next step (not started; it changes what the gate fetches, so I'd like a go-ahead): bound the ingress run list by time instead of by count, e.g. gh run list --workflow <ingress> --created ">=<window start>", keeping the existing "list reached the cap" guard but with a much smaller cap. That should turn ~10 s calls into ~1 s calls (~9 min saved per gate step) without changing which runs count. Before that, one more timing sample would tell us whether the slow calls are all ingress lists (the timing kind only says run list); I can add the workflow name to the kind if wanted.

This issue stays open until the post-fix medians are known.

Generated by Claude Code

fix(canary): a date-bounded ingress list at GitHub's 1000-result sear…

fix(canary): empty CANARY_INGRESS_HORIZON_TIERS disables the bound; t…

perf(canary-rollout): date-bound the Agent Ingress run list (the domi…

Update (2026-10-08 05:16Z). #1262 (date-bounded Agent Ingress run list + relabelled run-list timing) merged at 03:08Z. No scheduled run has started since (the 04:33Z slot did not fire; GitHub schedules are irregular), so the effect of #1262 is not measured yet. Re-checking after the next slot.

What the runs before #1262 (all on the #1260 code) show, from step timings (the cancelled runs have no retrievable logs, so no per-kind breakdown):

run (UTC)	"Run canary-rollout" step	outcome
10-07 06:21	12.4 min (+ 12.8 min sync-issues)	success
10-07 15:43	23.2 min	job cancelled at the 30-min timeout before the second gate step finished
10-07 21:30	19.7 min	job cancelled at the 30-min timeout before the second gate step finished

So the 06:21 sample (12.4/12.8 min) was the good case: two of the last three runs timed out again. The slowdown varies with the time of day, which fits a cost that scales with GitHub-side work (ingress run-list paging), not with script overhead (script time was ~1% in the one sample with a timing block). This is consistent with the diagnosis behind #1262, but it is still an inference until a post-#1262 run shows the run list [Agent Ingress] ... rows.

Next: read the first completed scheduled run after 03:08Z and post its per-step times and run-list rows here. This issue stays open until the post-fix medians are known.

Generated by Claude Code

First scheduled run on the #1262 code (run 37738211736, 2026-10-08 06:32Z, head 2e3d523 = the #1262 merge): cancelled at the 30-minute job timeout again.

step	time
Autocut new candidates	1.7 min
Run canary-rollout (promote-all)	19.9 min
Sync blocker issues + fleet-status summary	never finished (job cancelled)

So the first gate step is not faster than before the bound: 19.9 min, versus 23.2 and 19.7 min in the two pre-#1262 runs that also timed out, and 12.4 min in the one good run (10-07 06:21Z). The same time of day gave 12.4 min one day and 19.9 min the next, so most of the variation looks external (GitHub API latency/volume), not the script.

What I cannot tell, and why. GitHub keeps no logs for a job that was cancelled by its timeout (BlobNotFound, also for the steps that finished), so there is no canary timing block for this run, nor for the two earlier timeouts. I therefore cannot say whether the date-bounded ingress lists helped, did nothing, or hurt. One plausible way they hurt: a bounded list that reaches GitHub's 1,000-result cap without reaching the window start now costs the bounded read plus the unbounded fallback (the correct, fail-closed behavior, but slower than before for such repos). That is a hypothesis, not a finding.

What would settle it. One run that completes, so its logs survive: either a one-off higher timeout-minutes on the gate job, or a manual workflow_dispatch. I have not done either; the first changes the workflow (and needs standards/ci-standards.md read first), the second runs the real promotion gate including tag moves. Waiting on the owner's decision. This issue stays open.

Generated by Claude Code

test(canary-rollout): pin the gate job timeout floor at 45 min so the…

ci(canary-rollout): raise the gate job timeout 30 -> 60 min so a swee…

Dispatched run with surviving logs (run 37993970198, promote-all with dry_run=true, on the code with #1260 + #1262 + the 60-min timeout; no tag moves). It completed: "Run canary-rollout" step 16.3 min, job 16.4 min.

canary timing [promote-all]: wall=980s gh_calls=417 gh_time=973s (99% of wall) script_time=7s agent_run_json_calls=123
  run list [AgentShield]                    L=1000 calls=4 total=116.6s avg=29.15s max=32.2s
  run list [Dependency audit]               L=1000 calls=4 total=105.7s avg=26.42s max=28.3s
  run list [PR Review — Mention Trigger]    L=1000 calls=4 total= 98.5s avg=24.63s max=27.9s
  run list [Dependabot auto-merge]          L=1000 calls=4 total= 92.6s avg=23.15s max=24.9s
  run list [Dev-Lead Agent]                 L=1000 calls=4 total= 84.7s avg=21.17s max=22.2s
  run list [PR Auto-Review — Ready Check]   L=1000 calls=4 total= 81.5s avg=20.38s max=23.0s
  run list [Auto-add to Initiatives project] L=1000 calls=4 total= 76.3s avg=19.08s max=24.9s
  api repos/git/tags                        calls=240 total=73.5s avg=0.31s
  run list [CI Failure Analyst]             L=1000 calls=4 total= 63.7s avg=15.93s max=23.0s
  run list [Auto-rebase non-Dependabot PRs] L=1000 calls=4 total= 44.4s avg=11.09s max=19.4s
  run list [Apply repo settings]            L=1000 calls=5 total= 37.0s avg= 7.41s max=28.9s
  run list [Persona — Mention Router]       L=1000 calls=4 total= 29.0s avg= 7.25s max=27.1s

(the report prints the top 12 kinds by total time)

What this shows

Script time is still ~1% (7 s). All of the cost is in gh.
The dominant cost is not the Agent Ingress list. No run list [Agent Ingress] row is in the top 12 (so it totals < 29 s). The ~830 s (85% of the step) is the per-role (legacy) workflow lookups, gh run list --workflow <role workflow> -L 1000, 4-5 calls per workflow at 7-29 s each: ten pages of 100 runs per call, and the busy workflows (AgentShield, Dependency audit, PR Review mention trigger, Dependabot auto-merge, Dev-Lead, Ready Check) are the slow ones.
So the working diagnosis behind perf(canary-rollout): date-bound the Agent Ingress run list (the dominant gate cost) #1262 was incomplete. perf(canary-rollout): date-bound the Agent Ingress run list (the dominant gate cost) #1262 may have helped the ingress lists (they are no longer visible as a cost), but the earlier "58 run list calls ~607 s" in the first perf(canary-rollout): cut per-call overhead on the gate's hot path; add opt-in gh timing #1260 sample was almost certainly these same per-role lookups. The step took 16.3 min here vs 12.4 min in that sample: the per-page API latency varies a lot.
sync-issues re-reads the same lists in a separate process (769 s vs 745 s promote-all in the earlier sample). A full sweep therefore pays this cost twice, which is why the sweeps exceed 30 min even though one step is 12-16 min.

Not done / not proven: I did not dispatch a sync-issues run; its cost is inferred from the earlier sample. This is a single measurement.

Next-step options, not started:

A. Share the run-list cache between the sweep's gate steps (persist the per-process cache dir under $RUNNER_TEMP and reuse it in sync-issues; run lists only, not the tag/sha caches). Expected: roughly halves a full sweep, low semantic risk.
B. Lower or window the -L 1000 for the busiest workflows. This changes the evidence the gate sees (the newest 1000 runs of a busy workflow may span only a day or two), so it needs analysis first.
C. Fetch the lists concurrently (larger change).

Generated by Claude Code

test(canary): drop the PyYAML dependency; assert status in the cache-…

perf(canary): share the run-list cache across the sweep's steps (#1271)

First scheduled sweep on the merged cache change (#1271): run 38030436336, started 06:17Z, success in ~20 min (the previous scheduled runs were all cancelled at the old limit).

Step	Duration
Autocut	39 s
Run canary-rollout (`promote-all`)	15 m 31 s (`wall=931s`, 421 gh calls)
Sync blocker issues (`sync-issues`)	3 m 09 s (`wall=189s`, 536 gh calls, 0 `run list` calls)
Drift audit	27 s

sync-issues previously took ~12-16 min because it re-fetched the same per-role run lists. In this run it made no run list calls at all; what remains is tag/ref reads (357 git/tags calls, ~108 s, deliberately uncached) and issue edits. Per-call latency looks comparable to the earlier measurement (run list averaging ~18-26 s), so this is a like-for-like improvement rather than a quiet-API artefact. One sample, though.

promote-all is now the whole cost (~15.5 min, 99% gh time, dominated by 11 workflows × 4 run list -L 1000 calls at ~20 s each). That is option B/C territory (lowering/windowing the 1000 cap, or fetching concurrently), neither approved yet.

Open question for the owner: lower the 60-minute job timeout (currently floor 45 in the bats guard)? A 20-minute sweep leaves a lot of headroom, but one good sample on a day when scheduled runs were also irregular is thin. I would wait for two or three more scheduled runs first.

Generated by Claude Code

test(canary): assert run status and grep exit 1 in the option B tests (…

test(canary): date the capped-list fixture relative to now (#1259)

perf(canary): date-bound the per-role run list to one 15-day tier (#1259

Closing as fixed. Measured on the scheduled sweeps, before and after #1271 (shared run-list cache) and #1282 (per-role run list date-bounded to 15 days, option B):

Scheduled run	Code	Job time	`promote-all`	`sync-issues`	`promote-all` gh calls / agent_run_json calls
600 (2026-10-10 14:38Z)	before B	22m11s	989 s	190 s	436 / 128
601 (2026-10-10 20:16Z)	B (`f019c97`)	15m31s	604 s	182 s	549 / 158
609 (2026-10-10 23:46Z)	B (`98c8a23`)	15m54s	583 s	224 s	632 / 185

promote-all is about 39% faster on run 601. Run 609 did 45% more agent_run_json work than run 600 (185 vs 128 calls, and 7 promotions) and was still faster than run 600 (583 s vs 989 s). Per gh call it dropped from about 2.25 s to about 0.9 s.
sync-issues went from the 12 to 16 minutes measured before perf(canary): share the run-list cache across the sweep's steps #1271 to about 3 to 4 minutes, and is steady across these runs.
No behavior change: the same members are UNRESOLVED or blocked in all three runs (apply-repo-settings, idea-enhancer, idea-triage, initiative-planner), with the same warning and error counts. The extra summary lines in run 609 come from its promotions.
The job now takes about 16 minutes against a 60-minute timeout. Lowering the timeout to the 45-minute floor the tests enforce is possible but not needed; I have not changed it.

Residual cost is gh call latency (about 98% of promote-all wall time). Remaining levers would be fewer calls per sweep, not more date handling. If the cost climbs back up, reopen this or file a new issue.

Generated by Claude Code

Navigation Menu

Repository navigation

canary-rollout: gate evaluation ~40% slower since #1238 — 5 of 9 complete scheduled runs now hit the 30-minute timeout #1259

Summary

Evidence (scheduled runs of `canary-rollout.yml`, 2026-09-27 → 2026-10-07)

Measured so far (offline, stubbed `gh`)

Plan

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

canary-rollout: gate evaluation ~40% slower since #1238 — 5 of 9 complete scheduled runs now hit the 30-minute timeout #1259

Description

Summary

Evidence (scheduled runs of canary-rollout.yml, 2026-09-27 → 2026-10-07)

Measured so far (offline, stubbed gh)

Plan

Activity

don-petry commented on Oct 7, 2026

don-petry commented on Oct 8, 2026

don-petry commented on Oct 8, 2026

don-petry commented on Oct 9, 2026

don-petry commented on Oct 10, 2026

don-petry commented on Oct 11, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

Evidence (scheduled runs of `canary-rollout.yml`, 2026-09-27 → 2026-10-07)

Measured so far (offline, stubbed `gh`)