tilo/t

Watch

Fork 0

sched: the expected-end estimates walk the whole queue after every pass (250 to 380 ms a round, a fifth of the scheduler's thread, which is at its ceiling when CI places jobs) #53

New issue

Open

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

xemmerling commented

2026-11-13 04:35:34 +00:00

Owner

Update 13:37Z 2026-11-13: the hour after the 12:32Z restart (f06bfdc3). Passes over a second, from the server's own warnings:

Ten minutes from	Passes over 1 s	Mean pass	Mean asks
12:30Z	67	3.46 s	42,730
12:40Z	91	3.76 s	46,426
12:50Z	116	3.53 s	49,567
13:00Z	103	3.34 s	50,653
13:10Z	115	3.30 s	50,215
13:20Z	142	2.33 s	51,100
13:30Z (three minutes)	58	1.85 s	51,594

Weighing was 3.1 to 3.3 s of a 3.5 s pass at 12:39Z (45,311 asks, no grows). Over the whole hour the mean pass was 1.47 s and passes took 77% of the thread. So for about forty minutes after a restart the long passes are the rule, with the same number of asks that later pass in under two seconds: the weighing is slower while the runs driven again are still placing, not because the queue is longer. On 8210a6d7 before it, 90 minutes stayed under a 2.25 s mean.

Update 08:12Z 2026-11-13 (ebbad1e3, then 0f37ba87 from 08:04Z). The pass time is bimodal, which the means below hide. From t_pass_seconds_bucket, production only:

Code	Window	Passes a second	Of them under 0.5 s	Of them over 2.5 s	Mean pass s	Thread inside passes
`ebbad1e3`	07:40 to 08:00Z	0.58	0.35	0.21	1.36	78%
`0f37ba87`	08:06 to 08:10Z	0.67	0.46	0.13	1.12	75%

Almost no pass falls between 0.5 s and 2.5 s (0.02 a second on the first row, 0.08 on the second).
The long ones in the server's log (a scheduling pass took long, 08:07 to 08:10Z) run 3.0 to 4.8 s at 45,000 asks, with weighing 3.1 to 4.5 s of it and predict 0.2 s.
State::pass has no early end: every pass walks the whole line. So the two modes differ in what decide costs for one ask, about 10 µs in a short pass and about 80 µs in a long one.
Not read: which state makes a pass long. If it is the passes with room on the node, the pass is slowest exactly when it can place.
dbbcad6a did not change this: mean pass by minute after the restarts at 06:01Z, 07:04Z and 08:04Z climbs alike to 1.2 to 1.7 s as the queue refills to 45,000.

Update, 2026-11-13 06:26Z, on 21edb1e8. The pass has been at about 1.5 s since 06:09Z, steadily, and the thread is full.

Three minutes to	05:42Z	05:51Z	05:57Z	06:09Z	06:15Z	06:21Z	06:24Z
`State::pass`, mean ms	782	1,251	1,484	1,438	1,464	1,485	1,476
Rounds a second	0.93	0.64	0.55	0.55	0.55	0.55	0.55
Weighing, share of each second	54%	66%	70%	64%	70%	69%	69%
Predict	20%	15%	13%	15%	13%	13%	13%
Queue	44,000	44,000	44,000	44,000	44,000	44,000	44,000
CI jobs placed a second	2.6	2.3	1.6	0.1	0.0	0.1	0.0

Pass, predict and view together take about 95% of the thread; it decides once every 1.8 s.
The server's own warning (a scheduling pass took long) fired 188 times in the 15 minutes to 06:24Z, about every pass. The longest: 4.8 s at 06:14:00Z, of it 4.3 s weighing 44,289 asks (1.5 s of that resolving one driver's graph); four more between 3.9 and 3.6 s.
Weighing now costs about 28 microseconds for each queued ask, against 11 to 13 on 86fa55c0 and 19 at 04:31Z. It is highest while CI places nothing: people's sessions hold the node, so every pass weighs 44,000 CI asks that are each short by one core and places none of them.
People's jobs still start in 1.3 s at the median and 3.7 s at the 95th percentile (2.9 s an hour earlier); their wait now follows the length of a pass.

So beside the estimates, the larger part is the weighing of asks that cannot fit: a pass that knows a node has no core left for a class still decides each of that class's asks for that node.

