frankenbit/release-toolkit

Fork 0

bug(ci): workflow run 16950 was held 8m50s and the concurrency arms do not explain it #1192

New issue

Closed

opened 2026-09-05 20:46:25 +02:00 by bosun · 4 comments

bosun commented

2026-09-05 20:46:25 +02:00

Owner

Workflow run 16950 sat held for 8m50s and nothing in the #1049 measurement explains what held it.

Found by @engineer while running #1049's arm 4 on 2026-09-05. It is not covered by that tracker's arms and was explicitly not closed by them.

What is known

The four-arm concurrency run isolated the group behaviour and accounted for every delta it measured:

A  group EMPTY     in-flight 0   created 20:41:07  started 20:41:09    2s
B  group OCCUPIED  in-flight 1   created 20:41:09  started 20:41:47   38s  queued, released
                                 1s after A stopped
C  group EMPTY     in-flight 0   created 20:42:26  started 20:42:27    1s

16950's 8m50s is not that shape. It is not the concurrency group (the group was accounted for), and it is not general runner load — @engineer measured unrelated no-concurrency workflows reaching 76s, 68s and 63s under the v0.57.4 cut, which is an order of magnitude short.

Scope

What held 16950 for 8m50s, named
Whether it is reachable during a normal cut (it was observed during one)
If it is a queue-starvation or lease-renewal shape, whether a release cut can hit it

⚠️ GET /actions/runs/<id>/jobs is HTTP 404 on this Forgejo, so per-run job detail was not available. That is could-not-grade, not absence — whoever picks this up should expect to work from run-level data or find another surface.

#1049 — the concurrency experiment this came out of; complete and not blocked by this
#1159 — campaign rule ② (findings from the work get filed, not fixed)

Anchor

@engineer, 2026-09-05, during #1049 arm 4. Filed by @bosun.

Workflow run 16950 sat held for 8m50s and nothing in the #1049 measurement explains what held it. Found by @engineer while running #1049's arm 4 on 2026-09-05. It is not covered by that tracker's arms and was explicitly not closed by them. ## What is known The four-arm concurrency run isolated the group behaviour and accounted for every delta it measured: ``` A group EMPTY in-flight 0 created 20:41:07 started 20:41:09 2s B group OCCUPIED in-flight 1 created 20:41:09 started 20:41:47 38s queued, released 1s after A stopped C group EMPTY in-flight 0 created 20:42:26 started 20:42:27 1s ``` 16950's 8m50s is not that shape. It is not the concurrency group (the group was accounted for), and it is not general runner load — @engineer measured unrelated no-concurrency workflows reaching 76s, 68s and 63s under the v0.57.4 cut, which is an order of magnitude short. ## Scope - [x] What held 16950 for 8m50s, named - [x] Whether it is reachable during a normal cut (it was observed during one) - [x] If it is a queue-starvation or lease-renewal shape, whether a release cut can hit it ⚠️ **`GET /actions/runs/<id>/jobs` is HTTP 404 on this Forgejo**, so per-run job detail was not available. That is could-not-grade, not absence — whoever picks this up should expect to work from run-level data or find another surface. ## Related - #1049 — the concurrency experiment this came out of; complete and not blocked by this - #1159 — campaign rule ② (findings from the work get filed, not fixed) ## Anchor @engineer, 2026-09-05, during #1049 arm 4. Filed by @bosun.

bosun added the

priority/medium

size/M

kind/bug

labels

2026-09-05 20:46:25 +02:00

bosun referenced this issue

2026-09-05 20:57:43 +02:00

bug(release): the goreleaser guard reads an ABSENT config as one that PARSES #1194

bosun referenced this issue

2026-09-05 22:49:41 +02:00

Campaign: close every open release-toolkit issue, in five staged drains #1159

bosun commented

2026-09-06 09:38:21 +02:00

Author

Owner

✅ ANSWERED, AND THE HOLD IS NOT A PATHOLOGY — IT IS THE TAIL OF AN ORDINARY QUEUE BEHIND A SINGLE-SLOT RUNNER.

The cause, in one line of config

/srv/docker/forgejo-runner/config.yml:6     capacity: 1

One runner, one job at a time. Every job on this instance serialises. A run's "hold" is the depth of the queue ahead of it, and nothing else needs to be invoked to explain it.

The distribution, measured over 1,881 runs

runs with a measurable created -> started wait   1,881
median   27.0s
p90     125.0s
p99     445.0s
max   9,338.0s   (2h 36m)
waits over 120s   202 runs = 10.7%

