From a0fe86fb097b7f67fa193d4f14fd4dc48ee3cb7c Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Wed, 30 Sep 2026 21:51:10 -0300 Subject: [PATCH] boot: page-cache, the host's cache and the guest's, measured Three questions nothing here measured, one probe (task boot:page-cache, the lab's boot:page-cache): - a boot cold against warm: the release's files dropped from the host's page cache first, file by file with POSIX_FADV_DONTNEED - never drop_caches, which takes every other runner's cache on the host - and how much of the base image a cold boot reads; - what a guest's writes cost the host twice: the overlay's pages in the host's cache (mincore), with the disk as it is and with --disk-direct-over-backing; - whether the guest's page cache comes back: QEMU's resident memory at each step of a file written, read, dropped and removed. One rep on a laptop (2026-10-01, v20260930.02): a cold boot reads 47 MB of the 830 MB base; writing 512 MB leaves 514 MB of the overlay in the host's cache with writeback, kept after the guest drops and removes it, and 2 MB with the overlay O_DIRECT; QEMU's RSS returns when the guest drops its cache (free page reporting), not before. The lab's numbers are the ones to read. Co-Authored-By: Claude Opus 5.5 (1M context) --- .github/workflows/lab.yml | 1 + boot/Taskfile.yml | 11 ++ boot/pagecache_test.go | 352 ++++++++++++++++++++++++++++++++++++++ go.mod | 5 +- go.sum | 2 + 5 files changed, 370 insertions(+), 1 deletion(-) create mode 100644 boot/pagecache_test.go diff --git a/.github/workflows/lab.yml b/.github/workflows/lab.yml index 3e2f567..7a59c45 100644 --- a/.github/workflows/lab.yml +++ b/.github/workflows/lab.yml @@ -38,6 +38,7 @@ on: - boot:unitload - boot:ssh-load - boot:memory-policy + - boot:page-cache - boot:firmware - boot:firmware-stages - report diff --git a/boot/Taskfile.yml b/boot/Taskfile.yml index 266105e..2678a0d 100644 --- a/boot/Taskfile.yml +++ b/boot/Taskfile.yml @@ -34,6 +34,17 @@ tasks: cmds: - SPIN_SSH_LOAD=1 go test ./boot/ -run '^TestSSHUnderLoad$' -count=1 -v -timeout 30m + page-cache: + desc: >- + The page caches a machine has: a boot cold - the release's files dropped from the host's + cache first, file by file - against warm; and a guest writing, reading and removing a file, + with QEMU's memory and the overlay's and the base image's pages in the host's cache at each + step, the disk as it is against --disk-direct-over-backing. Needs /dev/kvm, a built release + and sudo. REPS= boots per variant, FILE_MB= the guest's file. + deps: [':tools'] + cmds: + - SPIN_PAGE_CACHE=1 go test ./boot/ -run '^TestPageCache$' -count=1 -v -timeout 60m + memory-policy: desc: >- A process that takes memory until something stops it, in a login session of a 1 GiB diff --git a/boot/pagecache_test.go b/boot/pagecache_test.go new file mode 100644 index 0000000..2729c68 --- /dev/null +++ b/boot/pagecache_test.go @@ -0,0 +1,352 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot_test + +import ( + "bufio" + "cmp" + "fmt" + "io/fs" + "os" + "os/exec" + "path/filepath" + "regexp" + "strconv" + "strings" + "syscall" + "testing" + "time" + "unsafe" + + "golang.org/x/sys/unix" + + "github.com/spin-stack/spin-machine/boot" +) + +// TestPageCache asks three questions of the page caches a machine has - the host's, which its disk +// is read through, and the guest's, which is the machine's own memory - that nothing else here +// measures: +// +// 1. What a boot costs cold: the first machine on a host that has just started, or whose cache +// something else has taken, reads the base image, the kernel and QEMU from the disk. The +// release's files are dropped from the host's cache (POSIX_FADV_DONTNEED, file by file - never +// drop_caches, which would take every other runner's cache on the host too) before each cold +// boot, and a warm boot follows each; interleaved, p50/p95, and how much of the base image a +// cold boot read. +// +// 2. What the guest's disk holds twice: a workspace that writes and reads its disk has those +// blocks in its own page cache and, through QEMU's writeback cache, in the host's as well - +// memory the host pays for a copy only the guest reads. The overlay's residency in the host's +// cache, read with mincore, after the guest wrote and read a file, with the disk as it is and +// with --disk-direct-over-backing (O_DIRECT for the overlay, the base still cached). +// +// 3. Whether the guest's page cache comes back: free page reporting returns what the guest +// frees, and page cache is not free. QEMU's resident memory at each step of the same boot - +// idle, the file written, the guest's cache full of it, the guest dropping its cache, the file +// removed - says what a workspace that read a lot costs the host until it lets go, and when it +// does. +// +// SPIN_PAGE_CACHE=1 run at all +// REPS= boots per variant (default 5) +// FILE_MB= the file the guest writes and reads (default 512, a quarter of the +// guest's memory: the overlay is made 2 GiB and the guest's root grown into it) +// +// Needs /dev/kvm, a built release and sudo (the guest's workload is a unit written into its +// overlay, as bench's variants are). +func TestPageCache(t *testing.T) { + if os.Getenv("SPIN_PAGE_CACHE") == "" { + t.Skip("set SPIN_PAGE_CACHE=1: this boots VMs cold and warm and fills their caches") + } + if !canSudo() { + t.Skip("the guest's workload is written into its overlay through qemu-nbd, which needs sudo") + } + out := releaseDir(t) + reps := envInt(t, "REPS", 5) + fileMB := envInt(t, "FILE_MB", 512) + + t.Run("cold boot", func(t *testing.T) { coldBoots(t, out, reps) }) + t.Run("caches", func(t *testing.T) { cacheSteps(t, out, reps, fileMB) }) +} + +// coldBoots boots the baseline cold and warm, interleaved, and logs both and what a cold boot read. +func coldBoots(t *testing.T, out string, reps int) { + v := labelled("baseline", without()) + base := filepath.Join(out, "image", "rootfs.qcow2") + samples := map[string]map[boot.Phase][]time.Duration{"cold": {}, "warm": {}} + var read []float64 + for range reps { + if err := evictTree(out); err != nil { + t.Fatal(err) + } + for _, label := range []string{"cold", "warm"} { + run := bootOnce(t, out, v) + if !run.Reached(boot.Usable) { + t.Fatalf("%s boot reached no login prompt:\n%s", label, tail(run.Output, 800)) + } + for _, p := range []boot.Phase{boot.Firmware, boot.Kernel, boot.PID1, boot.Usable} { + if d, ok := run.At[p]; ok { + samples[label][p] = append(samples[label][p], d) + } + } + if label == "cold" { + mb, _, err := resident(base) + if err != nil { + t.Fatal(err) + } + read = append(read, mb) + } + } + } + var b strings.Builder + fmt.Fprintf(&b, "\nmilliseconds from the moment before QEMU is exec'd, p50/p95 over %d boots each, interleaved;\n", reps) + fmt.Fprintf(&b, "cold: the release's files dropped from the host's page cache before the boot\n\n") + fmt.Fprintf(&b, "%-6s %10s %10s %10s %10s\n", "", "FIRMWARE", "KERNEL", "PID1", "USABLE") + for _, l := range []string{"cold", "warm"} { + fmt.Fprintf(&b, "%-6s", l) + for _, p := range []boot.Phase{boot.Firmware, boot.Kernel, boot.PID1, boot.Usable} { + fmt.Fprintf(&b, " %10s", cell(samples[l][p])) + } + fmt.Fprintln(&b) + } + fi, err := os.Stat(base) + if err != nil { + t.Fatal(err) + } + p50, _ := boot.Percentile(read, 0.5) + fmt.Fprintf(&b, "\na cold boot read %.0f MB of the base image's %.0f MB (p50 of the resident pages after it)\n", + p50, float64(fi.Size())/(1<<20)) + t.Log(b.String()) +} + +// The steps of the guest's workload, in the order it takes them, and what each is. +var cacheStepNames = []string{ + "idle", + "file written", + "guest cache full", + "guest dropped its cache", + "file removed", +} + +// cacheWorkload is the guest's side: a unit that runs once the machine is up, takes each step and +// says so on the console with what the guest sees - its page cache and free memory, in kB - and +// how long the step's I/O took, then waits for the host to measure before the next. %d is the +// file's size in MB. +const cacheWorkload = `#!/bin/sh +f=/var/tmp/pagecache.bin +say() { echo "PAGECACHE $1 $(awk '/^Cached:/{c=$2} /^MemFree:/{m=$2} END{print c, m}' /proc/meminfo) $2" > /dev/ttyS0; sleep 4; } +ms() { date +%%s%%3N; } +sync; echo 3 > /proc/sys/vm/drop_caches +say 0 0 +t=$(ms); dd if=/dev/zero of=$f bs=1M count=%d conv=fsync status=none || { echo "PAGECACHE-FAILED $(df -m / | tail -1)" > /dev/ttyS0; exit 1; } +say 1 $(( $(ms) - t )) +echo 3 > /proc/sys/vm/drop_caches +t=$(ms); cat $f > /dev/null; say 2 $(( $(ms) - t )) +echo 3 > /proc/sys/vm/drop_caches; sleep 6; say 3 0 +rm -f $f; fstrim / 2>/dev/null; sync; sleep 6; say 4 0 +echo PAGECACHE-DONE > /dev/ttyS0 +` + +const cacheUnit = `[Unit] +Description=page cache probe +After=multi-user.target + +[Service] +Type=oneshot +ExecStart=/bin/sh /usr/local/sbin/pagecache.sh +` + +var cacheLine = regexp.MustCompile(`PAGECACHE (\d) (\d+) (\d+) (\d+)`) + +// cacheStep is what one step of the workload measured: the guest's cache and free memory, the +// I/O's time, and on the host, QEMU's resident memory and the overlay's and the base image's +// pages in the host's page cache - all in MB but the time. +type cacheStep struct { + guestCache, guestFree, ms float64 + qemuRSS, overlayCache, baseCache float64 +} + +// cacheSteps boots the workload with the disk as it is and with the overlay O_DIRECT, reps times +// each, interleaved, and logs each step's p50. +func cacheSteps(t *testing.T, out string, reps, fileMB int) { + variants := []struct { + label string + flags []string + }{ + {"writeback", nil}, + {"direct overlay", []string{"--disk-direct-over-backing"}}, + } + got := map[string][][]cacheStep{} + for range reps { + for _, v := range variants { + got[v.label] = append(got[v.label], cacheBoot(t, out, v.flags, fileMB)) + } + } + var b strings.Builder + fmt.Fprintf(&b, "\na %d MB file written, read and removed in a 2048 MB guest, p50 over %d boots; MB but the I/O's ms.\n", fileMB, reps) + fmt.Fprintf(&b, "host: QEMU's resident memory, and the overlay's and the base image's pages in the host's page cache\n\n") + for _, v := range variants { + fmt.Fprintf(&b, "%s\n%-26s %8s %8s %8s %9s %9s %9s\n", v.label, "STEP", "I/O ms", "G.CACHE", "G.FREE", "QEMU RSS", "OVERLAY", "BASE") + for i, name := range cacheStepNames { + var col [6][]float64 + for _, run := range got[v.label] { + s := run[i] + for j, x := range []float64{s.ms, s.guestCache, s.guestFree, s.qemuRSS, s.overlayCache, s.baseCache} { + col[j] = append(col[j], x) + } + } + fmt.Fprintf(&b, "%-26s", name) + for j, c := range col { + p, _ := boot.Percentile(c, 0.5) + w := 8 + if j >= 3 { + w = 9 + } + fmt.Fprintf(&b, " %*.0f", w, p) + } + fmt.Fprintln(&b) + } + fmt.Fprintln(&b) + } + t.Log(b.String()) +} + +// cacheBoot runs the workload in one machine started with flags, and measures each of its steps +// on the host as the guest announces it. +func cacheBoot(t *testing.T, out string, flags []string, fileMB int) []cacheStep { + t.Helper() + dir := t.TempDir() + overlay := filepath.Join(dir, "overlay.qcow2") + base := filepath.Join(out, "image", "rootfs.qcow2") + // The base image's root has little room: the overlay is larger, and the root grown into it + // while the overlay is mounted, so the file is the size asked for. The base is not touched. + mustRun(t, filepath.Join(out, "bin", "qemu-img"), "create", "-f", "qcow2", "-F", "qcow2", "-b", base, overlay, "2G") + v := without() + v.setup = `resize2fs "$(findmnt -no SOURCE "$MNT")" >/dev/null` + v.files["/usr/local/sbin/pagecache.sh"] = fmt.Sprintf(cacheWorkload, fileMB) + v.files["/etc/systemd/system/pagecache.service"] = cacheUnit + v.links = map[string]string{"/etc/systemd/system/multi-user.target.wants/pagecache.service": "../pagecache.service"} + editOverlay(t, overlay, v) + + args := append([]string{"boot", "--release", out, "--disk", overlay, "--memory", "2048", "--cpus", "2", + "--console", "file:/dev/stdout", "--append", "init=/sbin/init"}, flags...) + cmd := exec.Command(filepath.Join(out, "bin", "spin-machine"), args...) + cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} + stdout, err := cmd.StdoutPipe() + if err != nil { + t.Fatal(err) + } + if err := cmd.Start(); err != nil { + t.Fatalf("launching the machine: %v", err) + } + kill := func() { + if pgid, err := syscall.Getpgid(cmd.Process.Pid); err == nil { + _ = syscall.Kill(-pgid, syscall.SIGKILL) + } + } + timer := time.AfterFunc(cmp.Or(time.Duration(envInt(t, "CACHE_TIMEOUT_S", 240))*time.Second, 4*time.Minute), kill) + defer func() { timer.Stop(); kill(); _ = cmd.Wait() }() + + // spin-machine execs QEMU in place: its pid is QEMU's. + pid := cmd.Process.Pid + steps := make([]cacheStep, len(cacheStepNames)) + seen := 0 + var console strings.Builder + sc := bufio.NewScanner(stdout) + sc.Buffer(make([]byte, 64<<10), 1<<20) + for sc.Scan() { + line := sc.Text() + console.WriteString(line + "\n") + if strings.Contains(line, "PAGECACHE-DONE") { + break + } + if strings.Contains(line, "PAGECACHE-FAILED") { + t.Fatalf("the guest's workload failed: %s", line) + } + m := cacheLine.FindStringSubmatch(line) + if m == nil { + continue + } + i, _ := strconv.Atoi(m[1]) + s := &steps[i] + s.guestCache, s.guestFree, s.ms = kb(m[2]), kb(m[3]), num(m[4]) + if s.qemuRSS, err = rss(pid); err != nil { + t.Fatal(err) + } + if s.overlayCache, _, err = resident(overlay); err != nil { + t.Fatal(err) + } + if s.baseCache, _, err = resident(base); err != nil { + t.Fatal(err) + } + seen++ + } + if seen != len(steps) { + t.Fatalf("the guest reported %d of %d steps; console tail:\n%s", seen, len(steps), tail([]byte(console.String()), 1500)) + } + return steps +} + +func kb(s string) float64 { return num(s) / 1024 } +func num(s string) float64 { n, _ := strconv.ParseFloat(s, 64); return n } + +// rss is the process pid's resident memory in MB: its anonymous and shared memory, which is the +// guest's RAM, and the file pages it maps. +func rss(pid int) (float64, error) { + raw, err := os.ReadFile(fmt.Sprintf("/proc/%d/status", pid)) + if err != nil { + return 0, err + } + for l := range strings.Lines(string(raw)) { + if v, ok := strings.CutPrefix(l, "VmRSS:"); ok { + return kb(strings.Fields(v)[0]), nil + } + } + return 0, fmt.Errorf("/proc/%d/status has no VmRSS", pid) +} + +// resident is how many MB of the file at p are in the host's page cache, by mincore over a +// mapping of it, and the file's size in MB. +func resident(p string) (float64, float64, error) { + f, err := os.Open(p) + if err != nil { + return 0, 0, err + } + defer func() { _ = f.Close() }() // read-only + fi, err := f.Stat() + if err != nil || fi.Size() == 0 { + return 0, 0, err + } + m, err := unix.Mmap(int(f.Fd()), 0, int(fi.Size()), unix.PROT_READ, unix.MAP_SHARED) + if err != nil { + return 0, 0, fmt.Errorf("mapping %s: %w", p, err) + } + defer func() { _ = unix.Munmap(m) }() // a mapping only read for its residency + page := os.Getpagesize() + vec := make([]byte, (len(m)+page-1)/page) + // x/sys/unix has no Mincore on Linux. + if _, _, errno := unix.Syscall(unix.SYS_MINCORE, uintptr(unsafe.Pointer(&m[0])), uintptr(len(m)), uintptr(unsafe.Pointer(&vec[0]))); errno != 0 { + return 0, 0, fmt.Errorf("mincore on %s: %w", p, errno) + } + n := 0 + for _, v := range vec { + n += int(v & 1) + } + return float64(n*page) / (1 << 20), float64(fi.Size()) / (1 << 20), nil +} + +// evictTree drops every file of the release tree at dir from the host's page cache: what the +// first machine on a host that has just started reads from the disk. Not drop_caches, which takes +// every other runner's cache on the host with it. +func evictTree(dir string) error { + return filepath.WalkDir(dir, func(p string, d fs.DirEntry, err error) error { + if err != nil || !d.Type().IsRegular() { + return err + } + f, err := os.Open(p) + if err != nil { + return err + } + defer func() { _ = f.Close() }() // opened only to advise on + return unix.Fadvise(int(f.Fd()), 0, 0, unix.FADV_DONTNEED) + }) +} diff --git a/go.mod b/go.mod index d07423a..3a71fb3 100644 --- a/go.mod +++ b/go.mod @@ -10,7 +10,10 @@ tool ( github.com/spin-stack/go-tools/cmd/versions ) -require github.com/spin-stack/go-tools v0.0.0-20260930221820-8ea51671c2d8 +require ( + github.com/spin-stack/go-tools v0.0.0-20260930221820-8ea51671c2d8 + golang.org/x/sys v0.48.0 +) require ( go.yaml.in/yaml/v3 v3.0.5 // indirect diff --git a/go.sum b/go.sum index f29bbeb..fd3cd47 100644 --- a/go.sum +++ b/go.sum @@ -10,5 +10,7 @@ golang.org/x/mod v0.41.0 h1:qJmnOUb4YB+FsEuM3HcWucdZASCPGhsX6uljO6pog0c= golang.org/x/mod v0.41.0/go.mod h1:Ek9pY8RKWXwsWvd3rQiHYtMqkjSUV+s1Rj7j4H5Ur6o= golang.org/x/sync v0.23.0 h1:KameEIfc1IkluZyXWLn39Wd4tURc6GbCiISGiZm2bQk= golang.org/x/sync v0.23.0/go.mod h1:sUUOizhqBxiL6pEWpqNLUiaJn1ShEbZ6BBqskPbjZm0= +golang.org/x/sys v0.48.0 h1:bbX/i/6MgT9BVLM9RT1thmxL04yeTAhbEz4SyadbXoo= +golang.org/x/sys v0.48.0/go.mod h1:hNLxWAXmnKAxqDtdwIYC4bM9oQPEecfsnNMuSxOs3og= golang.org/x/tools v0.50.0 h1:c2ifzfcuY7L90lZ2aKd8S4K2NpASF08SZx9ZuJkHmSU= golang.org/x/tools v0.50.0/go.mod h1:7ulVMw3831Mwi5EZD6RomGyffr4VFjuNYXf2BbCEAV0=