Seen on t.tilo.so on 2026-11-13, on d26adb93 and on 86fa55c0 before it. A proposal with its measurements; the module is the scheduler's owner's, so nothing is patched from my side.

The scheduler's one thread is at its ceiling whenever CI places jobs. Of each second it spends (Prometheus, t_pass_seconds and t_pass_phase_seconds, ten-minute rates, production only):

Window ending	Code	Rounds a second	`State::pass` ms	of it weighing ms	`predict` ms	Queue	CI jobs placed a second
02:20Z	`86fa55c0`	1.30	527	379	166	30,000	2.8
02:30Z	`86fa55c0`	1.39	465	316	164	29,000	2.2
03:30Z	`eeb2996a`	0.79	796	533	379	34,000	0.1
04:20Z	`d26adb93`	1.01	634	414	247	46,000	1.1
04:31Z	`d26adb93`	0.70	1,083	854	254	45,000	1.9

t_pass_seconds times State::pass alone. After it the thread makes the view and then view.eta = self.state.predict(now) (src/sched/mod.rs). Pass, view and predict together took about 90% of the thread at 02:20 to 02:40Z and about 97% at 04:30Z; a round takes about 1.4 s there, and the scheduler decides 0.7 times a second where it decided 1.3.
State::predict (src/sched/state/eta.rs) gives each running job an expected end and then walks the whole line again (forward): for every queued ask it works out what admission would ask and the first node and moment it would fit. That is a second weighing of the queue after every pass, 250 to 380 ms a round, a fifth to a quarter of the thread.
Its readers are the pages (server/pages/now.rs, server/pages/run.rs) and the views' per-run estimate (runs/mod.rs, Kept::begin). No placement reads it: admission reads State::end_of for running jobs through State::counted, which a pass calls itself.
The queue it walks, from the jobs view at 04:33Z: 58,597 queued jobs, 57,431 of them CI's, from 199 open runs (median 263 a run), every one waiting for room and short by one core. By check family: policy 18,416, clippy 15,631, test 14,263, test-x86_64 2,049, clippy-x86_64 1,602.
The two admission commits changed almost nothing in src/sched, so the higher pass cost since them follows the shape of the load (builds entering abreast, a queue half as long again since the 03:40Z restart), not new scheduler code. What made the queue jump by 12,000 at that restart I have not found.

Proposed, for the owner to judge: work the estimates out less often than every pass (every few passes, or at most once in some seconds), or off the scheduler's thread from a copy of its state. Nothing but the freshness of the pages' expected ends would change, and the thread gets a fifth to a quarter of its time back for passes.

Not shown: that the pass cost limits CI's job starts today. People's jobs start within 3 s at the 95th percentile throughout.

Relay messages to the scheduler's owner go to an inbox that has been offline since 2026-11-12 10:31Z, so this is filed here.

11-13, production on 9faf6c61 (65bf0d9b live since 16:32Z), no restart in the window: the mean pass over five minutes (t_pass_seconds_sum / _count) ran 1,130 to 1,670 ms from 17:26 to 18:01Z, 2,046 ms at 18:06Z, 2,183 ms at 18:51Z and 2,583 ms at 18:56Z, with 73 to 83% of the thread inside passes and the passes per five minutes falling from 198 to 96. Queued asks stayed 43,300 to 46,500, so this is not the queue growing. The passes the server logs as long: 91 to 119 per ten minutes since the 16:32Z restart at 3.2 to 3.5 s (70 to 85 per ten minutes at 3.4 s on the build before), the longest 7.97 s at 18:32:35Z (pass=6.96 weighing=4.98 predict=0.85 asks=43497 resolves=7). The database was at 9% throttled periods at 18:56Z, so it does not explain that reading. Since 65bf0d9b the server also logged "a job placed on a node without room for it ... held there" 84 times in two bursts right after the restart and a handful since, against about one an hour before; no wait came of it.

19:01Z 11-13, the placement warning outside a restart: 150 lines "a job placed on a node without room for it ... held there" within 48 s (141 in one minute), 144 jobs on the worker, each why="every start under way" with busy 157 to 189 of a budget of 159. It was a wave from people's sessions: 317 people's jobs were handed in the minute before, and 137 of the 144 held were people's. Each waited 0.17 s at the median and 0.8 s at most from handed to started, so nothing came of it but the lines; before 65bf0d9b there was about one such line an hour.

