From 8f7db549ae2d9d49d305ae9dded2386235fdb261 Mon Sep 17 00:00:00 2001 From: jochen Date: Sun, 11 Oct 2026 01:47:43 +0200 Subject: [PATCH 1/3] The setuid walk paces itself by the machine's I/O pressure (issue 433) The walk for setuid programs is put in the idle I/O class so it yields to everything else, but only a scheduler that schedules by class (BFQ) honours that. The control-node's disks run mq-deadline, which does not, so the walk read at full priority. On 2026-10-11 the walk started at 01:27, right after the engine applied a new controller, and ran sixteen minutes; it kept two spinning disks saturated, the bus whose store shares them stalled for half a minute twice, and the controller lost its lease and restarted each time. The walk now also paces itself by PSI, which reads the same whatever the scheduler: before it reads a directory, while some task has waited on I/O for more than 10 % of the last ten seconds, it pauses two seconds at a time. It looks at most every 250 ms, pauses at most 30 s in a row and then reads one more directory, so a machine that is never quiet is walked slowly but still judged. Its own reads count in the pressure, so on an otherwise idle machine it holds the disk below the bound. Pressure it cannot read pauses nothing, and is said once. A paced walk finds what an unpaced one finds; a walk ended while it pauses is an incomplete walk, never one that found nothing. --- internal/accounts/setuid_pace.go | 134 +++++++++++++++++++ internal/accounts/setuid_pace_test.go | 179 ++++++++++++++++++++++++++ internal/accounts/setuid_walk.go | 6 + internal/accounts/ways.go | 2 +- 4 files changed, 320 insertions(+), 1 deletion(-) create mode 100644 internal/accounts/setuid_pace.go create mode 100644 internal/accounts/setuid_pace_test.go diff --git a/internal/accounts/setuid_pace.go b/internal/accounts/setuid_pace.go new file mode 100644 index 0000000..ff91e57 --- /dev/null +++ b/internal/accounts/setuid_pace.go @@ -0,0 +1,134 @@ +package accounts + +// The walk for setuid programs yields to a busy disk (novox/hq issue 433). The walk is put in the idle I/O class +// (idle_linux.go), but only a disk scheduler that schedules by class honours that (BFQ does). The control-node's +// disks run mq-deadline, which does not, and there the walk read at full priority: on 2026-10-11 it kept two +// spinning disks saturated for sixteen minutes, the bus whose store shares those disks stalled for half a minute +// twice, and the controller lost its lease each time. So the walk also paces itself by the machine's I/O pressure +// (PSI), which reads the same whatever the scheduler: while some task has waited on I/O for more than PaceAbove +// of the last ten seconds, the walk pauses before it reads the next directory. +// +// The walk's own reads count in that pressure, so on a machine where nothing else waits it slows itself to keep +// the disk below the bound; that is the yielding the idle class promised. A pause in a row is at most PaceAtMost, +// then one more directory is read: on a machine that is never quiet the walk is slow, but it still ends, so a +// machine is never left unjudged for good (the fault issue 361 repaired). + +import ( + "bufio" + "bytes" + "context" + "fmt" + "log" + "os" + "strconv" + "strings" + "time" +) + +const ( + // PaceAbove is the I/O pressure, as the percentage of the last ten seconds in which some task waited on I/O + // (PSI's "some avg10"), above which the walk pauses. + PaceAbove = 10.0 + // PaceLook is how often the walk looks at the pressure while it walks. + PaceLook = 250 * time.Millisecond + // PacePause is one pause. + PacePause = 2 * time.Second + // PaceAtMost is the longest the walk pauses in a row before it reads one more directory. + PaceAtMost = 30 * time.Second + // ioPressureFile is where the kernel says the machine's I/O pressure. + ioPressureFile = "/proc/pressure/io" +) + +// pacer is what the walk asks before it reads a directory. A nil pacer never pauses. +type pacer struct { + pressure func() (float64, error) // some avg10, in percent + sleep func(context.Context, time.Duration) error + now func() time.Time + logf func(format string, args ...any) + + lastLook time.Time + saidBlind bool +} + +// newPacer paces by the machine's own I/O pressure. +func newPacer() *pacer { + return &pacer{ + pressure: func() (float64, error) { return readIOPressure(ioPressureFile) }, + sleep: sleepCtx, + now: time.Now, + logf: log.Printf, + } +} + +// yield pauses while the machine's I/O pressure is above PaceAbove, PacePause at a time and PaceAtMost in a row, +// looking at most every PaceLook. It ends early only with ctx, whose error ends the walk as incomplete. Pressure +// that cannot be read pauses nothing, and is said once: the walk then yields only where the idle class does. +func (pc *pacer) yield(ctx context.Context) error { + if pc == nil || pc.pressure == nil { + return nil + } + if !pc.lastLook.IsZero() && pc.now().Sub(pc.lastLook) < PaceLook { + return nil + } + defer func() { pc.lastLook = pc.now() }() + for waited := time.Duration(0); waited < PaceAtMost; waited += PacePause { + p, err := pc.pressure() + if err != nil { + if !pc.saidBlind && pc.logf != nil { + pc.logf("the walk for setuid programs cannot read the machine's I/O pressure, so it does not pace "+ + "itself and yields only where the disk's scheduler honours the idle class: %v", err) + } + pc.saidBlind = true + return nil + } + if p <= PaceAbove { + return nil + } + if err := pc.sleep(ctx, PacePause); err != nil { + return err + } + } + return nil +} + +// readIOPressure is the "some avg10" of a PSI file: the percentage of the last ten seconds in which some task +// waited on I/O. +func readIOPressure(path string) (float64, error) { + b, err := os.ReadFile(path) + if err != nil { + return 0, err + } + return parseIOPressure(b) +} + +func parseIOPressure(b []byte) (float64, error) { + sc := bufio.NewScanner(bytes.NewReader(b)) + for sc.Scan() { + fields := strings.Fields(sc.Text()) + if len(fields) == 0 || fields[0] != "some" { + continue + } + for _, f := range fields[1:] { + if v, ok := strings.CutPrefix(f, "avg10="); ok { + p, err := strconv.ParseFloat(v, 64) + if err != nil { + return 0, fmt.Errorf("the I/O pressure's avg10 is not a number: %q", v) + } + return p, nil + } + } + } + return 0, fmt.Errorf("the I/O pressure names no \"some\" line with avg10") +} + +// sleepCtx waits d, or until ctx ends. +func sleepCtx(ctx context.Context, d time.Duration) error { + t := time.NewTimer(d) + defer t.Stop() + select { + case <-ctx.Done(): + return ctx.Err() + case <-t.C: + return nil + } +} diff --git a/internal/accounts/setuid_pace_test.go b/internal/accounts/setuid_pace_test.go new file mode 100644 index 0000000..c0771fb --- /dev/null +++ b/internal/accounts/setuid_pace_test.go @@ -0,0 +1,179 @@ +package accounts + +import ( + "context" + "errors" + "fmt" + "slices" + "testing" + "time" +) + +// The walk for setuid programs yields to a busy disk by the machine's I/O pressure (novox/hq issue 433), because +// the idle I/O class it is put in is ignored by a disk scheduler that does not schedule by class, as the +// control-node's mq-deadline does not. + +// fakePace is a pacer whose pressure readings, sleeps and clock a test controls. +type fakePace struct { + readings []float64 // said in turn; the last is said again once they run out + read int + slept []time.Duration + clock time.Time + said []string + fail error +} + +func (f *fakePace) pacer() *pacer { + return &pacer{ + pressure: func() (float64, error) { + if f.fail != nil { + return 0, f.fail + } + i := min(f.read, len(f.readings)-1) + f.read++ + return f.readings[i], nil + }, + sleep: func(ctx context.Context, d time.Duration) error { + if err := ctx.Err(); err != nil { + return err + } + f.slept = append(f.slept, d) + f.clock = f.clock.Add(d) + return nil + }, + now: func() time.Time { return f.clock }, + logf: func(format string, args ...any) { f.said = append(f.said, fmt.Sprintf(format, args...)) }, + } +} + +func TestTheWalkPausesWhileTheDiskIsUnderPressure(t *testing.T) { + f := &fakePace{readings: []float64{42, 18, PaceAbove, 3}, clock: time.Unix(1_000_000, 0)} + pc := f.pacer() + if err := pc.yield(t.Context()); err != nil { + t.Fatal(err) + } + // 42 and 18 are above the bound; PaceAbove itself is not. + if want := []time.Duration{PacePause, PacePause}; !slices.Equal(f.slept, want) { + t.Fatalf("slept %v, want %v", f.slept, want) + } + if f.read != 3 { + t.Fatalf("read the pressure %d times, want 3", f.read) + } +} + +func TestTheWalkDoesNotPauseOnAQuietDisk(t *testing.T) { + f := &fakePace{readings: []float64{0.4}, clock: time.Unix(1_000_000, 0)} + if err := f.pacer().yield(t.Context()); err != nil { + t.Fatal(err) + } + if len(f.slept) != 0 { + t.Fatalf("slept %v on a quiet disk", f.slept) + } +} + +// A machine that is never quiet still sees the walk end: a pause in a row is bounded, then one more directory. +func TestTheWalkPausesAtMostPaceAtMostInARow(t *testing.T) { + f := &fakePace{readings: []float64{95}, clock: time.Unix(1_000_000, 0)} + pc := f.pacer() + if err := pc.yield(t.Context()); err != nil { + t.Fatal(err) + } + var total time.Duration + for _, d := range f.slept { + total += d + } + if total != PaceAtMost { + t.Fatalf("paused %v in a row, want %v", total, PaceAtMost) + } +} + +func TestTheWalkLooksAtThePressureAtMostEveryPaceLook(t *testing.T) { + f := &fakePace{readings: []float64{1}, clock: time.Unix(1_000_000, 0)} + pc := f.pacer() + for range 5 { + if err := pc.yield(t.Context()); err != nil { + t.Fatal(err) + } + f.clock = f.clock.Add(PaceLook / 10) + } + if f.read != 1 { + t.Fatalf("read the pressure %d times within %v, want once", f.read, PaceLook) + } + f.clock = f.clock.Add(PaceLook) + if err := pc.yield(t.Context()); err != nil { + t.Fatal(err) + } + if f.read != 2 { + t.Fatalf("read the pressure %d times after %v, want twice", f.read, PaceLook) + } +} + +// Pressure that cannot be read pauses nothing, and is said once rather than at every directory. +func TestAPressureThatCannotBeReadIsSaidOnce(t *testing.T) { + f := &fakePace{fail: errors.New("no such file"), clock: time.Unix(1_000_000, 0)} + pc := f.pacer() + for range 3 { + if err := pc.yield(t.Context()); err != nil { + t.Fatal(err) + } + f.clock = f.clock.Add(PaceLook) + } + if len(f.slept) != 0 || len(f.said) != 1 { + t.Fatalf("slept %v, said %q; want no pause and one line", f.slept, f.said) + } +} + +// A walk ended while it pauses is an incomplete walk, never one that found nothing. +func TestAWalkEndedWhileItPausesIsIncomplete(t *testing.T) { + top := tree(t, "bin/", "bin/su!") + f := &fakePace{readings: []float64{80}, clock: time.Unix(1_000_000, 0)} + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + pc := f.pacer() + // The engine stops while the walk waits for the disk: the context ends inside the pause, not before the walk. + pc.sleep = func(ctx context.Context, d time.Duration) error { + f.slept = append(f.slept, d) + cancel() + return ctx.Err() + } + w := mine() + w.pace = pc + p := &SetuidProgress{Mounts: []string{top}} + err := w.walk(ctx, p, func() {}) + if len(f.slept) == 0 { + t.Fatal("the walk never paused, so this proves nothing about a walk ended while it pauses") + } + if !errors.Is(err, context.Canceled) { + t.Fatalf("a walk ended while it paused answered %v", err) + } +} + +// Paced, the walk finds what it finds unpaced: pausing changes when, never what. +func TestAPacedWalkFindsWhatAnUnpacedWalkFinds(t *testing.T) { + top := tree(t, "bin/", "bin/su!", "bin/ls", "sbin/", "sbin/mount!", "usr/", "usr/lib/", "usr/lib/helper%") + plain := walkAll(t, mine(), top) + + f := &fakePace{readings: []float64{50, 2}, clock: time.Unix(1_000_000, 0)} + w := mine() + w.pace = f.pacer() + paced := walkAll(t, w, top) + if !slices.Equal(plain, paced) { + t.Fatalf("paced walk found %v, unpaced %v", paced, plain) + } + if len(f.slept) == 0 { + t.Fatal("the walk read its directories without asking the pacer: it never paused under pressure") + } +} + +func TestTheIOPressureIsReadAsTheKernelWritesIt(t *testing.T) { + got, err := parseIOPressure([]byte("some avg10=26.24 avg60=20.07 avg300=27.47 total=123456789\n" + + "full avg10=21.90 avg60=15.77 avg300=22.47 total=98765432\n")) + if err != nil || got != 26.24 { + t.Fatalf("read %v, %v; want 26.24", got, err) + } + for _, bad := range []string{"", "full avg10=1.00 avg60=0 avg300=0 total=0\n", "some avg10=x avg60=0\n"} { + if _, err := parseIOPressure([]byte(bad)); err == nil { + t.Errorf("%q was read as a pressure", bad) + } + } +} diff --git a/internal/accounts/setuid_walk.go b/internal/accounts/setuid_walk.go index 30c66f2..236ddb8 100644 --- a/internal/accounts/setuid_walk.go +++ b/internal/accounts/setuid_walk.go @@ -125,6 +125,8 @@ type walker struct { rootUID, rootGID uint32 every time.Duration mountPoints map[string]bool + // pace is asked before each directory is read (setuid_pace.go); nil never pauses. + pace *pacer } // walk carries p on to its end, calling checkpoint every w.every and after each filesystem. It ends early only @@ -232,6 +234,10 @@ func (w walker) walkMount(ctx context.Context, p *SetuidProgress, mount string, if d, ok := deviceOf(info); !ok || d != dev { return filepath.SkipDir // another filesystem, walked as its own or not at all (find's -xdev) } + // Before its entries are read: a busy disk is waited for here (novox/hq issue 433). + if err := w.pace.yield(ctx); err != nil { + return err + } case d.Type().IsRegular(): info, err := d.Info() // the entry's own, never through a link if errors.Is(err, fs.ErrNotExist) { diff --git a/internal/accounts/ways.go b/internal/accounts/ways.go index 90d68e9..372442d 100644 --- a/internal/accounts/ways.go +++ b/internal/accounts/ways.go @@ -426,7 +426,7 @@ func contains(xs []string, s string) bool { func (e Exec) setuidSearch(ctx context.Context, p *SetuidProgress, checkpoint func(), mountPoints map[string]bool) ([]string, error) { walk := e.Walk if walk == nil { - walk = walker{every: CheckpointEvery, mountPoints: mountPoints}.walk + walk = walker{every: CheckpointEvery, mountPoints: mountPoints, pace: newPacer()}.walk } if err := walk(ctx, p, checkpoint); err != nil { return nil, fmt.Errorf("the walk for setuid programs did not complete: %w", err) From 30242197fadd425b288c5de2eb70387e675d8afd Mon Sep 17 00:00:00 2001 From: jochen Date: Sun, 11 Oct 2026 01:53:25 +0200 Subject: [PATCH 2/3] The paced walk keeps a tenth of the time, and reads the pressure since its last look (review of issue 433) The review of #79 found that pacing alone brought back issue 361's fault. The control-node's own I/O pressure sits near the 10 % bound with no walk running, so a walk that paused 30 s for every 250 ms it read would read 0.8 % of the time: a 16-minute walk would take some 32 hours, outlive the age a search judges for, and be begun again at an engine restart, leaving the machine unjudged. A run of pauses is now at most nine times as long as the walk read since the one before, so the walk keeps at least a tenth of the time whatever the pressure, and takes at most ten times as long as unpaced: about 2.7 hours for the 16-minute walk, inside the 12 hours the controller waits quietly. A test ties the bound to rootsearch.Quiet. The pressure is the share of the time since the last look in which some task waited on I/O, from PSI's cumulative counter, not its ten-second average, which the kernel moves only every two seconds. A pause is 500 ms, then the pressure is looked at again. The engine's walker is built in one place, engineWalker, and a test fails if it is not paced by /proc/pressure/io. What the walk cannot read is said through the search's own channel (the cache's Say), as the rest of the search is, with what it means for the disk. --- internal/accounts/setuid_pace.go | 147 ++++++++++++------- internal/accounts/setuid_pace_test.go | 203 +++++++++++++++++++------- internal/accounts/ways.go | 12 +- 3 files changed, 257 insertions(+), 105 deletions(-) diff --git a/internal/accounts/setuid_pace.go b/internal/accounts/setuid_pace.go index ff91e57..a6273ea 100644 --- a/internal/accounts/setuid_pace.go +++ b/internal/accounts/setuid_pace.go @@ -5,20 +5,23 @@ package accounts // disks run mq-deadline, which does not, and there the walk read at full priority: on 2026-10-11 it kept two // spinning disks saturated for sixteen minutes, the bus whose store shares those disks stalled for half a minute // twice, and the controller lost its lease each time. So the walk also paces itself by the machine's I/O pressure -// (PSI), which reads the same whatever the scheduler: while some task has waited on I/O for more than PaceAbove -// of the last ten seconds, the walk pauses before it reads the next directory. +// (PSI), which reads the same whatever the scheduler. // -// The walk's own reads count in that pressure, so on a machine where nothing else waits it slows itself to keep -// the disk below the bound; that is the yielding the idle class promised. A pause in a row is at most PaceAtMost, -// then one more directory is read: on a machine that is never quiet the walk is slow, but it still ends, so a -// machine is never left unjudged for good (the fault issue 361 repaired). +// It looks every PaceLook at the share of the time since its last look in which some task waited on I/O — from +// the kernel's cumulative stall counter, not its ten-second average, which moves only every two seconds and would +// let the walk read blind that long. Above PaceAbove it pauses, PaceStep at a time, until the share falls below. +// +// **The walk keeps at least a tenth of the time, whatever the pressure** (the review of #79): a run of pauses is +// at most PaceRatio times as long as the walk read since the one before. The control-node's own load sits near +// PaceAbove with no walk running, so a walk that paused for as long as the pressure stayed high would take days, +// outlive the age a search judges for, and leave the machine unjudged — the fault issue 361 repaired. With the +// floor a walk takes at most 1 + PaceRatio times as long as it would unpaced, and its bursts are PaceLook long. import ( "bufio" "bytes" "context" "fmt" - "log" "os" "strconv" "strings" @@ -26,14 +29,17 @@ import ( ) const ( - // PaceAbove is the I/O pressure, as the percentage of the last ten seconds in which some task waited on I/O - // (PSI's "some avg10"), above which the walk pauses. + // PaceAbove is the share of the time since the last look, in percent, in which some task waited on I/O, above + // which the walk pauses. PaceAbove = 10.0 - // PaceLook is how often the walk looks at the pressure while it walks. + // PaceLook is how long the walk reads between two looks at the pressure: the longest it reads blind. PaceLook = 250 * time.Millisecond - // PacePause is one pause. - PacePause = 2 * time.Second - // PaceAtMost is the longest the walk pauses in a row before it reads one more directory. + // PaceStep is one pause, after which the pressure is looked at again. + PaceStep = 500 * time.Millisecond + // PaceRatio bounds a run of pauses to this many times the time the walk read since the run before: the walk + // keeps at least 1/(1+PaceRatio) of the time. + PaceRatio = 9 + // PaceAtMost is the longest run of pauses, whatever the walk read before it. PaceAtMost = 30 * time.Second // ioPressureFile is where the kernel says the machine's I/O pressure. ioPressureFile = "/proc/pressure/io" @@ -41,67 +47,100 @@ const ( // pacer is what the walk asks before it reads a directory. A nil pacer never pauses. type pacer struct { - pressure func() (float64, error) // some avg10, in percent - sleep func(context.Context, time.Duration) error - now func() time.Time - logf func(format string, args ...any) + // path is the pressure file read, kept so a test can see the engine's own walker reads the machine's. + path string + // stalled is the cumulative time some task waited on I/O (PSI's "some total"). + stalled func() (time.Duration, error) + sleep func(context.Context, time.Duration) error + now func() time.Time + say func(string) - lastLook time.Time + lastLook time.Time // when the pressure was last looked at + readSince time.Time // when the walk last began to read, after a run of pauses or at its start + prevAt time.Time // the time of the last sample of the counter + prevTotal time.Duration // the counter at that sample saidBlind bool } -// newPacer paces by the machine's own I/O pressure. -func newPacer() *pacer { +// newPacer paces by the machine's own I/O pressure, and says through say what it cannot do. +func newPacer(say func(string)) *pacer { return &pacer{ - pressure: func() (float64, error) { return readIOPressure(ioPressureFile) }, - sleep: sleepCtx, - now: time.Now, - logf: log.Printf, + path: ioPressureFile, + stalled: func() (time.Duration, error) { return readIOStalled(ioPressureFile) }, + sleep: sleepCtx, + now: time.Now, + say: say, } } -// yield pauses while the machine's I/O pressure is above PaceAbove, PacePause at a time and PaceAtMost in a row, -// looking at most every PaceLook. It ends early only with ctx, whose error ends the walk as incomplete. Pressure -// that cannot be read pauses nothing, and is said once: the walk then yields only where the idle class does. +// yield pauses while the machine's I/O pressure is above PaceAbove: looking at most every PaceLook, pausing +// PaceStep at a time, a run of pauses at most PaceRatio times what the walk read since the last run and never more +// than PaceAtMost. It ends early only with ctx, whose error ends the walk as incomplete. Pressure that cannot be +// read pauses nothing, and is said once. func (pc *pacer) yield(ctx context.Context) error { - if pc == nil || pc.pressure == nil { + if pc == nil || pc.stalled == nil { return nil } - if !pc.lastLook.IsZero() && pc.now().Sub(pc.lastLook) < PaceLook { + now := pc.now() + if pc.readSince.IsZero() { + pc.readSince = now + } + if !pc.lastLook.IsZero() && now.Sub(pc.lastLook) < PaceLook { return nil } - defer func() { pc.lastLook = pc.now() }() - for waited := time.Duration(0); waited < PaceAtMost; waited += PacePause { - p, err := pc.pressure() - if err != nil { - if !pc.saidBlind && pc.logf != nil { - pc.logf("the walk for setuid programs cannot read the machine's I/O pressure, so it does not pace "+ - "itself and yields only where the disk's scheduler honours the idle class: %v", err) - } - pc.saidBlind = true - return nil - } - if p <= PaceAbove { - return nil - } - if err := pc.sleep(ctx, PacePause); err != nil { + pc.lastLook = now + share, known, err := pc.sample(now) + if err != nil || !known || share <= PaceAbove { + return nil + } + budget := min(PaceAtMost, PaceRatio*now.Sub(pc.readSince)) + for paused := time.Duration(0); paused < budget; { + step := min(PaceStep, budget-paused) + if err := pc.sleep(ctx, step); err != nil { return err } + paused += step + share, known, err = pc.sample(pc.now()) + if err != nil || (known && share <= PaceAbove) { + break + } } + pc.readSince, pc.lastLook = pc.now(), pc.now() return nil } -// readIOPressure is the "some avg10" of a PSI file: the percentage of the last ten seconds in which some task -// waited on I/O. -func readIOPressure(path string) (float64, error) { +// sample is the share of the time since the last sample, in percent, in which some task waited on I/O; known is +// false for the first sample, which only sets where the next one counts from. +func (pc *pacer) sample(now time.Time) (float64, bool, error) { + total, err := pc.stalled() + if err != nil { + if !pc.saidBlind && pc.say != nil { + pc.say(fmt.Sprintf("the walk for setuid programs cannot read the machine's I/O pressure (%v), so it does "+ + "not pace itself: where the disk's scheduler ignores the idle class, it may load the disk at full "+ + "priority", err)) + } + pc.saidBlind = true + return 0, false, err + } + prevAt, prevTotal := pc.prevAt, pc.prevTotal + pc.prevAt, pc.prevTotal = now, total + elapsed := now.Sub(prevAt) + if prevAt.IsZero() || elapsed <= 0 || total < prevTotal { + return 0, false, nil + } + return 100 * float64(total-prevTotal) / float64(elapsed), true, nil +} + +// readIOStalled is the "some total" of a PSI file: the time, cumulative since boot, in which some task waited on I/O. +func readIOStalled(path string) (time.Duration, error) { b, err := os.ReadFile(path) if err != nil { return 0, err } - return parseIOPressure(b) + return parseIOStalled(b) } -func parseIOPressure(b []byte) (float64, error) { +func parseIOStalled(b []byte) (time.Duration, error) { sc := bufio.NewScanner(bytes.NewReader(b)) for sc.Scan() { fields := strings.Fields(sc.Text()) @@ -109,16 +148,16 @@ func parseIOPressure(b []byte) (float64, error) { continue } for _, f := range fields[1:] { - if v, ok := strings.CutPrefix(f, "avg10="); ok { - p, err := strconv.ParseFloat(v, 64) + if v, ok := strings.CutPrefix(f, "total="); ok { + us, err := strconv.ParseUint(v, 10, 64) if err != nil { - return 0, fmt.Errorf("the I/O pressure's avg10 is not a number: %q", v) + return 0, fmt.Errorf("the I/O pressure's total is not a count of microseconds: %q", v) } - return p, nil + return time.Duration(us) * time.Microsecond, nil } } } - return 0, fmt.Errorf("the I/O pressure names no \"some\" line with avg10") + return 0, fmt.Errorf("the I/O pressure names no \"some\" line with a total") } // sleepCtx waits d, or until ctx ends. diff --git a/internal/accounts/setuid_pace_test.go b/internal/accounts/setuid_pace_test.go index c0771fb..dd7c0a0 100644 --- a/internal/accounts/setuid_pace_test.go +++ b/internal/accounts/setuid_pace_test.go @@ -3,35 +3,54 @@ package accounts import ( "context" "errors" - "fmt" "slices" + "strings" "testing" "time" + + "github.com/novox/mesh-host/rootsearch" ) // The walk for setuid programs yields to a busy disk by the machine's I/O pressure (novox/hq issue 433), because // the idle I/O class it is put in is ignored by a disk scheduler that does not schedule by class, as the -// control-node's mq-deadline does not. +// control-node's mq-deadline does not — and it keeps a tenth of the time whatever the pressure, so it still ends. -// fakePace is a pacer whose pressure readings, sleeps and clock a test controls. +// fakePace is a pacer whose stall counter, sleeps and clock a test controls. type fakePace struct { - readings []float64 // said in turn; the last is said again once they run out - read int - slept []time.Duration - clock time.Time - said []string - fail error + // shares is the stall share, in percent, of each interval between two reads of the counter, in turn; the last + // is said again once they run out. The first read only sets the counter's start. + shares []float64 + i int + total time.Duration + lastRead time.Time + reads int + + clock time.Time + // tick moves the clock on at every look at it, as a walk reading directories takes time; zero does not. + tick time.Duration + slept []time.Duration + said []string + fail error +} + +func newFake(shares ...float64) *fakePace { + return &fakePace{shares: shares, clock: time.Unix(1_000_000, 0)} } func (f *fakePace) pacer() *pacer { return &pacer{ - pressure: func() (float64, error) { + stalled: func() (time.Duration, error) { if f.fail != nil { return 0, f.fail } - i := min(f.read, len(f.readings)-1) - f.read++ - return f.readings[i], nil + f.reads++ + if !f.lastRead.IsZero() { + s := f.shares[min(f.i, len(f.shares)-1)] + f.i++ + f.total += time.Duration(float64(f.clock.Sub(f.lastRead)) * s / 100) + } + f.lastRead = f.clock + return f.total, nil }, sleep: func(ctx context.Context, d time.Duration) error { if err := ctx.Err(); err != nil { @@ -41,54 +60,111 @@ func (f *fakePace) pacer() *pacer { f.clock = f.clock.Add(d) return nil }, - now: func() time.Time { return f.clock }, - logf: func(format string, args ...any) { f.said = append(f.said, fmt.Sprintf(format, args...)) }, + now: func() time.Time { + f.clock = f.clock.Add(f.tick) + return f.clock + }, + say: func(s string) { f.said = append(f.said, s) }, } } -func TestTheWalkPausesWhileTheDiskIsUnderPressure(t *testing.T) { - f := &fakePace{readings: []float64{42, 18, PaceAbove, 3}, clock: time.Unix(1_000_000, 0)} +func (f *fakePace) paused() time.Duration { + var total time.Duration + for _, d := range f.slept { + total += d + } + return total +} + +func TestTheWalkPausesWhileTheDiskIsUnderPressureAndGoesOnWhenItEases(t *testing.T) { + f := newFake(60, 40, 3) pc := f.pacer() + if err := pc.yield(t.Context()); err != nil { // the first look sets where the counter counts from + t.Fatal(err) + } + f.clock = f.clock.Add(300 * time.Millisecond) // the walk reads if err := pc.yield(t.Context()); err != nil { t.Fatal(err) } - // 42 and 18 are above the bound; PaceAbove itself is not. - if want := []time.Duration{PacePause, PacePause}; !slices.Equal(f.slept, want) { + // 60 % since the first look: pause; 40 % during the first pause: pause again; 3 %: go on. + if want := []time.Duration{PaceStep, PaceStep}; !slices.Equal(f.slept, want) { t.Fatalf("slept %v, want %v", f.slept, want) } - if f.read != 3 { - t.Fatalf("read the pressure %d times, want 3", f.read) +} + +func TestTheFirstLookOnlySetsWhereTheNextCountsFrom(t *testing.T) { + f := newFake(99) + if err := f.pacer().yield(t.Context()); err != nil { + t.Fatal(err) + } + if len(f.slept) != 0 { + t.Fatalf("slept %v on the first look, which has nothing to compare", f.slept) } } func TestTheWalkDoesNotPauseOnAQuietDisk(t *testing.T) { - f := &fakePace{readings: []float64{0.4}, clock: time.Unix(1_000_000, 0)} - if err := f.pacer().yield(t.Context()); err != nil { - t.Fatal(err) + f := newFake(0.4) + pc := f.pacer() + for range 10 { + if err := pc.yield(t.Context()); err != nil { + t.Fatal(err) + } + f.clock = f.clock.Add(PaceLook) } if len(f.slept) != 0 { t.Fatalf("slept %v on a quiet disk", f.slept) } } -// A machine that is never quiet still sees the walk end: a pause in a row is bounded, then one more directory. -func TestTheWalkPausesAtMostPaceAtMostInARow(t *testing.T) { - f := &fakePace{readings: []float64{95}, clock: time.Unix(1_000_000, 0)} +// The control-node's own load sits near the bound with no walk running: the walk must still end (issue 361). +func TestTheWalkKeepsATenthOfTheTimeWhateverThePressure(t *testing.T) { + f := newFake(100) + pc := f.pacer() + var read time.Duration + for range 400 { + if err := pc.yield(t.Context()); err != nil { + t.Fatal(err) + } + f.clock = f.clock.Add(PaceLook) + read += PaceLook + } + if f.paused() == 0 { + t.Fatal("never paused under constant pressure") + } + if f.paused() > PaceRatio*read { + t.Fatalf("paused %v while it read %v: more than %d times as long", f.paused(), read, PaceRatio) + } +} + +// What the floor promises against the ages a search is judged by: the walk that took 16m31s unpaced on the +// control-node on 2026-10-11, slowed to its worst, still completes well inside the time the controller stays quiet +// while it waits for a search, and so judges for most of its fresh age. +func TestTheSlowestPacedWalkStillJudgesInTime(t *testing.T) { + const unpaced = 16*time.Minute + 31*time.Second + worst := (1 + PaceRatio) * unpaced + if worst >= rootsearch.Quiet { + t.Fatalf("a walk paced to its worst takes %v, not less than the %v the controller waits quietly", worst, + rootsearch.Quiet) + } +} + +func TestARunOfPausesIsAtMostPaceAtMost(t *testing.T) { + f := newFake(100) pc := f.pacer() if err := pc.yield(t.Context()); err != nil { t.Fatal(err) } - var total time.Duration - for _, d := range f.slept { - total += d + f.clock = f.clock.Add(10 * time.Minute) // read a long time without a look: the ratio would allow 90 minutes + if err := pc.yield(t.Context()); err != nil { + t.Fatal(err) } - if total != PaceAtMost { - t.Fatalf("paused %v in a row, want %v", total, PaceAtMost) + if f.paused() != PaceAtMost { + t.Fatalf("paused %v in a row, want %v", f.paused(), PaceAtMost) } } func TestTheWalkLooksAtThePressureAtMostEveryPaceLook(t *testing.T) { - f := &fakePace{readings: []float64{1}, clock: time.Unix(1_000_000, 0)} + f := newFake(1) pc := f.pacer() for range 5 { if err := pc.yield(t.Context()); err != nil { @@ -96,21 +172,22 @@ func TestTheWalkLooksAtThePressureAtMostEveryPaceLook(t *testing.T) { } f.clock = f.clock.Add(PaceLook / 10) } - if f.read != 1 { - t.Fatalf("read the pressure %d times within %v, want once", f.read, PaceLook) + if f.reads != 1 { + t.Fatalf("read the pressure %d times within %v, want once", f.reads, PaceLook) } f.clock = f.clock.Add(PaceLook) if err := pc.yield(t.Context()); err != nil { t.Fatal(err) } - if f.read != 2 { - t.Fatalf("read the pressure %d times after %v, want twice", f.read, PaceLook) + if f.reads != 2 { + t.Fatalf("read the pressure %d times after %v, want twice", f.reads, PaceLook) } } -// Pressure that cannot be read pauses nothing, and is said once rather than at every directory. +// Pressure that cannot be read pauses nothing, and is said once, with what it means, rather than at every look. func TestAPressureThatCannotBeReadIsSaidOnce(t *testing.T) { - f := &fakePace{fail: errors.New("no such file"), clock: time.Unix(1_000_000, 0)} + f := newFake(0) + f.fail = errors.New("no such file") pc := f.pacer() for range 3 { if err := pc.yield(t.Context()); err != nil { @@ -121,12 +198,38 @@ func TestAPressureThatCannotBeReadIsSaidOnce(t *testing.T) { if len(f.slept) != 0 || len(f.said) != 1 { t.Fatalf("slept %v, said %q; want no pause and one line", f.slept, f.said) } + if !strings.Contains(f.said[0], "full priority") { + t.Errorf("the line does not say what it means for the disk: %q", f.said[0]) + } +} + +// The engine's own walk is paced by the machine's pressure, and says through the search's own channel. +func TestTheEnginesWalkIsPacedByTheMachinesPressure(t *testing.T) { + var said []string + w := engineWalker(nil, func(s string) { said = append(said, s) }) + if w.pace == nil || w.pace.path != ioPressureFile || w.pace.stalled == nil { + t.Fatalf("the engine's walker is not paced by %s: %+v", ioPressureFile, w.pace) + } + w.pace.say("x") + if len(said) != 1 { + t.Fatal("the engine's walker does not say through the search's channel") + } +} + +// many is a tree of enough directories that a walk reaches a look at the pressure partway. +func many(t *testing.T) string { + names := []string{"bin/", "bin/su!", "bin/ls", "sbin/", "sbin/mount!", "usr/lib/helper%"} + for _, d := range []string{"a", "b", "c", "d", "e", "f", "g", "h"} { + names = append(names, "usr/share/"+d+"/") + } + return tree(t, names...) } // A walk ended while it pauses is an incomplete walk, never one that found nothing. func TestAWalkEndedWhileItPausesIsIncomplete(t *testing.T) { - top := tree(t, "bin/", "bin/su!") - f := &fakePace{readings: []float64{80}, clock: time.Unix(1_000_000, 0)} + top := many(t) + f := newFake(80) + f.tick = 100 * time.Millisecond ctx, cancel := context.WithCancel(t.Context()) defer cancel() pc := f.pacer() @@ -138,8 +241,7 @@ func TestAWalkEndedWhileItPausesIsIncomplete(t *testing.T) { } w := mine() w.pace = pc - p := &SetuidProgress{Mounts: []string{top}} - err := w.walk(ctx, p, func() {}) + err := w.walk(ctx, &SetuidProgress{Mounts: []string{top}}, func() {}) if len(f.slept) == 0 { t.Fatal("the walk never paused, so this proves nothing about a walk ended while it pauses") } @@ -150,10 +252,11 @@ func TestAWalkEndedWhileItPausesIsIncomplete(t *testing.T) { // Paced, the walk finds what it finds unpaced: pausing changes when, never what. func TestAPacedWalkFindsWhatAnUnpacedWalkFinds(t *testing.T) { - top := tree(t, "bin/", "bin/su!", "bin/ls", "sbin/", "sbin/mount!", "usr/", "usr/lib/", "usr/lib/helper%") + top := many(t) plain := walkAll(t, mine(), top) - f := &fakePace{readings: []float64{50, 2}, clock: time.Unix(1_000_000, 0)} + f := newFake(80, 2) + f.tick = 100 * time.Millisecond w := mine() w.pace = f.pacer() paced := walkAll(t, w, top) @@ -166,13 +269,13 @@ func TestAPacedWalkFindsWhatAnUnpacedWalkFinds(t *testing.T) { } func TestTheIOPressureIsReadAsTheKernelWritesIt(t *testing.T) { - got, err := parseIOPressure([]byte("some avg10=26.24 avg60=20.07 avg300=27.47 total=123456789\n" + + got, err := parseIOStalled([]byte("some avg10=26.24 avg60=20.07 avg300=27.47 total=123456789\n" + "full avg10=21.90 avg60=15.77 avg300=22.47 total=98765432\n")) - if err != nil || got != 26.24 { - t.Fatalf("read %v, %v; want 26.24", got, err) + if err != nil || got != 123456789*time.Microsecond { + t.Fatalf("read %v, %v; want 123456789 µs", got, err) } - for _, bad := range []string{"", "full avg10=1.00 avg60=0 avg300=0 total=0\n", "some avg10=x avg60=0\n"} { - if _, err := parseIOPressure([]byte(bad)); err == nil { + for _, bad := range []string{"", "full avg10=1.00 avg60=0 avg300=0 total=1\n", "some avg10=1 total=x\n"} { + if _, err := parseIOStalled([]byte(bad)); err == nil { t.Errorf("%q was read as a pressure", bad) } } diff --git a/internal/accounts/ways.go b/internal/accounts/ways.go index 372442d..5e6f912 100644 --- a/internal/accounts/ways.go +++ b/internal/accounts/ways.go @@ -426,7 +426,11 @@ func contains(xs []string, s string) bool { func (e Exec) setuidSearch(ctx context.Context, p *SetuidProgress, checkpoint func(), mountPoints map[string]bool) ([]string, error) { walk := e.Walk if walk == nil { - walk = walker{every: CheckpointEvery, mountPoints: mountPoints, pace: newPacer()}.walk + var say func(string) + if e.Cache != nil { + say = e.Cache.Say + } + walk = engineWalker(mountPoints, say).walk } if err := walk(ctx, p, checkpoint); err != nil { return nil, fmt.Errorf("the walk for setuid programs did not complete: %w", err) @@ -439,6 +443,12 @@ func (e Exec) setuidSearch(ctx context.Context, p *SetuidProgress, checkpoint fu return e.unpackaged(ctx, slices.Compact(found)) } +// engineWalker is the walk the engine runs: checkpointed every CheckpointEvery, leaving other filesystems unread, +// and paced by the machine's I/O pressure (setuid_pace.go, novox/hq issue 433), saying through say what it cannot do. +func engineWalker(mountPoints map[string]bool, say func(string)) walker { + return walker{every: CheckpointEvery, mountPoints: mountPoints, pace: newPacer(say)} +} + // errorLines are the lines a command said on its error stream, as the runner words a failure: " exited N: // ", the prefix taken off the first line. Empty lines are dropped. func errorLines(err error, name string) []string { From f311fa36dc49c1e65460c439e4480f68ae161375 Mon Sep 17 00:00:00 2001 From: jochen Date: Sun, 11 Oct 2026 01:55:39 +0200 Subject: [PATCH 3/3] The setuid walk is paced before each file too, so a large directory is not read blind (review of issue 433) A file's own details (lstat) may be read from the disk as a directory is, so a directory of tens of thousands of files was read without a look and the header's promise that no burst is longer than PaceLook did not hold. The walk now asks the pacer before each file as well; the 250 ms gate makes that a clock read per file. A test with one directory of twenty files fails without it. The clock is read once after a run of pauses, and the constants test says that it guards the constants only. --- internal/accounts/setuid_pace.go | 6 ++++-- internal/accounts/setuid_pace_test.go | 22 +++++++++++++++++++++- internal/accounts/setuid_walk.go | 4 ++++ 3 files changed, 29 insertions(+), 3 deletions(-) diff --git a/internal/accounts/setuid_pace.go b/internal/accounts/setuid_pace.go index a6273ea..9cb23d2 100644 --- a/internal/accounts/setuid_pace.go +++ b/internal/accounts/setuid_pace.go @@ -1,6 +1,7 @@ package accounts -// The walk for setuid programs yields to a busy disk (novox/hq issue 433). The walk is put in the idle I/O class +// The walk for setuid programs yields to a busy disk (novox/hq issue 433). It asks before each directory and each +// file it reads, so no burst between two looks is longer than PaceLook, however large a directory. The walk is put in the idle I/O class // (idle_linux.go), but only a disk scheduler that schedules by class honours that (BFQ does). The control-node's // disks run mq-deadline, which does not, and there the walk read at full priority: on 2026-10-11 it kept two // spinning disks saturated for sixteen minutes, the bus whose store shares those disks stalled for half a minute @@ -105,7 +106,8 @@ func (pc *pacer) yield(ctx context.Context) error { break } } - pc.readSince, pc.lastLook = pc.now(), pc.now() + resumed := pc.now() + pc.readSince, pc.lastLook = resumed, resumed return nil } diff --git a/internal/accounts/setuid_pace_test.go b/internal/accounts/setuid_pace_test.go index dd7c0a0..5d117ef 100644 --- a/internal/accounts/setuid_pace_test.go +++ b/internal/accounts/setuid_pace_test.go @@ -138,7 +138,8 @@ func TestTheWalkKeepsATenthOfTheTimeWhateverThePressure(t *testing.T) { // What the floor promises against the ages a search is judged by: the walk that took 16m31s unpaced on the // control-node on 2026-10-11, slowed to its worst, still completes well inside the time the controller stays quiet -// while it waits for a search, and so judges for most of its fresh age. +// while it waits for a search. A guard on the constants only: that the code keeps to the ratio is proven by +// TestTheWalkKeepsATenthOfTheTimeWhateverThePressure. func TestTheSlowestPacedWalkStillJudgesInTime(t *testing.T) { const unpaced = 16*time.Minute + 31*time.Second worst := (1 + PaceRatio) * unpaced @@ -280,3 +281,22 @@ func TestTheIOPressureIsReadAsTheKernelWritesIt(t *testing.T) { } } } + +// One directory of many files is paced as it is read, not only between directories: a file's own details may be +// read from the disk too. +func TestADirectoryOfManyFilesIsPacedAsItIsRead(t *testing.T) { + names := []string{"bin/"} + for i := range 20 { + names = append(names, "bin/f"+strings.Repeat("x", i+1)) + } + top := tree(t, names...) + f := newFake(80, 2) + f.tick = 100 * time.Millisecond + w := mine() + w.pace = f.pacer() + walkAll(t, w, top) + // Two directories alone would be looked at once, 200 ms apart, within one look: no pause at all. + if len(f.slept) == 0 { + t.Fatal("a directory of twenty files was read without a pause under pressure") + } +} diff --git a/internal/accounts/setuid_walk.go b/internal/accounts/setuid_walk.go index 236ddb8..dac285a 100644 --- a/internal/accounts/setuid_walk.go +++ b/internal/accounts/setuid_walk.go @@ -239,6 +239,10 @@ func (w walker) walkMount(ctx context.Context, p *SetuidProgress, mount string, return err } case d.Type().IsRegular(): + // A file's own details may be read from the disk too: a directory of many files is paced as it is read. + if err := w.pace.yield(ctx); err != nil { + return err + } info, err := d.Info() // the entry's own, never through a link if errors.Is(err, fs.ErrNotExist) { return nil