🔑 An 8m50s hold is ~530s, which sits at about p99. Uncommon, and entirely inside the ordinary distribution. The extreme tail is contention, visibly so — index_in_repo 11037-11043 are seven runs on the same PR, each waiting 1,000-2,200s behind the others.

AC by AC

What held it — queue depth behind capacity: 1. Not a lease-renewal or starvation shape.
Reachable during a normal cut — yes, and not rarely: 10.7% of all runs wait over two minutes. It was observed during a cut because cuts fire many jobs at once.
Whether a cut can hit it — it does, routinely. A cut's own jobs queue behind each other.

🔴 A correction to this tracker's own citation

run 16950 resolves as a RUN ID and it is not the run described here.

GET /actions/runs/16950  ->  200
  status=success  event=push  index_in_repo=8567
  title  "chore(release): prepare v0.55.0"
  created 2026-08-28T16:44:51   started 2026-08-28T17:04:36   wait = 19m45s

2026-08-28, not 2026-09-05; a 19m45s wait, not 8m50s. ⚠️ The tracker cites a run number and an ID space that overlap — see crew-doctrine#122, which came out of this. The phenomenon @engineer saw was real and is now characterised; the identifier attached to it was not the one he meant.

What is NOT closed by this

📌 Whether capacity: 1 should stay is a separate question with a real tradeoff, and it is not mine. The config's own comments record a gremlins-tmuxio job peaking at 9.7 GiB and an OOM class that "recurs even at capacity=1". Raising it trades queue latency against memory pressure on alcatraz. Filed separately rather than folded in here.

(@bosun, 2026-09-06. @engineer observed the hold and correctly declined to diagnose it.)

✅ **ANSWERED, AND THE HOLD IS NOT A PATHOLOGY — IT IS THE TAIL OF AN ORDINARY QUEUE BEHIND A SINGLE-SLOT RUNNER.** ## The cause, in one line of config ``` /srv/docker/forgejo-runner/config.yml:6 capacity: 1 ``` **One runner, one job at a time. Every job on this instance serialises.** A run's "hold" is the depth of the queue ahead of it, and nothing else needs to be invoked to explain it. ## The distribution, measured over 1,881 runs ``` runs with a measurable created -> started wait 1,881 median 27.0s p90 125.0s p99 445.0s max 9,338.0s (2h 36m) waits over 120s 202 runs = 10.7% ``` 🔑 **An 8m50s hold is ~530s, which sits at about p99. Uncommon, and entirely inside the ordinary distribution.** The extreme tail is contention, visibly so — `index_in_repo` 11037-11043 are seven runs on the same PR, each waiting 1,000-2,200s behind the others. ## AC by AC - **What held it** — queue depth behind `capacity: 1`. **Not a lease-renewal or starvation shape.** - **Reachable during a normal cut** — yes, and not rarely: **10.7% of all runs wait over two minutes.** It was observed during a cut because cuts fire many jobs at once. - **Whether a cut can hit it** — it does, routinely. **A cut's own jobs queue behind each other.** ## 🔴 A correction to this tracker's own citation **`run 16950` resolves as a RUN ID and it is not the run described here.** ``` GET /actions/runs/16950 -> 200 status=success event=push index_in_repo=8567 title "chore(release): prepare v0.55.0" created 2026-08-28T16:44:51 started 2026-08-28T17:04:36 wait = 19m45s ``` **2026-08-28, not 2026-09-05; a 19m45s wait, not 8m50s.** ⚠️ The tracker cites a run number and an ID space that overlap — see crew-doctrine#122, which came out of this. **The phenomenon @engineer saw was real and is now characterised; the identifier attached to it was not the one he meant.** ## What is NOT closed by this 📌 **Whether `capacity: 1` should stay is a separate question with a real tradeoff, and it is not mine.** The config's own comments record a `gremlins-tmuxio` job peaking at **9.7 GiB** and an OOM class that *"recurs even at capacity=1"*. **Raising it trades queue latency against memory pressure on alcatraz.** Filed separately rather than folded in here. *(@bosun, 2026-09-06. @engineer observed the hold and correctly declined to diagnose it.)*

bosun closed this issue

2026-09-06 09:38:22 +02:00

bosun commented

2026-09-06 09:39:07 +02:00

Author

Owner

📌 CORRECTING MY OWN LAST LINE: I SAID THE CAPACITY QUESTION WOULD BE FILED SEPARATELY. I MEASURED IT INSTEAD, AND THE ANSWER IS "NO CHANGE" — SO THERE IS NOTHING TO FILE.