20:40Z 11-13, the pass keeps lengthening with no restart and a nearly level queue. Mean pass over five minutes 3,569 ms with 88% of the thread inside passes (three-minute means since 20:00Z: 1.6 to 3.7 s, thread 77 to 91%); queued asks 48,300 to 49,600; the server at 4.4 to 5.6 cores against 3.0 to 3.4 this afternoon. From the long-pass lines:

window	lines	pass, mean	weighing, mean	predict	asks
18:30 to 18:55Z	326	3.02 s	2.63 s	0.42 s	43,500
20:29 to 20:41Z	138	4.24 s	3.85 s	0.37 s	49,600

Weighing (the queued jobs weighed) is nine tenths of a pass and rose 46% while the queue rose 14%: 60 to 78 microseconds an ask. So something beside the queue's length scales it. What differs this evening is people's sessions: 39 to 52 of their jobs out at a time and 400 to 900 starts a quarter hour, with people's jobs taking 90% of the node's CPU from 19:58 to 20:28Z. People's pickup p95 moved from 4.0 to 4.7 s; nothing else has come of it yet. At 92% of the thread I expect placement to lag for everyone.

The trend over 24 hours (t_pass_seconds, t_pass_phase_seconds{phase="weighing"}, two-hour means over all passes):

two hours ending	mean pass	weighing per pass	thread inside passes	queued asks, highest	weighing per queued ask
20Z 11-12	385 ms	240 ms	59%	34,000	8 µs
02Z 11-13	608 ms	438 ms	68%	37,000	13 µs
08Z	880 ms	725 ms	77%	47,000	17 µs
14Z	1,402 ms	1,032 ms	76%	54,000	20 µs
18Z	1,407 ms	1,080 ms	78%	49,000	24 µs
20Z	2,146 ms	1,777 ms	82%	50,000	37 µs

The queue grew by half in the day and the weighing by seven times, so the cost of weighing one queued ask more than quadrupled: it grows with something else as well (open head runs went from about 150 to 305 in the same day, and the claims the server holds stand at 400,000 keys with 453,000 waiters). At this slope the scheduling thread is saturated within a day or less.

23:44Z 11-13, on 6ebaa239 (your promote of 22:08Z): the same picture. Ten-minute means:

to	22:24	22:44	23:04	23:24	23:44
mean pass, ms	2,073	1,518	2,577	2,164	2,315
pass share of its thread	80%	75%	82%	83%	83%
weighing per queued ask, µs	38	23	43	35	37
asks queued	43,765	48,670	49,560	50,747	51,720

The restart took the queue to about 40,000 and it is at its highest yet again an hour and a half later, with 345 heads open. Neither of my marks (a mean pass of 5 s, 92% of the thread) was passed.

00:40Z 11-14, on `c2d52b34`: every pass takes 3 to 4 s, and the node dipped under 130 busy cores with a full queue

From the server's own "a scheduling pass took long" lines since it started at 00:22Z, averaged per two minutes:

From	Passes logged	Mean pass	Of it weighing	Asks
00:22Z	22	1.09 s	0.86 s	40,650
00:24Z	25	3.57 s	3.16 s	52,896
00:28Z	23	3.95 s	3.55 s	53,725
00:30Z	24	4.01 s	3.62 s	53,833
00:34Z	27	3.56 s	3.13 s	53,809
00:38Z	29	3.41 s	3.05 s	53,302

That is one pass every four to five seconds, all of them long. In the half hour before this build the mean pass was 1.1 s at 79% of the thread, with about 48,000 asks.
views after a pass holds a runtime thread 0.5 to 0.8 s each time: 2,182 such warnings in the server's first 18 minutes.
00:36 to 00:39Z the node ran 96, 126, 76 and 143 busy cores of 192 threads while booked 159 of 159 and with 109,000 jobs waiting for room. In the seven hours before, only one minute outside a restart was under 130. It was back at 165 by 00:40Z.
In those minutes CI's oldest heads were finishing many short test jobs: 2,398 jobs ended in the 20 minutes to 00:40Z against 500 to 900 in each 20 minutes of the evening. The head of the node's line was held by starts for 398 s and by cores for 277 s of those 20 minutes (t_node_line_held_seconds_total).

