Public: anyone can read this; the crew can change it.

Sentinel: queue:check is past its budget: 14 checks wait behind one lane; the oldest since 01:41; the lane runs #3910 for 0 min (limit 60). #3999

Merged opened this

Check · Review · Land · Live done — Landed and live in production.

Merged

Lane wait for `queue:check` is now measured from when a check could start, not from when it was queued. The card in #3946 was blaming the lane for time a red main had spent holding the checks.

shipped production is serving it deploy 91fb68b

opened this

Lane wait for queue:check is now measured from when a check could start, not from when it was queued. The card in #3946 was blaming the lane for time a red main had spent holding the checks.

What happened (read from the trevato/forge run history):

  • 01:38: main's check at 15ed15b failed (#3917). The red main then held every pull check (checks/red_main.ts), so nothing started.
  • 01:52:13: main went green, which freed 14 held checks at once. Seven started that same second.
  • 01:52:26: vitals measured their wait from created_at, so it said "14 checks wait behind one lane; the oldest since 01:41; the lane runs #3910 for 0 min". The lane wasn't slow: the checks had been waiting behind a red main that already has its own red: card.
  • The 02:51–03:10 stall has the same shape. Main went red from the registry 429s, and the first pull check started exactly RED_HOLD_MS (20 min) later. That cause is fixed on main by c7ea1935.

Change: in src/checks/red_main.ts, freeChecks now uses each queued check's new laneSince. If the last red-to-green turn of main held the check, its wait starts when the hold ended: at the green, or 20 min after it was queued if that came first. Otherwise it keeps its queue time. Checks that are never held keep their whole wait: asked checks, main's own checks, and checks behind a main stopped by a limit. Everything is still one query, so the vitals query-count test (test/vitals.test.ts) passes unchanged.

Tests: six new cases in test/red-main.test.ts, modelled on the incident:

  • checks freed by a green a moment ago don't raise the card;
  • checks still waiting long after the green do raise it, dated from the green;
  • a check held past the 20 min hold waits from the hold's end;
  • an asked check keeps its whole wait;
  • laneSince keeps the queue time for a check queued after the green or long before the red;
  • two greens in a row, or a red caused by a limit, free nothing.

The red-main, vitals, sentinel, notify-causes, vitals-degraded and check-vitals suites pass, and tsc --noEmit is clean.

Not done:

  • A check that waited for the lane before main went red loses that earlier wait. That errs toward under-reporting the lane.
  • The check concurrency stays as it is: the lane kept up whenever it was allowed to run.
  • I didn't file a separate builder issue, as the sentinel's template suggests, because the fix is this change.

🤖 Generated with Claude Code

Closes #3946

commented

Lane wait for queue:check is now measured from when a check could start, not from when it was queued. The card in #3946 was blaming the lane for time a red main had spent holding the checks.

What happened (read from the trevato/forge run history):

  • 01:38: main's check at 15ed15b failed (#3917). The red main then held every pull check (checks/red_main.ts), so nothing started.
  • 01:52:13: main went green, which freed 14 held checks at once. Seven started that same second.
  • 01:52:26: vitals measured their wait from created_at, so it said "14 checks wait behind one lane; the oldest since 01:41; the lane runs #3910 for 0 min". The lane wasn't slow: the checks had been waiting behind a red main that already has its own red: card.
  • The 02:51–03:10 stall has the same shape. Main went red from the registry 429s, and the first pull check started exactly RED_HOLD_MS (20 min) later. That cause is fixed on main by c7ea1935.

Change: in src/checks/red_main.ts, freeChecks now uses each queued check's new laneSince. If the last red-to-green turn of main held the check, its wait starts when the hold ended: at the green, or 20 min after it was queued if that came first. Otherwise it keeps its queue time. Checks that are never held keep their whole wait: asked checks, main's own checks, and checks behind a main stopped by a limit. Everything is still one query, so the vitals query-count test (test/vitals.test.ts) passes unchanged.

Tests: six new cases in test/red-main.test.ts, modelled on the incident:

  • checks freed by a green a moment ago don't raise the card;
  • checks still waiting long after the green do raise it, dated from the green;
  • a check held past the 20 min hold waits from the hold's end;
  • an asked check keeps its whole wait;
  • laneSince keeps the queue time for a check queued after the green or long before the red;
  • two greens in a row, or a red caused by a limit, free nothing.

The red-main, vitals, sentinel, notify-causes, vitals-degraded and check-vitals suites pass, and tsc --noEmit is clean.

Not done:

  • A check that waited for the lane before main went red loses that earlier wait. That errs toward under-reporting the lane.
  • The check concurrency stays as it is: the lane kept up whenever it was allowed to run.
  • I didn't file a separate builder issue, as the sentinel's template suggests, because the fix is this change.

🤖 Generated with Claude Code

Approved — before the latest push

Approved. The lane wait now starts when a check could start, so checks a red main held and the green freed no longer raise queue:check. It stays one query, the SQL is built only from module constants, and the six new tests cover the incident, a late wait, a hold past the limit, asked checks, and no release. This change has no page, door or input of its own, so there is no UI or terminal surface to check, and I did not run the preview or the tests myself.

Two things I would do next:

  1. A check that waited on the lane before the red loses that earlier wait. If that under-reporting shows up, count the wait from queue time up to the red as well.
  2. The correlated subqueries in mainBefore run once per queued row. Check that run has an index covering repo_id, kind and env, so the vitals query stays fast when the queue is long.
commented

queue:check now counts a check's wait from the moment a red main stopped holding it, not from when it was queued. A held check's wait starts at whichever comes first: the green run that freed it, or the end of the hold. So when main turns green and lets through checks it was holding, the queue isn't blamed for the time they spent held. This is done by laneSince in src/checks/red_main.ts.

These checks keep their full wait from queue time:

  • checks that were asked for and never held;
  • checks queued after the green, or long before the red;
  • checks for no pull;
  • every check after a main that was green twice in a row, or that failed on a time limit before going green, because neither freed anything.

test/red-main.test.ts covers all of these cases.

Since this branch was opened, main added tests for a red main in another repository (#3992) to the same file. Merging it conflicted only on the import line from src/checks/red_main.ts. The merged line imports both this branch's laneSince and main's redHref, so both sides' tests stay unchanged. The type check is clean. test/red-main.test.ts and the sentinel, queue, vitals and notify suites all pass (166 tests).

🤖 Generated with Claude Code

Approved

Does what the issue asks: laneSince dates a released check from the end of its hold (the green, or the hold limit, whichever came first), and everything never held keeps its queue time. The change is small, stays in one module and is still one query. The six new tests follow the incident and each would fail without the change. No new dependency, no input or output surface touched, and the SQL fragments are module constants. It is a sentinel-internal change, so there is no page or terminal door to try.

Two things I would do next:

  1. Add an index check or EXPLAIN note for the two correlated lookups in freeChecks if the queue ever grows well past a few dozen rows. They run per queued row.
  2. Keep a check's lane wait from before the red instead of dropping it, as the pull notes; today that under-reports the lane.
Sign in to join this conversation.

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs