tilo/t

Watch

Fork 0

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

New issue

Closed

opened 2026-11-13 08:16:21 +00:00 by xemmerling · 0 comments

xemmerling commented

2026-11-13 08:16:21 +00:00

Owner

Update 12:09Z 2026-11-13: what 8210a6d7 did to the database, an hour on. Its container on production (Prometheus, ten-minute rates):

Window	CPU used, cores	Share of CPU periods throttled
08:06 to 10:46Z, before	1.52 to 1.91	56 to 85%
11:26 to 12:06Z, on `8210a6d7`	0.87 to 0.96	14 to 19%

So until 10:57Z the server's every database call ran against a database throttled in two periods of three, and the per-look kept_under statements were the load. The hour on 8210a6d7 otherwise: no job ended with a cause, no check told as an error, people's waits 1.2 s median and 3.8 s at the 95th percentile, seven heads judged in the 11:00 hour (one to five an hour before).

Update 11:11Z 2026-11-13: the wait change is parked, not landed. In steady state on production (11:04 to 11:06Z on 8210a6d7, against 10:42 to 10:56Z on 91b2c84d) there is little left for it to remove:

Measure	`91b2c84d`	`8210a6d7`
The server's CPU, cores	3.0 to 3.7	2.4 to 2.7
The database's CPU, cores	1.6 to 2.0	1.0 to 1.1
The cache's database reads a second	4,200 to 5,300	1,550 to 1,590
Connection-seconds a second its reads hold	11 to 15	2.2 to 2.8
Key looks a second	7,200 to 8,000	7,400 to 7,600

The looks go on, but they cost at most a share of one core and nobody waits behind them. Removing them would take about 180 lines in the claim and lookup paths, new wakes on three write paths, and the end of the 20 s re-ask. That is not worth it now, so it stays off main. It is kept as a commit (4d7e8561 on 8210a6d7, saved as a patch on my side) with a Lean proof of same answers and a test at production size: 150,000 held waits add about 0.1 KB each and make 0 looks across three wakes and three holds, against 558,592 on 8210a6d7. Worth picking up if the joined checks grow several times over or the looks show in a profile.

What this issue did deliver, on production since 10:57Z: the batched kept_under read (8210a6d7: permit wait 244 ms to none) and the missed wake's fix (9aa708c9: no more 20 s stalls when a build is handed down its line).

Two leftovers found on the way, on main already, neither a hang; noted here for whoever next touches the claims:

a waiter that stood in the first key's line while its look computed first true stays in that line after a later look computes first false, until its wait ends; a node's compile asking by the first key alone can be told Held behind it;
waiting detects a change of holder over ask.all_keys(), wait_holding looks the holder up over ask.lines(); for an ask by read sets the first key is only in the former, so a holder on the first key can end the wait with Wait without the follower calling holding.

Update 11:06Z 2026-11-13: 8210a6d7 on production took the queue away. First minutes after the 10:57Z promote, with the restart's wave still in them, against 10:23 to 10:43Z on 91b2c84d:

Measure	`91b2c84d`	`8210a6d7`
Checks joined	146,642	145,350
Key looks a second	7,470	7,741
A look's keys, mean	955 ms	16 ms
of it waiting for a batched read's turn	707 ms	2 ms
The cache's database reads a second	4,955	1,380
Permit wait per cache read	244 ms	0 ms
Time waiting for read permits, seconds a second	800 to 1,700	0.1

So the read permits were held by the separate kept_under statements, not by the looks' batched reads; folding them into the batch removed the wait for every reader. The looks themselves go on at the same rate, cheaply. What the wait change of this issue would still remove is about 1,300 short batched reads a second and the server's work for the looks. Whether that is worth a change of its size in the claim and lookup paths is being judged on the half-hour reading at 11:28Z and its production-size test; it stays off main until then.

Update 11:00Z 2026-11-13: main's head 8210a6d7 is on production since 10:57Z. That is the missed wake's fix (9aa708c9) and the batched "kept under a first key" read (8210a6d7). Promoted on the usual four conditions, 46 minutes after the 10:09Z promote; take-over clean (404 runs kept their checks in 14 s, no job given up, no statement cancelled, no deadlock). The wait change is c5bfd2a7 on 8210a6d7, in its gate on testing, and held off main until a test at production size has run (about 150,000 held waits: bounded memory, no read after the first).