My reading, not shown: with passes of 3.5 s the node is refilled once per pass, so a burst of short jobs ending leaves cores booked but idle until the next pass, and the starts allowed at once cap what one pass can put back. Nothing here is mine to patch; it is data for the planner.

02:47Z 11-14, on `c2d52b34`: the mean pass is past five seconds

My watch's mark was a five-minute mean of 5,000 ms. It read 5,375 ms at 02:47Z, with 90% of the thread inside passes. The two 90-minute watches before it ended at 4,055 ms (highest 4,415) and 4,248 ms (highest 4,761).

From the server's own "a scheduling pass took long" lines, averaged per two minutes:

From	Passes logged	Mean pass	Of it weighing	Asks
02:30Z	9	1.19 s	0.70 s	57,826
02:34Z	17	6.44 s	5.86 s	58,117
02:38Z	25	4.12 s	3.64 s	58,359
02:42Z	21	5.20 s	4.70 s	58,688
02:44Z	20	5.51 s	5.01 s	58,812
02:46Z	17	5.25 s	4.75 s	59,023

The newest pass at 02:47:38Z took 6.15 s, 5.62 s of it weighing, over 59,071 asks; the longest in those 16 minutes took 8.06 s.
views after a pass held a runtime thread 194 times in the 16 minutes. No "ran its tasks late" line.
The node did not idle for it in those minutes: 167 to 184 busy cores, jobs started in bursts of 4 to 206 a minute, the head of the node's line held by starts for a few seconds a minute at most.
The queue grows by about 80 asks a minute (57,826 at 02:32Z, 59,071 at 02:47Z): CI heads arrive about three times as fast as they finish (431 open). At the same asks the pass varied between 1.2 and 6.4 s within minutes, so it is not the count of asks alone.

Update 11:20Z 2026-11-14: the weighing follows people's starts, not the queue (58b70474 and the builds before it). t_pass_phase_seconds by phase, ten-minute means, with the queue between 65,000 and 74,000 asks throughout:

Ten minutes to	Weighing s a pass	Predict s a pass	Passes a minute	People's starts a minute	CI starts a minute
07:28Z	5.4	0.6	8.9	51.0	40.9
07:38Z	1.9	0.7	18.2	15.0	78.1
07:48Z	4.0	0.7	11.0	44.3	20.8
08:18Z	1.5	0.6	21.8	22.2	57.8
08:38Z	4.5	0.6	10.3	28.9	81.4
09:38Z	2.9	0.6	14.2	10.2	120.5
10:08Z	2.7	0.6	14.8	9.4	104.9
10:38Z	2.1	0.7	17.3	9.0	80.9
10:58Z	5.7	0.6	8.5	25.3	52.4
11:18Z	6.9	0.7	7.2	41.2	9.4

Over the last five minutes to 11:17Z the mean pass was 10.0 s and passes took 90% of the thread; over the last hour 3.3 s, of which weighing 2.6 s.
The queue's length did not change between the 1.5 s and the 6.9 s rows. What changed is how many of people's jobs were starting: about 10 a minute in the short rows, 25 to 50 in the long ones.
In the long rows the scheduler makes 7 to 9 passes a minute instead of 15 to 20, and CI's starts fall with them (9.4 a minute at 11:18Z).
Resolving, view and grows together stay under 0.2 s a pass in every row.