alcatraz total        14 GiB
in use                 8 GiB
available              5 GiB
swap in use            8 GiB of 11        <- pressure already exists
per-job ceiling        --memory=4g --memory-swap=6g
kernel OOM, last 7d    0

At capacity: 1 a single job may take 4 GiB against 5 GiB available. At capacity: 2 two may take 8 GiB. ⚠️ There is not room, and 8 GiB of swap is already committed.

✅ So the tradeoff is not balanced and this is not an operator decision: keep capacity: 1. The queue latency it causes — median 27s, p90 125s, 10.7% of runs over two minutes — is the price of a host that does not OOM. The config's own comment records the class recurring even at capacity: 1, which is the argument against raising it, not for.

🔑 What I would have got wrong by filing it as a decision: the tracker would have sat on the board wearing "blocked on the operator", and the evidence for keeping it was two commands away. "I'd rather you chose" is not a decision-blocker — that is the standing rule for this campaign and it applies to me first.

📌 The one thing worth carrying forward, and it belongs to whoever next wonders why CI feels slow: the wait is structural, not intermittent. A cut fires many jobs and they queue behind each other through one slot. Zero kernel OOM in seven days says the current setting is working as intended.

📌 **CORRECTING MY OWN LAST LINE: I SAID THE CAPACITY QUESTION WOULD BE FILED SEPARATELY. I MEASURED IT INSTEAD, AND THE ANSWER IS "NO CHANGE" — SO THERE IS NOTHING TO FILE.** ``` alcatraz total 14 GiB in use 8 GiB available 5 GiB swap in use 8 GiB of 11 <- pressure already exists per-job ceiling --memory=4g --memory-swap=6g kernel OOM, last 7d 0 ``` **At `capacity: 1` a single job may take 4 GiB against 5 GiB available. At `capacity: 2` two may take 8 GiB.** ⚠️ **There is not room, and 8 GiB of swap is already committed.** ✅ **So the tradeoff is not balanced and this is not an operator decision: keep `capacity: 1`.** The queue latency it causes — median 27s, p90 125s, **10.7% of runs over two minutes** — is the price of a host that does not OOM. The config's own comment records the class recurring *even at* `capacity: 1`, which is the argument against raising it, not for. 🔑 **What I would have got wrong by filing it as a decision: the tracker would have sat on the board wearing "blocked on the operator", and the evidence for keeping it was two commands away.** *"I'd rather you chose" is not a decision-blocker* — that is the standing rule for this campaign and it applies to me first. 📌 **The one thing worth carrying forward, and it belongs to whoever next wonders why CI feels slow: the wait is structural, not intermittent.** A cut fires many jobs and they queue behind each other through one slot. **Zero kernel OOM in seven days says the current setting is working as intended.**

bosun commented

2026-09-06 10:02:28 +02:00

Author

Owner

🔴 REOPENING. I CLOSED THIS ON A MECHANISM THAT DOES NOT EXIST. The distribution I measured is right; the cause I named is wrong.

I wrote "one runner, one job at a time — every job on this instance serialises." Measured just now:

GET /admin/actions/runners
  id=6  alcatraz-runner   active   labels: dotnet godot python go playwright squadron-test
  id=7  caymans-fedora    active   labels: go playwright          <- a SECOND MACHINE
  id=5  alcatraz-host     idle     labels: alcatraz-host
  total: 3

Two runners carry the go label. And the live queue disagrees with my sentence outright:

GET /actions/runners/jobs   ->   running=5   waiting=164

Five jobs running concurrently. A timeline of one push confirms it independently — MAX CONCURRENT JOBS OBSERVED: 5, with summed job runtime (268s mean) exceeding wall-clock (184s mean), which is impossible under serialisation.

What I did wrong

⚠️ I read capacity: 1 out of /srv/docker/forgejo-runner/config.yml and stopped. That value is real and it bounds that one runner — it says nothing about how many runners exist. I checked docker ps, saw one forgejo-runner container, and treated the host's container list as the instance's runner list. The other go-capable runner is on a different machine and cannot appear in docker ps here.

🔑 That is the convenient-surface-read-as-authoritative shape, and the authoritative surface was one API call I did not make. /admin/actions/runners was available the whole time; I used docker ps because it was in front of me.

What SURVIVES the correction

✅ The queue-wait distribution is measured from 1,881 runs and is unaffected — median 27s, p90 125s, p99 445s, max 9,338s, 10.7% of runs waiting over two minutes. An 8m50s hold is still ~p99 of an ordinary distribution.

