tilo/t

Watch

Fork 0

The node reached its disk floor under a people's wave: the freer ran out of things it may free, 21:33-22:27Z 11-13 #64

New issue

Open

opened 2026-11-13 22:28:18 +00:00 by xemmerling · 0 comments

xemmerling commented

2026-11-13 22:28:18 +00:00

Owner

Production, 9faf6c61 until 22:08Z and 6ebaa239 after it; the freer and the node's store are the same in both. Readings only; I changed nothing and cancelled nothing.

What happened. Under a wave of people's jobs the node's free disk fell from 1,203 GiB at 21:33Z to 452 GiB at 22:05Z, the floor (5% of 8,190 GiB is 409.5). It rose to 755 GiB while the 22:08Z restart paused starts, and at 22:27Z it is at 537 GiB and falling about 35 GiB a minute again.

Jobs it cost so far. Two ended at their own disk limit (clippy/api-tester 22:04:42, 6.7 GiB booked and 6.8 held; clippy/collaboration 22:16:00, 36.7 booked and 36.4 held), one did not start within 30 s (test/feeds 22:04:11). All people's jobs, all run again. The four cache refusals of issue #63 fell in the same minutes.

Who wrote it. In the ten minutes to 21:52Z people started 86 jobs with 1,271 GiB of disk booked, CI one. At 22:03Z the jobs out had booked: one principal's 3 sessions 52 jobs and 1,435 GiB, another's 6 sessions 47 jobs and 708 GiB, CI 13 jobs and 283 GiB. The largest: nine clippy/tilo-ui jobs at 76 GiB each, all started within 20 minutes.

What the node could do about it.

	21:07Z	21:42Z	21:57Z	22:07Z	22:27Z
offered disk, GiB	1,236	979	653	490	568
`t_node_disk_ceiling_bytes`, GiB	831	578	252	0	165

The volume was 100% busy throughout (md127: about 1.2 GB/s written and as much read; its four members at 87-89%).
The deleter ran at about one busy second a second and freed 110-250 GiB a minute in bursts, then 36-51 at 22:02-22:03Z; jobs wrote 55-85 GiB a minute, more at the wave's start.
From 22:20Z deleting/ stayed empty while 130 GiB went in five minutes. Seven samples of the t-freer thread: waiting (futex, nanosleep) with unchanged IO counters, then seconds at a time in an ioctl in state D. t disk --json: freeing 0. The ceiling says why: what it may free has run out.
A session's build was flattened in the same minute: 61.9 GB copied in 69 s.
On the node now: 10,335 layers, 9,360 snapshots, 12,229 shared entries, 109 job directories.

How I read it. Bookings hold nothing on the volume by design (the head comment of src/store/freer.rs), people's jobs start first and without a limit, and each brings a build directory of tens of GiB. So a wave can hold more than the volume has beyond its keep line; the cache gives way first, then there is nothing left to free, and the floor is the only brake. Two things I cannot judge from outside: whether layers and snapshots stay held longer than a job or session needs them, and whether flattening should wait while the volume is short.

No change proposed here; disk admission is yours, and a limit per principal is the user's decision. Evidence kept on my side: free disk by minute, the deleter's counters, the thread samples.

22:32Z, four more within 30 seconds. clippy/tilolang-host (46.1 GiB booked, 46.1 held), clippy-x86_64/imager (17.5 and 17.2), clippy/file-explorer (34.1 and 34.2) and clippy/tilo-room-host (38.5 and 38.6) each ended disk_full at its own limit after about 15 minutes of work, with 523 to 553 GiB free on the volume, above the floor. All four are one principal's people's jobs and all run again booked higher, which asks for more disk still. That makes six such ends since 22:04Z. So the brake is not only the floor: a job whose quota is not grown while the ceiling is this low loses its work at the quota.

Measured, 22:37Z: the grows are refused. t_sched_grow_total{what="disk"} per ten minutes:

