Poll the cgroup cache counter in test-ubuntu-reclaim-cache

[madolson]

The SAVE checkpoint at .github/workflows/daily.yml:801 reads the runner's cgroup file page cache counter the instant posix_fadvise returns, and that counter is not current yet. On cgroup v2's root cgroup memory.stat's file field is global_node_page_state(NR_FILE_PAGES), fed by per-CPU vmstat deltas the kernel folds in lazily, so it can read several MB above the settled value for up to a second after a large write is evicted. vmtouch reported /tmp/master/dump.rdb at 0/250032 resident pages in both observed failures, so the reclaim under test worked and only the counter was behind. This replaces the three single-shot compares with a bounded retry that polls for up to 10s and breaks as soon as the counter is within budget.

Details

Problem

daily.yml:797 runs save, :798 runs vmtouch, :801 reads memory.stat. Nothing in between. The other two checkpoints sample the same counter after sleep 1 # wait for the completion of cache reclaim bio (daily.yml:807 and daily.yml:825) and have not failed.

The two failures reported in #50:

test SAVE doesn't increase cache
3431657472
OK
/tmp/master/dump.rdb
[ ] 0/250032
[ ] 0/250032 Files: 1 Directories: 0 Resident Pages: 0/250032 0/976M 0% Elapsed: 0.008349 seconds
3462610944
##[error]Process completed with exit code 1.

Deltas 30,953,472 and 16,097,280 against the 8,000,000 budget, with the RDB at zero resident pages both times.

reclaimFilePageCache cannot be the defect. rdb.c:1701-1709 does fflush then fsync then a whole-file posix_fadvise, so by the time save returns every page is clean and dropped, which is what vmtouch measures. rio.c:155-161 already documents that the incremental fadvise calls during the write skip pages under writeback and leave them for "other chances to be reclaimed". The final fsync closes that gap for the mapping. It does not make the vmstat counter current.

Reproduction

Isolating the counter from valkey: write N files in parallel, fsync, posix_fadvise(DONTNEED), then read /proc/vmstat nr_file_pages (the same counter, times page size) at t=0, t=1s and t=2s. The forcing knob is the number of parallel writers, which is what determines how much per-CPU vmstat delta is pending when you read.

$ N=32 MB=32 LOOPS=8 bash skew.sh
loop 1 writers=32 32MB each  t=0s     1396736  t=1s      110592  t=2s       73728  stale=1286144
loop 2 writers=32 32MB each  t=0s     1912832  t=1s      118784  t=2s      118784  stale=1794048
loop 3 writers=32 32MB each  t=0s      483328  t=1s           0  t=2s        8192  stale=483328
loop 4 writers=32 32MB each  t=0s     1564672  t=1s       12288  t=2s       12288  stale=1552384
loop 5 writers=32 32MB each  t=0s     2306048  t=1s      -24576  t=2s      -32768  stale=2330624
loop 6 writers=32 32MB each  t=0s     3510272  t=1s        4096  t=2s        8192  stale=3506176
loop 7 writers=32 32MB each  t=0s     3362816  t=1s        4096  t=2s        4096  stale=3358720
loop 8 writers=32 32MB each  t=0s      778240  t=1s       16384  t=2s       24576  stale=761856

8 of 8. The unsettled read is 0.48 to 3.5 MB high; one second later it is within 120 KB of baseline. Turning the knob up crosses the 8,000,000 budget:

$ N=64 MB=128 LOOPS=5 bash skew.sh
loop 5 writers=64 128MB each  t=0s    11255808  t=1s     3780608  t=2s     3481600  stale=7475200

11.2 MB at t=0, which fails the assertion, against 3.8 MB one second later, which passes it.

Running the actual daily.yml SAVE checkpoint verbatim (same debug populate 10000 k 102400, same two servers, same flags) on a 32-CPU box reproduces the direction but not the magnitude, since the box has 246 GB of RAM against the runner's 16 GB:

loop  1 rdb_resident_pages=16       t=0s      860160 ok   | t=1s      380928 ok   | t=2s      401408 ok
loop  2 rdb_resident_pages=0        t=0s      348160 ok   | t=1s      151552 ok   | t=2s      176128 ok
loop  3 rdb_resident_pages=0        t=0s      286720 ok   | t=1s      364544 ok   | t=2s      352256 ok
loop  4 rdb_resident_pages=0        t=0s      802816 ok   | t=1s      249856 ok   | t=2s      294912 ok
loop  5 rdb_resident_pages=0        t=0s      192512 ok   | t=1s       65536 ok   | t=2s       73728 ok
loop  6 rdb_resident_pages=0        t=0s      163840 ok   | t=1s       77824 ok   | t=2s       77824 ok
=== failures: t=0s 0/6   t=1s 0/6   t=2s 0/6

t=0 reads above t=1s in 5 of 6 loops, up to 3.2x. The settled deltas match the 0.5 to 1.1 MB seen in passing CI runs. Absolute values stay under budget, so this arm does not fail before the patch and pass after it; the synthetic loop above is what crosses the budget.

Why a retry and not another sleep 1

sleep 1 is what the other two checkpoints do and it has held so far, but it is a duration where the thing being waited on is a condition. A retry waits exactly as long as the counter needs and no longer, and it costs nothing in the common case: the loop breaks on the first sample in every passing run.

The two existing sleep 1 # wait for the completion of cache reclaim bio lines stay. They also gate the vmtouch 0% checks at :808, :811 and :826, which the retry does not cover.

Not fixed here

/sys/fs/cgroup/memory.stat is the root cgroup, so the assertion counts the Actions runner writing step logs, journald, snapd and the apt-get install vmtouch from daily.yml:781 alongside valkey. A retry does not fix that, and in the reproduction above the loops that failed at 10 GB scale failed at t=0 and t=10s alike for exactly that reason. Attributing the measurement to a dedicated cgroup would be the real fix and is a larger change than this one.

This was generated by AI but verified, with love, by a human.