runs: a restart cancelled 14 running jobs of a person's run and held it ten minutes: a run driven again picks its scope anew, the read timed out, and the drive's end gave its jobs up #54

New issue

Open

opened 2026-11-13 04:59:13 +00:00 by xemmerling · 0 comments

xemmerling commented

2026-11-13 04:59:13 +00:00

Owner

Live, 2026-11-13 07:07Z. Production serves ebbad1e3 since 07:04:46Z (promoted by me; it holds f6b4ed5e). At that restart three people's runs that pick their own checks were open: r8c59837ad3 (bare t test), r9f3e178cff and rf2d592fea8 (last failures). Each logged a run driven again keeps the checks it told 10 to 11 s after the server started (kept 649 of 763, 70 of 79, 243 of 248) and went on. t_runs_before_asking{phase="planning"} read 0. No job was given up, no drive told nothing, no statement timed out. At 06:01Z, on the code before, the same kind of run sat 8 min 13 s in planning; at 04:44Z it timed out and lost 14 jobs. The point left to the owner (a drive ending in a transient error gives up the jobs it found open) stands.

Update, 2026-11-13 05:31Z. My part is on main as f6b4ed5e ("runs: a run driven again takes the checks it picked from its plan, and picks nothing anew"). A run driven again reads its planned event once, before it selects (Db::planned, the read that already decided whether the plan is told again), and a run of bare t test or --failed drives the checks that event names. A run that named its checks selects as before. A plan read that fails ends the drive as an unread one and never picks anew. Three tests in src/runs/engine/tests.rs take a run over after what it would pick has moved. The whole check set ran green twice on testing (runs re1918ceb03 and r1ed4d4b22f). It is not on production yet; the next restart that carries it is its first proof live.

The two points left to the owner below are unchanged: the give-up of followed jobs when a drive ends in a transient error, and why a touched run takes minutes to plan.

Seen on t.tilo.so at the restart of 2026-11-13 04:44Z (166e9649, server pod t-9fc997b7b-2nshh, leading epoch 549). Two runs of one person's session lost their running jobs and then told nothing for ten minutes. No job ended with a cause and no error was told, so nothing counted it.

What happened, from the server's log and the database

Time (Z)	What
04:44:17	The new server starts; it leads at 04:44:18 and shows the lead at 04:44:25.
04:44:35	A `blob_refs` read takes 10.6 s. At 04:44:53 "reading the cache's removed keys" is cancelled by the statement timeout. t-pg-1's liveness probe fails once.
04:45:01.365	`rc9958b84d1` (created 04:41:01, `select: touched`): `db error: canceling statement due to statement timeout: the run tells nothing more of this drive, and is driven again from its records once the store takes events again` (src/runs/run.rs). In the same millisecond its 15 jobs found open: `a job found open was dropped before its run took it over: it is given up` (src/jobs/follow.rs).
04:45:01.554	The same for `r78cc668040` (created 03:43:21, `select: touched`) and its one job.
04:45:01.850	Both: `driven again in this leadership, from its records`.
04:45:04 to :06	14 of the 16 jobs end `cancelled` (two had already ended): 13 had run 216 to 227 s, one `test/tilo-session` 2,805 s.
04:45 to 04:55	`t_runs_before_asking{phase="planning"}` reads 2. No log line, no event, no ask in the scheduler's view for either run. The take-over's lookups (`lookup_turn` 794) are done by 04:50.
04:55:15 and :20	`a run driven again keeps the checks it told run=rc9958b84d1 kept=150 of=583` and `run=r78cc668040 kept=466 of=486`. The cancelled checks are asked again from 04:55:16 (13 and 10 jobs).

The two restarts before it that night (02:42Z, 03:40Z) cancelled no job of a person; three and one touched runs were open then.

Cause, as far as I read it

A run of bare t test (Select::Touched) plans by reading what every check's cached verdicts read (runs::scope::picked, changed_against, CacheServer::reads_of_checks: the result_latest join and the read sets no index is held of). On this server that is slow at the best of times: from created to its planned event, the four such runs before 04:44Z took 161 s at the median and 851 s at the longest, against 0.1 s for 926 runs that named their checks. The cache's database reads wait for a permit throughout (300 to 1,400 seconds waited each second).
A run driven again plans from nothing. The planning phase of runs::run::run (from Phase::enter("planning") to drop((permit, planning))) reads nothing of the run's records, though its planned event already names the checks it picked. So each open touched run repeats that read at a take-over, when the database is busiest and the scope indexes are empty. Here it ran into the 30 s STATEMENT_TIMEOUT, which ended the drive. The second drive read it all again and took ten minutes. It also picked anew: of=583 where the run had planned 582.
A drive that ends so drops the jobs it found open before it took them over, and Taken's drop gives them up (Jobs::give_up), although the same run is driven again half a second later and would have followed them.

What I do, and what I leave to the owner

