A cold wave of unit graphs passes the resolver's 120 s limit: the resolver takes every graph at once #58

New issue

Open

opened 2026-11-13 12:41:52 +00:00 by xemmerling · 0 comments

xemmerling commented

2026-11-13 12:41:52 +00:00

Owner

Update 15:22Z 2026-11-13: the bound is on production since 15:14:52Z (123aaf58, my promote). That restart made no graph cold (the parse version did not change): no graph waited for a resolver and none was resolved in its first minutes, so the bound has not met a wave on production yet. The worker took the new build at 15:14:49Z and re-attached to its 54 jobs in 7 s. The next change of the graphs' keys is its first real test: look then for queued= above zero with resolvers=1 while about 40 resolve, resolves of seconds each, and no not resolved within 120 s line.

Update 13:53Z 2026-11-13: seen working in a deployed worker, on testing (b96c6335). A forced run of test/t-wrapper and clippy/t-wrapper from a local state with a new target path (run r99a90d9f70, both passed): two cold graphs waited at 13:47:26Z with queued=1 resolvers=1 and were answered by t-worker-hetzner-1 in 5.0 s and 10.4 s, failed=false. During testing's deploy the worker could not reach the new server for about a minute; the resolver's loop retried once a second and took graphs again afterwards. A wave has not been seen under the bound yet: the first on production comes with the next change of the graphs' keys.

Update 13:18Z 2026-11-13: fixed on main as 56fb34c9; not on production yet. cargo::resolver: a node takes a graph only when it can start its resolve, at most one per four of its CPUs at once. The resolver's loop takes a permit before it asks the server for a graph and lets it go when that resolve's task ends, however it ends. The bound is available_parallelism() / 4, at least 4: 40 on ci-x86-1, whose worker is given 163 CPUs, and 13 on testing's. The server is unchanged but for its words: a node at its bound has no ask open and still counts as a resolver by the graphs it holds (each Holding carries its Seen), so Graphs::waiting, resolvers= and the hand-back read it as present.

Wave of 1,000 graphs through the server's hand-out and its 120 s bound (paused time, node model 4 graphs a second)	Bounded at 40	Taken whole, as before
Answered	1,000	952
Failed as t's error	0	48
Past the bound	0	572
Longest from its take	14 s	120 s
All answered by	252 s	240 s

Forced whole check set on testing: 8 of 8 passed on the commit (run r1b522fbe5f), both new tests among them on Linux. It changes no job file and no protocol, and it only acts at the next cold wave, so it needs no promote of its own; it rides with the next batch. The label on the 27 checks (below) is not part of it.

What happened, 2026-11-13 12:32 to 12:38Z on t.tilo.so (f06bfdc3, promoted 12:32:20Z). The promote made every unit graph cold once (parse version 9). The node's one resolver took all of them at once and 66 of them passed RESOLVE_WITHIN on their first try. Each was answered on its second try, so no run failed and no check was told error. TRIES is 2: one more pass of the limit and every asker's run of that graph fails with t's own error.

Reading (server log of t-7c668b9d7b-8nvr7)	Value
Graphs queued at the peak (12:32:50Z, `queued=434 resolvers=1`)	434
Graphs answered 12:32 to 12:37Z	454, none answered as failed
Resolve seconds, answers of 12:32Z and of 12:36 to 12:37Z (few at once)	2 to 10
Resolve seconds, answers of 12:33Z (37)	median 60
Resolve seconds, answers of 12:34Z (281)	median 100, longest 114
`not resolved within 120 s of taking it`, all between 12:35:04.5 and 12:35:08.8Z	66
Their second try	0.17 to 34 s, median 1.9 s
The same after `91b2c84d` (10:11Z, 430 graphs wanted at once)	9 past 120 s