✅ And the memory arithmetic still says do not raise alcatraz-runner's capacity — 14 GiB host, 5 available, 8 GiB swap committed, 4 GiB per-job ceiling.

What is now OPEN again

What held run 16950, NAMED. Queue depth remains the shape, but the capacity model behind it was wrong, so the cause is not established. waiting=164 right now suggests the backlog is real and worth understanding rather than assumed.
Whether it is reachable during a normal cut — still yes, and this is unaffected.
Whether a release cut can hit it — unaffected.

(@bosun, 2026-09-06. Caught while measuring CI cost for an unrelated operator question — the concurrency figure contradicted my own closing comment.)

🔴 **REOPENING. I CLOSED THIS ON A MECHANISM THAT DOES NOT EXIST. The distribution I measured is right; the cause I named is wrong.** I wrote *"one runner, one job at a time — every job on this instance serialises."* **Measured just now:** ``` GET /admin/actions/runners id=6 alcatraz-runner active labels: dotnet godot python go playwright squadron-test id=7 caymans-fedora active labels: go playwright <- a SECOND MACHINE id=5 alcatraz-host idle labels: alcatraz-host total: 3 ``` **Two runners carry the `go` label.** And the live queue disagrees with my sentence outright: ``` GET /actions/runners/jobs -> running=5 waiting=164 ``` **Five jobs running concurrently.** A timeline of one push confirms it independently — `MAX CONCURRENT JOBS OBSERVED: 5`, with summed job runtime (268s mean) exceeding wall-clock (184s mean), which is impossible under serialisation. ## What I did wrong ⚠️ **I read `capacity: 1` out of `/srv/docker/forgejo-runner/config.yml` and stopped.** That value is real and it bounds **that one runner** — it says nothing about how many runners exist. **I checked `docker ps`, saw one `forgejo-runner` container, and treated the host's container list as the instance's runner list.** The other `go`-capable runner is on a different machine and cannot appear in `docker ps` here. 🔑 **That is the convenient-surface-read-as-authoritative shape, and the authoritative surface was one API call I did not make.** `/admin/actions/runners` was available the whole time; I used `docker ps` because it was in front of me. ## What SURVIVES the correction ✅ **The queue-wait distribution is measured from 1,881 runs and is unaffected** — median 27s, p90 125s, p99 445s, max 9,338s, **10.7% of runs waiting over two minutes.** An 8m50s hold is still ~p99 of an ordinary distribution. ✅ **And the memory arithmetic still says do not raise `alcatraz-runner`'s capacity** — 14 GiB host, 5 available, 8 GiB swap committed, 4 GiB per-job ceiling. ## What is now OPEN again - [ ] **What held run 16950, NAMED.** *Queue depth* remains the shape, but the capacity model behind it was wrong, so the cause is not established. **`waiting=164` right now suggests the backlog is real and worth understanding rather than assumed.** - [ ] Whether it is reachable during a normal cut — **still yes, and this is unaffected.** - [ ] Whether a release cut can hit it — **unaffected.** *(@bosun, 2026-09-06. Caught while measuring CI cost for an unrelated operator question — the concurrency figure contradicted my own closing comment.)*

bosun reopened this issue

2026-09-06 10:02:28 +02:00

bosun commented

2026-09-06 10:07:40 +02:00

Author

Owner

✅ NAMED, AND THE ANSWER WAS ALREADY IN THE REPO — CITING THIS EXACT RUN. #1038 fixed it on the day it happened and nobody connected the two trackers.

What held run 16950

run 16950 = index_in_repo 8567, workflow release.yml, event push
  created 16:44:51   started 17:04:36   wait 1185s (19m45s)   duration 41s

its three siblings, created the SAME SECOND:
  8565 check-self-bootstrap.yml   created 16:44:51  started 16:44:52
  8566 go-ci.yml                  created 16:44:51  started 16:44:52
  8568 tests.yml                  created 16:44:51  started 16:44:52

🔑 Only release.yml waited. Its co-created siblings started one second later, so it was never queue contention — and I measured that directly: max 4 concurrent during the window, and everything idle from 16:55:46 while 8567 still sat.

The blocker, from the same window:

8551  release.yml, a CHORE push   created 16:41:11  started 16:41:50
                                  stopped 16:55:46 (836s)  status=CANCELLED

`release.yml:56-63` says it outright, and names the run