ten minutes to	21:46	21:56	22:06	22:16	22:26	22:36
granted	29	28	28	22	25	8
refused	0	0	91	82	47	311

None was refused in the hour before 21:56Z. A refused grow leaves the job at its quota (src/sched/state.rs, the fits branch of a disk grow), and the six disk_full ends are jobs that then wrote into it.

22:42Z, on 6ebaa239. Free disk is at 436 GiB and falling again (496 at 22:40:35Z), with 171 entries waiting in deleting/. 27 asks wait for disk, and people's jobs now wait 180 s at the median and 492 s at the 95th percentile to start (376 started in 15 minutes); CI started 2.

22:42 to 22:48Z: the node ran at a quarter of its jobs for want of disk, with cores idle.

	22:40	22:42	22:44	22:46	22:48
offered disk, GiB	500	449	438	461	761
ceiling, GiB	152	32	32	47	351
jobs running	93	71	51	31	85
`t_node_busy_cores`	323	299	191	135	181
disk grows refused in the minute	69	119	208	116	3

The whole queue waited for disk (why=disk:107519 at 22:47Z, 125 of 159 cores booked). Four more jobs ended disk_full at their own limit in those minutes (22:43:43, 22:44:13, 22:44:58, 22:47:06), which makes ten since 22:04Z, all one principal's people's jobs. Then the freer caught up: 760 GiB free at 22:48Z and starts resumed (37 and 22 in the next two minutes).

22:51Z: recovered, with the wave still on. Free disk 760 GiB at 22:48:03Z, then 856, 911, 1,008 and 1,140 GiB at 22:51:03Z, as deleting/ drained from 446 entries to 0. No job ended by a cause after 22:47:06Z. Out at 22:51Z: one principal 31 jobs with 884 GiB of disk booked, CI 14 jobs with 642 GiB, the other principal 42 jobs with 302 GiB. The whole episode ran from 21:33Z to 22:51Z: the floor touched at 22:05Z (452 GiB) and nearly again at 22:42Z (436), ten disk_full ends and one setup end, and six minutes at a quarter of the node's jobs.

It happened again, 00:54Z to 01:45Z 11-14, on `c2d52b34`: a stall this time, not a pile of failed jobs

Timeline.

When	What
~00:54Z	A wave of people's runs begins. Free disk 1,261 GiB at 00:47Z.
01:13Z	85 of 86 running jobs are people's; CI started 3 jobs in 15 minutes.
01:26:31Z	Free disk at the floor (about 410 GiB). Nothing refused yet.
01:28Z to 01:38Z	Free disk goes on down under the floor: 387, 312, 318, 237, 165 GiB. Disk grows refused 1 to 8 a minute. A few people's jobs wait with kind `disk`.
01:39Z	The node's disk ceiling reads 0. No job is started from here on.
01:41:41Z	Lowest free disk read: 121 GiB.
01:41:31Z to 01:42:58Z	Four jobs end `disk_full`, all people's: two of principal quinten, two of xemmerling. No CI job fails for disk.
01:39Z to ~01:44Z	The node drains: running jobs 97, 42, 32, 26, 17, 8; busy cores down to 36; 116,603 CI jobs, 939 probes and 60 people's jobs wait for `disk`, each short by about 1.07 GB; grows refused 72 to 182 a minute.
01:45Z	Free disk 644 GiB, 175 busy cores, 147 of 159 cores booked. Nobody's hand.

Against 21:33Z on the older build: there the node kept placing, ten jobs ended disk_full and 311 grows were refused per ten minutes. Here a job short of the node's disk waited for it, so the cost was five minutes with no job started.

Who wrote. Per-session bytes written, from the jobs' cgroups (io.stat, two reads 20 s apart at 01:22Z): people's jobs 97 GiB a minute, CI nothing; one session 78 GiB a minute. In the jobs view the largest session then was claude:fa71a892… of principal xemmerling with 44 running jobs in 34 runs at once.