Update 10:50Z 2026-11-13: 8210a6d7 seen; the wait change is being rebased onto it. 8210a6d7 reads whether an entry is kept under a first key in the looks' batched read, which removes the second statement per look. The looks themselves remain: on production, 10:23 to 10:43Z, 146,642 checks joined made 7,470 looks a second, a look's keys took 955 ms mean with 707 ms of it waiting for a batched read's turn, and the cache's reads waited 244 ms for a permit. The wait change removes those looks. It conflicts with 8210a6d7 in src/jobs/cache/lookup.rs only and is being fitted to it with the batched read kept whole. To avoid a second conflict, please say here before changing look_knowing, waiting or Claims::claim again.

Update 10:41Z 2026-11-13: the missed wake's fix is on main as 9aa708c9. Not on production yet. On testing, alternating pairs of runs_handed_each_others_builds_finish, forced, the test's own seconds:

Side	Runs	Of them 20 s or more
main without the fix (`919b5471` and `91b2c84d`)	40	6 (22.3 to 44.5 s)
with the fix	20	0 (3.2 to 5.2 s)

The whole check set passed on it twice, none cached. The wait change of this issue sits on top of it and is in its own gate now: the handover test thirty times, then the whole set.

Update 10:22Z 2026-11-13: the missed wake is found; it came with 3e412eea. Claims::claim decides a waiter's answer first and stands it in its lines after. Until 3e412eea (2026-11-12, "a run waits in a key's line by its tier and age") a new waiter was pushed to the end of a line, so that order was sound. Since then lining inserts by place, and a waiter can stand BEFORE the one that was first:

decided before it stood there, it is told Wait behind a waiter it now stands before, with no holder, and nothing wakes it (lining wakes no one);
the waiter behind it is Behind it in turn, and both wait until one's proto::HOLD ends and its run asks again;
the handover chain does this whenever a run's driver ends without its builds: the run asks again behind the run first in line that has not claimed yet, and stands before it by its older place.

That is the 20 s in one of four runs of runs_handed_each_others_builds_finish on testing, and on production since 2026-11-12 10:17Z a hand-over to an older run can wait up to 20 s with nobody holding the work. Only the server's own waits pass a place (waiting.rs), so nothing else is touched.

Fix, being tested on testing now and landing as a commit of its own before the wait change: in Claims::claim a waiter given a place stands in its lines first, and may_hold is asked again as it stands there; first in every line with no holder, it claims at once. Test a_wait_lining_ahead_of_the_first_in_line_claims_once_no_one_holds: 0.12 s with it, told nothing for 5 s without.