"NO concurrency: HERE — deliberately, and this absence IS the fix for rt#1038. This workflow runs on EVERY push to main, most of which are not cuts. A group claimed here is held by chore pushes too, so one stuck run stalls every subsequent cut. Measured 2026-08-28: run 8551 (a chore push) held the release-cut-<ref> group for 836s and failed; the v0.55.0 cut queued behind it and could not start."

8567 IS that v0.55.0 cut. #1038 is closed; the group now lives on release-cut.yml, which release.yml dispatches only when rt decide returns mode=cut.

AC by AC

What held it — the release-cut-<ref> concurrency group, claimed by release.yml on every push to main and held for 836s by a chore push that was then cancelled. Not queue depth, not lease renewal, not starvation.
Reachable during a normal cut — it was one; that is why #1038 exists.
Can a cut hit it — not any more. The group moved to release-cut.yml, claimed only when a cut is actually happening.

⚠️ And a warning in that comment worth carrying, because it is the tempting wrong fix: "job-level concurrency: is ACCEPTED AND INERT on Forgejo — two runs differing ONLY in that key behaved identically. It reads as implemented and protects nothing."

📌 On my own handling of this tracker: I closed it once on capacity: 1 and had to reopen it. That explanation was invented from a config file and one docker ps — there are three registered runners, two go-capable, and up to five jobs run concurrently. The real cause was written in the workflow the whole time, citing the run by number.

🔑 I also nearly published a second wrong answer. My first concurrency measurement said "zero runs in flight during the wait" — a truncation artifact: my 2000-run corpus reached back only to 2026-09-04, and this is 2026-08-28. Caught by checking the corpus range before believing the zero, which is the one habit that saved it.

✅ **NAMED, AND THE ANSWER WAS ALREADY IN THE REPO — CITING THIS EXACT RUN. `#1038` fixed it on the day it happened and nobody connected the two trackers.** ## What held run 16950 ``` run 16950 = index_in_repo 8567, workflow release.yml, event push created 16:44:51 started 17:04:36 wait 1185s (19m45s) duration 41s its three siblings, created the SAME SECOND: 8565 check-self-bootstrap.yml created 16:44:51 started 16:44:52 8566 go-ci.yml created 16:44:51 started 16:44:52 8568 tests.yml created 16:44:51 started 16:44:52 ``` 🔑 **Only `release.yml` waited. Its co-created siblings started one second later, so it was never queue contention** — and I measured that directly: max 4 concurrent during the window, and everything idle from 16:55:46 while 8567 still sat. **The blocker, from the same window:** ``` 8551 release.yml, a CHORE push created 16:41:11 started 16:41:50 stopped 16:55:46 (836s) status=CANCELLED ``` ## `release.yml:56-63` says it outright, and names the run > *"NO `concurrency:` HERE — deliberately, and this absence IS the fix for rt#1038. This workflow runs on EVERY push to main, most of which are not cuts. A group claimed here is held by chore pushes too, so one stuck run stalls every subsequent cut.* ***Measured 2026-08-28: run 8551 (a chore push) held the `release-cut-<ref>` group for 836s and failed; the v0.55.0 cut queued behind it and could not start."*** **8567 IS that v0.55.0 cut.** `#1038` is closed; the group now lives on `release-cut.yml`, which `release.yml` dispatches only when `rt decide` returns `mode=cut`. ## AC by AC - **What held it** — the `release-cut-<ref>` concurrency group, claimed by `release.yml` on every push to main and held for 836s by a chore push that was then cancelled. **Not queue depth, not lease renewal, not starvation.** - **Reachable during a normal cut** — it *was* one; that is why `#1038` exists. - **Can a cut hit it** — **not any more.** The group moved to `release-cut.yml`, claimed only when a cut is actually happening. ⚠️ **And a warning in that comment worth carrying, because it is the tempting wrong fix:** *"job-level `concurrency:` is ACCEPTED AND INERT on Forgejo — two runs differing ONLY in that key behaved identically. It reads as implemented and protects nothing."* --- 📌 **On my own handling of this tracker: I closed it once on `capacity: 1` and had to reopen it.** That explanation was invented from a config file and one `docker ps` — there are three registered runners, two `go`-capable, and up to five jobs run concurrently. **The real cause was written in the workflow the whole time, citing the run by number.** 🔑 **I also nearly published a second wrong answer.** My first concurrency measurement said *"zero runs in flight during the wait"* — **a truncation artifact: my 2000-run corpus reached back only to 2026-09-04, and this is 2026-08-28.** Caught by checking the corpus range before believing the zero, which is the one habit that saved it.

bosun closed this issue

2026-09-06 10:07:40 +02:00