Cause. resolve_loop (src/cargo/resolver.rs) asks for the next graph the moment it takes one and resolves each on its own task, with nothing bounding how many run side by side. The server's limit runs from the take. So in a wave the limit, which is there to tell a hung cargo, measures how long a resolve waits behind the 400 others its own resolver took: alone a resolve takes 2 to 10 s, in the wave 60 to 120 s, at 3.6 to 4.7 graphs a second whatever the number at once. A wave of twice this size, or the same wave on a slower minute, uses both tries.

Proposal. The resolver takes a graph only when it can start it: at most a fixed number of resolves side by side on a node (I propose one per four of the node's CPUs, at least four: 48 on ci-x86-1). The rest stay queued on the server, where waiting for a resolver has no deadline, and the wave drains at the same rate with each resolve a few seconds long. The server, RESOLVE_WITHIN and TRIES stay as they are. Test at production size: a wave of 1,000 graphs wanted at once, none past the limit, none retried.

I am commissioning this now, in the resolver alone. Say here if you would rather bound it on the server's side or have it differently.

Added 13:06Z: what the wave cost the runs, and a label it left behind.

Reading, restart to 12:58Z (Prometheus)	Value
Family waits for a unit graph (`t_family_graph_wait_seconds`)	1,245, mean 104 s, median 117 s, p90 262 s, none over 300 s
Graphs over 120 s from their first ask (`t_unit_graph_answered_seconds`)	266 of 499
Resolves (`t_unit_graph_resolve_seconds`)	mean 71 s, median 79 s, p90 112 s

The bound removes the passes of the limit, not this wait: the wave drains at about four graphs a second either way.

A label: since the restart the jobs view shows the same 27 queued test checks of nine open head runs (r0007cc86b1, r3e056df797 and seven more) with wait kind resolver, while no graph is queued or resolving. They are not held by it: the test family of r0007cc86b1 told four checks at 12:35:12Z, after its graph, and its other test checks stand queued for room. Standing::Queued with the resolver's wait is said in the driver's graph loop while no resolver is fit (the first half minute after the restart) and nothing replaces it for a check until something else is said of it. Not part of the change I commissioned.

**Update 15:22Z 2026-11-13: the bound is on production since 15:14:52Z (123aaf58, my promote).** That restart made no graph cold (the parse version did not change): no graph waited for a resolver and none was resolved in its first minutes, so the bound has not met a wave on production yet. The worker took the new build at 15:14:49Z and re-attached to its 54 jobs in 7 s. The next change of the graphs' keys is its first real test: look then for `queued=` above zero with `resolvers=1` while about 40 resolve, resolves of seconds each, and no `not resolved within 120 s` line. **Update 13:53Z 2026-11-13: seen working in a deployed worker, on testing (b96c6335).** A forced run of `test/t-wrapper` and `clippy/t-wrapper` from a local state with a new target path (run r99a90d9f70, both passed): two cold graphs waited at 13:47:26Z with `queued=1 resolvers=1` and were answered by t-worker-hetzner-1 in 5.0 s and 10.4 s, `failed=false`. During testing's deploy the worker could not reach the new server for about a minute; the resolver's loop retried once a second and took graphs again afterwards. A wave has not been seen under the bound yet: the first on production comes with the next change of the graphs' keys. **Update 13:18Z 2026-11-13: fixed on main as 56fb34c9; not on production yet.** `cargo::resolver: a node takes a graph only when it can start its resolve, at most one per four of its CPUs at once.` The resolver's loop takes a permit before it asks the server for a graph and lets it go when that resolve's task ends, however it ends. The bound is `available_parallelism() / 4`, at least 4: 40 on ci-x86-1, whose worker is given 163 CPUs, and 13 on testing's. The server is unchanged but for its words: a node at its bound has no ask open and still counts as a resolver by the graphs it holds (each `Holding` carries its `Seen`), so `Graphs::waiting`, `resolvers=` and the hand-back read it as present. | Wave of 1,000 graphs through the server's hand-out and its 120 s bound (paused time, node model 4 graphs a second) | Bounded at 40 | Taken whole, as before | |---|---|---| | Answered | 1,000 | 952 | | Failed as t's error | 0 | 48 | | Past the bound | 0 | 572 | | Longest from its take | 14 s | 120 s | | All answered by | 252 s | 240 s | Forced whole check set on testing: 8 of 8 passed on the commit (run r1b522fbe5f), both new tests among them on Linux. It changes no job file and no protocol, and it only acts at the next cold wave, so it needs no promote of its own; it rides with the next batch. The label on the 27 checks (below) is not part of it. **What happened, 2026-11-13 12:32 to 12:38Z on t.tilo.so (f06bfdc3, promoted 12:32:20Z).** The promote made every unit graph cold once (parse version 9). The node's one resolver took all of them at once and 66 of them passed `RESOLVE_WITHIN` on their first try. Each was answered on its second try, so no run failed and no check was told `error`. `TRIES` is 2: one more pass of the limit and every asker's run of that graph fails with t's own error. | Reading (server log of t-7c668b9d7b-8nvr7) | Value | |---|---| | Graphs queued at the peak (12:32:50Z, `queued=434 resolvers=1`) | 434 | | Graphs answered 12:32 to 12:37Z | 454, none answered as failed | | Resolve seconds, answers of 12:32Z and of 12:36 to 12:37Z (few at once) | 2 to 10 | | Resolve seconds, answers of 12:33Z (37) | median 60 | | Resolve seconds, answers of 12:34Z (281) | median 100, longest 114 | | `not resolved within 120 s of taking it`, all between 12:35:04.5 and 12:35:08.8Z | 66 | | Their second try | 0.17 to 34 s, median 1.9 s | | The same after 91b2c84d (10:11Z, 430 graphs wanted at once) | 9 past 120 s | **Cause.** `resolve_loop` (src/cargo/resolver.rs) asks for the next graph the moment it takes one and resolves each on its own task, with nothing bounding how many run side by side. The server's limit runs from the take. So in a wave the limit, which is there to tell a hung cargo, measures how long a resolve waits behind the 400 others its own resolver took: alone a resolve takes 2 to 10 s, in the wave 60 to 120 s, at 3.6 to 4.7 graphs a second whatever the number at once. A wave of twice this size, or the same wave on a slower minute, uses both tries. **Proposal.** The resolver takes a graph only when it can start it: at most a fixed number of resolves side by side on a node (I propose one per four of the node's CPUs, at least four: 48 on ci-x86-1). The rest stay queued on the server, where waiting for a resolver has no deadline, and the wave drains at the same rate with each resolve a few seconds long. The server, `RESOLVE_WITHIN` and `TRIES` stay as they are. Test at production size: a wave of 1,000 graphs wanted at once, none past the limit, none retried. I am commissioning this now, in the resolver alone. Say here if you would rather bound it on the server's side or have it differently. **Added 13:06Z: what the wave cost the runs, and a label it left behind.** | Reading, restart to 12:58Z (Prometheus) | Value | |---|---| | Family waits for a unit graph (`t_family_graph_wait_seconds`) | 1,245, mean 104 s, median 117 s, p90 262 s, none over 300 s | | Graphs over 120 s from their first ask (`t_unit_graph_answered_seconds`) | 266 of 499 | | Resolves (`t_unit_graph_resolve_seconds`) | mean 71 s, median 79 s, p90 112 s | The bound removes the passes of the limit, not this wait: the wave drains at about four graphs a second either way. A label: since the restart the jobs view shows the same 27 queued test checks of nine open head runs (r0007cc86b1, r3e056df797 and seven more) with wait kind `resolver`, while no graph is queued or resolving. They are not held by it: the test family of r0007cc86b1 told four checks at 12:35:12Z, after its graph, and its other test checks stand queued for room. `Standing::Queued` with the resolver's wait is said in the driver's graph loop while no resolver is fit (the first half minute after the restart) and nothing replaces it for a check until something else is said of it. Not part of the change I commissioned.

xemmerling referenced this issue

2026-11-13 12:51:06 +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#58

No description provided.

Rows
Columns