Mine (the run's planning; a developer is on it): a run driven again takes the checks it picked from its planned event and does not pick its scope again. Where its records hold no plan it plans as today. That removes the read from every take-over and makes a run's selection one decision.
For the owner of the take-over (jobs/follow.rs, not patched by me): whether a drive that ends in a transient database error and is driven again should hand the jobs it found open to that next drive rather than give them up. With point 2 fixed this trigger is gone, but any other transient error in a resumed drive before it reaches its jobs still cancels them.
Not addressed here: why a touched run takes minutes to plan at all. One part is the cache's database pool: about 113,000 joined checks each read their keys again every 20 s (CacheServer::waiting, proto::HOLD), 6,000 key reads a second.

**Live, 2026-11-13 07:07Z.** Production serves ebbad1e3 since 07:04:46Z (promoted by me; it holds f6b4ed5e). At that restart three people's runs that pick their own checks were open: `r8c59837ad3` (bare `t test`), `r9f3e178cff` and `rf2d592fea8` (last failures). Each logged `a run driven again keeps the checks it told` 10 to 11 s after the server started (kept 649 of 763, 70 of 79, 243 of 248) and went on. `t_runs_before_asking{phase="planning"}` read 0. No job was given up, no drive told nothing, no statement timed out. At 06:01Z, on the code before, the same kind of run sat 8 min 13 s in planning; at 04:44Z it timed out and lost 14 jobs. The point left to the owner (a drive ending in a transient error gives up the jobs it found open) stands. --- **Update, 2026-11-13 05:31Z.** My part is on main as f6b4ed5e ("runs: a run driven again takes the checks it picked from its plan, and picks nothing anew"). A run driven again reads its `planned` event once, before it selects (`Db::planned`, the read that already decided whether the plan is told again), and a run of bare `t test` or `--failed` drives the checks that event names. A run that named its checks selects as before. A plan read that fails ends the drive as an unread one and never picks anew. Three tests in src/runs/engine/tests.rs take a run over after what it would pick has moved. The whole check set ran green twice on testing (runs re1918ceb03 and r1ed4d4b22f). It is not on production yet; the next restart that carries it is its first proof live. The two points left to the owner below are unchanged: the give-up of followed jobs when a drive ends in a transient error, and why a `touched` run takes minutes to plan. --- Seen on t.tilo.so at the restart of 2026-11-13 04:44Z (166e9649, server pod t-9fc997b7b-2nshh, leading epoch 549). Two runs of one person's session lost their running jobs and then told nothing for ten minutes. No job ended with a cause and no error was told, so nothing counted it. **What happened, from the server's log and the database** | Time (Z) | What | |---|---| | 04:44:17 | The new server starts; it leads at 04:44:18 and shows the lead at 04:44:25. | | 04:44:35 | A `blob_refs` read takes 10.6 s. At 04:44:53 "reading the cache's removed keys" is cancelled by the statement timeout. t-pg-1's liveness probe fails once. | | 04:45:01.365 | `rc9958b84d1` (created 04:41:01, `select: touched`): `db error: canceling statement due to statement timeout: the run tells nothing more of this drive, and is driven again from its records once the store takes events again` (src/runs/run.rs). In the same millisecond its 15 jobs found open: `a job found open was dropped before its run took it over: it is given up` (src/jobs/follow.rs). | | 04:45:01.554 | The same for `r78cc668040` (created 03:43:21, `select: touched`) and its one job. | | 04:45:01.850 | Both: `driven again in this leadership, from its records`. | | 04:45:04 to :06 | 14 of the 16 jobs end `cancelled` (two had already ended): 13 had run 216 to 227 s, one `test/tilo-session` 2,805 s. | | 04:45 to 04:55 | `t_runs_before_asking{phase="planning"}` reads 2. No log line, no event, no ask in the scheduler's view for either run. The take-over's lookups (`lookup_turn` 794) are done by 04:50. | | 04:55:15 and :20 | `a run driven again keeps the checks it told run=rc9958b84d1 kept=150 of=583` and `run=r78cc668040 kept=466 of=486`. The cancelled checks are asked again from 04:55:16 (13 and 10 jobs). | The two restarts before it that night (02:42Z, 03:40Z) cancelled no job of a person; three and one `touched` runs were open then. **Cause, as far as I read it** 1. A run of bare `t test` (`Select::Touched`) plans by reading what every check's cached verdicts read (`runs::scope::picked`, `changed_against`, `CacheServer::reads_of_checks`: the `result_latest` join and the read sets no index is held of). On this server that is slow at the best of times: from created to its `planned` event, the four such runs before 04:44Z took 161 s at the median and 851 s at the longest, against 0.1 s for 926 runs that named their checks. The cache's database reads wait for a permit throughout (300 to 1,400 seconds waited each second). 2. A run driven again plans from nothing. The planning phase of `runs::run::run` (from `Phase::enter("planning")` to `drop((permit, planning))`) reads nothing of the run's records, though its `planned` event already names the checks it picked. So each open `touched` run repeats that read at a take-over, when the database is busiest and the scope indexes are empty. Here it ran into the 30 s `STATEMENT_TIMEOUT`, which ended the drive. The second drive read it all again and took ten minutes. It also picked anew: `of=583` where the run had planned 582. 3. A drive that ends so drops the jobs it found open before it took them over, and `Taken`'s drop gives them up (`Jobs::give_up`), although the same run is driven again half a second later and would have followed them. **What I do, and what I leave to the owner** - Mine (the run's planning; a developer is on it): a run driven again takes the checks it picked from its `planned` event and does not pick its scope again. Where its records hold no plan it plans as today. That removes the read from every take-over and makes a run's selection one decision. - For the owner of the take-over (`jobs/follow.rs`, not patched by me): whether a drive that ends in a transient database error and is driven again should hand the jobs it found open to that next drive rather than give them up. With point 2 fixed this trigger is gone, but any other transient error in a resumed drive before it reaches its jobs still cancels them. - Not addressed here: why a `touched` run takes minutes to plan at all. One part is the cache's database pool: about 113,000 joined checks each read their keys again every 20 s (`CacheServer::waiting`, `proto::HOLD`), 6,000 key reads a second.

xemmerling referenced this issue

2026-11-13 06:18:20 +00:00

scope: the read of what a plan's checks read walks 436,000 verdict rows (17.6 s) and times out in bursts of 11 to 16 after every restart; askers of the same checks should share one read #56

No labels

No milestone

No project

No assignees

1 participant

Notifications

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference

tilo/t#54

No description provided.

Rows
Columns