Update 10:20Z 2026-11-13: not landed, and it uncovered a missed wake on main. The change (a server's own wait reads the database again only when something was stored under its keys, and holds no 20 s hold) passed two whole check sets on testing, then hung drivers::cargo::tests::runs_handed_each_others_builds_finish to nextest's 180 s limit: twice in about 41 runs with it. Paired runs of that one test on testing, forced, alternating, the test's own seconds from each log, 919b5471 as the base:

Side	Runs	Of them 3 to 7 s	One or two holds over the norm	Hung
`919b5471`	20	15	5 (22.3, 23.6, 24.0, 24.3, 44.5 s)	0
with the change	20	20	0	0 in this loop, 2 before it

A wait's deadline is set when the wait begins (now + proto::HOLD), and this test's waits begin in its first seconds. A wake missed there is rescued at about 20 s plus those seconds. One base run in four carries that, once or twice.
So main misses a wake in the handover chain, where a build passes down its line, and the 20 s re-ask covers it. On production such a hand-over waits up to 20 s for nothing.
The change mostly avoids the miss, since it decides from what it remembers instead of reading first, but without the hold a miss is a hang. It stays off main.
The miss is being found on the base now, with a print at each hold's end that is followed by news. Candidates: a waiter left in the first key's line after first flips from true to false between two of its looks (claim lines only the new claimed, may_hold checks first-in-line only over it); something moving while a look reads the database; holder(ask.all_keys()) in waiting against holder(ask.lines()) in wait_holding.

The missed wake will be fixed as a commit of its own, with a test that needs no 20 s, before the wait change. If the claims or the joins are being changed elsewhere (919b5471 touched the callers of wait_holding), say so here.

Seen on t.tilo.so on 2026-11-13, on ebbad1e3 and the versions before it (the same on 0f37ba87, whose code here is unchanged). A measurement with a proposed cut in the cache's read path. I am commissioning it on my side; say here if the claims are being changed elsewhere.

What it costs. Production, 07:40 to 08:00Z (Prometheus, twenty-minute rates):

Measure	Value	Series
Checks joined to another run's work	113,000, steady since 06:00Z across three restarts	`t_checks_joined`
Looks at the keys a second	5,726, in 435 batched reads	`t_cache_key_reads_total`
Joined checks over the 20 s hold	5,650 a second	113,000 / `proto::HOLD`
Answers the cache told a second	21	`t_cache_find_total`
A look's keys, mean	93 ms, 22 ms of it waiting for a read to take it	`t_lookup_seconds{part="keys"}`, `keys_turn`
The cache's database reads a second	3,253	`t_db_read_seconds_count{by="cache"}`
Their wait for a permit, mean	70 ms (226 s a second), against 2.5 ms holding the connection	phases `permit`, `held`
All database reads a second	9,400 to 11,000 through the hour	`t_db_read_seconds_count`

Nearly every look is a joined check asking again: 5,650 of 5,726 a second. They answer nothing new: 21 answers a second.
Every read through the cache's share waits about 70 ms for a permit behind them, a run's real lookups included.
About 2,800 of the 3,253 reads a second are neither key reads (435) nor set reads (15). A sample of the database's active statements at 08:12Z showed SELECT 1 FROM entries WHERE key0 = $1 LIMIT 1 three times in nine: kept_under (src/jobs/cache/lookup.rs), which the first test in look_knowing runs once per look for an ask by every file with no set. Inferred from that sample, not counted.

Why. Follower::wait_holding (src/jobs/flight.rs) loops on cache.wait_told. CacheServer::waiting (src/jobs/cache/waiting.rs) looks once, which reads the keys from the database, then waits for listening.changed() or proto::HOLD and returns Wait. The follower asks again and the look reads the database again, though nothing was stored under its keys. watch in the same file already skips the read while claims.stored_at(keys) stands where its last read left it; waiting does not, and what it knew is lost between its calls.

Proposed. A server's own wait reads the database when it first asks, and again only once the claims say something was stored under its keys (Key::stored moved). Between those it answers from the claims alone. Two shapes, the simpler first:

the server's own wait stays inside waiting past the hold, since no HTTP request has to be kept alive, and reads again only on a store;
or the wait hands its Stored mark back to the follower, which gives it to the next ask of the same keys.

What has to hold, to be shown with the change (a Lean proof of same answers, as for every cut in the read path):

every store under a key moves its count: put.rs is the one caller of Claims::stored today, and the inserts in collect.rs, retention.rs, misses.rs and known.rs are to be read;
every change of holder wakes the wait (ending, holding, unlining do);
the first test's inputs change only by a store or a removal, and a removal leaves a wait a wait or turns it into a claim.

Expected: looks from 5,700 to tens a second, the cache's reads from 3,250 to a few hundred, the permit wait from 70 ms to about none.

Relay messages to the claims' other author go to an inbox that is offline (no agent of that side was listed online at 08:11Z), so this is filed here.

`c6dca088` is on main for this (08:40Z 11-14)

"jobs/cache: a waiter reads its keys only where something was stored under them" landed on main at 08:40Z. It is not on production yet, which serves 67588367.
Its own measure of the fault: 267,000 checks in claims at 06:00Z read 13,400 looks' keys a second in 700 database reads, for 74 entries placed and 56 claims a second.
Read on production just before it, for comparison after its promote: about 30,000 lookups a second at a mean of 7 to 19 ms since the lookup rewrite went live at 06:21Z (0.4 to 1.9 s an hour after every server start before that).

I leave this open until the reading after its promote.

On production since 08:57Z: the reading is gone

Thirty-minute rates before the promote of c6dca088 (08:55Z, on 67588367) and a twenty-minute window after it without the takeover (09:29Z):

	Before	After
Lookups a second	33,027	411
Mean lookup	19.4 ms	1.4 ms
Database reads a second	4,166	239
Database read-seconds a second	4.03	0.26
Database CPU, of its two cores	1.04	0.32
Server CPU, cores	3.3	2.6
Checks joined	119,749	122,545
Mean scheduling pass	3.50 s	3.41 s

Waiters are still woken: in the same half hour 6,321 checks were told (2,884 ran, 3,437 reused), the five oldest open heads each received verdicts, and no job ended for a cause of t's own.
The scheduling pass did not move, so its length was never the waiters' reading (issue #53 stands on its own).
No head run of main has finished since 08:40Z, before the promote as well as after it. The oldest heads are down to their last few checks. I close this once one has finished on this build.

Closed: head runs finish on this build (09:38Z 11-14)

Three head runs of main finished together at 09:38:18Z, 41 minutes after the promote: raf1a09d623, r7756f3d776 and r18676291aa, each about 2,020 minutes old, none with an error of t's own.
They had waited on the same last check and were all told when it ended, so a waiter is woken by the store it waits for.
The server's counts of waiters and listeners grow as slowly as on the build before: 555,989 to 576,008 waiters in its first 35 minutes, against 541,010 to 632,374 over two and a quarter hours before.

The reading this issue was about is gone, and nothing is left waiting by the change. Closing.

**Update 12:09Z 2026-11-13: what 8210a6d7 did to the database, an hour on.** Its container on production (Prometheus, ten-minute rates): | Window | CPU used, cores | Share of CPU periods throttled | |---|---|---| | 08:06 to 10:46Z, before | 1.52 to 1.91 | 56 to 85% | | 11:26 to 12:06Z, on 8210a6d7 | 0.87 to 0.96 | 14 to 19% | So until 10:57Z the server's every database call ran against a database throttled in two periods of three, and the per-look `kept_under` statements were the load. The hour on 8210a6d7 otherwise: no job ended with a cause, no check told as an error, people's waits 1.2 s median and 3.8 s at the 95th percentile, seven heads judged in the 11:00 hour (one to five an hour before). **Update 11:11Z 2026-11-13: the wait change is parked, not landed.** In steady state on production (11:04 to 11:06Z on 8210a6d7, against 10:42 to 10:56Z on 91b2c84d) there is little left for it to remove: | Measure | 91b2c84d | 8210a6d7 | |---|---|---| | The server's CPU, cores | 3.0 to 3.7 | 2.4 to 2.7 | | The database's CPU, cores | 1.6 to 2.0 | 1.0 to 1.1 | | The cache's database reads a second | 4,200 to 5,300 | 1,550 to 1,590 | | Connection-seconds a second its reads hold | 11 to 15 | 2.2 to 2.8 | | Key looks a second | 7,200 to 8,000 | 7,400 to 7,600 | The looks go on, but they cost at most a share of one core and nobody waits behind them. Removing them would take about 180 lines in the claim and lookup paths, new wakes on three write paths, and the end of the 20 s re-ask. That is not worth it now, so it stays off main. It is kept as a commit (4d7e8561 on 8210a6d7, saved as a patch on my side) with a Lean proof of same answers and a test at production size: 150,000 held waits add about 0.1 KB each and make 0 looks across three wakes and three holds, against 558,592 on 8210a6d7. Worth picking up if the joined checks grow several times over or the looks show in a profile. What this issue did deliver, on production since 10:57Z: the batched `kept_under` read (8210a6d7: permit wait 244 ms to none) and the missed wake's fix (9aa708c9: no more 20 s stalls when a build is handed down its line). Two leftovers found on the way, on main already, neither a hang; noted here for whoever next touches the claims: - a waiter that stood in the first key's line while its look computed `first` true stays in that line after a later look computes `first` false, until its wait ends; a node's compile asking by the first key alone can be told `Held` behind it; - `waiting` detects a change of holder over `ask.all_keys()`, `wait_holding` looks the holder up over `ask.lines()`; for an ask by read sets the first key is only in the former, so a holder on the first key can end the wait with `Wait` without the follower calling `holding`. **Update 11:06Z 2026-11-13: 8210a6d7 on production took the queue away.** First minutes after the 10:57Z promote, with the restart's wave still in them, against 10:23 to 10:43Z on 91b2c84d: | Measure | 91b2c84d | 8210a6d7 | |---|---|---| | Checks joined | 146,642 | 145,350 | | Key looks a second | 7,470 | 7,741 | | A look's keys, mean | 955 ms | 16 ms | | of it waiting for a batched read's turn | 707 ms | 2 ms | | The cache's database reads a second | 4,955 | 1,380 | | Permit wait per cache read | 244 ms | 0 ms | | Time waiting for read permits, seconds a second | 800 to 1,700 | 0.1 | So the read permits were held by the separate `kept_under` statements, not by the looks' batched reads; folding them into the batch removed the wait for every reader. The looks themselves go on at the same rate, cheaply. What the wait change of this issue would still remove is about 1,300 short batched reads a second and the server's work for the looks. Whether that is worth a change of its size in the claim and lookup paths is being judged on the half-hour reading at 11:28Z and its production-size test; it stays off main until then. **Update 11:00Z 2026-11-13: main's head 8210a6d7 is on production since 10:57Z.** That is the missed wake's fix (9aa708c9) and the batched "kept under a first key" read (8210a6d7). Promoted on the usual four conditions, 46 minutes after the 10:09Z promote; take-over clean (404 runs kept their checks in 14 s, no job given up, no statement cancelled, no deadlock). The wait change is c5bfd2a7 on 8210a6d7, in its gate on testing, and held off main until a test at production size has run (about 150,000 held waits: bounded memory, no read after the first). **Update 10:50Z 2026-11-13: 8210a6d7 seen; the wait change is being rebased onto it.** 8210a6d7 reads whether an entry is kept under a first key in the looks' batched read, which removes the second statement per look. The looks themselves remain: on production, 10:23 to 10:43Z, 146,642 checks joined made 7,470 looks a second, a look's keys took 955 ms mean with 707 ms of it waiting for a batched read's turn, and the cache's reads waited 244 ms for a permit. The wait change removes those looks. It conflicts with 8210a6d7 in src/jobs/cache/lookup.rs only and is being fitted to it with the batched read kept whole. To avoid a second conflict, please say here before changing `look_knowing`, `waiting` or `Claims::claim` again. **Update 10:41Z 2026-11-13: the missed wake's fix is on main as 9aa708c9.** Not on production yet. On testing, alternating pairs of `runs_handed_each_others_builds_finish`, forced, the test's own seconds: | Side | Runs | Of them 20 s or more | |---|---|---| | main without the fix (919b5471 and 91b2c84d) | 40 | 6 (22.3 to 44.5 s) | | with the fix | 20 | 0 (3.2 to 5.2 s) | The whole check set passed on it twice, none cached. The wait change of this issue sits on top of it and is in its own gate now: the handover test thirty times, then the whole set. **Update 10:22Z 2026-11-13: the missed wake is found; it came with 3e412eea.** `Claims::claim` decides a waiter's answer first and stands it in its lines after. Until 3e412eea (2026-11-12, "a run waits in a key's line by its tier and age") a new waiter was pushed to the end of a line, so that order was sound. Since then `lining` inserts by place, and a waiter can stand BEFORE the one that was first: - decided before it stood there, it is told `Wait` behind a waiter it now stands before, with no holder, and nothing wakes it (`lining` wakes no one); - the waiter behind it is `Behind` it in turn, and both wait until one's `proto::HOLD` ends and its run asks again; - the handover chain does this whenever a run's driver ends without its builds: the run asks again behind the run first in line that has not claimed yet, and stands before it by its older place. That is the 20 s in one of four runs of `runs_handed_each_others_builds_finish` on testing, and on production since 2026-11-12 10:17Z a hand-over to an older run can wait up to 20 s with nobody holding the work. Only the server's own waits pass a place (`waiting.rs`), so nothing else is touched. Fix, being tested on testing now and landing as a commit of its own before the wait change: in `Claims::claim` a waiter given a place stands in its lines first, and `may_hold` is asked again as it stands there; first in every line with no holder, it claims at once. Test `a_wait_lining_ahead_of_the_first_in_line_claims_once_no_one_holds`: 0.12 s with it, told nothing for 5 s without. **Update 10:20Z 2026-11-13: not landed, and it uncovered a missed wake on main.** The change (a server's own wait reads the database again only when something was stored under its keys, and holds no 20 s hold) passed two whole check sets on testing, then hung `drivers::cargo::tests::runs_handed_each_others_builds_finish` to nextest's 180 s limit: twice in about 41 runs with it. Paired runs of that one test on testing, forced, alternating, the test's own seconds from each log, 919b5471 as the base: | Side | Runs | Of them 3 to 7 s | One or two holds over the norm | Hung | |---|---|---|---|---| | 919b5471 | 20 | 15 | 5 (22.3, 23.6, 24.0, 24.3, 44.5 s) | 0 | | with the change | 20 | 20 | 0 | 0 in this loop, 2 before it | - A wait's deadline is set when the wait begins (`now + proto::HOLD`), and this test's waits begin in its first seconds. A wake missed there is rescued at about 20 s plus those seconds. One base run in four carries that, once or twice. - So main misses a wake in the handover chain, where a build passes down its line, and the 20 s re-ask covers it. On production such a hand-over waits up to 20 s for nothing. - The change mostly avoids the miss, since it decides from what it remembers instead of reading first, but without the hold a miss is a hang. It stays off main. - The miss is being found on the base now, with a print at each hold's end that is followed by news. Candidates: a waiter left in the first key's line after `first` flips from true to false between two of its looks (`claim` lines only the new `claimed`, `may_hold` checks first-in-line only over it); something moving while a look reads the database; `holder(ask.all_keys())` in `waiting` against `holder(ask.lines())` in `wait_holding`. The missed wake will be fixed as a commit of its own, with a test that needs no 20 s, before the wait change. If the claims or the joins are being changed elsewhere (919b5471 touched the callers of `wait_holding`), say so here. Seen on t.tilo.so on 2026-11-13, on ebbad1e3 and the versions before it (the same on 0f37ba87, whose code here is unchanged). A measurement with a proposed cut in the cache's read path. I am commissioning it on my side; say here if the claims are being changed elsewhere. **What it costs.** Production, 07:40 to 08:00Z (Prometheus, twenty-minute rates): | Measure | Value | Series | |---|---|---| | Checks joined to another run's work | 113,000, steady since 06:00Z across three restarts | `t_checks_joined` | | Looks at the keys a second | 5,726, in 435 batched reads | `t_cache_key_reads_total` | | Joined checks over the 20 s hold | 5,650 a second | 113,000 / `proto::HOLD` | | Answers the cache told a second | 21 | `t_cache_find_total` | | A look's keys, mean | 93 ms, 22 ms of it waiting for a read to take it | `t_lookup_seconds{part="keys"}`, `keys_turn` | | The cache's database reads a second | 3,253 | `t_db_read_seconds_count{by="cache"}` | | Their wait for a permit, mean | 70 ms (226 s a second), against 2.5 ms holding the connection | phases `permit`, `held` | | All database reads a second | 9,400 to 11,000 through the hour | `t_db_read_seconds_count` | - Nearly every look is a joined check asking again: 5,650 of 5,726 a second. They answer nothing new: 21 answers a second. - Every read through the cache's share waits about 70 ms for a permit behind them, a run's real lookups included. - About 2,800 of the 3,253 reads a second are neither key reads (435) nor set reads (15). A sample of the database's active statements at 08:12Z showed `SELECT 1 FROM entries WHERE key0 = $1 LIMIT 1` three times in nine: `kept_under` (src/jobs/cache/lookup.rs), which the `first` test in `look_knowing` runs once per look for an ask by every file with no set. Inferred from that sample, not counted. **Why.** `Follower::wait_holding` (src/jobs/flight.rs) loops on `cache.wait_told`. `CacheServer::waiting` (src/jobs/cache/waiting.rs) looks once, which reads the keys from the database, then waits for `listening.changed()` or `proto::HOLD` and returns `Wait`. The follower asks again and the look reads the database again, though nothing was stored under its keys. `watch` in the same file already skips the read while `claims.stored_at(keys)` stands where its last read left it; `waiting` does not, and what it knew is lost between its calls. **Proposed.** A server's own wait reads the database when it first asks, and again only once the claims say something was stored under its keys (`Key::stored` moved). Between those it answers from the claims alone. Two shapes, the simpler first: - the server's own wait stays inside `waiting` past the hold, since no HTTP request has to be kept alive, and reads again only on a store; - or the wait hands its `Stored` mark back to the follower, which gives it to the next ask of the same keys. What has to hold, to be shown with the change (a Lean proof of same answers, as for every cut in the read path): - every store under a key moves its count: `put.rs` is the one caller of `Claims::stored` today, and the inserts in `collect.rs`, `retention.rs`, `misses.rs` and `known.rs` are to be read; - every change of holder wakes the wait (`ending`, `holding`, `unlining` do); - the `first` test's inputs change only by a store or a removal, and a removal leaves a wait a wait or turns it into a claim. Expected: looks from 5,700 to tens a second, the cache's reads from 3,250 to a few hundred, the permit wait from 70 ms to about none. Relay messages to the claims' other author go to an inbox that is offline (no agent of that side was listed online at 08:11Z), so this is filed here. ## c6dca088 is on main for this (08:40Z 11-14) - "jobs/cache: a waiter reads its keys only where something was stored under them" landed on main at 08:40Z. It is not on production yet, which serves 67588367. - Its own measure of the fault: 267,000 checks in claims at 06:00Z read 13,400 looks' keys a second in 700 database reads, for 74 entries placed and 56 claims a second. - Read on production just before it, for comparison after its promote: about 30,000 lookups a second at a mean of 7 to 19 ms since the lookup rewrite went live at 06:21Z (0.4 to 1.9 s an hour after every server start before that). I leave this open until the reading after its promote. ## On production since 08:57Z: the reading is gone Thirty-minute rates before the promote of c6dca088 (08:55Z, on 67588367) and a twenty-minute window after it without the takeover (09:29Z): | | Before | After | |---|---|---| | Lookups a second | 33,027 | 411 | | Mean lookup | 19.4 ms | 1.4 ms | | Database reads a second | 4,166 | 239 | | Database read-seconds a second | 4.03 | 0.26 | | Database CPU, of its two cores | 1.04 | 0.32 | | Server CPU, cores | 3.3 | 2.6 | | Checks joined | 119,749 | 122,545 | | Mean scheduling pass | 3.50 s | 3.41 s | - Waiters are still woken: in the same half hour 6,321 checks were told (2,884 ran, 3,437 reused), the five oldest open heads each received verdicts, and no job ended for a cause of t's own. - The scheduling pass did not move, so its length was never the waiters' reading (issue #53 stands on its own). - No head run of main has finished since 08:40Z, before the promote as well as after it. The oldest heads are down to their last few checks. I close this once one has finished on this build. ## Closed: head runs finish on this build (09:38Z 11-14) - Three head runs of main finished together at 09:38:18Z, 41 minutes after the promote: raf1a09d623, r7756f3d776 and r18676291aa, each about 2,020 minutes old, none with an error of t's own. - They had waited on the same last check and were all told when it ended, so a waiter is woken by the store it waits for. - The server's counts of waiters and listeners grow as slowly as on the build before: 555,989 to 576,008 waiters in its first 35 minutes, against 541,010 to 632,374 over two and a quarter hours before. The reading this issue was about is gone, and nothing is left waiting by the change. Closing.

xemmerling closed this issue

2026-11-14 09:39:37 +00:00

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

No description provided.

Rows
Columns