utils/exit_clock_linux_test.go
Rama main · réplica de lectura del repositorio original.
//go:build linux
package utils
import (
"fmt"
"maps"
"math"
"math/rand"
"os"
"os/exec"
"path/filepath"
"slices"
"strconv"
"strings"
"sync/atomic"
"syscall"
"testing"
"time"
"go.keploy.io/server/v3/internal/starvetest"
"go.keploy.io/server/v3/utils/stall"
"golang.org/x/sys/unix"
)
// clockRig is an ExitClock on a wall clock and a keploy runnable clock the
// test moves, reading thread accounts and block devices the test sets.
type clockRig struct {
wall time.Time
own *stall.ManualClock
tasks map[int]taskTime
ok bool
disks diskMark
disksOK bool
// below is, by device name, the devices directly below it; belowRead
// counts the reads of it.
below map[string][]string
belowRead map[string]int
// readTakes is how long a read of the threads' accounts takes: the
// wall clock moves on by it as they are read, as it does for a keploy
// held off the CPU between reading the wall clock and reading them.
readTakes time.Duration
c *ExitClock
last time.Duration
}
func newClockRig(tasks map[int]taskTime) *clockRig {
return newClockRigOf(tasks, time.Hour, diskMark{"259:0": {}})
}
// newClockRigOf is a clockRig of a stop that judges on bound, which takes a
// thread standing in the kernel for that long for wedged, the host's block
// devices first read as disks.
func newClockRigOf(tasks map[int]taskTime, bound time.Duration, disks diskMark) *clockRig {
return newClockRigWedged(tasks, bound, bound, disks)
}
// newClockRigWedged is newClockRigOf, taking a thread standing in the kernel
// for wedge for wedged. Its credit of the waits in the kernel in all is far
// beyond what its tests look at, so they pin the rules of one stretch; a
// stop's is wedge (newClockRigCredited).
func newClockRigWedged(tasks map[int]taskTime, bound, wedge time.Duration, disks diskMark) *clockRig {
return newClockRigCredited(tasks, bound, wedge, time.Hour, disks)
}
// newClockRigCredited is newClockRigWedged, crediting the waits in the
// kernel, since the processes' last progress, for credit in all.
func newClockRigCredited(tasks map[int]taskTime, bound, wedge, credit time.Duration, disks diskMark) *clockRig {
r := &clockRig{wall: time.Unix(1000, 0), own: &stall.ManualClock{}, tasks: tasks, ok: true,
disks: disks, disksOK: true, below: map[string][]string{}, belowRead: map[string]int{}}
r.c = newExitClock(nil, bound, wedge, credit, r.own, func() time.Time { return r.wall },
func([]Reached) (map[int]taskTime, bool) {
r.wall = r.wall.Add(r.readTakes)
return maps.Clone(r.tasks), r.ok
},
func() (diskMark, bool) { return maps.Clone(r.disks), r.disksOK },
func(name string) []string { r.belowRead[name]++; return r.below[name] })
return r
}
// serves makes the host's disk serve I/O for d of the next look: it
// completes I/O, and has I/O in flight for d.
func (r *clockRig) serves(d time.Duration) {
n := r.disks["259:0"]
n.done++
n.busy += d
r.disks["259:0"] = n
}
// look moves wall time by w and keploy's runnable time by own, lets step
// change the threads' accounts, and returns what the clock added.
func (r *clockRig) look(w, own time.Duration, step func(map[int]taskTime)) time.Duration {
r.wall = r.wall.Add(w)
r.own.Advance(own)
if step != nil {
step(r.tasks)
}
now := r.c.Runnable()
added := now - r.last
r.last = now
return added
}
// adds changes thread tid's account by ran, waited and slices, and sets
// whether it is runnable.
func adds(tid int, ran, waited time.Duration, slices uint64, runnable bool) func(map[int]taskTime) {
return func(m map[int]taskTime) {
t := m[tid]
t.ran += ran
t.waited += waited
t.slices += slices
t.runnable = runnable
m[tid] = t
}
}
// A stop's stall is counted only in the time the stopped processes could run
// (and keploy with them): w less the time their threads waited for a CPU, and
// never less than the CPU they had. A wait still going on, which the kernel
// adds to a thread's account only once it ends, is counted as it goes, and
// not again when it ends.
func TestTheExitClockCountsOnlyTheTimeTheProcessesCouldRun(t *testing.T) {
const w = 100 * time.Millisecond
ms := time.Millisecond
t.Run("a thread that sleeps could run all of it", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {ran: ms, slices: 3}})
for i := range 5 {
if got := r.look(w, w, nil); got != w {
t.Fatalf("look %d added %v, want %v", i, got, w)
}
}
})
t.Run("a thread held off the CPU throughout could run none of it", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {ran: ms, slices: 3, runnable: true}})
for i := range 5 {
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("look %d added %v of a thread waiting for a CPU since before it, want none", i, got)
}
}
// Its wait ends 90 ms into the next look, and it runs 10 ms: the
// kernel adds all 590 ms of that wait now, of which 500 were counted.
if got := r.look(w, w, adds(1, 10*ms, 590*ms, 1, true)); got != 10*ms {
t.Fatalf("the look its wait ended in added %v, want the 10ms it ran", got)
}
// Waiting again, from before this look: none.
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("a thread waiting again added %v, want none", got)
}
})
t.Run("a wait counted as it went is not counted again when it ends", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {slices: 3, runnable: true}})
for range 5 {
r.look(w, w, nil)
}
// Its 510 ms wait ends 10 ms into the look; it runs 1 ms, and then
// sleeps on its own: it could run the 90 ms after its wait.
if got := r.look(w, w, adds(1, ms, 510*ms, 1, false)); got != 90*ms {
t.Fatalf("the look its wait ended in added %v, want 90ms", got)
}
// A later wait, begun and ended within a look (80 ms, then 20 ms
// run): all of it is new, none of the first is taken off it.
if got := r.look(w, w, adds(1, 20*ms, 80*ms, 1, false)); got != 20*ms {
t.Fatalf("a later wait's look added %v, want 20ms", got)
}
})
t.Run("a thread runnable at a look is taken to have waited for a CPU all of it that it did not run", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {slices: 3}})
// Asleep at the last look, woken since, and waiting for a CPU now:
// when it woke is not known, so all of the look is taken for its
// wait.
if got := r.look(w, w, adds(1, 0, 0, 0, true)); got != 0 {
t.Fatalf("added %v of a thread waiting for a CPU at the look, want none", got)
}
// Still waiting at the next look, given no CPU since: all of it.
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("added %v of a thread waiting since the last look, want none", got)
}
})
t.Run("a thread given the CPU since the last look and waiting for it again could run only what it ran", func(t *testing.T) {
// Waiting for a CPU from the first look on: its wait ends 40 ms
// into the next, it runs 5 ms, and waits again, through the look.
// The kernel books that wait only once it ends.
r := newClockRig(map[int]taskTime{1: {slices: 3, runnable: true}})
if got := r.look(w, w, adds(1, 5*ms, 40*ms, 1, true)); got != 5*ms {
t.Fatalf("the look it ran in added %v, want the 5ms it ran", got)
}
for i := range 3 {
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("look %d added %v of a thread still waiting, want none", i, got)
}
}
// That wait ends 40 ms into a look, 395 ms long; it runs 5 ms, and
// waits again: what of the wait was counted is not counted again.
if got := r.look(w, w, adds(1, 5*ms, 395*ms, 1, true)); got != 5*ms {
t.Fatalf("the next look it ran in added %v, want the 5ms it ran", got)
}
// It ends 30 ms into the next, 85 ms long, and it runs 5 ms and
// sleeps on its own: it could run the 70 ms after its wait.
if got := r.look(w, w, adds(1, 5*ms, 85*ms, 1, false)); got != 70*ms {
t.Fatalf("the look it went to sleep in added %v, want 70ms", got)
}
})
t.Run("a look after a read held up is no longer than the time since that read", func(t *testing.T) {
// A thread spinning on a CPU it shares. keploy, held off the CPU
// between reading the wall clock and reading the thread's account,
// reads it 6 ms late: of the 106 ms since the last read, the thread
// ran 53 and waited 53, given the CPU just then.
r := newClockRig(map[int]taskTime{1: {slices: 1, runnable: true}})
r.readTakes = 6 * ms
got := r.look(w, w, adds(1, 53*ms, 53*ms, 5, true))
r.readTakes = 0
// 94 ms after that read, it ran 47 and waited 47 since, and has
// just gone to sleep: it could run only the 47 ms it ran.
got += r.look(94*ms, w, adds(1, 47*ms, 47*ms, 5, false))
if got != 100*ms {
t.Fatalf("added %v of a thread that ran 100ms and waited 100ms of the 200ms between the reads of it, want the 100ms it ran", got)
}
})
t.Run("a wait counted as it goes past a read held up is counted no longer than it was", func(t *testing.T) {
// The same, read 6 ms late: of the 106 ms since the last read, it
// ran 53 and waited 53, given the CPU just then.
r := newClockRig(map[int]taskTime{1: {slices: 1, runnable: true}})
r.readTakes = 6 * ms
got := r.look(w, w, adds(1, 53*ms, 53*ms, 5, true))
r.readTakes = 0
// 94 ms after that read, it ran 40 and waited 44 since, and has
// waited again for 10 ms, a wait the kernel has not booked yet.
got += r.look(94*ms, w, adds(1, 40*ms, 44*ms, 4, true))
// That wait ends 10 ms into the next look (20 ms long), and the
// thread runs the 90 ms after it and has just gone to sleep: of the
// wait its account books now, the look takes off as counted before
// only the 10 ms the last look counted, not 16: the 6 ms the read
// before it was held up are no wait of the thread's.
got += r.look(w, w, adds(1, 90*ms, 20*ms, 1, false))
if got != 183*ms {
t.Fatalf("added %v of a thread that ran 183ms and never slept, want the 183ms it ran", got)
}
})
t.Run("a look is the least time between the reads of a thread at both looks", func(t *testing.T) {
// Two threads asleep, each read in 1 ms: at the first look from 0
// to 1 ms and from 1 to 2 ms; at the next, held up 6 ms first, from
// 106 to 107 and 107 to 108; at the last, the second held up 5 ms,
// from 200 to 201 and 206 to 207. The look is 105 ms, then 93 ms,
// the least time between a thread's two reads: neither waited at all.
base := time.Unix(1000, 0)
var wall time.Duration
reads := [][2]time.Duration{{0, 0}, {6 * ms, 0}, {0, 5 * ms}}
look := 0
read := func([]Reached) (map[int]taskTime, bool) {
m := map[int]taskTime{}
for i, tid := range []int{1, 2} {
wall += reads[look][i]
from := base.Add(wall)
wall += ms
m[tid] = taskTime{slices: 3, from: from, to: base.Add(wall)}
}
look++
return m, true
}
own := &stall.ManualClock{}
c := newExitClock(nil, time.Hour, time.Hour, time.Hour, own, func() time.Time { return base.Add(wall) }, read,
func() (diskMark, bool) { return nil, false }, nil)
for _, at := range []time.Duration{100 * ms, 200 * ms} {
wall = at
own.Advance(time.Hour)
c.Runnable()
}
if c.ran != 198*ms {
t.Fatalf("counted %v of two threads asleep, want 198ms: the least time between each one's two reads, 105ms and 93ms", c.ran)
}
})
t.Run("the waits a thread's account booked after it was read count in the look", func(t *testing.T) {
// Asleep at the look, it waited 20 ms and ran 10 since the last;
// and as its state was read its account booked 15 ms more.
r := newClockRig(map[int]taskTime{1: {slices: 3}})
got := r.look(w, w, func(m map[int]taskTime) {
adds(1, 10*ms, 20*ms, 1, false)(m)
th := m[1]
th.missed = 15 * ms
m[1] = th
})
if got != 65*ms {
t.Fatalf("added %v, want 65ms: neither the 20ms nor the 15ms it waited", got)
}
})
t.Run("a run a look counted as a thread went to sleep is not counted again", func(t *testing.T) {
// On a CPU since its last tick, 4 ms, as its account is read, and
// asleep as its state is: the look counts all of it as time it
// could run, and its account read again holds those 4 ms.
r := newClockRig(map[int]taskTime{1: {slices: 3}})
got := r.look(w, w, func(m map[int]taskTime) {
adds(1, 10*ms, 20*ms, 1, false)(m)
th := m[1]
th.ranAgain = th.ran + 4*ms
m[1] = th
})
if got != 80*ms {
t.Fatalf("the look it went to sleep in added %v, want the 80ms it did not wait", got)
}
// Waiting for a CPU since, given none: its account books the 4 ms
// now, which are no part of this look.
got = r.look(w, w, func(m map[int]taskTime) {
adds(1, 4*ms, 0, 0, true)(m)
th := m[1]
th.ranAgain = 0
m[1] = th
})
if got != 0 {
t.Fatalf("the look after added %v of a thread waiting for a CPU throughout, want none", got)
}
})
t.Run("a look takes no read times it cannot vouch for", func(t *testing.T) {
// Two threads asleep, each read in 1 ms, at four looks. At the
// second, 100 ms on and held up 6 ms first, the second thread's
// read is not timed: the first's alone makes the look, 106 - 1. At
// the third, 200 ms on, the first is held up 4 ms and its id names
// another thread now (its account below the last), and the second
// was not timed at the last look: none makes it, so it is from the
// end of the last read of them all to the start of this one, 200 -
// 107. At the fourth, 300 ms on, the first's read is timed at 250
// ms, before the look began: not taken; the second's makes it, 300
// - 206.
base := time.Unix(1000, 0)
var wall time.Duration
at := func(d time.Duration) time.Time { return base.Add(d) }
look := 0
read := func([]Reached) (map[int]taskTime, bool) {
one, two := taskTime{ran: 9, slices: 3}, taskTime{slices: 3}
switch look {
case 0:
one.from, one.to, two.from, two.to = at(0), at(ms), at(ms), at(2*ms)
wall = 2 * ms
case 1:
one.from, one.to = at(106*ms), at(107*ms)
wall = 107 * ms
case 2:
one.ran = 1
one.from, one.to, two.from, two.to = at(204*ms), at(205*ms), at(205*ms), at(206*ms)
wall = 206 * ms
case 3:
one.ran = 1
one.from, one.to, two.from, two.to = at(250*ms), at(251*ms), at(300*ms), at(301*ms)
wall = 301 * ms
}
look++
return map[int]taskTime{1: one, 2: two}, true
}
own := &stall.ManualClock{}
c := newExitClock(nil, time.Hour, time.Hour, time.Hour, own, func() time.Time { return base.Add(wall) }, read,
func() (diskMark, bool) { return nil, false }, nil)
for _, start := range []time.Duration{100 * ms, 200 * ms, 300 * ms} {
wall = start
own.Advance(time.Hour)
c.Runnable()
}
if want := (106-1)*ms + (200-107)*ms + (300-206)*ms; c.ran != want {
t.Fatalf("counted %v of two threads asleep, want %v", c.ran, want)
}
})
t.Run("a stall started again counts no sleep taken for a wait before it", func(t *testing.T) {
// Asleep for 95 ms of a look, then woken and waiting for a CPU: all
// of the look is taken for its wait. The processes make progress
// there, and the stall starts again.
r := newClockRig(map[int]taskTime{1: {slices: 3}})
m := newExitMeter(r.c, time.Hour)
m.Advance(ExitMark{Running: 2})
r.look(w, w, adds(1, 0, 0, 0, true))
if !m.Advance(ExitMark{Running: 1}) {
t.Fatal("a process gone was no progress")
}
// Its 10 ms wait ends 5 ms into the next look; it runs 5 ms and
// sleeps the 90 ms left: it could run 95 ms of it. Of its wait, the
// 5 ms before the stall began count in it too, as a wait.
r.look(w, w, adds(1, 5*ms, 10*ms, 1, false))
if got := m.Stalled(); got != 90*ms {
t.Fatalf("the stall counted %v of a thread that could run 95ms of it, want 90ms: none of its sleep before the stall began", got)
}
})
t.Run("a stop's first stall counts no sleep taken for a wait before it", func(t *testing.T) {
// Asleep at the clock's first look; 2 ms on, as the stop's meter is
// made, woken and waiting for a CPU: both are taken for its wait.
r := newClockRig(map[int]taskTime{1: {slices: 3}})
r.wall = r.wall.Add(2 * ms)
r.own.Advance(2 * ms)
adds(1, 0, 0, 0, true)(r.tasks)
m := newExitMeter(r.c, time.Hour)
// Its 2 ms wait ends; it runs 4 ms and sleeps 95: it could run 99
// ms of the look. Of its wait, the 1 ms before the stall began
// counts in it too, as a wait.
r.look(w, w, adds(1, 4*ms, 2*ms, 1, false))
if got := m.Stalled(); got != 98*ms {
t.Fatalf("the first stall counted %v of a thread that could run 99ms of it, want 98ms: none of its sleep before the stall began", got)
}
})
t.Run("a thread on a loaded host could run what it did not wait", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {}})
for i := range 5 {
if got := r.look(w, w, adds(1, 10*ms, 90*ms, 5, i%2 == 0)); got != 10*ms {
t.Fatalf("look %d added %v, want 10ms", i, got)
}
}
})
t.Run("a thread spinning on a quarter of a CPU could run a quarter", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {runnable: true}})
for i := range 5 {
if got := r.look(w, w, adds(1, 25*ms, 75*ms, 10, true)); got != 25*ms {
t.Fatalf("look %d added %v, want 25ms", i, got)
}
}
})
t.Run("eight threads each on a quarter of a CPU could run all of it", func(t *testing.T) {
r := newClockRig(map[int]taskTime{})
for tid := range 8 {
r.tasks[tid] = taskTime{runnable: true}
}
for i := range 5 {
got := r.look(w, w, func(m map[int]taskTime) {
for tid := range 8 {
adds(tid, 25*ms, 75*ms, 10, true)(m)
}
})
if got != w {
t.Fatalf("look %d added %v, want %v: they had two CPUs' worth", i, got, w)
}
}
// keploy's clock, sampled, may catch up more than w between two
// looks: the processes still could run no more than w of it.
got := r.look(w, w+50*ms, func(m map[int]taskTime) {
for tid := range 8 {
adds(tid, 25*ms, 75*ms, 10, true)(m)
}
})
if got != w {
t.Fatalf("a look keploy's clock caught up in added %v, want %v", got, w)
}
})
t.Run("a thread alone on a CPU, running throughout, could run all of it", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {slices: 1, runnable: true}})
for i := range 5 {
if got := r.look(w, w, adds(1, w, 0, 0, true)); got != w {
t.Fatalf("look %d added %v, want %v", i, got, w)
}
}
})
t.Run("one of the processes held off the CPU holds the stall of all", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {}, 2: {runnable: true}})
for i := range 5 {
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("look %d added %v, want none while thread 2 waits", i, got)
}
}
})
t.Run("keploy held off the CPU counts none of it", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {}})
if got := r.look(w, 0, nil); got != 0 {
t.Fatalf("added %v while keploy could not run, want none", got)
}
if got := r.look(w, 30*ms, nil); got != 30*ms {
t.Fatalf("added %v while keploy could run 30ms, want that", got)
}
})
t.Run("with no account of the processes it is keploy's runnable time", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {runnable: true}})
r.ok = false
if got := r.look(w, 70*ms, nil); got != 70*ms {
t.Fatalf("added %v, want keploy's 70ms", got)
}
// Keploy's clock read over a longer span than the look's: no more
// than the look.
if got := r.look(w, 2*w, nil); got != w {
t.Fatalf("added %v with keploy's clock %v on, want no more than the look's %v", got, 2*w, w)
}
})
t.Run("a look that read nothing sets the next one's account against none", func(t *testing.T) {
// A thread a second old, asleep; one look reads nothing.
r := newClockRig(map[int]taskTime{1: {slices: 3, age: 10 * w}})
r.ok = false
if got := r.look(w, w, nil); got != w {
t.Fatalf("the look that read nothing added %v, want keploy's %v", got, w)
}
// Read again: across both looks it ran 150 ms, and waited 50 ms
// for a CPU, all of it in this one. Set against the account read
// before the look that read nothing, the 150 ms would fill this
// look; of the CPU it had since, this look holds none it cannot
// have had before, and it waited 50 ms of it.
r.ok = true
if got := r.look(w, w, adds(1, 150*ms, 50*ms, 2, false)); got != 50*ms {
t.Fatalf("the look after one that read nothing added %v, want the 50ms it did not wait", got)
}
})
t.Run("a thread new since the last look counts its whole account", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {}})
if got := r.look(w, w, func(m map[int]taskTime) { m[2] = taskTime{waited: w, slices: 1} }); got != 0 {
t.Fatalf("a new thread that waited all of it left %v, want none", got)
}
// A thread id given to another meanwhile: its account is below the
// last, and counts whole.
if got := r.look(w, w, func(m map[int]taskTime) { m[2] = taskTime{ran: 40 * ms, waited: 60 * ms, slices: 1} }); got != 40*ms {
t.Fatalf("a thread id given to another added %v, want the 40ms it ran", got)
}
// A thread new since the last look and waiting for a CPU at this
// one, its age not known: all of the look it did not run is taken
// for its wait.
if got := r.look(w, w, func(m map[int]taskTime) { m[3] = taskTime{ran: 10 * ms, waited: 30 * ms, slices: 1, runnable: true} }); got != 10*ms {
t.Fatalf("a new thread waiting for a CPU added %v, want the 10ms it ran", got)
}
// Its id given to another, which waited 20 ms, ran 5 and sleeps:
// what was counted of the first one's wait is not the second's.
if got := r.look(w, w, func(m map[int]taskTime) { m[3] = taskTime{ran: 5 * ms, waited: 20 * ms, slices: 1} }); got != 80*ms {
t.Fatalf("a thread id given to another after a wait added %v, want the 80ms after its wait", got)
}
})
t.Run("a thread new since the last look waited for a CPU no longer than it lived", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {slices: 3}})
// Started 12 ms before the look (a shell's child, at its exec), it
// ran 2 ms and waits for a CPU: it waited 10 ms at most.
if got := r.look(w, w, func(m map[int]taskTime) {
m[2] = taskTime{ran: 2 * ms, waited: ms, slices: 1, runnable: true, age: 12 * ms}
}); got != 90*ms {
t.Fatalf("a thread 12ms old, waiting for a CPU, added %v, want 90ms", got)
}
// That one gone, another new to the look but older than it (a
// thread of a process the stop reads from now on), waiting for a
// CPU: the 2 ms it ran in its life may all have been before the
// look, which holds all of the look for its wait.
if got := r.look(w, w, func(m map[int]taskTime) {
delete(m, 2)
m[3] = taskTime{ran: 2 * ms, slices: 1, runnable: true, age: 3 * w}
}); got != 0 {
t.Fatalf("a thread new to the look, older than it, waiting for a CPU, added %v, want none", got)
}
// Its wait ends 40 ms into the next look, 240 ms long: it may have
// begun before the first look, of which no more than the look was
// counted. It runs 5 ms and sleeps: the rest of that wait is taken
// off this look.
if got := r.look(w, w, adds(3, 5*ms, 240*ms, 1, false)); got != 5*ms {
t.Fatalf("the look the wait of a thread older than the look it was new to ended in added %v, want the 5ms it ran", got)
}
})
t.Run("a thread new to the look but older than it ran in it no more than it cannot have run before", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {slices: 3}})
// 300 ms old, 250 ms on a CPU in its life, waiting for one now:
// at least 50 of those in the look, and the rest of it a wait.
if got := r.look(w, w, func(m map[int]taskTime) {
m[2] = taskTime{ran: 250 * ms, waited: 40 * ms, slices: 9, runnable: true, age: 3 * w}
}); got != 50*ms {
t.Fatalf("a thread 300ms old with 250ms on a CPU added %v, want the 50ms of it the look holds", got)
}
// Asleep, the same: the 250 ms may have been before the look but
// for 50, and its 40 ms of waits all in it.
r = newClockRig(map[int]taskTime{1: {slices: 3}})
if got := r.look(w, w, func(m map[int]taskTime) {
m[2] = taskTime{ran: 250 * ms, waited: 40 * ms, slices: 9, age: 3 * w}
}); got != 60*ms {
t.Fatalf("a sleeping thread 300ms old with 250ms on a CPU added %v, want the 60ms it did not wait", got)
}
})
}
// However late keploy reads a thread's account after the wall time it read
// before it, and however long the read takes, the clock counts no more of the
// time than the thread could run, from its first look or from any start of a
// stall (ExitMeter.Reset). Of a thousand random timelines of a thread taking
// turns on a CPU it shares, and now and then asleep, each read 41 times (at
// the clock's start, then at 40 looks), the read held up before and after it
// by as much as 8 ms one time in ten and inside it by as much as 3 ms one
// time in twenty, timed, or not, for the thread alone, and its state read
// after its account (and its account again after that, where its state shows
// it not runnable), each held up as much, the clock counted none more than
// the thread ran and slept from the read at the start, or a stall's start, to
// the read at any look after, but for what it ran before that read that the
// kernel booked only after it (the run since the last scheduler tick: a tick
// at most). Measured from the wall time before one read to the wall time
// before the next, with what it counted of the waits as they went kept across
// a stall's start, and no account read again after the state (the clock
// before), the clock counted 158 of them more from its start, by up to 10.1
// ms, and 262 from its start or a stall's, by up to 13.3 ms; with that count
// kept alone, 67 from a stall's start, by up to 8.6 ms; with no account read
// again alone, 6, by up to 4.8 ms.
func TestTheExitClockCountsNoMoreThanAThreadCouldRunHoweverLateItsReadsCome(t *testing.T) {
rng := rand.New(rand.NewSource(1))
held := func(n int, most time.Duration) time.Duration {
if rng.Intn(n) == 0 {
return time.Duration(rng.Int63n(int64(most)))
}
return time.Duration(rng.Intn(20)) * time.Microsecond
}
for trial := range 1000 {
life := randomTimeline(rng, 2*time.Second)
timed := rng.Intn(2) == 0
base := time.Unix(1000, 0)
var wall, at, sinceTick time.Duration
read := func([]Reached) (map[int]taskTime, bool) {
wall += held(10, 8*time.Millisecond)
from := wall
wall += held(20, 3*time.Millisecond)
at = wall
tt, lag := life.account(at)
sinceTick = lag
wall += held(20, 3*time.Millisecond)
to := wall
// Its state, read after its account, and where that shows it
// not runnable, its account again after that (readTaskTimesIn).
wall += held(20, 3*time.Millisecond)
state, _ := life.account(wall)
tt.runnable = state.runnable
if !tt.runnable {
wall += held(20, 3*time.Millisecond)
if again, _ := life.account(wall); again.ran != tt.ran || again.waited != tt.waited || again.slices != tt.slices {
tt.missed = max(again.waited-tt.waited, 0)
tt.turned = again.slices != tt.slices
tt.ranAgain = again.ran
}
}
if timed {
tt.from, tt.to = base.Add(from), base.Add(to)
}
wall += held(10, 8*time.Millisecond)
return map[int]taskTime{1: tt}, true
}
own := &stall.ManualClock{}
c := newExitClock(nil, time.Hour, time.Hour, time.Hour, own, func() time.Time { return base.Add(wall) }, read,
func() (diskMark, bool) { return nil, false }, nil)
// The stall's starts: the clock's, and those after a look the test
// starts it again at (as ExitMeter.Reset does), each with its count
// so far, the moment its read took the account, and the run it held
// that the kernel booked only after.
type start struct {
ran, at, sinceTick time.Duration
}
starts := []start{{c.ran, at, sinceTick}}
for range 40 {
wall += time.Duration(rng.Intn(25000)+500) * time.Microsecond
own.Advance(time.Hour)
c.Runnable()
for _, st := range starts {
if counted, could := c.ran-st.ran, life.could(st.at, at)+st.sinceTick; counted > could {
t.Fatalf("timeline %d (reads timed: %v): from %v to %v the clock counted %v, more than the %v the thread could run", trial, timed, st.at, at, counted, could)
}
}
if rng.Intn(8) == 0 {
c.restarted()
starts = append(starts, start{c.ran, at, sinceTick})
}
}
}
}
// timeline is a thread's life as spans in which it is on a CPU ('R'),
// waiting for one ('W'), or asleep ('S').
type timeline []lifeSpan
// lifeSpan is a span of a thread's life (timeline).
type lifeSpan struct {
state byte
from, to time.Duration
}
// timelineTick is the scheduler's tick (HZ=250), at which the kernel books a
// thread's time on a CPU so far.
const timelineTick = 4 * time.Millisecond
// randomTimeline is a thread that takes turns on a CPU it shares for d and
// more: turns and waits of up to 6 ms, and after one turn in twenty a sleep
// of up to 3 ms, after which it waits for the CPU or is given it at once.
func randomTimeline(rng *rand.Rand, d time.Duration) timeline {
var l timeline
state := byte('R')
for at := time.Duration(0); at < d+time.Second; {
n := 6000
if state == 'S' {
n = 3000
}
to := at + time.Duration(rng.Intn(n)+1)*time.Microsecond
l = append(l, lifeSpan{state, at, to})
at = to
switch {
case state == 'R' && rng.Intn(20) == 0:
state = 'S'
case state == 'R':
state = 'W'
case state == 'W' || rng.Intn(2) == 0:
state = 'R'
default:
state = 'W'
}
}
return l
}
// account is the kernel's account of the thread at t: each wait booked once
// it ends, as the thread is given the CPU, and its time on one at each tick
// and at the end of each turn; and what it has run since the last tick, on a
// CPU at t, that the account does not show yet.
func (l timeline) account(t time.Duration) (tt taskTime, sinceTick time.Duration) {
for _, s := range l {
if s.from >= t {
break
}
if t < s.to {
tt.runnable = s.state != 'S'
}
switch {
case s.state == 'R':
tt.slices++
if s.to <= t {
tt.ran += s.to - s.from
break
}
tick := max(t/timelineTick*timelineTick, s.from)
tt.ran += tick - s.from
sinceTick = t - tick
case s.state == 'W' && s.to <= t:
tt.waited += s.to - s.from
}
}
return tt, sinceTick
}
// could is how long, from a to b, the thread ran or slept.
func (l timeline) could(a, b time.Duration) (d time.Duration) {
for _, s := range l {
if s.state != 'W' {
d += max(min(s.to, b)-max(s.from, a), 0)
}
}
return d
}
// A thread held in the kernel (D) waits for no CPU, and the kernel does not
// say on what it waits. While the host's storage serves I/O, the time it
// served is taken for a wait on it (a disk a loaded host keeps busy serves
// others first); the time storage served nothing counts, as a wait in the
// kernel then is on no storage, and one held there for ever must still let
// the stop go on. So does all of it where a device stood still with I/O in
// flight (dead storage), or where the thread can reach storage the host's
// disks do not show (a network filesystem).
func TestTheExitClockTakesAWaitInTheKernelOnStorageThatServesForAWait(t *testing.T) {
const w = 100 * time.Millisecond
ms := time.Millisecond
held := taskTime{ran: ms, slices: 3, blocked: true, seen: true}
t.Run("held in the kernel while no storage serves, it could run all of it", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: held})
for i := range 5 {
if got := r.look(w, w, nil); got != w {
t.Fatalf("look %d added %v of a thread held in the kernel with storage serving nothing, want %v", i, got, w)
}
}
})
t.Run("held in the kernel while storage serves throughout, it waited all of it", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: held})
for i := range 5 {
r.serves(w)
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("look %d added %v of a thread held in the kernel while storage served throughout, want none", i, got)
}
}
})
t.Run("held in the kernel while storage serves part of it, it could run the rest", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: held})
r.serves(30 * ms)
if got := r.look(w, w, nil); got != 70*ms {
t.Fatalf("added %v with storage serving 30ms of it, want 70ms", got)
}
})
t.Run("of the time it neither ran nor waited for a CPU, what storage served is a wait", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: held})
// It waited 20 ms for a CPU, ran 10 and went into the kernel: of
// the 70 ms left, storage served all.
r.serves(w)
got := r.look(w, w, func(m map[int]taskTime) {
adds(1, 10*ms, 20*ms, 1, false)(m)
th := m[1]
th.blocked, th.seen = true, true
m[1] = th
})
if got != 10*ms {
t.Fatalf("added %v, want the 10ms it ran", got)
}
})
t.Run("a thread new since the last look waited on storage no longer than it lived", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {slices: 3}})
// Started 50 ms before the look, it waited 10 for a CPU, ran 10
// and went into the kernel: of the 30 left, storage served all.
r.serves(w)
if got := r.look(w, w, func(m map[int]taskTime) {
m[2] = taskTime{ran: 10 * ms, waited: 10 * ms, slices: 1, blocked: true, seen: true, age: 50 * ms}
}); got != 60*ms {
t.Fatalf("added %v, want the 50ms before it began and the 10ms it ran", got)
}
})
t.Run("storage that had I/O in flight longer than the look served no more than the look", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: held, 2: {slices: 1}})
r.serves(3 * w)
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("added %v, want none", got)
}
})
// A device standing still: I/O in flight, none completed, its busy
// time not moved (a kernel that moves it only as requests start and
// end shows a device so whose requests outlast the look).
const bound = 3 * w
standing := func() *clockRig {
return newClockRigOf(map[int]taskTime{1: held}, bound, diskMark{"259:0": {}, "8:0": {done: 7, inFlight: 1}})
}
completes := func(r *clockRig, dev string) {
n := r.disks[dev]
n.done++
n.busy += w
r.disks[dev] = n
}
// turn is the held thread's turn on a CPU as its I/O completes, too
// short to count here: its stretch in the kernel ends, so a test of a
// device's stretch is not one of the thread's.
turn := adds(1, 0, 0, 1, false)
t.Run("a device standing still with I/O in flight serves, as a slow one does", func(t *testing.T) {
r := standing()
for i := range 2 {
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("look %d added %v while a device stood still with I/O in flight, want none", i, got)
}
}
})
t.Run("one that stood still for the stall bound of the time at stake is dead, and serves none while it stands, whatever another serves", func(t *testing.T) {
r := standing()
for i, want := range []time.Duration{0, 0, w, w} {
r.serves(w)
if got := r.look(w, w, nil); got != want {
t.Fatalf("look %d of a device standing still added %v, want %v", i, got, want)
}
}
completes(r, "8:0")
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("the look in which it completed I/O added %v, want none", got)
}
})
t.Run("a stretch standing still ends as the device completes I/O", func(t *testing.T) {
r := standing()
for i := range 8 {
var step func(map[int]taskTime)
if i%3 == 2 {
completes(r, "8:0")
step = turn
}
if got := r.look(w, w, step); got != 0 {
t.Fatalf("look %d added %v of a device completing I/O every third look, want none", i, got)
}
}
})
t.Run("a stretch standing still is the device's own", func(t *testing.T) {
r := standing()
r.disks["8:16"] = diskCount{done: 3, inFlight: 1}
r.look(w, w, nil) // both stand: one look of each's stretch
for i := range 8 {
completes(r, []string{"8:0", "8:16"}[i%2])
if got := r.look(w, w, turn); got != 0 {
t.Fatalf("look %d added %v of two devices standing still in turn, want none", i, got)
}
}
})
t.Run("time no thread waits in the kernel is not at stake", func(t *testing.T) {
r := standing()
r.tasks[1] = taskTime{ran: ms, slices: 3, seen: true}
for range 5 {
r.look(w, w, nil)
}
r.tasks[1] = held
for i := range 2 {
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("look %d in the kernel added %v, want none: the device's stretch began with it", i, got)
}
}
})
t.Run("the time at stake is no more than keploy could run", func(t *testing.T) {
r := standing()
for i := range 5 {
if got := r.look(w, w/4, nil); got != 0 {
t.Fatalf("look %d added %v, want none", i, got)
}
}
})
// An encrypted volume (dm-1) on an LVM volume (dm-0) on a partition of
// a disk, which another partition shares.
stacked := func() *clockRig {
r := newClockRigOf(map[int]taskTime{1: held}, bound, diskMark{
"253:1": {name: "dm-1", done: 2, inFlight: 1}, "253:0": {name: "dm-0", done: 5, inFlight: 1},
"259:3": {name: "nvme0n1p3", done: 10, inFlight: 1}, "259:1": {name: "nvme0n1p1"}, "259:0": {name: "nvme0n1", done: 40, inFlight: 1},
})
r.below = map[string][]string{"dm-1": {"dm-0"}, "dm-0": {"nvme0n1p3"}, "nvme0n1p3": {"nvme0n1"}, "nvme0n1p1": {"nvme0n1"}}
return r
}
t.Run("a volume standing still on a disk completing I/O serves, however long it stands", func(t *testing.T) {
r := stacked()
for i := range 12 {
completes(r, "259:0") // the disk, for another partition's I/O
if got := r.look(w, w, turn); got != 0 {
t.Fatalf("look %d added %v while the volumes stood still on a disk completing I/O, want none", i, got)
}
}
for name, n := range r.belowRead {
if n != 1 {
t.Errorf("the devices below %s were read %d times, want once", name, n)
}
}
})
t.Run("a volume standing still on a disk standing still too is dead once they stood still for the bound", func(t *testing.T) {
r := stacked()
for i, want := range []time.Duration{0, 0, w, w} {
if got := r.look(w, w, nil); got != want {
t.Fatalf("look %d of volumes and their disk standing still added %v, want %v", i, got, want)
}
}
})
// A thread held in the kernel at two looks, with no turn on a CPU between
// them (its slices unchanged), stood in the kernel throughout. What it
// waits on the kernel does not say: busy storage serves it at last, but a
// wait on no storage (a lock a wedged driver holds, a frozen cgroup) is
// waited on for ever while the host's storage serves others.
serving := func() *clockRig { return newClockRigOf(map[int]taskTime{1: held}, bound, diskMark{"259:0": {}}) }
t.Run("one that stood in the kernel for the stall bound of the time at stake is wedged, and counts while it stands, whatever storage serves", func(t *testing.T) {
r := serving()
for i, want := range []time.Duration{0, 0, 0, w, w} {
r.serves(w)
if got := r.look(w, w, nil); got != want {
t.Fatalf("look %d of a thread standing in the kernel, storage serving, added %v, want %v", i, got, want)
}
}
// Its turn on a CPU ends the stretch: it ran 1 ms, and the rest of
// the look was a wait on storage that served.
r.serves(w)
if got := r.look(w, w, adds(1, ms, 0, 1, false)); got != ms {
t.Fatalf("the look in which it had a turn on a CPU added %v, want the %v it ran", got, ms)
}
r.serves(w)
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("the look after its turn added %v, want none: its stretch began again", got)
}
})
t.Run("a turn on a CPU as its state is read ends its stretch too", func(t *testing.T) {
// Held in the kernel at each look, its account the same at each,
// but given a CPU as its state was read (turned): it stands in the
// kernel at no look, and storage that serves holds all of it.
r := serving()
for i := range 6 {
r.serves(w)
got := r.look(w, w, func(m map[int]taskTime) {
th := m[1]
th.turned = true
m[1] = th
})
if got != 0 {
t.Fatalf("look %d of a thread given a CPU as its state was read added %v, want none", i, got)
}
}
})
t.Run("a run a look counted as a thread went into the kernel is no time it neither ran nor waited after", func(t *testing.T) {
// On a CPU since its last tick, 4 ms, as its account is read, and
// held in the kernel as its state is, storage serving none of the
// look: the look counts all it did not wait.
r := newClockRig(map[int]taskTime{1: {slices: 3}})
r.look(w, w, func(m map[int]taskTime) {
adds(1, 10*ms, 20*ms, 1, false)(m)
th := m[1]
th.ranAgain, th.blocked, th.seen = th.ran+4*ms, true, true
m[1] = th
})
// Held in the kernel since, storage serving throughout: its
// account books those 4 ms now, which are no part of this look,
// all of which was a wait on storage.
r.serves(w)
got := r.look(w, w, func(m map[int]taskTime) {
adds(1, 4*ms, 0, 0, false)(m)
th := m[1]
th.ranAgain, th.blocked, th.seen = 0, true, true
m[1] = th
})
if got != 0 {
t.Fatalf("the look it was held in the kernel throughout, storage serving, added %v, want none", got)
}
})
t.Run("one is taken for wedged no sooner than the kernel reports a task hung, where that is longer than the bound", func(t *testing.T) {
r := newClockRigWedged(map[int]taskTime{1: held}, bound, 5*w, diskMark{"259:0": {}})
for i, want := range []time.Duration{0, 0, 0, 0, 0, w, w} {
r.serves(w)
if got := r.look(w, w, nil); got != want {
t.Fatalf("look %d of a thread standing in the kernel, storage serving, added %v, want %v", i, got, want)
}
}
})
t.Run("a stretch in the kernel ends as the thread has a turn on a CPU", func(t *testing.T) {
r := serving()
for i := range 12 {
r.serves(w)
step := func(map[int]taskTime) {}
if i%3 == 2 {
step = adds(1, ms, 0, 1, false)
}
if got := r.look(w, w, step); got > ms {
t.Fatalf("look %d added %v of a thread whose waits in the kernel end every third look, want at most the %v it ran", i, got, ms)
}
}
})
t.Run("a stretch in the kernel is the thread's own", func(t *testing.T) {
// Each has a turn every fourth look, one a look after the other:
// each stands for three looks at most, short of a bound of four,
// and at two looks in a row both stand. Taken from the other's
// stretch, each would be taken for wedged there.
r := newClockRigOf(map[int]taskTime{1: held, 2: held}, 4*w, diskMark{"259:0": {}})
for i := range 12 {
r.serves(w)
step := func(map[int]taskTime) {}
if i%4 < 2 {
step = adds(1+i%4, ms, 0, 1, false)
}
if got := r.look(w, w, step); got > ms {
t.Fatalf("look %d added %v of two threads whose waits in the kernel end in turn, want at most the %v one ran", i, got, ms)
}
}
})
t.Run("a stretch in the kernel grows by no more than keploy could run", func(t *testing.T) {
r := serving()
for i := range 8 {
r.serves(w)
if got := r.look(w, w/4, nil); got != 0 {
t.Fatalf("look %d added %v of a thread standing in the kernel for %v of keploy's runnable time, want none", i, got, time.Duration(i+1)*w/4)
}
}
})
t.Run("a stretch in the kernel grows by none while a dead device takes all its time", func(t *testing.T) {
// Two looks served, two with the device under it dead (all of them
// counts already), then it serves again: up to the last look, the
// thread had the stall bound of credit only after the fifth.
r := standing()
for i, want := range []time.Duration{0, 0, w, w} {
r.serves(w)
if got := r.look(w, w, nil); got != want {
t.Fatalf("look %d added %v, want %v", i, got, want)
}
}
completes(r, "8:0")
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("the look in which the device completed I/O added %v, want none", got)
}
completes(r, "8:0")
if got := r.look(w, w, nil); got != w {
t.Fatalf("the look after it had the bound of credit added %v, want %v", got, w)
}
})
t.Run("a thread that went into the kernel on the turn it had at the last look starts its stretch at the next", func(t *testing.T) {
// On a CPU at the last look (runnable), it ran on into the kernel
// on that turn: its slices are unchanged, but it was not held
// there throughout the look. A bound of two and a half looks: the
// look it went in on, counted, would take it there a look sooner.
r := newClockRigOf(map[int]taskTime{1: {ran: ms, slices: 3, runnable: true}}, 5*w/2, diskMark{"259:0": {}})
r.serves(w)
r.look(w, w, func(m map[int]taskTime) {
th := m[1]
th.ran += 10 * ms
th.runnable, th.blocked, th.seen = false, true, true
m[1] = th
})
for i, want := range []time.Duration{0, 0, 0, w} {
r.serves(w)
if got := r.look(w, w, nil); got != want {
t.Fatalf("look %d after it went into the kernel added %v, want %v", i, got, want)
}
}
})
t.Run("a thread new to a look starts no stretch in the kernel", func(t *testing.T) {
r := serving()
for i := range 2 {
r.serves(w)
r.look(w, w, nil)
_ = i
}
// Thread 1 has a turn and stands again; thread 2 is new, and held.
r.serves(w)
r.look(w, w, func(m map[int]taskTime) {
adds(1, 0, 0, 1, false)(m)
m[2] = taskTime{slices: 1, blocked: true, seen: true, age: w}
})
for i := range 3 {
r.serves(w)
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("look %d added %v, want none: neither thread stood for the bound", i, got)
}
}
})
t.Run("one that can reach storage the host's disks do not show is taken to wait on none", func(t *testing.T) {
unseen := held
unseen.seen = false
r := newClockRig(map[int]taskTime{1: unseen})
r.serves(w)
if got := r.look(w, w, nil); got != w {
t.Fatalf("added %v of a thread that can reach a network filesystem, want %v", got, w)
}
})
t.Run("one asleep on its own (S) could run all of it, whatever storage serves", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {ran: ms, slices: 3, seen: true}})
r.serves(w)
if got := r.look(w, w, nil); got != w {
t.Fatalf("added %v of a sleeping thread, want %v", got, w)
}
})
t.Run("a look between reads of the disks of which one read none has storage serving none", func(t *testing.T) {
r := newClockRig(map[int]taskTime{1: held})
r.disksOK = false
r.serves(w)
if got := r.look(w, w, nil); got != w {
t.Fatalf("the look that read no disks added %v, want %v", got, w)
}
r.disksOK = true
r.serves(w)
if got := r.look(w, w, nil); got != w {
t.Fatalf("the look after one that read no disks added %v, want %v", got, w)
}
r.serves(w)
if got := r.look(w, w, nil); got != 0 {
t.Fatalf("a look between two reads of the disks added %v, want none", got)
}
})
}
// A thread whose waits in the kernel each end, making no progress between
// them, has a turn on a CPU between any two, and stands in the kernel for no
// stretch: a wait that ends does not say the next is not the same. Its waits
// there are credited, since the processes' last progress, for no more than
// the kernel's hung-task time of the time at stake in all, the stop's, of
// whichever of their threads; then every thread's time there counts, as
// while storage serves none, until their next progress.
func TestTheExitClockCreditsWaitsInTheKernelForTheHungTaskTimeInAll(t *testing.T) {
const w = 100 * time.Millisecond
const wedge = 3 * w
held := taskTime{ran: time.Millisecond, slices: 3, blocked: true, seen: true}
// A stop's clock: its credit in all is its hung-task time.
stop := func(tasks map[int]taskTime) *clockRig {
return newClockRigCredited(tasks, wedge, wedge, wedge, diskMark{"259:0": {}})
}
// turn is a thread's turn on a CPU between two of its waits in the
// kernel, too short to count here: no stretch of it stands.
turn := func(tid int, blocked bool) func(map[int]taskTime) {
return func(m map[int]taskTime) {
adds(tid, 0, 0, 1, false)(m)
th := m[tid]
th.blocked = blocked
m[tid] = th
}
}
t.Run("waits that each end are credited for the hung-task time, and count after", func(t *testing.T) {
r := stop(map[int]taskTime{1: held})
for i, want := range []time.Duration{0, 0, 0, w, w, w} {
r.serves(w)
if got := r.look(w, w, turn(1, true)); got != want {
t.Fatalf("look %d of a thread in the kernel in turns, storage serving, added %v, want %v", i, got, want)
}
}
})
t.Run("the credit starts again at the processes' progress, and only there", func(t *testing.T) {
r := stop(map[int]taskTime{1: held})
for range 4 {
r.serves(w)
r.look(w, w, turn(1, true))
}
r.c.progressed()
for i, want := range []time.Duration{0, 0, 0, w} {
r.serves(w)
if got := r.look(w, w, turn(1, true)); got != want {
t.Fatalf("look %d after the processes' progress added %v, want %v", i, got, want)
}
}
})
t.Run("the credit is the processes', not one thread's", func(t *testing.T) {
// Each is in the kernel at every other look, asleep (S) between:
// counted by each thread's own waits, each would have the
// hung-task time of credit, twice the stop's.
r := stop(map[int]taskTime{1: held, 2: {ran: time.Millisecond, slices: 3, seen: true}})
for i, want := range []time.Duration{0, 0, 0, w, w, w} {
r.serves(w)
step := func(m map[int]taskTime) { turn(1, i%2 == 1)(m); turn(2, i%2 == 0)(m) }
if got := r.look(w, w, step); got != want {
t.Fatalf("look %d of two threads in the kernel in turns, storage serving, added %v, want %v", i, got, want)
}
}
})
t.Run("the credit is spent by no more than keploy could run", func(t *testing.T) {
r := stop(map[int]taskTime{1: held})
for i := range 12 {
r.serves(w)
if got := r.look(w, w/4, turn(1, true)); got != 0 {
t.Fatalf("look %d added %v, with %v of credit spent, want none", i, got, time.Duration(i)*w/4)
}
}
r.serves(w)
if got := r.look(w, w/4, turn(1, true)); got != w/4 {
t.Fatalf("the look after the credit was spent added %v, want the %v keploy could run", got, w/4)
}
})
t.Run("a keploy held off the CPU spends the credit before the stall", func(t *testing.T) {
// The thread runs 20 ms of each look between its waits in the
// kernel, there for the other 80 ms, its storage serving. Where
// keploy could run less than the thread could, its time is set
// against the thread's waits first: the stall counts only what it
// could run past them while the credit stands, then all of it.
const ran = 20 * time.Millisecond
for _, tc := range []struct {
name string
own, before time.Duration // keploy's time a look; what the stall counts a look while the credit stands
creditLooks int
}{
{"keploy runnable throughout", w, ran, 4},
{"keploy runnable for half of it", w / 2, 0, 6},
{"keploy runnable for a tenth of it", w / 10, 0, 30},
} {
t.Run(tc.name, func(t *testing.T) {
r := stop(map[int]taskTime{1: held})
step := func(m map[int]taskTime) {
adds(1, ran, 0, 1, false)(m)
th := m[1]
th.blocked = true
m[1] = th
}
for i := range tc.creditLooks + 2 {
want := tc.before
if i >= tc.creditLooks {
want = tc.own
}
r.serves(w)
if got := r.look(w, tc.own, step); got != want {
t.Fatalf("look %d, keploy runnable for %v of it, added %v, want %v (credit spent: %v of %v)", i, tc.own, got, want, r.c.credited, wedge)
}
}
})
}
})
t.Run("a thread standing in the kernel spends the credit too", func(t *testing.T) {
// A credit of two looks, short of the hung-task time of three.
r := newClockRigCredited(map[int]taskTime{1: held}, wedge, wedge, 2*w, diskMark{"259:0": {}})
for i, want := range []time.Duration{0, 0, w, w} {
r.serves(w)
if got := r.look(w, w, nil); got != want {
t.Fatalf("look %d of a thread standing in the kernel added %v, want %v", i, got, want)
}
}
})
}
// The kernel reports a task hung once it has stood in an uninterruptible
// sleep, given no CPU, for its hung_task_timeout_secs; where it keeps none,
// or the detector is off (0), its default, two minutes.
func TestTheKernelsHungTaskTimeIsReadAsItWritesIt(t *testing.T) {
dir := t.TempDir()
for _, tc := range []struct {
name, file string
want time.Duration
}{
{"set", "30\n", 30 * time.Second},
{"the default", "120\n", 2 * time.Minute},
{"off", "0\n", hungTaskDefault},
{"not a number", "x\n", hungTaskDefault},
{"longer than a Duration holds", "18446744073709551615\n", time.Duration(math.MaxInt64)},
} {
path := filepath.Join(dir, strings.ReplaceAll(tc.name, " ", "-"))
if err := os.WriteFile(path, []byte(tc.file), 0o644); err != nil {
t.Fatal(err)
}
if got := hungTaskTime(path); got != tc.want {
t.Errorf("%s (%q): %v, want %v", tc.name, tc.file, got, tc.want)
}
}
if got := hungTaskTime(filepath.Join(dir, "none")); got != hungTaskDefault {
t.Errorf("a kernel built without the detector: %v, want %v", got, hungTaskDefault)
}
if hungTaskDefault != 2*time.Minute {
t.Errorf("the kernel's default hung-task time is two minutes, not %v", hungTaskDefault)
}
const host = "/proc/sys/kernel/hung_task_timeout_secs"
if hostStorage.hung == nil {
t.Fatal("a stop reads no hung-task time of this kernel")
}
if got, want := hostStorage.hung(), hungTaskTime(host); got != want {
t.Errorf("a stop reads a hung-task time of %v, want this kernel's %v (%s)", got, want, host)
}
}
// A stop's clock takes a thread standing in the kernel for wedged once it has
// stood there for the kernel's hung-task time, or for the stall bound where
// that is longer.
func TestAStopsClockTakesAThreadForWedgedAtTheKernelsHungTaskTime(t *testing.T) {
for _, tc := range []struct {
name string
hung func() time.Duration
bound, wedge time.Duration
}{
{"hung-task time longer", func() time.Duration { return time.Minute }, time.Second, time.Minute},
{"bound longer", func() time.Duration { return time.Second }, time.Minute, time.Minute},
{"none read", nil, time.Second, time.Second},
} {
st := hostStorage
st.hung = tc.hung
testStorage.Store(&st)
c, release := NewExitClock(nil, tc.bound)
release()
testStorage.Store(nil)
if c.wedge != tc.wedge {
t.Errorf("%s: a thread is taken for wedged after %v, want %v", tc.name, c.wedge, tc.wedge)
}
if c.credit != tc.wedge {
t.Errorf("%s: the waits in the kernel are credited for %v in all, want %v", tc.name, c.credit, tc.wedge)
}
}
}
// A kill names the bound it killed on as the clock measured it: of the time
// both the processes and keploy could run where its last look read their
// account; of keploy's runnable time where it did not.
func TestTheExitClockSaysWhatItMeasured(t *testing.T) {
r := newClockRig(map[int]taskTime{1: {slices: 3}})
if got, want := r.c.Said(time.Minute), "1m0s of its and keploy's runnable time"; got != want {
t.Fatalf("read: said %q, want %q", got, want)
}
r.ok = false
r.look(time.Second, time.Second, nil)
if got, want := r.c.Said(time.Minute), "1m0s of keploy's runnable time"; got != want {
t.Fatalf("not read: said %q, want %q", got, want)
}
}
// Storage served, between two reads of the host's block devices, for the
// longest that a device which completed I/O, or has I/O in flight, had I/O
// in flight, at most the time between the reads; one with I/O in flight at
// both that completed none had it throughout. Those with I/O in flight that
// completed none stood still, but for one stacked on a device that completed
// I/O (a volume, a partition): its I/O is served there.
func TestStorageServedIsTheLongestADeviceServingWasBusy(t *testing.T) {
const w = 100 * time.Millisecond
ms := time.Millisecond
// Every device under each, by name: an encrypted volume (dm-1) on an
// LVM volume (dm-0) on a partition (nvme0n1p3) of a disk.
under := map[string][]string{
"dm-1": {"dm-0", "nvme0n1p3", "nvme0n1"},
"dm-0": {"nvme0n1p3", "nvme0n1"},
"nvme0n1p3": {"nvme0n1"},
}
for _, tc := range []struct {
name string
before, now diskMark
want time.Duration
still []string
}{
{"none read", diskMark{}, diskMark{}, 0, nil},
{"idle", diskMark{"8:0": {done: 5}}, diskMark{"8:0": {done: 5}}, 0, nil},
{"given I/O since, completing none yet", diskMark{"8:0": {done: 5}}, diskMark{"8:0": {done: 5, inFlight: 2, busy: 40 * ms}}, 40 * ms, []string{"8:0"}},
{"completing I/O", diskMark{"8:0": {done: 5, busy: 10 * ms}}, diskMark{"8:0": {done: 9, busy: 70 * ms}}, 60 * ms, nil},
{"the longest of two", diskMark{"8:0": {done: 5}, "8:1": {done: 5}}, diskMark{"8:0": {done: 6, busy: 20 * ms}, "8:1": {done: 7, busy: 50 * ms}}, 50 * ms, nil},
{"no more than the time between", diskMark{"8:0": {done: 5}}, diskMark{"8:0": {done: 6, busy: 3 * w}}, w, nil},
{"a device new since", diskMark{}, diskMark{"8:0": {done: 6, busy: 50 * ms}}, 0, nil},
{"one standing still with I/O in flight, its busy time not moved", diskMark{"8:0": {done: 5}, "8:16": {done: 3, inFlight: 1, busy: ms}}, diskMark{"8:0": {done: 6, busy: 50 * ms}, "8:16": {done: 3, inFlight: 1, busy: ms}}, w, []string{"8:16"}},
{"one that drained its I/O", diskMark{"8:0": {done: 5}, "8:16": {done: 3, inFlight: 1}}, diskMark{"8:0": {done: 6, busy: 50 * ms}, "8:16": {done: 4, busy: 5 * ms}}, 50 * ms, nil},
{"one given I/O since, completing none yet, and another completing", diskMark{"8:0": {done: 5}, "8:16": {done: 3}}, diskMark{"8:0": {done: 6, busy: 50 * ms}, "8:16": {done: 3, inFlight: 1, busy: ms}}, 50 * ms, []string{"8:16"}},
{"two standing still", diskMark{"8:0": {done: 5, inFlight: 1}, "8:16": {done: 3, inFlight: 4}}, diskMark{"8:0": {done: 5, inFlight: 1}, "8:16": {done: 3, inFlight: 4}}, w, []string{"8:0", "8:16"}},
{"its counts gone back (another device)", diskMark{"8:0": {done: 9, busy: w}}, diskMark{"8:0": {done: 2, inFlight: 1, busy: ms}}, 0, nil},
{"its busy time gone back (another device)", diskMark{"8:0": {done: 2, busy: w}}, diskMark{"8:0": {done: 9, busy: ms}}, 0, nil},
{"a volume standing still while the partition under it completes I/O",
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}, "259:3": {name: "nvme0n1p3", done: 10, inFlight: 1}},
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}, "259:3": {name: "nvme0n1p3", done: 12, inFlight: 1, busy: 15 * ms}}, w, nil},
{"volumes stacked on one another, and a partition, standing still while the disk under them all completes I/O",
diskMark{"253:1": {name: "dm-1", done: 2, inFlight: 1}, "253:0": {name: "dm-0", done: 5, inFlight: 3}, "259:3": {name: "nvme0n1p3", done: 10, inFlight: 1}, "259:0": {name: "nvme0n1", done: 40}},
diskMark{"253:1": {name: "dm-1", done: 2, inFlight: 1}, "253:0": {name: "dm-0", done: 5, inFlight: 3}, "259:3": {name: "nvme0n1p3", done: 10, inFlight: 1}, "259:0": {name: "nvme0n1", done: 41, busy: 2 * ms}}, w, nil},
{"a volume and the partition under it both standing still",
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}, "259:3": {name: "nvme0n1p3", done: 10, inFlight: 1}},
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}, "259:3": {name: "nvme0n1p3", done: 10, inFlight: 1}}, w, []string{"253:0", "259:3"}},
{"a volume standing still on a partition idle",
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}, "259:3": {name: "nvme0n1p3", done: 10}},
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}, "259:3": {name: "nvme0n1p3", done: 10}}, w, []string{"253:0"}},
{"a volume standing still on a partition whose counts went back (another device)",
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}, "259:3": {name: "nvme0n1p3", done: 10, busy: w}},
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}, "259:3": {name: "nvme0n1p3", done: 12, busy: ms}}, w, []string{"253:0"}},
{"a volume standing still on a partition new since",
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}},
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}, "259:3": {name: "nvme0n1p3", done: 12, busy: ms}}, w, []string{"253:0"}},
{"a volume standing still while a disk it is not on completes I/O",
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}, "8:0": {name: "sda", done: 10}},
diskMark{"253:0": {name: "dm-0", done: 5, inFlight: 3}, "8:0": {name: "sda", done: 11, busy: ms}}, w, []string{"253:0"}},
} {
served, still := storageServed(w, tc.before, tc.now, func(name string) []string { return under[name] })
if served != tc.want || !slices.Equal(still, tc.still) {
t.Errorf("%s: served %v, standing still %v; want %v, %v", tc.name, served, still, tc.want, tc.still)
}
}
}
// The kernel's counters are unsigned 64-bit: one longer than a Duration holds
// is the longest Duration, never a negative one.
func TestAKernelCounterLongerThanADurationHoldsIsTheLongestOne(t *testing.T) {
fits := uint64(math.MaxInt64 / int64(startTick))
for _, tc := range []struct {
n uint64
unit time.Duration
want time.Duration
}{
{0, time.Millisecond, 0},
{12, time.Millisecond, 12 * time.Millisecond},
{math.MaxInt64, time.Nanosecond, math.MaxInt64},
{math.MaxInt64 + 1, time.Nanosecond, math.MaxInt64},
{math.MaxUint64, time.Nanosecond, math.MaxInt64},
{fits, startTick, time.Duration(fits) * startTick},
{fits + 1, startTick, math.MaxInt64},
{math.MaxUint64, time.Millisecond, math.MaxInt64},
} {
if got := durationOf(tc.n, tc.unit); got != tc.want {
t.Errorf("%d × %v: %v, want %v", tc.n, tc.unit, got, tc.want)
}
}
}
// /proc/diskstats is read whatever the kernel's count of fields: discards
// from Linux 4.18 and flushes from 5.5 are I/O completed too.
func TestDiskstatsAreReadAsEachKernelWritesThem(t *testing.T) {
path := filepath.Join(t.TempDir(), "diskstats")
stats := strings.Join([]string{
" 259 0 nvme0n1 100 1 800 50 200 2 1600 90 3 120 140 10 0 80 4 30 7",
" 259 1 nvme0n1p1 10 0 80 5 20 0 160 9 0 12 14 1 0 8 0",
" 8 0 sda 7 0 56 4 8 0 64 6 1 9 10",
" 8 16 sdb 1 0 8 1 1 0 8 1 0 18446744073709551615 1",
" 7 0 loop0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0",
"garbage",
}, "\n") + "\n"
if err := os.WriteFile(path, []byte(stats), 0o644); err != nil {
t.Fatal(err)
}
got, ok := readDiskstats(path)
if !ok {
t.Fatal("not read")
}
ms := time.Millisecond
want := diskMark{
"259:0": {name: "nvme0n1", done: 100 + 200 + 10 + 30, inFlight: 3, busy: 120 * ms},
"259:1": {name: "nvme0n1p1", done: 10 + 20 + 1, busy: 12 * ms},
"8:0": {name: "sda", done: 7 + 8, inFlight: 1, busy: 9 * ms},
"8:16": {name: "sdb", done: 1 + 1, busy: math.MaxInt64},
"7:0": {name: "loop0"},
}
if !maps.Equal(got, want) {
t.Fatalf("read %+v, want %+v", got, want)
}
if _, ok := readDiskstats(filepath.Join(t.TempDir(), "none")); ok {
t.Fatal("a missing file was read")
}
if got, ok := readDiskstats("/proc/diskstats"); ok && len(got) == 0 {
t.Fatal("this host's diskstats read as no device")
}
}
// A block device is stacked on the devices sysfs names its slaves (a
// device-mapper, md or bcache device's), and a partition on its disk; one
// sysfs cannot show is on none.
func TestABlockDeviceIsOnItsSlavesAndAPartitionOnItsDisk(t *testing.T) {
sys := t.TempDir()
devices := filepath.Join(sys, "devices")
class := filepath.Join(sys, "class", "block")
for _, dir := range []string{
"devices/nvme0/nvme0n1/nvme0n1p3", "devices/nvme0/nvme0n1/nvme0n1p1",
"devices/virtual/dm-0/slaves", "devices/virtual/dm-1/slaves",
"devices/virtual/md0/slaves", "devices/cciss/cciss!c0d0/cciss!c0d0p1",
"devices/virtual/loop0", "class/block",
} {
if err := os.MkdirAll(filepath.Join(sys, dir), 0o755); err != nil {
t.Fatal(err)
}
}
for _, f := range []string{"nvme0/nvme0n1/nvme0n1p3", "nvme0/nvme0n1/nvme0n1p1", "cciss/cciss!c0d0/cciss!c0d0p1"} {
if err := os.WriteFile(filepath.Join(devices, f, "partition"), []byte("1\n"), 0o644); err != nil {
t.Fatal(err)
}
}
link := func(target, name string) {
t.Helper()
if err := os.Symlink(target, name); err != nil {
t.Fatal(err)
}
}
for name, target := range map[string]string{
"nvme0n1": "nvme0/nvme0n1", "nvme0n1p3": "nvme0/nvme0n1/nvme0n1p3", "nvme0n1p1": "nvme0/nvme0n1/nvme0n1p1",
"dm-0": "virtual/dm-0", "dm-1": "virtual/dm-1", "md0": "virtual/md0",
"cciss!c0d0": "cciss/cciss!c0d0", "cciss!c0d0p1": "cciss/cciss!c0d0/cciss!c0d0p1", "loop0": "virtual/loop0",
} {
link(filepath.Join("..", "..", "devices", target), filepath.Join(class, name))
}
link(filepath.Join("..", "..", "..", "nvme0", "nvme0n1", "nvme0n1p3"), filepath.Join(devices, "virtual", "dm-0", "slaves", "nvme0n1p3"))
link(filepath.Join("..", "..", "dm-0"), filepath.Join(devices, "virtual", "dm-1", "slaves", "dm-0"))
link(filepath.Join("..", "..", "..", "nvme0", "nvme0n1", "nvme0n1p1"), filepath.Join(devices, "virtual", "md0", "slaves", "nvme0n1p1"))
link(filepath.Join("..", "..", "..", "cciss", "cciss!c0d0", "cciss!c0d0p1"), filepath.Join(devices, "virtual", "md0", "slaves", "cciss!c0d0p1"))
for name, want := range map[string][]string{
"dm-1": {"dm-0"},
"dm-0": {"nvme0n1p3"},
"nvme0n1p3": {"nvme0n1"},
"nvme0n1": nil,
"md0": {"cciss/c0d0p1", "nvme0n1p1"},
"cciss/c0d0p1": {"cciss/c0d0"},
"loop0": nil,
"sdz": nil,
} {
got := storageBelow(class, name)
slices.Sort(got)
if !slices.Equal(got, want) {
t.Errorf("%s is on %q, want %q", name, got, want)
}
}
// This host's own, as a stop reads them: whatever it has, a partition
// is on its disk.
disks, _ := hostStorage.disks()
for _, n := range disks {
if _, err := os.Stat(filepath.Join("/sys/class/block", n.name, "partition")); err == nil {
if got := hostStorage.below(n.name); len(got) != 1 || !strings.HasPrefix(n.name, got[0]) {
t.Errorf("this host's partition %s is on %q, not its disk", n.name, got)
}
}
}
}
// A thread's filesystems are on storage the host's disks show only where each
// mount of its namespace is on a block device, or on none: one served over a
// network or by a process (or of a type not known) is not, nor are mounts
// that cannot be read.
func TestAThreadSeesItsStorageOnlyWhereEveryMountIsOnTheHostsDisks(t *testing.T) {
local := strings.Join([]string{
"45 1 0:37 /root / rw,relatime shared:1 - btrfs /dev/nvme0n1p6 rw,subvol=/root",
"47 45 0:41 / /usr/lib/firmware/vendor rw,relatime shared:2 - tmpfs vendorfw rw",
"60 45 0:22 / /proc rw,nosuid shared:13 - proc proc rw",
"61 60 0:50 / /proc/sys/fs/binfmt_misc rw,relatime shared:30 master:4 - autofs systemd-1 rw,fd=37",
"70 45 0:60 / /var/lib/docker/overlay2/x/merged rw,relatime - overlay overlay rw,lowerdir=/a,upperdir=/b",
"71 45 259:4 / /boot rw,relatime shared:3 - ext4 /dev/nvme0n1p4 rw",
"72 45 0:61 / /mnt/my\\040dir rw,relatime - xfs /dev/sdb1 rw",
}, "\n") + "\n"
for _, tc := range []struct {
name string
mounts string
want bool
}{
{"on disks and memory", local, true},
{"and an NFS mount", local + "80 45 0:70 / /mnt/nfs rw,relatime shared:40 - nfs4 server:/export rw,vers=4.2\n", false},
{"and a FUSE one", local + "81 45 0:71 / /run/user/1000/doc rw,nosuid shared:41 - fuse.portal portal rw\n", false},
{"and one of a type not known", local + "82 45 0:72 / /mnt/x rw - lustre 10.0.0.1@tcp:/fs rw\n", false},
{"a line without its separator", local + "83 45 0:73 / /mnt/y rw tmpfs\n", false},
{"none", "", false},
} {
task := t.TempDir()
if err := os.WriteFile(filepath.Join(task, "mountinfo"), []byte(tc.mounts), 0o644); err != nil {
t.Fatal(err)
}
if got := mountsSeen(task); got != tc.want {
t.Errorf("%s: seen %v, want %v", tc.name, got, tc.want)
}
}
if mountsSeen(filepath.Join(t.TempDir(), "gone")) {
t.Error("a thread whose mounts cannot be read sees its storage")
}
}
// fakeProc writes a /proc of processes under a temporary directory: each a
// leader state and start time, and threads of it, each a state, an account,
// the processes it started, its mounts, and its mount namespace (ns/mnt;
// none written where "").
type fakeThread struct {
tid int
state byte
ran, wait, slice uint64
children string
mounts, ns string
}
func fakeProc(t *testing.T, procs map[int]struct {
state byte
start uint64
threads []fakeThread
}) string {
t.Helper()
root := t.TempDir()
write := func(path, s string) {
if err := os.MkdirAll(filepath.Dir(path), 0o755); err != nil {
t.Fatal(err)
}
if err := os.WriteFile(path, []byte(s), 0o644); err != nil {
t.Fatal(err)
}
}
stat := func(pid int, state byte, start uint64, threads int) string {
// pid (comm) state, then fields 4..52: num_threads is field 20,
// starttime field 22.
f := make([]string, 49)
for i := range f {
f[i] = "0"
}
f[20-4] = strconv.Itoa(threads)
f[22-4] = strconv.FormatUint(start, 10)
return fmt.Sprintf("%d (app) %c %s\n", pid, state, strings.Join(f, " "))
}
for pid, p := range procs {
dir := filepath.Join(root, strconv.Itoa(pid))
write(filepath.Join(dir, "stat"), stat(pid, p.state, p.start, len(p.threads)))
for _, th := range p.threads {
tdir := filepath.Join(dir, "task", strconv.Itoa(th.tid))
write(filepath.Join(tdir, "stat"), stat(th.tid, th.state, p.start, len(p.threads)))
write(filepath.Join(tdir, "schedstat"), fmt.Sprintf("%d %d %d\n", th.ran, th.wait, th.slice))
write(filepath.Join(tdir, "children"), th.children)
if th.mounts != "" {
write(filepath.Join(tdir, "mountinfo"), th.mounts)
}
if th.ns != "" {
if err := os.MkdirAll(filepath.Join(tdir, "ns"), 0o755); err != nil {
t.Fatal(err)
}
if err := os.Symlink(th.ns, filepath.Join(tdir, "ns", "mnt")); err != nil {
t.Fatal(err)
}
}
}
}
return root
}
// The account is read of every thread of each process as it was named (pid
// and start time), its leader exited or not, and of the processes it runs
// now: a Go process exiting has a zombie leader while its other threads,
// killed, wait for a CPU to get out, and a shutdown may wait on a child it
// started since the stop began. A pid that names another process now is not
// read. A thread held in the kernel (D) is neither runnable nor asleep on its
// own, and whether it can reach only storage the host's disks show is read
// of the mounts of its own namespace (once for threads that share one): a
// zombie leader's show none, and a thread may have a namespace of its own.
func TestTheExitClockReadsEveryThreadOfItsProcesses(t *testing.T) {
type proc = struct {
state byte
start uint64
threads []fakeThread
}
local := "45 1 0:37 / / rw shared:1 - xfs /dev/nvme0n1p3 rw\n46 45 0:22 / /proc rw - proc proc rw\n"
remote := local + "47 45 0:40 / /mnt/nfs rw - nfs4 server:/export rw\n"
root := fakeProc(t, map[int]proc{
// 102 and 103 share a namespace, read once (103 shows no mounts of
// its own); 104 has one of its own, which reaches NFS.
100: {state: 'Z', start: 7, threads: []fakeThread{{100, 'Z', 5, 1, 2, "", "", ""}, {101, 'R', 6, 9, 3, "400 ", local, "mnt:[1]"}, {102, 'D', 2, 2, 2, "", local, "mnt:[1]"}, {103, 'D', 1, 1, 1, "", "", "mnt:[1]"}, {104, 'D', 1, 1, 1, "", remote, "mnt:[2]"}}},
200: {state: 'S', start: 9, threads: []fakeThread{{200, 'S', 1, 2, 3, "", "", ""}}},
400: {state: 'S', start: 11, threads: []fakeThread{{400, 'S', 4, 4, 4, "401", remote, ""}, {403, 'D', 1, 1, 1, "", remote, ""}}},
401: {state: 'R', start: 12, threads: []fakeThread{{401, 'R', 0, 0, 0, "", "", ""}, {402, 'D', 3, 3, 3, "", "", ""}}},
})
// Read 2 s after the system booted: a thread started at tick 7 (of
// 10ms) is 1.93 s old.
boot := func() time.Duration { return 2 * time.Second }
from := time.Now()
got, ok := readTaskTimesIn(root, []Reached{{PID: 100, Start: 7}, {PID: 200, Start: 8}, {PID: 300, Start: 1}}, boot, mountsSeen)
to := time.Now()
if !ok {
t.Fatal("the zombie-led process was not read")
}
// Each thread's read is timed within the read of them all; the rest of
// its account is as the files say.
for tid, th := range got {
if !readWithin(th, from, to) {
t.Errorf("thread %d was read from %v to %v, not within the read of them all, from %v to %v", tid, th.from, th.to, from, to)
}
th.from, th.to = time.Time{}, time.Time{}
got[tid] = th
}
ms := time.Millisecond
want := map[int]taskTime{
100: {ran: 5, waited: 1, slices: 2, age: 1930 * ms},
101: {ran: 6, waited: 9, slices: 3, runnable: true, age: 1930 * ms},
102: {ran: 2, waited: 2, slices: 2, blocked: true, seen: true, age: 1930 * ms},
103: {ran: 1, waited: 1, slices: 1, blocked: true, seen: true, age: 1930 * ms},
104: {ran: 1, waited: 1, slices: 1, blocked: true, age: 1930 * ms},
400: {ran: 4, waited: 4, slices: 4, age: 1890 * ms},
403: {ran: 1, waited: 1, slices: 1, blocked: true, age: 1890 * ms},
401: {runnable: true, age: 1880 * ms},
402: {ran: 3, waited: 3, slices: 3, blocked: true, age: 1880 * ms},
}
if !maps.Equal(got, want) {
t.Fatalf("read %+v, want %+v (400 and 401 run under 100, pid 200 names another process now, 300 is gone; 102 and 103 can reach only local storage, 104 and 403 an NFS mount, and 402's mounts cannot be read)", got, want)
}
if _, ok := readTaskTimesIn(root, []Reached{{PID: 200, Start: 8}}, boot, mountsSeen); ok {
t.Fatal("a process another now has the pid of was read")
}
}
// The exit clock reads every thread its processes have: a listing of a
// process's threads taken while others exit can leave out one that is there
// throughout, so listings that hold fewer threads than the process counts
// are taken again. Where none make up the count, the threads of all of them
// are read, after a bounded number of counts, and the look counts only what
// they ran: a thread it missed cannot make the processes seem able to run
// for longer than they could.
func TestTheExitClockReadsEveryThreadItsProcessCounts(t *testing.T) {
type proc = struct {
state byte
start uint64
threads []fakeThread
}
root := fakeProc(t, map[int]proc{
600: {state: 'S', start: 7, threads: []fakeThread{{600, 'S', 1, 1, 1, "", "", ""}, {601, 'S', 2, 2, 2, "", "", ""}}},
})
stat, err := os.ReadFile(filepath.Join(root, "600", "stat"))
if err != nil {
t.Fatal(err)
}
withCount := func(n int) string {
f := strings.Fields(string(stat))
f[19] = strconv.Itoa(n)
return strings.Join(f, " ") + "\n"
}
// The process's stat is read first to tell it is the one named; as it
// is read again, for its count, thread 602 is put in the listing: one
// the listing before left out.
serveStat(t, filepath.Join(root, "600", "stat"), func(n int) string {
if n == 2 {
dir := filepath.Join(root, "600", "task", "602")
for name, body := range map[string]string{"stat": strings.Replace(string(stat), "600 (app) S", "602 (app) R", 1), "schedstat": "3 3 3\n", "children": ""} {
if err := os.MkdirAll(dir, 0o755); err != nil {
t.Error(err)
}
if err := os.WriteFile(filepath.Join(dir, name), []byte(body), 0o644); err != nil {
t.Error(err)
}
}
}
if n == 1 {
return string(stat)
}
return withCount(3)
})
never := func(string) bool { return true }
got, ok := readTaskTimesIn(root, []Reached{{PID: 600, Start: 7}}, func() time.Duration { return 0 }, never)
if !ok {
t.Fatal("the process was not read")
}
if ids := slices.Sorted(maps.Keys(got)); !slices.Equal(ids, []int{600, 601, 602}) {
t.Fatalf("read threads %v; want 600, 601 and 602, the one the first listing left out (and no mark of a listing not shown whole)", ids)
}
// A count no listing makes up: after taskListings counts, the threads
// of every listing, and the process marked as read from listings not
// shown whole; not a listing taken for ever, nor only the last one. 701
// is in the first listing alone: the first count's read moves it out.
root = fakeProc(t, map[int]proc{
700: {state: 'S', start: 7, threads: []fakeThread{{700, 'S', 1, 1, 1, "", "", ""}, {701, 'S', 2, 2, 2, "", "", ""}}},
})
stat, err = os.ReadFile(filepath.Join(root, "700", "stat"))
if err != nil {
t.Fatal(err)
}
// The count is the server goroutine's: it serves the stat again at the
// exit clock's read below, after the check of it.
var counts atomic.Int32
serveStat(t, filepath.Join(root, "700", "stat"), func(int) string {
if counts.Add(1) == 1 {
if err := os.Rename(filepath.Join(root, "700", "task", "701"), filepath.Join(root, "701-hidden")); err != nil {
t.Error(err)
}
}
return withCount(5)
})
ids, whole, gone, err := taskIDs(root, 700)
if err != nil || gone || whole || !slices.Equal(ids, []string{"700", "701"}) {
t.Fatalf("taskIDs = %v, whole %v, gone %v, %v; want 700 and 701, every thread the listings held, not whole", ids, whole, gone, err)
}
if n := int(counts.Load()); n != taskListings {
t.Fatalf("%d counts read; want %d", n, taskListings)
}
// Read by the exit clock, the same process is marked: its look counts
// only what its threads ran.
if err := os.Rename(filepath.Join(root, "701-hidden"), filepath.Join(root, "700", "task", "701")); err != nil {
t.Fatal(err)
}
got, ok = readTaskTimesIn(root, []Reached{{PID: 700, Start: 7}}, func() time.Duration { return 0 }, never)
if !ok {
t.Fatal("the process was not read")
}
if mark, marked := got[-700]; !marked || !mark.partial {
t.Fatalf("read %v; want process 700 marked as read from listings not shown whole", got)
}
// A thread started between the first listing and the count (803) is
// held by the count and not by that listing: that pair falls short, and
// the next pair (the second listing, which holds it, and a new count)
// is whole.
root = fakeProc(t, map[int]proc{
800: {state: 'S', start: 7, threads: []fakeThread{{800, 'S', 1, 1, 1, "", "", ""}, {801, 'S', 2, 2, 2, "", "", ""}}},
})
stat, err = os.ReadFile(filepath.Join(root, "800", "stat"))
if err != nil {
t.Fatal(err)
}
counts.Store(0)
serveStat(t, filepath.Join(root, "800", "stat"), func(int) string {
if counts.Add(1) == 1 {
dir := filepath.Join(root, "800", "task", "803")
if err := os.MkdirAll(dir, 0o755); err != nil {
t.Error(err)
}
}
return withCount(3)
})
ids, whole, gone, err = taskIDs(root, 800)
if err != nil || gone || !whole || !slices.Equal(ids, []string{"800", "801", "803"}) || counts.Load() != 2 {
t.Fatalf("a thread started as the count was read: taskIDs = %v, whole %v, gone %v, %v, after %d counts; want 800, 801 and 803, whole, after 2", ids, whole, gone, err, counts.Load())
}
// A look with such a thread counts only what the threads ran: here
// one waited for a CPU all the look, which, missed by a listing, would
// leave the look seeming all runnable.
ms := time.Millisecond
before := map[int]taskTime{1: {ran: 10 * ms, waited: 0}}
now := map[int]taskTime{1: {ran: 30 * ms, waited: 0, partial: true}}
if could := lookAt(100*ms, before, now, map[int]time.Duration{}).could(0); could != 20*ms {
t.Fatalf("a look with a thread from a listing not shown whole could run %v; want 20ms, what it ran", could)
}
now[1] = taskTime{ran: 30 * ms, waited: 0}
if could := lookAt(100*ms, before, now, map[int]time.Duration{}).could(0); could != 100*ms {
t.Fatalf("a whole look of a thread that ran 20ms of 100ms, runnable for none of the rest and waiting none: could %v; want 100ms", could)
}
}
// A thread's state is read after its account, and one its state shows not
// runnable may have been waiting for a CPU when its account was read: then
// it has been given the CPU since, which booked the whole wait. Its account
// is read again after its state: the waits it booked since count too
// (missed), a turn on a CPU since ends a stretch in the kernel (turned), its
// time on a CPU then is kept (ranAgain), and one whose account is gone by
// then is taken for runnable.
func TestAThreadNotRunnableIsReadAgainForTheWaitsItBookedAsItsStateWasRead(t *testing.T) {
type proc = struct {
state byte
start uint64
threads []fakeThread
}
root := fakeProc(t, map[int]proc{
500: {state: 'S', start: 7, threads: []fakeThread{{500, 'S', 5, 1, 2, "", "", ""}, {501, 'D', 3, 1, 1, "", "", ""}, {502, 'S', 4, 4, 4, "", "", ""}, {503, 'S', 2, 2, 2, "", "", ""}}},
})
// Threads 500, 501 and 503 move on as their state is read: their stat
// is a FIFO whose writer, once it is opened, moves their account on (or,
// for 503, which exits, removes it) and only then gives the stat.
for tid, moved := range map[string]string{"500": "6 3 3\n", "501": "4 2 2\n", "503": ""} {
dir := filepath.Join(root, "500", "task", tid)
stat, err := os.ReadFile(filepath.Join(dir, "stat"))
if err != nil {
t.Fatal(err)
}
fifo := filepath.Join(dir, "stat")
if err := os.Remove(fifo); err != nil {
t.Fatal(err)
}
if err := unix.Mkfifo(fifo, 0o600); err != nil {
t.Fatal(err)
}
end := make(chan struct{})
go func() {
defer close(end)
f, err := os.OpenFile(fifo, os.O_WRONLY, 0)
if err != nil {
return
}
defer func() { _ = f.Close() }()
account := filepath.Join(dir, "schedstat")
if moved == "" {
_ = os.Remove(account)
} else if os.WriteFile(account+".moved", []byte(moved), 0o644) == nil {
_ = os.Rename(account+".moved", account)
}
_, _ = f.Write(stat)
}()
t.Cleanup(func() {
// A writer still waiting for its reader is let go.
if f, err := os.OpenFile(fifo, os.O_RDONLY|unix.O_NONBLOCK, 0); err == nil {
_ = f.Close()
}
<-end
})
}
got, ok := readTaskTimesIn(root, []Reached{{PID: 500, Start: 7}}, func() time.Duration { return 0 }, func(string) bool { return true })
if !ok {
t.Fatal("the process was not read")
}
for tid, th := range got {
th.from, th.to = time.Time{}, time.Time{}
got[tid] = th
}
want := map[int]taskTime{
500: {ran: 5, waited: 1, slices: 2, missed: 2, turned: true, ranAgain: 6},
501: {ran: 3, waited: 1, slices: 1, blocked: true, seen: true, missed: 1, turned: true, ranAgain: 4},
502: {ran: 4, waited: 4, slices: 4},
503: {ran: 2, waited: 2, slices: 2, runnable: true},
}
if !maps.Equal(got, want) {
t.Fatalf("read %+v, want %+v (500 and 501 booked waits and turns as their state was read, 502 did not, 503 exited)", got, want)
}
}
// startProc starts command under sh for the test.
func startProc(t *testing.T, command string) []Reached {
t.Helper()
return startCmd(t, exec.Command("sh", "-c", command))
}
// startSleeper starts a process that sleeps until the test's process is
// gone, however that ends: a shell reading its stdin, a pipe no one writes
// to, whose write end the test's process alone holds, so the shell reads the
// pipe's end once that process is gone.
func startSleeper(t *testing.T) []Reached {
t.Helper()
cmd := exec.Command("sh", "-c", "read -r line")
if _, err := cmd.StdinPipe(); err != nil {
t.Fatal(err)
}
return startCmd(t, cmd)
}
// startCmd starts cmd for the test, in a process group of its own, which the
// test kills, whole, at its end.
func startCmd(t *testing.T, cmd *exec.Cmd) []Reached {
t.Helper()
cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
if err := cmd.Start(); err != nil {
t.Fatal(err)
}
t.Cleanup(func() { _ = unix.Kill(-cmd.Process.Pid, unix.SIGKILL); _ = cmd.Wait() })
p, ok := ProcOf(cmd.Process.Pid)
if !ok {
t.Fatal("the process is gone")
}
return []Reached{p}
}
// liveRig makes ExitClocks of live processes on the wall clock, each with
// its reads of them kept (readSpans), on a keploy runnable clock the test
// moves (looks) by more than any look, and on storage that serves throughout
// (servingDisks), so what they count is the processes' own account of the
// CPU alone. A process that only spins is held in the kernel too, now and
// then: on a page of it the kernel is migrating (a fault that waits in
// migration_entry_wait, uninterruptible), which the CPU it had does not show,
// and which the clock counts as time it could run where the host's disks
// serve less (ExitClock). On .142 under memory load, the two spinners of 150
// runs of a test like TestTheExitClockOfAProcessSharingACPU were so held 176
// times, for 8 µs to 16 ms. With storage serving throughout, the clock takes
// each such hold a look finds for a wait.
type liveRig struct {
own *stall.ManualClock
spans map[*ExitClock]*readSpans
}
func newLiveRig() *liveRig {
return &liveRig{own: &stall.ManualClock{}, spans: map[*ExitClock]*readSpans{}}
}
func (r *liveRig) clock(procs []Reached) *ExitClock {
s := &readSpans{}
c := newExitClock(procs, time.Hour, time.Hour, time.Hour, r.own, time.Now, s.read, servingDisks(), nil)
r.spans[c] = s
return c
}
// looks looks at clocks n times, each after a pause, moving keploy's
// runnable time on by an hour each time (so that it bounds no look), and
// returns the wall time that passed.
func (r *liveRig) looks(n int, clocks ...*ExitClock) time.Duration {
start := time.Now()
for range n {
time.Sleep(20 * time.Millisecond)
r.own.Advance(time.Hour)
for _, c := range clocks {
c.Runnable()
}
}
return time.Since(start)
}
// readSpans is an ExitClock's reader of live processes, which keeps what
// each read of them read. Each read is held up first, by as much as 5 ms, as
// a loaded host holds keploy off the CPU between reading the wall clock and
// reading the processes (ExitClock).
type readSpans struct {
reads []map[int]taskTime
}
// read reads procs' account, taking every filesystem a thread held in the
// kernel can reach for one on the host's block devices (mountsSeen), as
// servingDisks are.
func (s *readSpans) read(procs []Reached) (map[int]taskTime, bool) {
time.Sleep(time.Duration(rand.Int63n(int64(5 * time.Millisecond))))
m, ok := readTaskTimesSeen(procs, func(string) bool { return true })
s.reads = append(s.reads, maps.Clone(m))
return m, ok
}
// window is the time from the start of the first read of thread tid's
// account to the end of the last, which holds every moment the kernel took
// one at.
func (s *readSpans) window(t *testing.T, tid int) time.Duration {
t.Helper()
first, last := s.reads[0][tid], s.reads[len(s.reads)-1][tid]
if first.from.IsZero() || last.to.IsZero() {
t.Fatalf("thread %d was not read, timed, at the first read and the last", tid)
}
return last.to.Sub(first.from)
}
// still says whether read i found threads, none of them runnable, nor any
// whose account moved as its state was read.
func (s *readSpans) still(i int) bool {
m := s.reads[i]
for _, th := range m {
if th.runnable || th.missed > 0 || th.turned || th.ranAgain > 0 {
return false
}
}
return len(m) > 0
}
// asleep is how many reads found threads, and none of them runnable.
func (s *readSpans) asleep() (n int) {
for _, m := range s.reads {
if len(m) > 0 && !slices.ContainsFunc(slices.Collect(maps.Values(m)), func(th taskTime) bool { return th.runnable }) {
n++
}
}
return n
}
// servingDisks is the host's block devices as one disk that serves I/O
// throughout every look: it completes some, and has I/O in flight, between
// any two reads of it.
func servingDisks() func() (diskMark, bool) {
var d diskCount
return func() (diskMark, bool) {
d.done++
d.busy += time.Hour
return diskMark{"259:0": d}, true
}
}
// between is the time between the reads of the one thread of the clock's
// process: from the end of each read of it to the start of the next.
func (s *readSpans) between(t *testing.T) (d time.Duration) {
t.Helper()
for i := 1; i < len(s.reads); i++ {
if len(s.reads[i-1]) != 1 || len(s.reads[i]) != 1 {
t.Fatalf("read %d threads, then %d: want the one", len(s.reads[i-1]), len(s.reads[i]))
}
for tid, th := range s.reads[i] {
b, ok := s.reads[i-1][tid]
if !ok {
t.Fatalf("thread %d is new to read %d", tid, i)
}
d += th.from.Sub(b.to)
}
}
return d
}
// cpuSince is the CPU time the threads of an account had since an earlier
// one of the same processes, and the time they waited for a CPU, by the
// kernel.
func cpuSince(before, now map[int]taskTime) (ran, waited time.Duration) {
for tid, t := range now {
b := before[tid]
if t.ran < b.ran {
b = taskTime{}
}
ran += t.ran - b.ran
waited += t.waited - b.waited
}
return ran, waited
}
// spinning waits until process p spins: it has run for 10 ms on a CPU, by
// its own account, which one still starting has not (its program paged in
// from storage, held in the kernel). Its time held there is a wait only for
// what storage served of it (ExitClock), so a test of a process that only
// spins starts once it does: on .142 at load 20, one started 61 ms before the
// first look was held in the kernel for 470 ms, and the few hundred
// microseconds of each look storage did not serve counted, as they must.
// The test's own timeout is the only bound.
func spinning(t *testing.T, p Reached) {
t.Helper()
for {
if ran, _ := starvetest.Ran(p.PID); ran >= 10*time.Millisecond {
return
}
if now, ok := ProcOf(p.PID); !ok || now != p {
t.Fatalf("process %d is gone", p.PID)
}
time.Sleep(time.Millisecond)
}
}
// asleep waits until process p runs program comm and sleeps, with no more
// to run.
func asleep(t *testing.T, p Reached, comm string) {
t.Helper()
for {
st, ok := ReadProcStat(p.PID)
if !ok {
t.Fatalf("process %d is gone", p.PID)
}
b, err := os.ReadFile("/proc/" + strconv.Itoa(p.PID) + "/comm")
if err != nil {
t.Fatalf("read process %d's command: %v", p.PID, err)
}
if st.State == 'S' && strings.TrimSpace(string(b)) == comm {
return
}
time.Sleep(time.Millisecond)
}
}
// On the kernel's own account: a process held off the CPU (runnable, given
// none) could run no more than the CPU it had while a stop waits on it, and
// one that sleeps all of the time.
func TestTheExitClockOfAProcessHeldOffTheCPU(t *testing.T) {
starvetest.TakesACPU(t)
if !schedAccountKept() {
t.Skip("this kernel keeps no account of a thread's time on and waiting for a CPU")
}
spinner, sleeper := startProc(t, starvetest.ShellSpin("")), startSleeper(t)
asleep(t, sleeper[0], "sh")
spinning(t, spinner[0])
release := starvetest.Hold(t, spinner[0].PID)
defer release()
rig := newLiveRig()
held, sleeping := rig.clock(spinner), rig.clock(sleeper)
first := maps.Clone(held.last)
total := rig.looks(20, held, sleeping)
if ran, _ := cpuSince(first, held.last); held.ran > ran {
t.Errorf("a process held off the CPU could run %v of %v by the clock, more than the %v of CPU it had", held.ran, total, ran)
}
if between := rig.spans[sleeping].between(t); sleeping.ran != between {
t.Errorf("a process that sleeps could run %v of the %v between the reads of it (of %v) by the clock; want all of it", sleeping.ran, between, total)
}
}
// On the kernel's own account: a process that spins and sleeps in turn, on
// a CPU it shares, could run only what it ran and slept, however its turns
// and sleeps fall between the looks, and however late keploy reads it. Read
// first while asleep, its account unmoved as its state was read (so with no
// wait for a CPU going on, nor run the kernel has not booked), it ran and
// slept, from the moment the kernel took that account to the moment it took
// the last, all of that time but its waits for a CPU: those its account
// booked by the last read, and the one it may be in then. So the clock counts
// no more than the time from the start of the first read of its account to
// the end of the last (readSpans.window), less those its account booked. A
// look that finds it asleep counts all of its time but the waits its account
// booked since the last look, less what of them the clock counted as they
// went: what the test looks at, so the looks go on until ten found it asleep.
func TestTheExitClockOfAProcessSharingACPU(t *testing.T) {
starvetest.TakesACPU(t)
if !schedAccountKept() {
t.Skip("this kernel keeps no account of a thread's time on and waiting for a CPU")
}
bash, err := exec.LookPath("bash")
if err != nil {
t.Skip("no bash, whose read times out, to sleep in without starting a process")
}
var mine unix.CPUSet
if err := unix.SchedGetaffinity(0, &mine); err != nil {
t.Skipf("cannot read this process's CPUs: %v", err)
}
cpu := -1
for i := 0; i < len(mine)*64; i++ {
if mine.IsSet(i) {
cpu = i
}
}
if cpu < 0 {
t.Skip("this process may run on no CPU")
}
var one unix.CPUSet
one.Set(cpu)
fifo := filepath.Join(t.TempDir(), "unwritten")
if err := unix.Mkfifo(fifo, 0o600); err != nil {
t.Fatal(err)
}
sharer, other := startCmd(t, exec.Command(bash, "-c", spinSleep(fifo))), startProc(t, starvetest.ShellSpin(""))
for _, p := range []Reached{sharer[0], other[0]} {
if err := unix.SchedSetaffinity(p.PID, &one); err != nil {
t.Skipf("cannot pin process %d to CPU %d: %v", p.PID, cpu, err)
}
}
for _, p := range []Reached{sharer[0], other[0]} {
spinning(t, p)
}
rig := newLiveRig()
var c *ExitClock
for tries := 0; ; tries++ {
if c = rig.clock(sharer); rig.spans[c].still(0) {
break
}
if now, ok := ProcOf(sharer[0].PID); !ok || now != sharer[0] {
t.Fatalf("process %d is gone", sharer[0].PID)
}
if tries == 5000 {
t.Fatalf("process %d was found asleep at none of %d reads: it does not sleep", sharer[0].PID, tries)
}
time.Sleep(time.Millisecond)
}
first, reads := maps.Clone(c.last), rig.spans[c]
var total time.Duration
for looks := 0; looks < 40 || reads.asleep() < 11; looks++ {
if looks == 5000 {
t.Fatalf("the process was asleep at %d of %d looks: it hardly sleeps", reads.asleep()-1, looks)
}
total += rig.looks(1, c)
if now, ok := ProcOf(sharer[0].PID); !ok || now != sharer[0] {
t.Fatalf("process %d is gone", sharer[0].PID)
}
}
ran, waited := cpuSince(first, c.last)
if waited == 0 {
t.Fatalf("the process waited for no CPU in %v: the test shared none", total)
}
window := reads.window(t, sharer[0].PID)
if could := window - waited; c.ran > could {
t.Errorf("a process sharing a CPU, spinning and sleeping in turn, could run %v of %v by the clock, more than the %v it could: of the %v from its first read to its last, it waited %v for a CPU (and ran %v; %d of %d looks found it asleep)",
c.ran, total, could, window, waited, ran, reads.asleep()-1, len(reads.reads)-1)
}
}
// spinSleep is a bash loop that, while this process (the test's) runs, as
// ShellSpin, counts to three thousand and sleeps 10 ms, in turn: the count
// takes bash milliseconds of CPU, as a rule more than the scheduler gives it
// in one turn on a CPU it shares, so it waits for one, as well as sleeping
// (the test fails where it waited for none). The sleep is a read's timeout
// on fifo, which no one writes, so the shell starts no process to sleep in,
// and its look for the test's process is a kill(2) of no signal, which never
// sleeps.
func spinSleep(fifo string) string {
return fmt.Sprintf("exec 3<>'%s'; while kill -0 %d; do i=0; while [ $i -lt 3000 ]; do i=$((i+1)); done; read -t 0.01 -u 3; done", fifo, os.Getpid())
}