The freer's own account at 01:42:02Z. "the volume needs 473,300,496,219 bytes more free": keep 1,319 GB, floor 439.7 GB, available 123.9 GB, freeing 380.8 GB (handed to the deleter, not yet gone), pending 853.7 GB, freed 13 candidates of 218.7 GB in that pass, kept 548 candidates whose blocks other files share: 970.8 GB that freeing would not return.

Where the volume's 8,047 GiB used sat (01:39Z, du -sx with short limits; shared blocks counted more than once). cas/packs 2,835 GiB in 741 files; layers 12,101 directories, of them build layers b- 6,424 with a random sample of 14 at a mean 1.65 GiB (largest 10.4), every other kind under 100 MiB a layer; scratch 318 GiB; deleting 122 GiB. A people's session's build is about 59 GB, and the worker flattened five such in twelve minutes (t::store::snapshots: flattened a session's build … bytes=59113234798).

What I could not explain, and where a fix would have to look.

The store's index lists 3,214 build layers; 2,466 of them had not been used for over two hours (1,576 for 6 to 24 h, 365 for over a day), worth 1,909 hours to make again. None of them was part of a job's mount at 01:41Z. They stayed while the volume stood up to 290 GiB under its floor. Whether they are among the 548 "kept: shared" candidates, held by something, or not listed at all, I have not read.
What is freed trails in the deleter (380 GB queued at the worst minute; single trees of 159 and 51 GiB), and it removes a tree with up to 16 threads already.
Nothing bounds what people's sessions write together: a job's quota bounds one job, and a booking holds nothing on the volume (freer.rs says so on purpose). Thirty-four runs of one session can outwrite the freer for half an hour.

I changed nothing on production. The readings are in my notes; the scripts are disk-floor-reading.sh and disk-floor-watch*.sh.

