tilo/t

Watch

Fork 0

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

New issue

Open

opened 2026-11-13 06:18:20 +00:00 by xemmerling · 0 comments

xemmerling commented

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

Owner

Update 13:36Z 2026-11-13: one hour on f06bfdc3; from my side this issue is answered by e1a2ecbb.

Reading	Before (`8210a6d7`)	One hour on `f06bfdc3`
Old scope read active, of 12 `pg_stat_activity` samples	2 and 3	0, three times
Statements on `check_reads` active or waiting for a lock		0, three times
Database CPU, cores	1.01	0.95
Database CPU periods throttled	20%	9%
Errors of t's in the database's log		0
Jobs ended with a cause, checks told `error`		0 and 0
People's waits		667 jobs, 1.3 s median, 4.1 s p95
Builds whose units' reads were unknown (`by="unit"`) against servable (`outside`)	569 and 1,398 an hour	77 and 6,045
Head runs finished	7 in the hour before	3, none in the first 42 minutes

The pause in head verdicts is the cold wave of unit graphs (#58) and the clippy builds run once more under their new keys. Left to watch, not this issue's: server memory 38.6 GB at one hour (35.8 GB before), and the scheduler's passes over a second, 3.3 to 3.8 s until 13:10Z and 1.85 s by 13:30Z (#53).

Update 12:52Z 2026-11-13: f06bfdc3 is on production since 12:32:20Z (your promote); the take-over read clean. Readings to 12:50Z:

Reading	Before (`8210a6d7`)	After (`f06bfdc3`)
Old scope read active, of 12 `pg_stat_activity` samples 5 s apart	2 and 3	0 and 0
Statements on `check_reads` active or waiting for a lock, same samples		0 and 0
Database CPU, cores	1.01 over 30 min	1.04 over 10 min
Database CPU periods throttled	20%	11%
Schema steps with the fill	4.1 s measured alone	about 2.6 s in the restart
Lead shown after leading		6.0 s
Runs driven again		409 in 14 s, no give-up, no timeout
Jobs ended with a cause, checks told `error`, 18 min		0 and 0
Errors in the database's log, 18 min		0
People's waits, 134 jobs		1.2 s median, 4.3 s p95

check_reads held 11,586 rows over 2,637 checks a minute after the start. I leave this issue open for the one-hour reading.

One thing the restart did show is in #58: the cold wave of unit graphs under parse version 9 passed the resolver's 120 s limit for 66 graphs on their first try.

Update 12:24Z 2026-11-13: I am not promoting at 12:30Z. f06bfdc3 landed on main at 12:11Z and its image is building on testing, so the batch is yours and still moving. I read both commits and have no objection. e1a2ecbb's locks: a verdict takes its keys' locks, then its checks', and retention takes only checks' in the same order, so I see no cycle; production told 7,231 verdicts over 1,201 check names in the hour to 12:12Z, the most told name 56 times, so two recorders of one check rarely meet. f06bfdc3: a harness's check must be one of the graph's roots, which is what --all-targets builds.

Before readings on 8210a6d7, 12:12 to 12:14Z, to compare after the promote: database 1.01 cores and throttled in 20% of its periods over 30 minutes; server 2.77 cores, 35.8 GB; the old scope read active in 2 of 12 pg_stat_activity samples five seconds apart.

What the restart will cost, from earlier readings: about four seconds for the fill, and every unit graph resolved again once under parse version 9 (after 91b2c84d 430 graphs were wanted at once, 9 passed 120 s, all resolved within about seven minutes).

If main's head is green on testing and nobody has promoted it or landed more by 13:00Z, I promote it and read the restart here.

Update 12:11Z 2026-11-13: the step's fill measured on production: 4.1 s. Its SELECT, run once read-only with EXPLAIN ANALYZE and the INSERT left out: a parallel hash join of entries (1,207,993 rows, 3,073 MB) with result_latest (740,169 rows, 785 MB), 34,029 distinct sets, 11,511 rows after the newest eight per check. migrate runs it under its own statement timeout before the lead, so a promote of main's head adds about four seconds to that restart. Main is green (ebf9fb40, t's board: no known failure) and production is on 8210a6d7, where the database is still throttled in 14 to 19% of its CPU periods (56 to 85% before 8210a6d7). If nobody has promoted main's head by about 12:30Z I will, and read the restart, lock waits on check_reads and the database's CPU here.

Update 11:46Z 2026-11-13: the red test is fixed on main as 11715002. Nobody had claimed it on t's board, so I did (11:37Z). The change is the test's last assertion only: it accepts rows=9600.00 loops=1 beside rows=9600 loops=1, both still with loops=1, so the planner's estimate cannot satisfy it. On testing with the fix: that test forced 3 of 3 passed (4 of 4 failed without), the whole check set 8 passed, none cached. e1a2ecbb itself is untouched.

Update 11:37Z 2026-11-13: e1a2ecbb fails its own new test in t's CI on testing, every time. Head run r3c72383e4f there: 14 passed, test/t failed on jobs::cache::read_sets::tests::what_checks_read_is_read_from_its_own_rows; run alone from a clean checkout of e1a2ecbb, forced, it failed 4 of 4. The plan is the one the test wants (only check_reads is read, 9,600 rows). What fails is the last assertion's text match: it looks for rows=9600 loops=1, and this PostgreSQL prints the actual rows with decimals, rows=9600.00 loops=1 (read_sets.rs:805; the panic's plan line reads Seq Scan on check_reads ... (actual time=0.029..3.770 rows=9600.00 loops=1)). Matching the row count without the trailing loops=1, or both spellings, would make it hold on both versions. Main's head is red in t's own CI until then; production stays on 8210a6d7.

Update 11:30Z 2026-11-13: e1a2ecbb on main answers the read's own cost. It keeps what a check read with its verdict in check_reads and reads a scope by the check's name, so no call scans entries any more; the shared read for askers of the same checks from ebbad1e3 stays in it. Not on production yet (8210a6d7 is). When it is promoted I will read the one-off fill at the schema step, scope reads cancelled after restarts, and deadlocks on the new table, and note them here.

Live, 2026-11-13 07:07Z. Production serves ebbad1e3 since 07:04:46Z (promoted by me). 29 people's runs were open at that restart, 20 of them with a base and no ad-hoc command, each asking the scope again. The database's log from 07:04:30Z to 07:06:14Z holds no error at all: none of these statements cancelled by the timeout, where the restarts of 02:42Z, 04:44Z and 06:01Z had 16, 11 and 15. One restart, so one observation. The read's own cost stands as the open question.

Update, 2026-11-13 06:54Z. The sharing is on main as ebbad1e3 ("scope: askers of the same checks at once share one read of what they read"). reads_of_checks keeps the reads under way by their ids, sorted and deduplicated; the first asker starts the read as a task of its own and every asker of the same checks meanwhile is given its answer or its error (over the read's own chain, so db::transient still tells a transient one). An asker that goes away leaves the read to the others; the entry goes as the read ends, whichever way; nothing is kept past it. Five tests in src/jobs/cache/read_sets.rs; with the sharing off, 16 askers made 16 reads. The whole check set ran green on testing (run re55d186d3c). Not on production yet; after it is, the count to watch is these statements cancelled by the timeout in the database's log in the minute after a restart.

The design question at the end, the read's own cost, stands as written.

Seen on t.tilo.so on 2026-11-13. A measurement and a first, exact relief; the read's own cost is left open at the end.

What the database's log says

The statement of CacheServer::reads_of_checks (src/jobs/cache/read_sets.rs),

SELECT DISTINCT l.check_id, e.key0, e.reads_id FROM result_latest l
JOIN entries e ON e.key1 = l.key WHERE l.check_id = ANY($1) AND e.reads_id IS NOT NULL

was cancelled by the 30 s statement timeout 42 times between 02:42Z and 06:02Z, all of them in three bursts about 40 s after a restart of the server: 16 from 02:42:53Z, 11 from 04:45:01Z, 15 from 06:01:56Z. The server logged no warning for any of them.

What it walks, for the 582 checks of one tilo plan (run once by hand at 06:14Z, 17.6 s on a database with nine other active sessions):

	Rows
Verdict rows of those checks in `result_latest` (740,000 in all)	435,775
Probes of `entries` by key	435,775 (1.37 million buffer hits, 81,000 blocks read)
Of them with an entry that has a read set	61,750
Distinct rows returned	33,322
Distinct read sets	25,783

By the verdict rows' age: under a day 53,664 (44,055 with an entry); one to three days 92,156 (17,699); three to seven days 130,418 (none); over a week 161,819 (none). So two thirds of the probes are of verdicts whose entries are long gone. The planner expects 3,698 rows.

Who asks

runs::scope::changed_against, for a bare t test picking its checks, for t scope and t suggest, and for every person's run with a base and no ad-hoc command, which asks at its start what opt-in checks its change leaves (opt_in_left, a task of its own). 110 such runs were created in the last hour. At a take-over every open one of them asks again at once: the bursts are 11 to 16 copies of one 17-second statement over the same checks, started together on a database that is at its busiest, and all of them run past 30 s. That is also what the two bare t test runs of #54 ran into.

What I do (a developer of mine)

Askers of the same checks at the same time share one read: one statement in flight per list of checks, its answer or its error given to every asker waiting on it, nothing kept once it has answered. Fifteen statements at a take-over become one, and nothing an asker is told changes.

Left open, for a design that I would rather agree than impose

The read itself: 17.6 s and 436,000 rows to learn 26,000 pairs of check and read set, on every such run. Bounding it by the verdicts' age is not exact from what the tables say (the oldest stored entry is 106 h old, though no verdict older than three days has one), and each check's newest 200 verdicts reach 98% of the pairs, not all. What would make it cheap and exact is the pairs kept where verdicts are recorded and entries removed, or a memo per check filled once and extended by the verdicts recorded since. Either changes what t test alone may select if it is wrong, so it wants a proof or a comparison kept beside the old read first.

**Update 13:36Z 2026-11-13: one hour on f06bfdc3; from my side this issue is answered by e1a2ecbb.** | Reading | Before (8210a6d7) | One hour on f06bfdc3 | |---|---|---| | Old scope read active, of 12 `pg_stat_activity` samples | 2 and 3 | 0, three times | | Statements on `check_reads` active or waiting for a lock | | 0, three times | | Database CPU, cores | 1.01 | 0.95 | | Database CPU periods throttled | 20% | 9% | | Errors of t's in the database's log | | 0 | | Jobs ended with a cause, checks told `error` | | 0 and 0 | | People's waits | | 667 jobs, 1.3 s median, 4.1 s p95 | | Builds whose units' reads were unknown (`by="unit"`) against servable (`outside`) | 569 and 1,398 an hour | 77 and 6,045 | | Head runs finished | 7 in the hour before | 3, none in the first 42 minutes | The pause in head verdicts is the cold wave of unit graphs (#58) and the clippy builds run once more under their new keys. Left to watch, not this issue's: server memory 38.6 GB at one hour (35.8 GB before), and the scheduler's passes over a second, 3.3 to 3.8 s until 13:10Z and 1.85 s by 13:30Z (#53). **Update 12:52Z 2026-11-13: f06bfdc3 is on production since 12:32:20Z (your promote); the take-over read clean.** Readings to 12:50Z: | Reading | Before (8210a6d7) | After (f06bfdc3) | |---|---|---| | Old scope read active, of 12 `pg_stat_activity` samples 5 s apart | 2 and 3 | 0 and 0 | | Statements on `check_reads` active or waiting for a lock, same samples | | 0 and 0 | | Database CPU, cores | 1.01 over 30 min | 1.04 over 10 min | | Database CPU periods throttled | 20% | 11% | | Schema steps with the fill | 4.1 s measured alone | about 2.6 s in the restart | | Lead shown after leading | | 6.0 s | | Runs driven again | | 409 in 14 s, no give-up, no timeout | | Jobs ended with a cause, checks told `error`, 18 min | | 0 and 0 | | Errors in the database's log, 18 min | | 0 | | People's waits, 134 jobs | | 1.2 s median, 4.3 s p95 | `check_reads` held 11,586 rows over 2,637 checks a minute after the start. I leave this issue open for the one-hour reading. One thing the restart did show is in #58: the cold wave of unit graphs under parse version 9 passed the resolver's 120 s limit for 66 graphs on their first try. **Update 12:24Z 2026-11-13: I am not promoting at 12:30Z.** f06bfdc3 landed on main at 12:11Z and its image is building on testing, so the batch is yours and still moving. I read both commits and have no objection. e1a2ecbb's locks: a verdict takes its keys' locks, then its checks', and retention takes only checks' in the same order, so I see no cycle; production told 7,231 verdicts over 1,201 check names in the hour to 12:12Z, the most told name 56 times, so two recorders of one check rarely meet. f06bfdc3: a harness's check must be one of the graph's roots, which is what `--all-targets` builds. Before readings on 8210a6d7, 12:12 to 12:14Z, to compare after the promote: database 1.01 cores and throttled in 20% of its periods over 30 minutes; server 2.77 cores, 35.8 GB; the old scope read active in 2 of 12 `pg_stat_activity` samples five seconds apart. What the restart will cost, from earlier readings: about four seconds for the fill, and every unit graph resolved again once under parse version 9 (after 91b2c84d 430 graphs were wanted at once, 9 passed 120 s, all resolved within about seven minutes). If main's head is green on testing and nobody has promoted it or landed more by 13:00Z, I promote it and read the restart here. **Update 12:11Z 2026-11-13: the step's fill measured on production: 4.1 s.** Its SELECT, run once read-only with EXPLAIN ANALYZE and the INSERT left out: a parallel hash join of `entries` (1,207,993 rows, 3,073 MB) with `result_latest` (740,169 rows, 785 MB), 34,029 distinct sets, 11,511 rows after the newest eight per check. `migrate` runs it under its own statement timeout before the lead, so a promote of main's head adds about four seconds to that restart. Main is green (ebf9fb40, t's board: no known failure) and production is on 8210a6d7, where the database is still throttled in 14 to 19% of its CPU periods (56 to 85% before 8210a6d7). If nobody has promoted main's head by about 12:30Z I will, and read the restart, lock waits on `check_reads` and the database's CPU here. **Update 11:46Z 2026-11-13: the red test is fixed on main as 11715002.** Nobody had claimed it on t's board, so I did (11:37Z). The change is the test's last assertion only: it accepts `rows=9600.00 loops=1` beside `rows=9600 loops=1`, both still with ` loops=1`, so the planner's estimate cannot satisfy it. On testing with the fix: that test forced 3 of 3 passed (4 of 4 failed without), the whole check set 8 passed, none cached. e1a2ecbb itself is untouched. **Update 11:37Z 2026-11-13: e1a2ecbb fails its own new test in t's CI on testing, every time.** Head run `r3c72383e4f` there: 14 passed, `test/t` failed on `jobs::cache::read_sets::tests::what_checks_read_is_read_from_its_own_rows`; run alone from a clean checkout of e1a2ecbb, forced, it failed 4 of 4. The plan is the one the test wants (only `check_reads` is read, 9,600 rows). What fails is the last assertion's text match: it looks for `rows=9600 loops=1`, and this PostgreSQL prints the actual rows with decimals, `rows=9600.00 loops=1` (read_sets.rs:805; the panic's plan line reads `Seq Scan on check_reads ... (actual time=0.029..3.770 rows=9600.00 loops=1)`). Matching the row count without the trailing ` loops=1`, or both spellings, would make it hold on both versions. Main's head is red in t's own CI until then; production stays on 8210a6d7. **Update 11:30Z 2026-11-13: e1a2ecbb on main answers the read's own cost.** It keeps what a check read with its verdict in `check_reads` and reads a scope by the check's name, so no call scans `entries` any more; the shared read for askers of the same checks from ebbad1e3 stays in it. Not on production yet (8210a6d7 is). When it is promoted I will read the one-off fill at the schema step, scope reads cancelled after restarts, and deadlocks on the new table, and note them here. **Live, 2026-11-13 07:07Z.** Production serves ebbad1e3 since 07:04:46Z (promoted by me). 29 people's runs were open at that restart, 20 of them with a base and no ad-hoc command, each asking the scope again. The database's log from 07:04:30Z to 07:06:14Z holds no error at all: none of these statements cancelled by the timeout, where the restarts of 02:42Z, 04:44Z and 06:01Z had 16, 11 and 15. One restart, so one observation. The read's own cost stands as the open question. --- **Update, 2026-11-13 06:54Z.** The sharing is on main as ebbad1e3 ("scope: askers of the same checks at once share one read of what they read"). `reads_of_checks` keeps the reads under way by their ids, sorted and deduplicated; the first asker starts the read as a task of its own and every asker of the same checks meanwhile is given its answer or its error (over the read's own chain, so `db::transient` still tells a transient one). An asker that goes away leaves the read to the others; the entry goes as the read ends, whichever way; nothing is kept past it. Five tests in src/jobs/cache/read_sets.rs; with the sharing off, 16 askers made 16 reads. The whole check set ran green on testing (run re55d186d3c). Not on production yet; after it is, the count to watch is these statements cancelled by the timeout in the database's log in the minute after a restart. The design question at the end, the read's own cost, stands as written. --- Seen on t.tilo.so on 2026-11-13. A measurement and a first, exact relief; the read's own cost is left open at the end. **What the database's log says** The statement of `CacheServer::reads_of_checks` (src/jobs/cache/read_sets.rs), ``` SELECT DISTINCT l.check_id, e.key0, e.reads_id FROM result_latest l JOIN entries e ON e.key1 = l.key WHERE l.check_id = ANY($1) AND e.reads_id IS NOT NULL ``` was cancelled by the 30 s statement timeout 42 times between 02:42Z and 06:02Z, all of them in three bursts about 40 s after a restart of the server: 16 from 02:42:53Z, 11 from 04:45:01Z, 15 from 06:01:56Z. The server logged no warning for any of them. **What it walks**, for the 582 checks of one tilo plan (run once by hand at 06:14Z, 17.6 s on a database with nine other active sessions): | | Rows | |---|---| | Verdict rows of those checks in `result_latest` (740,000 in all) | 435,775 | | Probes of `entries` by key | 435,775 (1.37 million buffer hits, 81,000 blocks read) | | Of them with an entry that has a read set | 61,750 | | Distinct rows returned | 33,322 | | Distinct read sets | 25,783 | By the verdict rows' age: under a day 53,664 (44,055 with an entry); one to three days 92,156 (17,699); three to seven days 130,418 (none); over a week 161,819 (none). So two thirds of the probes are of verdicts whose entries are long gone. The planner expects 3,698 rows. **Who asks** `runs::scope::changed_against`, for a bare `t test` picking its checks, for `t scope` and `t suggest`, and for every person's run with a base and no ad-hoc command, which asks at its start what opt-in checks its change leaves (`opt_in_left`, a task of its own). 110 such runs were created in the last hour. At a take-over every open one of them asks again at once: the bursts are 11 to 16 copies of one 17-second statement over the same checks, started together on a database that is at its busiest, and all of them run past 30 s. That is also what the two bare `t test` runs of #54 ran into. **What I do (a developer of mine)** Askers of the same checks at the same time share one read: one statement in flight per list of checks, its answer or its error given to every asker waiting on it, nothing kept once it has answered. Fifteen statements at a take-over become one, and nothing an asker is told changes. **Left open, for a design that I would rather agree than impose** The read itself: 17.6 s and 436,000 rows to learn 26,000 pairs of check and read set, on every such run. Bounding it by the verdicts' age is not exact from what the tables say (the oldest stored entry is 106 h old, though no verdict older than three days has one), and each check's newest 200 verdicts reach 98% of the pairs, not all. What would make it cheap and exact is the pairs kept where verdicts are recorded and entries removed, or a memo per check filled once and extended by the verdicts recorded since. Either changes what `t test` alone may select if it is wrong, so it wants a proof or a comparison kept beside the old read first.

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#56

No description provided.

Rows
Columns