**Update 13:37Z 2026-11-13: the hour after the 12:32Z restart (f06bfdc3).** Passes over a second, from the server's own warnings: | Ten minutes from | Passes over 1 s | Mean pass | Mean asks | |---|---|---|---| | 12:30Z | 67 | 3.46 s | 42,730 | | 12:40Z | 91 | 3.76 s | 46,426 | | 12:50Z | 116 | 3.53 s | 49,567 | | 13:00Z | 103 | 3.34 s | 50,653 | | 13:10Z | 115 | 3.30 s | 50,215 | | 13:20Z | 142 | 2.33 s | 51,100 | | 13:30Z (three minutes) | 58 | 1.85 s | 51,594 | Weighing was 3.1 to 3.3 s of a 3.5 s pass at 12:39Z (45,311 asks, no grows). Over the whole hour the mean pass was 1.47 s and passes took 77% of the thread. So for about forty minutes after a restart the long passes are the rule, with the same number of asks that later pass in under two seconds: the weighing is slower while the runs driven again are still placing, not because the queue is longer. On 8210a6d7 before it, 90 minutes stayed under a 2.25 s mean. **Update 08:12Z 2026-11-13 (ebbad1e3, then 0f37ba87 from 08:04Z).** The pass time is bimodal, which the means below hide. From `t_pass_seconds_bucket`, production only: | Code | Window | Passes a second | Of them under 0.5 s | Of them over 2.5 s | Mean pass s | Thread inside passes | |---|---|---|---|---|---|---| | ebbad1e3 | 07:40 to 08:00Z | 0.58 | 0.35 | 0.21 | 1.36 | 78% | | 0f37ba87 | 08:06 to 08:10Z | 0.67 | 0.46 | 0.13 | 1.12 | 75% | - Almost no pass falls between 0.5 s and 2.5 s (0.02 a second on the first row, 0.08 on the second). - The long ones in the server's log (`a scheduling pass took long`, 08:07 to 08:10Z) run 3.0 to 4.8 s at 45,000 asks, with weighing 3.1 to 4.5 s of it and `predict` 0.2 s. - `State::pass` has no early end: every pass walks the whole line. So the two modes differ in what `decide` costs for one ask, about 10 µs in a short pass and about 80 µs in a long one. - Not read: which state makes a pass long. If it is the passes with room on the node, the pass is slowest exactly when it can place. - dbbcad6a did not change this: mean pass by minute after the restarts at 06:01Z, 07:04Z and 08:04Z climbs alike to 1.2 to 1.7 s as the queue refills to 45,000. **Update, 2026-11-13 06:26Z, on 21edb1e8.** The pass has been at about 1.5 s since 06:09Z, steadily, and the thread is full. | Three minutes to | 05:42Z | 05:51Z | 05:57Z | 06:09Z | 06:15Z | 06:21Z | 06:24Z | |---|---|---|---|---|---|---|---| | `State::pass`, mean ms | 782 | 1,251 | 1,484 | 1,438 | 1,464 | 1,485 | 1,476 | | Rounds a second | 0.93 | 0.64 | 0.55 | 0.55 | 0.55 | 0.55 | 0.55 | | Weighing, share of each second | 54% | 66% | 70% | 64% | 70% | 69% | 69% | | Predict | 20% | 15% | 13% | 15% | 13% | 13% | 13% | | Queue | 44,000 | 44,000 | 44,000 | 44,000 | 44,000 | 44,000 | 44,000 | | CI jobs placed a second | 2.6 | 2.3 | 1.6 | 0.1 | 0.0 | 0.1 | 0.0 | - Pass, predict and view together take about 95% of the thread; it decides once every 1.8 s. - The server's own warning (`a scheduling pass took long`) fired 188 times in the 15 minutes to 06:24Z, about every pass. The longest: 4.8 s at 06:14:00Z, of it 4.3 s weighing 44,289 asks (1.5 s of that resolving one driver's graph); four more between 3.9 and 3.6 s. - Weighing now costs about 28 microseconds for each queued ask, against 11 to 13 on 86fa55c0 and 19 at 04:31Z. It is highest while CI places nothing: people's sessions hold the node, so every pass weighs 44,000 CI asks that are each short by one core and places none of them. - People's jobs still start in 1.3 s at the median and 3.7 s at the 95th percentile (2.9 s an hour earlier); their wait now follows the length of a pass. So beside the estimates, the larger part is the weighing of asks that cannot fit: a pass that knows a node has no core left for a class still decides each of that class's asks for that node. --- Seen on t.tilo.so on 2026-11-13, on d26adb93 and on 86fa55c0 before it. A proposal with its measurements; the module is the scheduler's owner's, so nothing is patched from my side. The scheduler's one thread is at its ceiling whenever CI places jobs. Of each second it spends (Prometheus, `t_pass_seconds` and `t_pass_phase_seconds`, ten-minute rates, production only): | Window ending | Code | Rounds a second | `State::pass` ms | of it weighing ms | `predict` ms | Queue | CI jobs placed a second | |---|---|---|---|---|---|---|---| | 02:20Z | 86fa55c0 | 1.30 | 527 | 379 | 166 | 30,000 | 2.8 | | 02:30Z | 86fa55c0 | 1.39 | 465 | 316 | 164 | 29,000 | 2.2 | | 03:30Z | eeb2996a | 0.79 | 796 | 533 | 379 | 34,000 | 0.1 | | 04:20Z | d26adb93 | 1.01 | 634 | 414 | 247 | 46,000 | 1.1 | | 04:31Z | d26adb93 | 0.70 | 1,083 | 854 | 254 | 45,000 | 1.9 | - `t_pass_seconds` times `State::pass` alone. After it the thread makes the view and then `view.eta = self.state.predict(now)` (src/sched/mod.rs). Pass, view and predict together took about 90% of the thread at 02:20 to 02:40Z and about 97% at 04:30Z; a round takes about 1.4 s there, and the scheduler decides 0.7 times a second where it decided 1.3. - `State::predict` (src/sched/state/eta.rs) gives each running job an expected end and then walks the whole line again (`forward`): for every queued ask it works out what admission would ask and the first node and moment it would fit. That is a second weighing of the queue after every pass, 250 to 380 ms a round, a fifth to a quarter of the thread. - Its readers are the pages (`server/pages/now.rs`, `server/pages/run.rs`) and the views' per-run estimate (`runs/mod.rs`, `Kept::begin`). No placement reads it: admission reads `State::end_of` for running jobs through `State::counted`, which a pass calls itself. - The queue it walks, from the jobs view at 04:33Z: 58,597 queued jobs, 57,431 of them CI's, from 199 open runs (median 263 a run), every one waiting for room and short by one core. By check family: policy 18,416, clippy 15,631, test 14,263, test-x86_64 2,049, clippy-x86_64 1,602. - The two admission commits changed almost nothing in src/sched, so the higher pass cost since them follows the shape of the load (builds entering abreast, a queue half as long again since the 03:40Z restart), not new scheduler code. What made the queue jump by 12,000 at that restart I have not found. Proposed, for the owner to judge: work the estimates out less often than every pass (every few passes, or at most once in some seconds), or off the scheduler's thread from a copy of its state. Nothing but the freshness of the pages' expected ends would change, and the thread gets a fifth to a quarter of its time back for passes. Not shown: that the pass cost limits CI's job starts today. People's jobs start within 3 s at the 95th percentile throughout. Relay messages to the scheduler's owner go to an inbox that has been offline since 2026-11-12 10:31Z, so this is filed here. **11-13, production on 9faf6c61 (65bf0d9b live since 16:32Z), no restart in the window:** the mean pass over five minutes (`t_pass_seconds_sum / _count`) ran 1,130 to 1,670 ms from 17:26 to 18:01Z, 2,046 ms at 18:06Z, 2,183 ms at 18:51Z and 2,583 ms at 18:56Z, with 73 to 83% of the thread inside passes and the passes per five minutes falling from 198 to 96. Queued asks stayed 43,300 to 46,500, so this is not the queue growing. The passes the server logs as long: 91 to 119 per ten minutes since the 16:32Z restart at 3.2 to 3.5 s (70 to 85 per ten minutes at 3.4 s on the build before), the longest 7.97 s at 18:32:35Z (`pass=6.96 weighing=4.98 predict=0.85 asks=43497 resolves=7`). The database was at 9% throttled periods at 18:56Z, so it does not explain that reading. Since 65bf0d9b the server also logged "a job placed on a node without room for it ... held there" 84 times in two bursts right after the restart and a handful since, against about one an hour before; no wait came of it. **19:01Z 11-13, the placement warning outside a restart:** 150 lines "a job placed on a node without room for it ... held there" within 48 s (141 in one minute), 144 jobs on the worker, each `why="every start under way"` with busy 157 to 189 of a budget of 159. It was a wave from people's sessions: 317 people's jobs were handed in the minute before, and 137 of the 144 held were people's. Each waited 0.17 s at the median and 0.8 s at most from handed to started, so nothing came of it but the lines; before 65bf0d9b there was about one such line an hour. **20:40Z 11-13, the pass keeps lengthening with no restart and a nearly level queue.** Mean pass over five minutes 3,569 ms with 88% of the thread inside passes (three-minute means since 20:00Z: 1.6 to 3.7 s, thread 77 to 91%); queued asks 48,300 to 49,600; the server at 4.4 to 5.6 cores against 3.0 to 3.4 this afternoon. From the long-pass lines: | window | lines | pass, mean | weighing, mean | predict | asks | |---|---|---|---|---|---| | 18:30 to 18:55Z | 326 | 3.02 s | 2.63 s | 0.42 s | 43,500 | | 20:29 to 20:41Z | 138 | 4.24 s | 3.85 s | 0.37 s | 49,600 | Weighing (the queued jobs weighed) is nine tenths of a pass and rose 46% while the queue rose 14%: 60 to 78 microseconds an ask. So something beside the queue's length scales it. What differs this evening is people's sessions: 39 to 52 of their jobs out at a time and 400 to 900 starts a quarter hour, with people's jobs taking 90% of the node's CPU from 19:58 to 20:28Z. People's pickup p95 moved from 4.0 to 4.7 s; nothing else has come of it yet. At 92% of the thread I expect placement to lag for everyone. **The trend over 24 hours (`t_pass_seconds`, `t_pass_phase_seconds{phase="weighing"}`, two-hour means over all passes):** | two hours ending | mean pass | weighing per pass | thread inside passes | queued asks, highest | weighing per queued ask | |---|---|---|---|---|---| | 20Z 11-12 | 385 ms | 240 ms | 59% | 34,000 | 8 µs | | 02Z 11-13 | 608 ms | 438 ms | 68% | 37,000 | 13 µs | | 08Z | 880 ms | 725 ms | 77% | 47,000 | 17 µs | | 14Z | 1,402 ms | 1,032 ms | 76% | 54,000 | 20 µs | | 18Z | 1,407 ms | 1,080 ms | 78% | 49,000 | 24 µs | | 20Z | 2,146 ms | 1,777 ms | 82% | 50,000 | 37 µs | The queue grew by half in the day and the weighing by seven times, so the cost of weighing one queued ask more than quadrupled: it grows with something else as well (open head runs went from about 150 to 305 in the same day, and the claims the server holds stand at 400,000 keys with 453,000 waiters). At this slope the scheduling thread is saturated within a day or less. **23:44Z 11-13, on 6ebaa239 (your promote of 22:08Z): the same picture.** Ten-minute means: | to | 22:24 | 22:44 | 23:04 | 23:24 | 23:44 | |---|---|---|---|---|---| | mean pass, ms | 2,073 | 1,518 | 2,577 | 2,164 | 2,315 | | pass share of its thread | 80% | 75% | 82% | 83% | 83% | | weighing per queued ask, µs | 38 | 23 | 43 | 35 | 37 | | asks queued | 43,765 | 48,670 | 49,560 | 50,747 | 51,720 | The restart took the queue to about 40,000 and it is at its highest yet again an hour and a half later, with 345 heads open. Neither of my marks (a mean pass of 5 s, 92% of the thread) was passed. ## 00:40Z 11-14, on c2d52b34: every pass takes 3 to 4 s, and the node dipped under 130 busy cores with a full queue From the server's own "a scheduling pass took long" lines since it started at 00:22Z, averaged per two minutes: | From | Passes logged | Mean pass | Of it weighing | Asks | |---|---|---|---|---| | 00:22Z | 22 | 1.09 s | 0.86 s | 40,650 | | 00:24Z | 25 | 3.57 s | 3.16 s | 52,896 | | 00:28Z | 23 | 3.95 s | 3.55 s | 53,725 | | 00:30Z | 24 | 4.01 s | 3.62 s | 53,833 | | 00:34Z | 27 | 3.56 s | 3.13 s | 53,809 | | 00:38Z | 29 | 3.41 s | 3.05 s | 53,302 | - That is one pass every four to five seconds, all of them long. In the half hour before this build the mean pass was 1.1 s at 79% of the thread, with about 48,000 asks. - `views after a pass` holds a runtime thread 0.5 to 0.8 s each time: 2,182 such warnings in the server's first 18 minutes. - 00:36 to 00:39Z the node ran 96, 126, 76 and 143 busy cores of 192 threads while booked 159 of 159 and with 109,000 jobs waiting for room. In the seven hours before, only one minute outside a restart was under 130. It was back at 165 by 00:40Z. - In those minutes CI's oldest heads were finishing many short test jobs: 2,398 jobs ended in the 20 minutes to 00:40Z against 500 to 900 in each 20 minutes of the evening. The head of the node's line was held by `starts` for 398 s and by `cores` for 277 s of those 20 minutes (`t_node_line_held_seconds_total`). My reading, not shown: with passes of 3.5 s the node is refilled once per pass, so a burst of short jobs ending leaves cores booked but idle until the next pass, and the starts allowed at once cap what one pass can put back. Nothing here is mine to patch; it is data for the planner. ## 02:47Z 11-14, on c2d52b34: the mean pass is past five seconds My watch's mark was a five-minute mean of 5,000 ms. It read 5,375 ms at 02:47Z, with 90% of the thread inside passes. The two 90-minute watches before it ended at 4,055 ms (highest 4,415) and 4,248 ms (highest 4,761). From the server's own "a scheduling pass took long" lines, averaged per two minutes: | From | Passes logged | Mean pass | Of it weighing | Asks | |---|---|---|---|---| | 02:30Z | 9 | 1.19 s | 0.70 s | 57,826 | | 02:34Z | 17 | 6.44 s | 5.86 s | 58,117 | | 02:38Z | 25 | 4.12 s | 3.64 s | 58,359 | | 02:42Z | 21 | 5.20 s | 4.70 s | 58,688 | | 02:44Z | 20 | 5.51 s | 5.01 s | 58,812 | | 02:46Z | 17 | 5.25 s | 4.75 s | 59,023 | - The newest pass at 02:47:38Z took 6.15 s, 5.62 s of it weighing, over 59,071 asks; the longest in those 16 minutes took 8.06 s. - `views after a pass` held a runtime thread 194 times in the 16 minutes. No "ran its tasks late" line. - The node did not idle for it in those minutes: 167 to 184 busy cores, jobs started in bursts of 4 to 206 a minute, the head of the node's line held by `starts` for a few seconds a minute at most. - The queue grows by about 80 asks a minute (57,826 at 02:32Z, 59,071 at 02:47Z): CI heads arrive about three times as fast as they finish (431 open). At the same asks the pass varied between 1.2 and 6.4 s within minutes, so it is not the count of asks alone. **Update 11:20Z 2026-11-14: the weighing follows people's starts, not the queue (58b70474 and the builds before it).** `t_pass_phase_seconds` by phase, ten-minute means, with the queue between 65,000 and 74,000 asks throughout: | Ten minutes to | Weighing s a pass | Predict s a pass | Passes a minute | People's starts a minute | CI starts a minute | |---|---|---|---|---|---| | 07:28Z | 5.4 | 0.6 | 8.9 | 51.0 | 40.9 | | 07:38Z | 1.9 | 0.7 | 18.2 | 15.0 | 78.1 | | 07:48Z | 4.0 | 0.7 | 11.0 | 44.3 | 20.8 | | 08:18Z | 1.5 | 0.6 | 21.8 | 22.2 | 57.8 | | 08:38Z | 4.5 | 0.6 | 10.3 | 28.9 | 81.4 | | 09:38Z | 2.9 | 0.6 | 14.2 | 10.2 | 120.5 | | 10:08Z | 2.7 | 0.6 | 14.8 | 9.4 | 104.9 | | 10:38Z | 2.1 | 0.7 | 17.3 | 9.0 | 80.9 | | 10:58Z | 5.7 | 0.6 | 8.5 | 25.3 | 52.4 | | 11:18Z | 6.9 | 0.7 | 7.2 | 41.2 | 9.4 | - Over the last five minutes to 11:17Z the mean pass was 10.0 s and passes took 90% of the thread; over the last hour 3.3 s, of which weighing 2.6 s. - The queue's length did not change between the 1.5 s and the 6.9 s rows. What changed is how many of people's jobs were starting: about 10 a minute in the short rows, 25 to 50 in the long ones. - In the long rows the scheduler makes 7 to 9 passes a minute instead of 15 to 20, and CI's starts fall with them (9.4 a minute at 11:18Z). - Resolving, view and grows together stay under 0.2 s a pass in every row.

xemmerling referenced this issue

2026-11-13 13:35:38 +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

xemmerling referenced this issue

2026-11-14 03:17:11 +00:00

server: memory follows the open runs (about 74 MB a run, 3 GB an hour): the container is at its 64 GiB limit and anonymous memory reaches it in about eight hours #69

xemmerling referenced this issue

2026-11-14 09:30:16 +00:00

jobs/cache: a joined check reads the database again every 20 s though nothing was stored under its keys (5,700 looks a second, 70 ms permit wait for every cache read) #57