Production, 9faf6c61 until 22:08Z and 6ebaa239 after it; the freer and the node's store are the same in both. Readings only; I changed nothing and cancelled nothing. **What happened.** Under a wave of people's jobs the node's free disk fell from 1,203 GiB at 21:33Z to 452 GiB at 22:05Z, the floor (5% of 8,190 GiB is 409.5). It rose to 755 GiB while the 22:08Z restart paused starts, and at 22:27Z it is at 537 GiB and falling about 35 GiB a minute again. **Jobs it cost so far.** Two ended at their own disk limit (clippy/api-tester 22:04:42, 6.7 GiB booked and 6.8 held; clippy/collaboration 22:16:00, 36.7 booked and 36.4 held), one did not start within 30 s (test/feeds 22:04:11). All people's jobs, all run again. The four cache refusals of issue #63 fell in the same minutes. **Who wrote it.** In the ten minutes to 21:52Z people started 86 jobs with 1,271 GiB of disk booked, CI one. At 22:03Z the jobs out had booked: one principal's 3 sessions 52 jobs and 1,435 GiB, another's 6 sessions 47 jobs and 708 GiB, CI 13 jobs and 283 GiB. The largest: nine `clippy/tilo-ui` jobs at 76 GiB each, all started within 20 minutes. **What the node could do about it.** | | 21:07Z | 21:42Z | 21:57Z | 22:07Z | 22:27Z | |---|---|---|---|---|---| | offered disk, GiB | 1,236 | 979 | 653 | 490 | 568 | | `t_node_disk_ceiling_bytes`, GiB | 831 | 578 | 252 | 0 | 165 | - The volume was 100% busy throughout (md127: about 1.2 GB/s written and as much read; its four members at 87-89%). - The deleter ran at about one busy second a second and freed 110-250 GiB a minute in bursts, then 36-51 at 22:02-22:03Z; jobs wrote 55-85 GiB a minute, more at the wave's start. - From 22:20Z `deleting/` stayed empty while 130 GiB went in five minutes. Seven samples of the `t-freer` thread: waiting (futex, nanosleep) with unchanged IO counters, then seconds at a time in an `ioctl` in state D. `t disk --json`: freeing 0. The ceiling says why: what it may free has run out. - A session's build was flattened in the same minute: 61.9 GB copied in 69 s. - On the node now: 10,335 layers, 9,360 snapshots, 12,229 shared entries, 109 job directories. **How I read it.** Bookings hold nothing on the volume by design (the head comment of src/store/freer.rs), people's jobs start first and without a limit, and each brings a build directory of tens of GiB. So a wave can hold more than the volume has beyond its keep line; the cache gives way first, then there is nothing left to free, and the floor is the only brake. Two things I cannot judge from outside: whether layers and snapshots stay held longer than a job or session needs them, and whether flattening should wait while the volume is short. No change proposed here; disk admission is yours, and a limit per principal is the user's decision. Evidence kept on my side: free disk by minute, the deleter's counters, the thread samples. **22:32Z, four more within 30 seconds.** clippy/tilolang-host (46.1 GiB booked, 46.1 held), clippy-x86_64/imager (17.5 and 17.2), clippy/file-explorer (34.1 and 34.2) and clippy/tilo-room-host (38.5 and 38.6) each ended `disk_full` at its own limit after about 15 minutes of work, with 523 to 553 GiB free on the volume, above the floor. All four are one principal's people's jobs and all run again booked higher, which asks for more disk still. That makes six such ends since 22:04Z. So the brake is not only the floor: a job whose quota is not grown while the ceiling is this low loses its work at the quota. **Measured, 22:37Z: the grows are refused.** `t_sched_grow_total{what="disk"}` per ten minutes: | ten minutes to | 21:46 | 21:56 | 22:06 | 22:16 | 22:26 | 22:36 | |---|---|---|---|---|---|---| | granted | 29 | 28 | 28 | 22 | 25 | 8 | | refused | 0 | 0 | 91 | 82 | 47 | 311 | None was refused in the hour before 21:56Z. A refused grow leaves the job at its quota (src/sched/state.rs, the `fits` branch of a disk grow), and the six `disk_full` ends are jobs that then wrote into it. **22:42Z, on 6ebaa239.** Free disk is at 436 GiB and falling again (496 at 22:40:35Z), with 171 entries waiting in `deleting/`. 27 asks wait for disk, and people's jobs now wait 180 s at the median and 492 s at the 95th percentile to start (376 started in 15 minutes); CI started 2. **22:42 to 22:48Z: the node ran at a quarter of its jobs for want of disk, with cores idle.** | | 22:40 | 22:42 | 22:44 | 22:46 | 22:48 | |---|---|---|---|---|---| | offered disk, GiB | 500 | 449 | 438 | 461 | 761 | | ceiling, GiB | 152 | 32 | 32 | 47 | 351 | | jobs running | 93 | 71 | 51 | 31 | 85 | | `t_node_busy_cores` | 323 | 299 | 191 | 135 | 181 | | disk grows refused in the minute | 69 | 119 | 208 | 116 | 3 | The whole queue waited for disk (`why=disk:107519` at 22:47Z, 125 of 159 cores booked). Four more jobs ended `disk_full` at their own limit in those minutes (22:43:43, 22:44:13, 22:44:58, 22:47:06), which makes ten since 22:04Z, all one principal's people's jobs. Then the freer caught up: 760 GiB free at 22:48Z and starts resumed (37 and 22 in the next two minutes). **22:51Z: recovered, with the wave still on.** Free disk 760 GiB at 22:48:03Z, then 856, 911, 1,008 and 1,140 GiB at 22:51:03Z, as `deleting/` drained from 446 entries to 0. No job ended by a cause after 22:47:06Z. Out at 22:51Z: one principal 31 jobs with 884 GiB of disk booked, CI 14 jobs with 642 GiB, the other principal 42 jobs with 302 GiB. The whole episode ran from 21:33Z to 22:51Z: the floor touched at 22:05Z (452 GiB) and nearly again at 22:42Z (436), ten `disk_full` ends and one `setup` end, and six minutes at a quarter of the node's jobs. ## It happened again, 00:54Z to 01:45Z 11-14, on c2d52b34: a stall this time, not a pile of failed jobs **Timeline.** | When | What | |---|---| | ~00:54Z | A wave of people's runs begins. Free disk 1,261 GiB at 00:47Z. | | 01:13Z | 85 of 86 running jobs are people's; CI started 3 jobs in 15 minutes. | | 01:26:31Z | Free disk at the floor (about 410 GiB). Nothing refused yet. | | 01:28Z to 01:38Z | Free disk goes on down under the floor: 387, 312, 318, 237, 165 GiB. Disk grows refused 1 to 8 a minute. A few people's jobs wait with kind `disk`. | | 01:39Z | The node's disk ceiling reads 0. No job is started from here on. | | 01:41:41Z | Lowest free disk read: 121 GiB. | | 01:41:31Z to 01:42:58Z | Four jobs end `disk_full`, all people's: two of principal quinten, two of xemmerling. No CI job fails for disk. | | 01:39Z to ~01:44Z | The node drains: running jobs 97, 42, 32, 26, 17, 8; busy cores down to 36; 116,603 CI jobs, 939 probes and 60 people's jobs wait for `disk`, each short by about 1.07 GB; grows refused 72 to 182 a minute. | | 01:45Z | Free disk 644 GiB, 175 busy cores, 147 of 159 cores booked. Nobody's hand. | Against 21:33Z on the older build: there the node kept placing, ten jobs ended `disk_full` and 311 grows were refused per ten minutes. Here a job short of the node's disk waited for it, so the cost was five minutes with no job started. **Who wrote.** Per-session bytes written, from the jobs' cgroups (`io.stat`, two reads 20 s apart at 01:22Z): people's jobs 97 GiB a minute, CI nothing; one session 78 GiB a minute. In the jobs view the largest session then was `claude:fa71a892…` of principal xemmerling with 44 running jobs in 34 runs at once. **The freer's own account at 01:42:02Z.** "the volume needs 473,300,496,219 bytes more free": keep 1,319 GB, floor 439.7 GB, available 123.9 GB, `freeing` 380.8 GB (handed to the deleter, not yet gone), pending 853.7 GB, freed 13 candidates of 218.7 GB in that pass, kept 548 candidates whose blocks other files share: 970.8 GB that freeing would not return. **Where the volume's 8,047 GiB used sat (01:39Z, `du -sx` with short limits; shared blocks counted more than once).** `cas/packs` 2,835 GiB in 741 files; `layers` 12,101 directories, of them build layers `b-` 6,424 with a random sample of 14 at a mean 1.65 GiB (largest 10.4), every other kind under 100 MiB a layer; `scratch` 318 GiB; `deleting` 122 GiB. A people's session's build is about 59 GB, and the worker flattened five such in twelve minutes (`t::store::snapshots: flattened a session's build … bytes=59113234798`). **What I could not explain, and where a fix would have to look.** - The store's index lists 3,214 build layers; 2,466 of them had not been used for over two hours (1,576 for 6 to 24 h, 365 for over a day), worth 1,909 hours to make again. None of them was part of a job's mount at 01:41Z. They stayed while the volume stood up to 290 GiB under its floor. Whether they are among the 548 "kept: shared" candidates, held by something, or not listed at all, I have not read. - What is freed trails in the deleter (380 GB queued at the worst minute; single trees of 159 and 51 GiB), and it removes a tree with up to 16 threads already. - Nothing bounds what people's sessions write together: a job's quota bounds one job, and a booking holds nothing on the volume (freer.rs says so on purpose). Thirty-four runs of one session can outwrite the freer for half an hour. I changed nothing on production. The readings are in my notes; the scripts are `disk-floor-reading.sh` and `disk-floor-watch*.sh`.

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

No description provided.

Rows
Columns