diff --git a/.github/workflows/lab.yml b/.github/workflows/lab.yml index 23d7c20..53b8ab9 100644 --- a/.github/workflows/lab.yml +++ b/.github/workflows/lab.yml @@ -36,10 +36,7 @@ on: - boot:userspace - boot:systemd - boot:waits - - boot:jobs - boot:ssh-first - - boot:exits - - boot:mmio - boot:ssh-load - boot:page-cache - boot:firmware diff --git a/boot/Taskfile.yml b/boot/Taskfile.yml index 625ee14..2d3dfec 100644 --- a/boot/Taskfile.yml +++ b/boot/Taskfile.yml @@ -193,20 +193,6 @@ tasks: cmds: - SPIN_BOOT_WAITS=1 go test ./boot/ -run '^TestBootWaits$' -count=1 -v -timeout 20m - jobs: - desc: >- - PID 1's job queue as it changed during the boot, recorded live over systemd's private - socket by boot/jobwatch, a diagnostic binary built into each boot's overlay: what was - waiting and what was running every BUCKET ms, the boot:waits gaps with the jobs running - through them, jobs that did not end done, and the jobs the first SSH login after the boot - sets off. Interleaved with boots - without it, and the first table is what recording cost. Needs KVM, a built release and - sudo. REPS= boots of each, CPUS= vCPUs of both (3 gives the recorder room of its own), - LINGER= how long it records after startup, RAW= keeps the dumps. - deps: [':tools'] - cmds: - - SPIN_BOOT_JOBS=1 go test ./boot/ -run '^TestBootJobs$' -count=1 -v -timeout 30m - ssh-first: desc: >- When a workspace can first be logged into from the host over SSH, through the machine's @@ -218,28 +204,6 @@ tasks: cmds: - SPIN_SSH_FIRST=1 go test ./boot/ -run '^TestFirstSSH$' -count=1 -v -timeout 30m - exits: - desc: >- - What each phase of a boot made KVM do, from the host: VM exits by kind, EPT faults, and - how the guest's RAM is mapped (4K/2M/1G, and how much of it the host holds in huge - pages), for the machine as built and without its virtio-rng device, interleaved. Reads - /sys/kernel/debug/kvm, so the host must run one VM at a time. Needs KVM, a built release - and sudo. REPS= boots of each row, CPUS= vCPUs. - deps: [':tools'] - cmds: - - SPIN_BOOT_EXITS=1 go test ./boot/ -run '^TestExitTimeline$' -count=1 -v -timeout 30m - - mmio: - desc: >- - Who the guest's exits to QEMU are, counted from QEMU's own trace from a launch to the - login prompt: every PCI configuration access by device and direction, and every MMIO - and port access by the region it reached. Counts, not times, so any host answers. - SPIN_KERNEL_B= counts a second kernel beside the release's. Needs KVM and a built - release; no sudo. TOP= regions. - deps: [':tools'] - cmds: - - SPIN_BOOT_MMIO=1 go test ./boot/ -run '^TestMMIOCensus$' -count=1 -v -timeout 10m - firmware-stages: desc: >- Where the time before the kernel goes on the machine a workspace boots: QEMU's start and diff --git a/boot/bench_test.go b/boot/bench_test.go index 2d0c091..d9f4ae6 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -88,8 +88,8 @@ func without(units ...string) variant { // boots, 2026-09-26); image/build.sh forbids the disk. // - serial-getty Type=simple instead of Type=idle: within noise of the echo (2026-09-10). // And again once spin lingered and user@1000.service was in the boot transaction: 346/358 -// against 423/441, 20 boots, lab run 43362067503 (2026-11-13) - now the image's -// (serial-getty@.service.d/type.conf). +// against 423/441, 20 boots, lab run 43362067503 (2026-11-13), and in the image for a day: +// removed because nothing a workspace does waits for the console's prompt. // - loop.max_loop=0 8250.nr_uarts=1, and CONFIG_VT=n: no change to a login prompt // (2026-09-26). udev's coldplug overlaps the boot rather than delaying it. // - 19 udev rule files for hardware the machine cannot have, masked: no change, same day. diff --git a/boot/exits_test.go b/boot/exits_test.go deleted file mode 100644 index e62cc20..0000000 --- a/boot/exits_test.go +++ /dev/null @@ -1,244 +0,0 @@ -// SPDX-License-Identifier: Apache-2.0 - -package boot_test - -import ( - "bufio" - "cmp" - "fmt" - "os" - "os/exec" - "path/filepath" - "slices" - "strconv" - "strings" - "testing" - "time" -) - -// What the guest made KVM do in each phase of a boot: VM exits by kind, EPT faults, and how -// its memory ended up mapped, from the host. -// -// It exists because the bench fleet and a laptop disagree by 3-4x on exactly the initcalls -// that touch emulated hardware - acpi_init 14 ms against 4, virtio_pci 6.5 against 2.3 - and -// by nothing on one that does not (inet_init, 7.6 and 7.4), 2026-11-12. Time spent outside the -// guest is invisible from inside it: a trace sees a function take long, not that it took long -// because every config space access left the guest. So this counts the leaving. -// -// KVM keeps the counts in /sys/kernel/debug/kvm, summed over every VM on the host, so the -// host must run one VM at a time - the bench fleet does. A root shell reads them in a loop -// from before QEMU is exec'd to the login; boot:waits's dump, in the same boot, says where on -// the host's clock each phase began, and each phase gets the counts that rose inside it. -// -// SPIN_BOOT_EXITS=1 run at all -// REPS= boots of each row (default 5) -// CPUS= vCPUs (default 2) -// -// The rows: the machine as built, and the same machine without its virtio-rng device - a -// machine with another fingerprint, booted through machineCommand. -func TestExitTimeline(t *testing.T) { - if os.Getenv("SPIN_BOOT_EXITS") == "" { - t.Skip("set SPIN_BOOT_EXITS=1: boots VMs and reads KVM's counters through sudo") - } - out := releaseDir(t) - if !canSudo() { - t.Skip("KVM's counters are in debugfs, which needs root") - } - if err := exec.Command("sudo", "test", "-r", "/sys/kernel/debug/kvm/exits").Run(); err != nil { - t.Skip("no /sys/kernel/debug/kvm/exits: debugfs is not mounted, or KVM keeps no counters here") - } - reps := envInt(t, "REPS", 5) - cpus := cmp.Or(os.Getenv("CPUS"), "2") - const target = "serial-getty@ttyS0.service" - - asBuilt := waitsVariant(cpus) - noRNG := waitsVariant(cpus) - noRNG.label, noRNG.without = "no virtio-rng", []string{"virtio-rng-pci"} - rows := []variant{asBuilt, noRNG} - rows[0].label = "as built" - - got := map[string][][]phaseCounts{} - ram := map[string][]hostRAM{} - for range reps { - for _, v := range rows { - stop := sampleKVM(t) - b := bootWaits(t, out, v, target, "SPIN-WAITS-END") - got[v.label] = append(got[v.label], phasesOf(b, stop())) - ram[v.label] = append(ram[v.label], b.ram) - } - } - - var r strings.Builder - fmt.Fprintf(&r, "\nwhat each phase made KVM do, p50 over %d boots of each, %s vCPUs, interleaved\n", reps, cpus) - for _, v := range rows { - fmt.Fprintf(&r, "\n %s\n\n %-28s %7s %8s %7s %7s %8s %7s %7s\n", v.label, - "PHASE", "MS", "EXITS", "IO", "MMIO", "EPT-PF", "HALT", "EMUL") - for i, name := range phaseNames { - col := func(f func(phaseCounts) float64) float64 { - var xs []float64 - for _, boot := range got[v.label] { - xs = append(xs, f(boot[i])) - } - return pct(xs, 50) - } - fmt.Fprintf(&r, " %-28s %7.1f %8.0f %7.0f %7.0f %8.0f %7.0f %7.0f\n", name, - col(func(p phaseCounts) float64 { return p.ms }), - col(func(p phaseCounts) float64 { return float64(p.d[cExits]) }), - col(func(p phaseCounts) float64 { return float64(p.d[cIO]) }), - col(func(p phaseCounts) float64 { return float64(p.d[cMMIO]) }), - col(func(p phaseCounts) float64 { return float64(p.d[cPF]) }), - col(func(p phaseCounts) float64 { return float64(p.d[cHalt]) }), - col(func(p phaseCounts) float64 { return float64(p.d[cEmul]) })) - } - last := got[v.label] - var k4, m2, g1 []float64 - for _, boot := range last { - end := boot[len(boot)-1].end - k4, m2, g1 = append(k4, float64(end[c4k])), append(m2, float64(end[c2m])), append(g1, float64(end[c1g])) - } - var rss, huge []float64 - for _, b := range ram[v.label] { - rss, huge = append(rss, b.residentMB), append(huge, b.hugeMB) - } - fmt.Fprintf(&r, "\n at the login, p50: KVM maps the guest in %.0f 4K pages, %.0f 2M, %.0f 1G;\n"+ - " the host holds %.0f MiB of its RAM, %.0f MiB of it in huge pages\n", - pct(k4, 50), pct(m2, 50), pct(g1, 50), pct(rss, 50), pct(huge, 50)) - } - t.Log(r.String()) -} - -// The counters, in the order the sampler prints them. -var kvmCounters = []string{"exits", "io_exits", "mmio_exits", "pf_taken", "halt_exits", - "insn_emulation", "pages_4k", "pages_2m", "pages_1g"} - -const ( - cExits = iota - cIO - cMMIO - cPF - cHalt - cEmul - c4k - c2m - c1g -) - -type kvmSample struct { - at time.Time - v []int64 -} - -// sampleKVM starts a root shell that prints the counters with a nanosecond timestamp as fast as -// it can, waits for its first sample, and returns a function that stops it and returns what it -// read. Without a sleep: a sample is a fork of date and nine reads, a millisecond or so, on a -// core of its own. -func sampleKVM(t *testing.T) (stop func() []kvmSample) { - t.Helper() - dir := t.TempDir() - halt := filepath.Join(dir, "stop") - script := `cd /sys/kernel/debug/kvm || exit 1 -while [ ! -e "$1" ]; do - line=$(date +%s%N) - for f in ` + strings.Join(kvmCounters, " ") + `; do read v < "$f"; line="$line $v"; done - echo "$line" -done` - cmd := exec.Command("sudo", "sh", "-c", script, "sampler", halt) - pipe, err := cmd.StdoutPipe() - if err != nil { - t.Fatalf("sampler pipe: %v", err) - } - if err := cmd.Start(); err != nil { - t.Fatalf("starting the sampler: %v", err) - } - done := make(chan []kvmSample) - first := make(chan struct{}) - go func() { - var got []kvmSample - sc := bufio.NewScanner(pipe) - for sc.Scan() { - f := strings.Fields(sc.Text()) - if len(f) != 1+len(kvmCounters) { - continue - } - ns, err := strconv.ParseInt(f[0], 10, 64) - if err != nil { - continue - } - s := kvmSample{at: time.Unix(0, ns)} - for _, x := range f[1:] { - n, _ := strconv.ParseInt(x, 10, 64) - s.v = append(s.v, n) - } - got = append(got, s) - if len(got) == 1 { - close(first) - } - } - done <- got - }() - // The first sample is taken before the machine is launched, so a phase that starts at the - // launch has a count to start from. - select { - case <-first: - case <-time.After(10 * time.Second): - t.Fatal("the sampler printed nothing in ten seconds") - } - return func() []kvmSample { - if err := os.WriteFile(halt, nil, 0o644); err != nil { - t.Fatalf("stopping the sampler: %v", err) - } - _ = cmd.Wait() - s := <-done - if len(s) < 10 { - t.Fatalf("the sampler read %d samples", len(s)) - } - return s - } -} - -var phaseNames = []string{ - "QEMU and firmware", - "kernel", - "PID 1 to units loaded", - "units loaded to getty forked", - "getty forked to login prompt", -} - -type phaseCounts struct { - ms float64 - d []int64 // counts that rose in the phase - end []int64 // counts at its end -} - -// phasesOf cuts one boot's samples at its phase boundaries: the launch, guest monotonic zero, -// PID 1, the end of the unit load, the getty's fork and the login prompt, each on the host's -// clock by boot:waits's anchor. -func phasesOf(b waitsBoot, s []kvmSample) []phaseCounts { - at := func(d time.Duration) time.Time { return b.start.Add(d) } - edges := []time.Time{ - b.start, - at(b.kernel), - at(b.kernel + b.w.Manager.Userspace), - at(b.kernel + b.w.Manager.UnitsLoadFinish), - at(b.kernel + b.target().Start), - at(b.kernel + b.usable), - } - // The last sample taken at or before t. - value := func(t time.Time) []int64 { - i, _ := slices.BinarySearchFunc(s, t, func(x kvmSample, t time.Time) int { return x.at.Compare(t) }) - if i < len(s) && s[i].at.Equal(t) { - return s[i].v - } - return s[max(0, i-1)].v - } - var out []phaseCounts - for i := 0; i+1 < len(edges); i++ { - a, z := value(edges[i]), value(edges[i+1]) - p := phaseCounts{ms: float64(edges[i+1].Sub(edges[i])) / float64(time.Millisecond), end: z} - for j := range a { - p.d = append(p.d, z[j]-a[j]) - } - out = append(out, p) - } - return out -} diff --git a/boot/jobs.go b/boot/jobs.go deleted file mode 100644 index 0d7476d..0000000 --- a/boot/jobs.go +++ /dev/null @@ -1,220 +0,0 @@ -// SPDX-License-Identifier: Apache-2.0 - -package boot - -import ( - "cmp" - "fmt" - "slices" - "strconv" - "strings" - "time" -) - -// What PID 1 said about its jobs while the guest booted, as boot/jobwatch recorded it: the -// live complement to Waits. Waits knows when each unit started and was ready; a JobLog knows -// what systemd was holding in its queue at each moment, which job it was running, how each -// one ended, and the jobs queued after the initial transaction. -// -// Every time here is when jobwatch received the signal, on guest CLOCK_MONOTONIC: later than -// the event by the signal's trip, which JobLog.Lag measures against systemd's own timestamps. - -// Job is one job's life. Queued is zero for a job of the initial transaction, which was -// queued before jobwatch connected; Running is zero for a job that went from waiting straight -// to removed without being reported running, which a job that finishes in the same dispatch -// does. -type Job struct { - ID int - Unit string - Initial bool // queued before jobwatch connected: listed, not announced - Queued time.Duration - Running time.Duration - Removed time.Duration - Result string // done, canceled, timeout, failed, dependency, skipped; empty while pending -} - -// UnitState is a unit's ActiveState changing. -type UnitState struct { - At time.Duration - Unit string - State string -} - -// JobLog is one boot's record. -type JobLog struct { - Connected time.Duration // Subscribe returned: nothing before this was seen live - Finished time.Duration // StartupFinished arrived; zero when it came before Connected - Jobs []Job - States []UnitState -} - -// ParseJobs reads jobwatch's record: one event per line, " ". -func ParseJobs(s string) (JobLog, error) { - var l JobLog - byID := map[int]int{} - job := func(id string) (*Job, error) { - n, err := strconv.Atoi(id) - if err != nil { - return nil, fmt.Errorf("job id %q: %w", id, err) - } - i, ok := byID[n] - if !ok { - i = len(l.Jobs) - byID[n] = i - l.Jobs = append(l.Jobs, Job{ID: n}) - } - return &l.Jobs[i], nil - } - for line := range strings.SplitSeq(s, "\n") { - f := strings.Fields(strings.TrimRight(line, "\r")) - if len(f) < 2 { - continue - } - us, err := strconv.ParseInt(f[0], 10, 64) - if err != nil { - continue // the console around the record - } - at := time.Duration(us) * time.Microsecond - want := map[string]int{"C": 2, "F": 2, "L": 6, "N": 4, "S": 4, "R": 5, "A": 4, "E": 2}[f[1]] - if want == 0 || len(f) < want { - return JobLog{}, fmt.Errorf("event %q: unknown, or fewer than %d fields", line, want) - } - switch f[1] { - case "E": - return JobLog{}, fmt.Errorf("jobwatch stopped: %s", strings.Join(f[2:], " ")) - case "C": - l.Connected = at - case "F": - if len(f) == 2 { - l.Finished = at - } - case "L": - j, err := job(f[2]) - if err != nil { - return JobLog{}, err - } - j.Unit = f[3] - if f[5] == "running" { - j.Running = at - } - case "N": - j, err := job(f[2]) - if err != nil { - return JobLog{}, err - } - j.Unit, j.Queued = f[3], at - case "S": - j, err := job(f[2]) - if err != nil { - return JobLog{}, err - } - if f[3] == "running" && j.Running == 0 { - j.Running = at - } - case "R": - j, err := job(f[2]) - if err != nil { - return JobLog{}, err - } - j.Unit, j.Removed, j.Result = f[3], at, f[4] - case "A": - l.States = append(l.States, UnitState{At: at, Unit: f[2], State: f[3]}) - } - } - if l.Connected == 0 { - return JobLog{}, fmt.Errorf("no C line: jobwatch never subscribed") - } - // A job whose only trace is a state change or a removal was queued before jobwatch - // connected and finished before ListJobs answered: it was there, and nothing more is known. - for i := range l.Jobs { - j := &l.Jobs[i] - if j.Queued == 0 { - j.Initial = true - } - // systemd announces few of its jobs' state changes - 5 of 28 in a boot on 2026-11-12 - - // and a job that ran unannounced would read as waiting until it was removed. Its unit - // leaving inactive is the job running, and that is announced. - if j.Running == 0 { - from := max(j.Queued, l.Connected) - for _, s := range l.States { - if s.Unit == j.Unit && s.At >= from && (j.Removed == 0 || s.At <= j.Removed) && - (s.State == "activating" || s.State == "active") { - j.Running = s.At - break - } - } - } - } - return l, nil -} - -// Pending is the jobs in PID 1's queue at t, split by whether systemd was running them or -// they were waiting on another job. A job of the initial transaction counts from Connected, -// since nothing earlier was seen. -func (l JobLog) Pending(t time.Duration) (waiting, running []Job) { - for _, j := range l.Jobs { - from := j.Queued - if j.Initial { - from = l.Connected - } - if t < from || (j.Removed > 0 && t >= j.Removed) { // mutate-exempt: durations here are whole microseconds, so 0 and 1ns split them alike - continue - } - if j.Running > 0 && t >= j.Running { // mutate-exempt: durations here are whole microseconds, so 0 and 1ns split them alike - running = append(running, j) - } else { - waiting = append(waiting, j) - } - } - return waiting, running -} - -// Unfinished is every job that did not end done: a failure, a timeout, a job cancelled or -// skipped. A dependency result is a job that failed only because another did. -func (l JobLog) Unfinished() []Job { - var out []Job - for _, j := range l.Jobs { - if j.Result != "done" { - out = append(out, j) - } - } - slices.SortFunc(out, func(a, b Job) int { return cmp.Compare(a.ID, b.ID) }) - return out -} - -// Late is every job queued after jobwatch connected, by when. -func (l JobLog) Late() []Job { - var out []Job - for _, j := range l.Jobs { - if !j.Initial { - out = append(out, j) - } - } - slices.SortFunc(out, func(a, b Job) int { return cmp.Or(cmp.Compare(a.Queued, b.Queued), cmp.Compare(a.ID, b.ID)) }) - return out -} - -// Lag is how far behind systemd's own clock jobwatch heard a unit become active: the stamp -// of each ActiveState=active it received against the unit's ActiveEnterTimestampMonotonic, -// for every unit Waits has. It is what "live" means for this record. -// -// Only the first active a unit is heard to enter, and only for a unit that entered it after -// jobwatch subscribed: systemd sends ActiveState with every change to a unit's properties, so -// a unit already active is announced again and again, and counting those read a p95 of 42 ms -// that was a unit's age and not a delay (2026-11-12). -func (l JobLog) Lag(w Waits) []time.Duration { - var out []time.Duration - seen := map[string]bool{} - for _, s := range l.States { - if s.State != "active" || seen[s.Unit] { - continue - } - seen[s.Unit] = true - u, ok := w.Unit(s.Unit) - if !ok || u.Ready < l.Connected || s.At < u.Ready { - continue - } - out = append(out, s.At-u.Ready) - } - return out -} diff --git a/boot/jobs_test.go b/boot/jobs_test.go deleted file mode 100644 index 6806390..0000000 --- a/boot/jobs_test.go +++ /dev/null @@ -1,229 +0,0 @@ -// SPDX-License-Identifier: Apache-2.0 - -package boot - -import ( - "os" - "slices" - "strings" - "testing" - "time" -) - -// A real boot's record and the waits dump of the same boot: task boot:jobs RAW= on -// 2026-11-12, the release as it stood then. -func realJobs(t *testing.T) (JobLog, Waits) { - t.Helper() - b, err := os.ReadFile("testdata/jobs-2026-11-12.txt") - if err != nil { - t.Fatal(err) - } - l, err := ParseJobs(string(b)) - if err != nil { - t.Fatal(err) - } - b, err = os.ReadFile("testdata/jobs-waits-2026-11-12.txt") - if err != nil { - t.Fatal(err) - } - m, us, err := ParseWaits(string(b)) - if err != nil { - t.Fatal(err) - } - return l, NewWaits(m, us) -} - -func TestParseJobsReadsARealBoot(t *testing.T) { - l, w := realJobs(t) - if l.Connected == 0 || l.Finished <= l.Connected { - t.Fatalf("connected at %v, finished at %v", l.Connected, l.Finished) - } - if len(l.Jobs) == 0 { - t.Fatal("no jobs") - } - for _, j := range l.Jobs { - if j.Unit == "" { - t.Errorf("job %d has no unit", j.ID) - } - if j.Removed > 0 && j.Result == "" { - t.Errorf("job %d (%s) removed with no result", j.ID, j.Unit) - } - if j.Running > 0 && j.Removed > 0 && j.Running > j.Removed { - t.Errorf("job %d (%s) running at %v after it was removed at %v", j.ID, j.Unit, j.Running, j.Removed) - } - } - // The record and the timestamps are two accounts of one boot: jobwatch cannot have heard - // a unit become active before systemd stamped it, and should not be far behind. - lag := l.Lag(w) - if len(lag) == 0 { - t.Fatal("no unit heard becoming active") - } - for _, d := range lag { - if d < 0 || d > 100*time.Millisecond { - t.Errorf("a lag of %v", d) - } - } -} - -func TestPending(t *testing.T) { - l, err := ParseJobs(` -1000 C -1001 L 1 a.service start waiting -1002 L 2 b.service start running -1500 N 3 c.service -2000 A a.service activating -3000 R 2 b.service done -4000 R 1 a.service failed -5000 R 3 c.service done -`) - if err != nil { - t.Fatal(err) - } - for _, c := range []struct { - at int - waiting, running int - }{ - {999, 0, 0}, // before jobwatch connected, nothing was seen - {1500, 2, 1}, // a waiting, c just queued, b running since listed - {2500, 1, 2}, // a's unit activating is a running - {3500, 1, 1}, // b removed - {5000, 0, 0}, // c removed at that instant - } { - w, r := l.Pending(time.Duration(c.at) * time.Microsecond) - if len(w) != c.waiting || len(r) != c.running { - t.Errorf("at %dus: %d waiting, %d running; want %d, %d", c.at, len(w), len(r), c.waiting, c.running) - } - } - if u := l.Unfinished(); len(u) != 1 || u[0].Unit != "a.service" { - t.Errorf("unfinished = %+v", u) - } - if late := l.Late(); len(late) != 1 || late[0].Unit != "c.service" { - t.Errorf("late = %+v", late) - } -} - -// A record that ends in an error, or never subscribed, is that and not a boot with no jobs. -func TestParseJobsRefuses(t *testing.T) { - for name, rec := range map[string]string{ - "error": "1000 C\n2000 E subscribing to PID 1: timeout\n", - "no subscribe": "1001 L 1 a.service start waiting\n", - "short line": "1000 C\n1001 R 1 a.service\n", - "unknown event": "1000 C\n1001 Q 1\n", - } { - if _, err := ParseJobs(rec); err == nil { - t.Errorf("%s: parsed", name) - } - } -} - -// Every kind of event has its number of fields, and a line with fewer is an error, not an event -// read short; an E line is jobwatch's own error, said in its words. -func TestParseJobsHoldsEachEventToItsFields(t *testing.T) { - for _, short := range []string{ - "1001 L 1 a.service start", "1001 N 1", "1001 S 1", "1001 R 1 a.service", "1001 A a.service", - } { - if _, err := ParseJobs("1000 C\n" + short + "\n"); err == nil { - t.Errorf("%q: parsed", short) - } - } - _, err := ParseJobs("1000 C\n2000 E subscribing to PID 1: timeout\n") - if err == nil || !strings.Contains(err.Error(), "jobwatch stopped: subscribing to PID 1: timeout") { - t.Errorf("an E line read as %v", err) - } - if _, err := ParseJobs("1000 C\n2000 E\n"); err == nil || !strings.Contains(err.Error(), "jobwatch stopped") { - t.Errorf("a bare E line read as %v", err) - } - l, err := ParseJobs("1000 C\n1500 F\n9000 F already\n") - if err != nil || l.Finished != 1500*time.Microsecond { - t.Errorf("finished at %v (%v); want the plain F line's 1.5ms", l.Finished, err) - } -} - -// What jobwatch saw of each job: queued before it connected or after, when it ran - the first -// state change to running, or else its unit leaving inactive while the job was there - and the -// smallest timestamps, where a comparison with zero is off by one or not. -func TestParseJobsReadsEachJob(t *testing.T) { - l, err := ParseJobs(` -1 C -1 L 7 x.service start waiting -1 L 8 y.service start running -1 N 9 z.service -1 R 7 x.service done -2 S 10 running -3 S 10 running -3 R 10 seen-removed-only.service done -5 R 11 removed-only.service done -1500 N 20 c.service -1400 A c.service activating -1600 A other.service activating -1700 A c.service deactivating -1800 A c.service active -5000 R 20 c.service done -6000 A c.service activating -2000 N 21 pending.service -2100 A pending.service activating -`) - if err != nil { - t.Fatal(err) - } - job := map[string]Job{} - for _, j := range l.Jobs { - job[j.Unit] = j - } - if j := job["seen-removed-only.service"]; j.Running != us(2) { - t.Errorf("the first state change to running is at %v, want 2us", j.Running) - } - if j := job["c.service"]; j.Running != us(1800) { - t.Errorf("c.service ran from %v, want 1.8ms: its unit becoming active after it was queued", j.Running) - } - if j := job["pending.service"]; j.Running != us(2100) || j.Removed != 0 { - t.Errorf("a job still pending ran from %v, removed %v; want 2.1ms and not removed", j.Running, j.Removed) - } - var late []string - for _, j := range l.Late() { - late = append(late, j.Unit) - } - if want := []string{"z.service", "c.service", "pending.service"}; !slices.Equal(late, want) { - t.Errorf("late = %v, want %v: a job listed or seen only removed was queued before", late, want) - } - // At the first microsecond: x was removed, y was running since it was listed, z had just - // been queued, and the two seen only later were there from when jobwatch connected. - waiting, running := l.Pending(us(1)) - if len(running) != 1 || running[0].Unit != "y.service" { - t.Errorf("running at 1us: %v", running) - } - var w []string - for _, j := range waiting { - w = append(w, j.Unit) - } - slices.Sort(w) - if want := []string{"removed-only.service", "seen-removed-only.service", "z.service"}; !slices.Equal(w, want) { - t.Errorf("waiting at 1us: %v, want %v", w, want) - } -} - -// How far behind systemd jobwatch heard a unit become active: once per unit, only for a unit -// that became active after jobwatch subscribed, never a stamp before systemd's. -func TestLagCountsEachUnitOnce(t *testing.T) { - l, err := ParseJobs(` -1000 C -1600 A u.service active -1700 A u.service active -1400 A odd.service active -950 A early.service active -1200 A v.service activating -1300 A gone.service active -`) - if err != nil { - t.Fatal(err) - } - w := NewWaits(Manager{}, []Unit{ - unitAt("u.service", 1400, 1500), - unitAt("odd.service", 1400, 1500), - unitAt("early.service", 800, 900), - unitAt("v.service", 1100, 1150), - }) - if got := l.Lag(w); !slices.Equal(got, []time.Duration{us(100)}) { - t.Errorf("lag = %v, want [100us]", got) - } -} diff --git a/boot/jobwatch/main.go b/boot/jobwatch/main.go deleted file mode 100644 index d36467b..0000000 --- a/boot/jobwatch/main.go +++ /dev/null @@ -1,189 +0,0 @@ -// SPDX-License-Identifier: Apache-2.0 - -// jobwatch records what PID 1 says about its jobs while a guest boots, as they happen: the -// live half of task boot:waits, which reads systemd's timestamps after the fact. It is what -// bootvine (codeberg.org/wvhulle/bootvine) reads to draw its tree, without the tree. -// -// What it sees that the timestamps do not keep: when a job went from waiting to running -// (systemd dispatched it), how each job ended, and jobs queued after the initial transaction -// - socket and path activation, the first login's - with the moment they were queued. -// -// It talks to PID 1 on /run/systemd/private, which exists from PID 1's first moment and before -// any bus daemon; systemd sends every signal to every connection on that socket, Subscribe or -// not, and Subscribe is called anyway because a systemd that changed that would otherwise send -// nothing and this would report a boot with no jobs. Each event is stamped with -// CLOCK_MONOTONIC, systemd's own clock, when it is received, and kept in memory: writing to -// the serial console during the boot is a VM exit per byte inside what is being measured. The -// whole record is written once, after the boot. -// -// Diagnostic input, never part of a release: boot/jobwatch_probe_test.go builds it into a -// boot's own overlay. -// -// jobwatch -// -// writes the record to console once startup has finished, linger has passed since, and -// after-unit (another probe's writer, which shares the console) has gone inactive. -package main - -import ( - "fmt" - "os" - "strconv" - "strings" - "time" - - "github.com/godbus/dbus/v5" - "golang.org/x/sys/unix" -) - -// main is the binary a guest runs, and a guest is what holds it. -// -// mutate-lane: ./boot.TestBootJobs, which boots a guest with jobwatch in it and reads its record. -func main() { - if len(os.Args) != 4 { - fmt.Fprintln(os.Stderr, "usage: jobwatch ") - os.Exit(2) - } - linger, err := time.ParseDuration(os.Args[2]) - if err != nil { - fmt.Fprintf(os.Stderr, "jobwatch: linger %q: %v\n", os.Args[2], err) - os.Exit(2) - } - rec, err := watch(linger, os.Args[3]) - // What was recorded is written even when watching failed: a record that ends early says - // where it ended, and the error is its last line. - if err != nil { - rec = append(rec, fmt.Sprintf("%d E %v", now(), err)) - } - if err := os.WriteFile(os.Args[1], []byte("SPIN-JOBS-BEGIN\n"+strings.Join(rec, "\n")+"\nSPIN-JOBS-END\n"), 0); err != nil { - fmt.Fprintf(os.Stderr, "jobwatch: writing %s: %v\n", os.Args[1], err) - os.Exit(1) - } -} - -// now is CLOCK_MONOTONIC in microseconds, which is what systemd's *TimestampMonotonic are. -// -// mutate-lane: ./boot.TestBootJobs, whose Lag holds these stamps to systemd's own. -func now() int64 { - var ts unix.Timespec - _ = unix.ClockGettime(unix.CLOCK_MONOTONIC, &ts) - return ts.Nano() / 1000 -} - -// watch is the conversation with PID 1 over its private socket, which only a booted guest has. -// -// mutate-lane: ./boot.TestBootJobs, which parses what this recorded with boot.ParseJobs. -func watch(linger time.Duration, after string) ([]string, error) { - var rec []string - add := func(format string, a ...any) { rec = append(rec, fmt.Sprintf("%d ", now())+fmt.Sprintf(format, a...)) } - - conn, err := dbus.Dial("unix:path=/run/systemd/private") - if err != nil { - return rec, fmt.Errorf("connecting to /run/systemd/private: %w", err) - } - defer conn.Close() - // No Hello: there is no bus daemon on this socket to say it to. - if err := conn.Auth(nil); err != nil { - return rec, fmt.Errorf("authenticating to PID 1: %w", err) - } - // Large, because a channel godbus finds full is a signal lost, and a lost JobRemoved is a - // job that reads as never finished. - signals := make(chan *dbus.Signal, 1<<14) - conn.Signal(signals) - - manager := conn.Object("org.freedesktop.systemd1", "/org/freedesktop/systemd1") - // A message that arrives in the same read as the handshake's BEGIN is left unread by PID 1 - // until something else arrives on the socket, so the first message is a ping nobody waits - // for and the second is the one that matters. Without it Subscribe never returned and the - // boot finished around it (2026-11-12); bootvine works around the same thing with libdbus. - if err := manager. - Go("org.freedesktop.DBus.Peer.Ping", dbus.FlagNoReplyExpected, nil).Err; err != nil { - return rec, fmt.Errorf("pinging PID 1: %w", err) - } - if err := manager.Call("org.freedesktop.systemd1.Manager.Subscribe", 0).Err; err != nil { - return rec, fmt.Errorf("subscribing to PID 1: %w", err) - } - add("C") - - // The jobs queued before this connected, which is the initial transaction: when they were - // queued is not known, only that it was before now. - var jobs [][]any - if err := manager.Call("org.freedesktop.systemd1.Manager.ListJobs", 0).Store(&jobs); err != nil { - return rec, fmt.Errorf("listing PID 1's jobs: %w", err) - } - for _, j := range jobs { - add("L %v %v %v %v", j[0], j[1], j[2], j[3]) - } - var finish uint64 - if err := manager.Call("org.freedesktop.DBus.Properties.Get", 0, - "org.freedesktop.systemd1.Manager", "FinishTimestampMonotonic").Store(&finish); err != nil { - return rec, fmt.Errorf("reading FinishTimestampMonotonic: %w", err) - } - finished := finish != 0 - if finished { - add("F already") - } - var lingerUntil <-chan time.Time - if finished { - lingerUntil = time.After(linger) - } - lingered, afterDone := false, false - - for !(lingered && afterDone) { - select { - case <-lingerUntil: - lingered, lingerUntil = true, nil - case s, ok := <-signals: - if !ok { - return rec, fmt.Errorf("PID 1 closed the connection") - } - switch s.Name { - case "org.freedesktop.systemd1.Manager.JobNew": - add("N %v %v", s.Body[0], s.Body[2]) - case "org.freedesktop.systemd1.Manager.JobRemoved": - add("R %v %v %v", s.Body[0], s.Body[2], s.Body[3]) - case "org.freedesktop.systemd1.Manager.StartupFinished": - add("F") - if !finished { - finished, lingerUntil = true, time.After(linger) - } - case "org.freedesktop.DBus.Properties.PropertiesChanged": - iface, _ := s.Body[0].(string) - changed, _ := s.Body[1].(map[string]dbus.Variant) - p := string(s.Path) - switch { - case iface == "org.freedesktop.systemd1.Job": - if v, ok := changed["State"]; ok { - add("S %s %v", strings.TrimPrefix(p, "/org/freedesktop/systemd1/job/"), v.Value()) - } - case iface == "org.freedesktop.systemd1.Unit": - if v, ok := changed["ActiveState"]; ok { - unit := unescape(strings.TrimPrefix(p, "/org/freedesktop/systemd1/unit/")) - add("A %s %v", unit, v.Value()) - if unit == after && (v.Value() == "inactive" || v.Value() == "failed") { - afterDone = true - } - } - } - } - } - } - return rec, nil -} - -// unescape reads a unit's name back from its object path, where systemd writes every byte that -// is not a letter or a digit as _ and two hex digits: dev-vda.device is dev_2dvda_2edevice. -func unescape(s string) string { - var b strings.Builder - for i := 0; i < len(s); i++ { - if s[i] == '_' && i+2 < len(s) { - if n, err := strconv.ParseUint(s[i+1:i+3], 16, 8); err == nil { // mutate-exempt: two hex digits are at most 0xff, which every bit size from 8 up holds - b.WriteByte(byte(n)) - i += 2 - continue - } - } - b.WriteByte(s[i]) - } - return b.String() -} diff --git a/boot/jobwatch/main_test.go b/boot/jobwatch/main_test.go deleted file mode 100644 index 0cd33d5..0000000 --- a/boot/jobwatch/main_test.go +++ /dev/null @@ -1,32 +0,0 @@ -// SPDX-License-Identifier: Apache-2.0 - -package main - -import "testing" - -func TestUnescape(t *testing.T) { - for path, unit := range map[string]string{ - "dev_2dvda_2edevice": "dev-vda.device", - "system_2dserial_5cx2dgetty_2eslice": `system-serial\x2dgetty.slice`, - "serial_2dgetty_40ttyS0_2eservice": "serial-getty@ttyS0.service", - "_2d_2emount": "-.mount", - } { - if got := unescape(path); got != unit { - t.Errorf("unescape(%q) = %q, want %q", path, got, unit) - } - } -} - -// An escape at the very end of a path is read, and an escape cut short is left as it is: a path -// is systemd's, and a unit name may end in one. -func TestUnescapeAtTheEnd(t *testing.T) { - for path, unit := range map[string]string{ - "a_2e": "a.", - "a_2": "a_2", - "a_": "a_", - } { - if got := unescape(path); got != unit { - t.Errorf("unescape(%q) = %q, want %q", path, got, unit) - } - } -} diff --git a/boot/jobwatch_probe_test.go b/boot/jobwatch_probe_test.go deleted file mode 100644 index a3abaae..0000000 --- a/boot/jobwatch_probe_test.go +++ /dev/null @@ -1,250 +0,0 @@ -// SPDX-License-Identifier: Apache-2.0 - -package boot_test - -import ( - "cmp" - "fmt" - "os" - "os/exec" - "path/filepath" - "regexp" - "slices" - "strings" - "testing" - "time" - - "github.com/spin-stack/spin-machine/boot" -) - -// PID 1's job queue as it changed during the boot, recorded live by boot/jobwatch over -// systemd's private socket, beside task boot:waits's account of the same boot. -// -// Live means a process on the guest's vCPUs during the phase being measured, so this -// interleaves boots with jobwatch and without it, and the first table is what recording cost. -// CPUS=3 gives the recorder a vCPU to itself and is compared against three vCPUs without it in -// the same run: a vCPU more is a different machine, and its numbers are not the shipped -// machine's. -// -// After the boot it makes the first SSH login (testdata/first-login.sh) and records the jobs that -// sets off - sshd through ssh.socket, logind, the user's manager - which is the part of being -// usable that a workspace waits for and the boot's own timestamps never contain. -// -// SPIN_BOOT_JOBS=1 run at all -// REPS= boots of each variant (default 5) -// CPUS= vCPUs of both (default 2) -// LINGER= how long jobwatch keeps recording after startup finishes (default 2s) -// BUCKET= the queue's resolution over time (default 10) -// RAW= also write each recorded boot's two dumps there, as testdata is made -// TARGET=, TOP=, GAP= as task boot:waits -func TestBootJobs(t *testing.T) { - if os.Getenv("SPIN_BOOT_JOBS") == "" { - t.Skip("set SPIN_BOOT_JOBS=1: boots VMs and needs sudo to write into their overlays") - } - out := releaseDir(t) - if !canSudo() { - t.Skip("this writes a unit and a binary into the boot's own overlay through qemu-nbd, which needs sudo") - } - reps := envInt(t, "REPS", 5) - top := envInt(t, "TOP", 15) - minGap := time.Duration(envInt(t, "GAP", 1)) * time.Millisecond - bucket := time.Duration(envInt(t, "BUCKET", 10)) * time.Millisecond - target := cmp.Or(os.Getenv("TARGET"), "serial-getty@ttyS0.service") - raw := os.Getenv("RAW") - linger := cmp.Or(os.Getenv("LINGER"), "2s") - if _, err := time.ParseDuration(linger); err != nil { - t.Fatalf("LINGER=%q: %v", linger, err) - } - - // Static, because it runs in a guest whose libraries are not this host's. - bin := filepath.Join(t.TempDir(), "spin-jobwatch") - build := exec.Command("go", "build", "-trimpath", "-ldflags=-s -w", "-o", bin, "./jobwatch") - build.Env = append(os.Environ(), "CGO_ENABLED=0") - if b, err := build.CombinedOutput(); err != nil { - t.Fatalf("building jobwatch: %v\n%s", err, b) - } - - plain := waitsVariant(cmp.Or(os.Getenv("CPUS"), "2")) - watched := waitsVariant(plain.cpus) - watched.label = "jobwatch" - // DefaultDependencies=no and nothing it is ordered after, so it starts with the first - // dispatch of the initial transaction. It writes its record once spin-login.service is - // done, since everything here shares the console. - watched.files["/etc/systemd/system/spin-jobwatch.service"] = `[Unit] -Description=Record PID 1's jobs as they happen -DefaultDependencies=no -[Service] -Type=simple -ExecStart=/usr/local/sbin/spin-jobwatch /dev/ttyS0 ` + linger + ` spin-login.service -[Install] -WantedBy=sysinit.target -` - watched.links["/etc/systemd/system/sysinit.target.wants/spin-jobwatch.service"] = "/etc/systemd/system/spin-jobwatch.service" - watched.setup = `install -D -m 0755 ` + bin + ` "$MNT/usr/local/sbin/spin-jobwatch"` - - // The first SSH login, started when spin-waits.service exits rather than wanted by a - // target: a oneshot in the initial transaction would hold startup open until it was done, - // and move the finish timestamp boot:waits reads. - script, err := os.ReadFile(filepath.Join("testdata", "first-login.sh")) - if err != nil { - t.Fatal(err) - } - watched.files["/usr/local/sbin/spin-first-login.sh"] = string(script) - watched.files["/etc/systemd/system/spin-login.service"] = `[Unit] -Description=The first SSH login, for jobwatch to record -[Service] -Type=oneshot -StandardOutput=null -ExecStart=/bin/sh /usr/local/sbin/spin-first-login.sh -` - watched.files["/etc/systemd/system/spin-waits.service.d/login.conf"] = "[Service]\nExecStopPost=/bin/systemctl start --no-block spin-login.service\n" - - type jobsBoot struct { - waitsBoot - log boot.JobLog - login string // the first SSH login in ms as the guest timed it, or FAIL - again string // a second, right after it - cold string // a third, after the page cache was dropped - } - var base []waitsBoot - var rec []jobsBoot - for rep := range reps { - base = append(base, bootWaits(t, out, plain, target, "SPIN-WAITS-END")) - b := bootWaits(t, out, watched, target, "SPIN-JOBS-END") - s := b.console - begin, stop := strings.Index(s, "SPIN-JOBS-BEGIN"), strings.Index(s, "SPIN-JOBS-END") - if begin < 0 || stop < begin { - t.Fatalf("no record between SPIN-JOBS-BEGIN and -END; tail:\n%s", tail([]byte(s), 2000)) - } - record := s[begin+len("SPIN-JOBS-BEGIN") : stop] - if raw != "" { - for name, content := range map[string]string{"waits": b.dump, "jobs": record} { - f := filepath.Join(raw, fmt.Sprintf("%s-%02d.txt", name, rep+1)) - if err := os.WriteFile(f, []byte(content), 0o644); err != nil { - t.Fatalf("writing %s: %v", f, err) - } - } - } - l, err := boot.ParseJobs(record) - if err != nil { - t.Fatalf("reading jobwatch's record: %v", err) - } - m := reFirstLogin.FindStringSubmatch(s) - if m == nil { - t.Fatalf("no SPIN-LOGIN line: the first login did not run; tail:\n%s", tail([]byte(s), 2000)) - } - rec = append(rec, jobsBoot{b, l, m[1], m[2], m[3]}) - } - - ms := func(d time.Duration) string { return fmt.Sprintf("%.1f", float64(d)/float64(time.Millisecond)) } - p := func(ds []time.Duration, q float64) string { d, _ := boot.Percentile(ds, q); return ms(d) } - var b strings.Builder - - fmt.Fprintf(&b, "\nWHAT RECORDING COSTS: ms on the host's clock, p50/p95 over %d boots of each, %s vCPUs, interleaved\n\n", reps, plain.cpus) - fmt.Fprintf(&b, " %-12s %15s %15s %15s\n", "", "UNITS LOADED", "GETTY FORKED", "LOGIN") - row := func(name string, bs []waitsBoot) { - var loaded, forked, login []time.Duration - for _, x := range bs { - loaded = append(loaded, x.kernel+x.w.Manager.UnitsLoadFinish) - forked = append(forked, x.kernel+x.target().Start) - login = append(login, x.kernel+x.usable) - } - fmt.Fprintf(&b, " %-12s %7s/%-7s %7s/%-7s %7s/%-7s\n", name, - p(loaded, .5), p(loaded, .95), p(forked, .5), p(forked, .95), p(login, .5), p(login, .95)) - } - row("without", base) - var recW []waitsBoot - for _, x := range rec { - recW = append(recW, x.waitsBoot) - } - row("jobwatch", recW) - - var logins, again, cold []string - for _, x := range rec { - logins, again, cold = append(logins, x.login), append(again, x.again), append(cold, x.cold) - } - fmt.Fprintf(&b, "\n SSH logins after the boot, ms as the guest timed them, p50 / p95 / max\n"+ - " the first %s\n a second, right after %s\n a third, page cache dropped %s\n", - loginSummary(logins), loginSummary(again), loginSummary(cold)) - - var lag []time.Duration - var connected []time.Duration - for _, x := range rec { - lag = append(lag, x.log.Lag(x.w)...) - connected = append(connected, x.log.Connected) - } - fmt.Fprintf(&b, "\n jobwatch subscribed at %s ms of guest time (p50), units loaded at %s; it heard a unit\n"+ - " become active %s ms after systemd stamped it (p50, p95 %s, %d events)\n", - p(connected, .5), ms(rec[0].w.Manager.UnitsLoadFinish), p(lag, .5), p(lag, .95), len(lag)) - - med := slices.Clone(rec) - slices.SortFunc(med, func(a, c jobsBoot) int { return cmp.Compare(a.kernel+a.usable, c.kernel+c.usable) }) - x := med[len(med)/2] - login := max(x.usable, x.target().Ready) - fmt.Fprintf(&b, "\nTHE MEDIAN RECORDED BOOT, login at %s ms; guest ms from the kernel's start\n", ms(x.kernel+x.usable)) - - // The queue over time: what bootvine's tree is, one line per bucket. Running is systemd - // working on a job - a service starting, a device job waiting for udev - and waiting is a - // job held behind another's ordering. - fmt.Fprintf(&b, "\n PID 1's queue every %s ms, from jobwatch subscribing to the login\n\n", ms(bucket)) - fmt.Fprintf(&b, " %8s %7s %7s %s\n", "AT", "WAITING", "RUNNING", "RUNNING JOBS") - for at := x.log.Connected.Truncate(bucket) + bucket; at <= login+bucket; at += bucket { - waiting, running := x.log.Pending(at) - var names []string - for _, j := range running { - names = append(names, j.Unit) - } - slices.Sort(names) - fmt.Fprintf(&b, " %8s %7d %7d %s\n", ms(at), len(waiting), len(running), clipList(names, 4)) - } - - // What systemd was doing while no unit was activating: the running jobs are what it was - // waiting on, and a gap with none was systemd's own time. - fmt.Fprintf(&b, "\n the boot:waits gaps, with the jobs that were running through them\n\n") - for _, g := range x.w.Gaps(x.target().Start, minGap) { - mid := g.From + (g.To-g.From)/2 - _, running := x.log.Pending(mid) - var names []string - for _, j := range running { - names = append(names, j.Unit) - } - slices.Sort(names) - what := clipList(names, 4) - if g.From < x.log.Connected { - what += " (jobwatch not yet subscribed for part of it)" - } - fmt.Fprintf(&b, " %8s %8s %7s %s\n", ms(g.From), ms(g.To), ms(g.To-g.From), cmp.Or(what, "(no job running)")) - } - - unfinished := x.log.Unfinished() - fmt.Fprintf(&b, "\n jobs that did not end done: %d\n\n", len(unfinished)) - for _, j := range unfinished[:min(top, len(unfinished))] { - fmt.Fprintf(&b, " %8s %-10s %s\n", ms(j.Removed), cmp.Or(j.Result, "pending"), j.Unit) - } - - late := x.log.Late() - fmt.Fprintf(&b, "\n jobs queued after jobwatch subscribed: %d (startup finished at %s; the first login took %s ms)\n\n", - len(late), ms(x.w.Manager.Finish), x.login) - fmt.Fprintf(&b, " %8s %8s %8s %-10s %s\n", "QUEUED", "RUNNING", "REMOVED", "RESULT", "UNIT") - for _, j := range late[:min(top, len(late))] { - fmt.Fprintf(&b, " %8s %8s %8s %-10s %s\n", ms(j.Queued), msOrDash(j.Running), msOrDash(j.Removed), cmp.Or(j.Result, "pending"), j.Unit) - } - t.Log(b.String()) -} - -// SPIN-LOGIN 123 again=45 cold=80, any of them FAIL: testdata/first-login.sh's one line. -var reFirstLogin = regexp.MustCompile(`SPIN-LOGIN (\d+|FAIL) again=(\d+|FAIL) cold=(\d+|FAIL)`) - -func msOrDash(d time.Duration) string { - if d == 0 { - return "-" - } - return fmt.Sprintf("%.1f", float64(d)/float64(time.Millisecond)) -} - -func clipList(names []string, n int) string { - if len(names) <= n { - return strings.Join(names, " ") - } - return strings.Join(names[:n], " ") + fmt.Sprintf(" +%d", len(names)-n) -} diff --git a/boot/mmio_test.go b/boot/mmio_test.go deleted file mode 100644 index d977809..0000000 --- a/boot/mmio_test.go +++ /dev/null @@ -1,170 +0,0 @@ -// SPDX-License-Identifier: Apache-2.0 - -package boot_test - -import ( - "cmp" - "fmt" - "os" - "os/exec" - "path/filepath" - "regexp" - "slices" - "strings" - "syscall" - "testing" - "time" -) - -// Who the guest's exits to QEMU are, counted: every PCI configuration access by device and -// direction, and every MMIO and port access by the memory region QEMU dispatched it to, from a -// launch to the login prompt, from QEMU's own trace (pci_cfg_read/write, -// memory_region_ops_read/write). -// -// boot:exits says how many exits each phase has and the bench fleet says what one costs - -// about 20 us for an MMIO exit there, against a few on a laptop (2026-11-12). This says whose -// they are, which is what a change to the kernel or to QEMU acts on. Counts, not times, so it -// answers the same on any host. -// -// QEMU itself also writes to some of these regions (an MSI it raises through kvm-apic-msi), so -// a region's count is accesses, not only exits; PCI configuration and the devices' BARs are the -// guest's. -// -// SPIN_BOOT_MMIO=1 run at all -// SPIN_KERNEL_B= a second kernel, counted beside the release's -// TOP= regions to list (default 20) -func TestMMIOCensus(t *testing.T) { - if os.Getenv("SPIN_BOOT_MMIO") == "" { - t.Skip("set SPIN_BOOT_MMIO=1: boots a VM with QEMU tracing every device access") - } - out := releaseDir(t) - top := envInt(t, "TOP", 20) - cli := filepath.Join(out, "bin", "spin-machine") - - kernels := []struct{ label, path string }{{"release", ""}} - if k := kernelB(t); k != "" { - kernels = append(kernels, struct{ label, path string }{"kernel B", k}) - } - counts := map[string]map[string]int{} - var keys []string - for _, k := range kernels { - // Without --disk the base is under QEMU's -snapshot, so nothing is written to it and no - // overlay needs sudo. The getty is agetty, whose second only adds what an idle guest does. - flags := []string{"--memory", "2048", "--cpus", "2"} - if k.path != "" { - flags = append(flags, "--kernel", k.path) - } - c := mmioCensus(t, machineArgs(t, cli, out, flags)) - counts[k.label] = c - for key := range c { - if !slices.Contains(keys, key) { - keys = append(keys, key) - } - } - } - - var b strings.Builder - fmt.Fprintf(&b, "\naccesses from a launch to the login prompt, by QEMU's trace\n\n %-52s", "") - for _, k := range kernels { - fmt.Fprintf(&b, " %10s", k.label) - } - b.WriteString("\n") - row := func(key string) { - fmt.Fprintf(&b, " %-52s", key) - for _, k := range kernels { - fmt.Fprintf(&b, " %10d", counts[k.label][key]) - } - b.WriteString("\n") - } - // Configuration accesses by device first, then regions by how busy they were on the release. - slices.SortFunc(keys, func(a, c string) int { - ca, cc := strings.HasPrefix(a, "config "), strings.HasPrefix(c, "config ") - if ca != cc { - if ca { - return -1 - } - return 1 - } - return cmp.Or(cmp.Compare(counts["release"][c], counts["release"][a]), cmp.Compare(a, c)) - }) - n := 0 - for _, key := range keys { - if strings.HasPrefix(key, "config ") || n < top { - if !strings.HasPrefix(key, "config ") { - n++ - } - row(key) - } - } - t.Log(b.String()) -} - -var ( - // "… pci_cfg_read virtio-rng-pci 00:03.0 @0x6 -> 0x10" - rePCICfg = regexp.MustCompile(`pci_cfg_(read|write) (\S+) (\S+) @`) - // "… memory_region_ops_read cpu 0 mr 0x… addr 0xcfc value 0x… size 4 name 'pci-conf-data'" - reMROps = regexp.MustCompile(`memory_region_ops_(read|write) .* name '([^']*)'`) -) - -// mmioCensus boots QEMU with args, its device accesses traced, until the login prompt, and -// counts them: "config " and "region ". -func mmioCensus(t *testing.T, args []string) map[string]int { - t.Helper() - dir := t.TempDir() - log := filepath.Join(dir, "trace") - full := append(slices.Clone(args[1:]), "-D", log) - for _, ev := range []string{"pci_cfg_read", "pci_cfg_write", "memory_region_ops_read", "memory_region_ops_write"} { - full = append(full, "-trace", "enable="+ev) - } - cmd := exec.Command(args[0], full...) - cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} - r, w, err := os.Pipe() - if err != nil { - t.Fatal(err) - } - cmd.Stdout, cmd.Stderr = w, w - if err := cmd.Start(); err != nil { - t.Fatalf("launching QEMU: %v", err) - } - _ = w.Close() - defer func() { - _ = syscall.Kill(-cmd.Process.Pid, syscall.SIGKILL) - _ = cmd.Wait() - _ = r.Close() - }() - var console strings.Builder - buf := make([]byte, 65536) - deadline := time.Now().Add(90 * time.Second) - for !strings.Contains(console.String(), "login:") { - if err := r.SetReadDeadline(deadline); err != nil { - t.Fatal(err) - } - n, err := r.Read(buf) - console.Write(buf[:n]) - if err != nil { - t.Fatalf("no login prompt: %v\n%s", err, tail([]byte(console.String()), 2000)) - } - } - // QEMU writes its trace as it goes; what is in the file at the prompt is the boot. - raw, err := os.ReadFile(log) - if err != nil { - t.Fatal(err) - } - c := map[string]int{} - for line := range strings.SplitSeq(string(raw), "\n") { - if m := rePCICfg.FindStringSubmatch(line); m != nil { - // An empty slot is a vendor ID read or two, and there are dozens: one row. - if m[2] == "empty" { - m[3] = "slots" - } - c["config "+m[2]+" "+m[3]+" "+m[1]]++ - } else if m := reMROps.FindStringSubmatch(line); m != nil { - c["region "+m[2]]++ - } - } - if len(c) == 0 { - t.Fatalf("the trace counted nothing: QEMU without its log trace backend, or a format this does not read; its start:\n%s", - tail(raw[:min(len(raw), 2000)], 2000)) - } - return c -} diff --git a/boot/ssh_first_test.go b/boot/ssh_first_test.go index fe55ffb..27fed67 100644 --- a/boot/ssh_first_test.go +++ b/boot/ssh_first_test.go @@ -37,8 +37,8 @@ import ( // same boot, with the getty an echo as boot:bench's baseline has it, so the two read side by // side. // -// What `login` holds beyond `listen` is the first login's own chain, which boot:jobs records -// from inside: sshd's host keys generated, the key exchange, PAM, logind, the user's manager. +// What `login` holds beyond `listen` is the first login's own chain: sshd's host keys, the key +// exchange, PAM, logind, the user's manager. // // SPIN_SSH_FIRST=1 run at all // REPS= boots of each row (default 10) diff --git a/boot/testdata/first-login.sh b/boot/testdata/first-login.sh deleted file mode 100644 index 37d5c8f..0000000 --- a/boot/testdata/first-login.sh +++ /dev/null @@ -1,32 +0,0 @@ -#!/bin/sh -# SPDX-License-Identifier: Apache-2.0 -# The first SSH login into a guest that has just booted, for task boot:jobs: jobwatch records -# the jobs it sets off - sshd through ssh.socket, logind, the user's manager. Diagnostic, in a -# disposable test guest; runs once, as root, after spin-waits.service has written its dump. -set -eu - -ssh-keygen -q -t ed25519 -N '' -f /run/first-login-key -install -d -m 700 -o spin -g spin /home/spin/.ssh -install -m 600 -o spin -g spin /run/first-login-key.pub /home/spin/.ssh/authorized_keys - -# One login, in ms, or FAIL. -login() { - t0=$(date +%s%N) - if timeout 30 ssh -F /dev/null -i /run/first-login-key -o BatchMode=yes \ - -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o LogLevel=error \ - spin@127.0.0.1 true /proc/sys/vm/drop_caches -cold=$(login) -echo "SPIN-LOGIN $first again=$again cold=$cold" >/dev/ttyS0 diff --git a/boot/testdata/jobs-2026-11-12.txt b/boot/testdata/jobs-2026-11-12.txt deleted file mode 100644 index 85095e5..0000000 --- a/boot/testdata/jobs-2026-11-12.txt +++ /dev/null @@ -1,173 +0,0 @@ - -113569 C -113687 L 54 dbus.socket start waiting -113689 L 59 docker.socket start waiting -113690 L 64 systemd-user-sessions.service start waiting -113690 L 55 systemd-hostnamed.socket start waiting -113691 L 51 ssh.socket start waiting -113691 L 63 spin-waits.service start waiting -113691 L 52 sshd-keygen.service start waiting -113692 L 29 systemd-pcrphase-sysinit.service start waiting -113692 L 27 systemd-udev-trigger.service start running -113693 L 31 systemd-tmpfiles-setup.service start waiting -113693 L 43 systemd-tmpfiles-clean.timer start waiting -113693 L 66 getty-static.service start waiting -113694 L 44 fstrim.timer start waiting -113694 L 3 sysinit.target start waiting -113695 L 67 getty@tty1.service start waiting -113695 L 16 systemd-udevd.service start running -113697 L 73 dev-ttyS0.device start running -113698 L 2 basic.target start waiting -113698 L 65 getty.target start waiting -113699 L 1 multi-user.target start waiting -113699 L 61 containerd.socket start waiting -113699 L 57 systemd-logind-varlink.socket start waiting -113700 L 42 timers.target start waiting -113700 L 10 systemd-pcrphase.service start waiting -113700 L 48 sshd-unix-local.socket start waiting -113701 L 35 systemd-journald.service start running -113701 L 71 serial-getty@ttyS0.service start waiting -113701 L 47 sockets.target start waiting -123367 A systemd-journald.service active -123371 R 35 systemd-journald.service done -123372 A systemd-journald-dev-log.socket active -123373 A systemd-journald.socket active -123373 A systemd-journald.service active -125130 A systemd-tmpfiles-setup.service inactive -125132 A systemd-tmpfiles-setup.service activating -125132 S 31 running -128160 A systemd-tmpfiles-setup.service activating -131111 A systemd-udevd.service activating -131548 A systemd-udevd-kernel.socket active -134281 A systemd-tmpfiles-setup.service active -134282 R 31 systemd-tmpfiles-setup.service done -134283 A systemd-tmpfiles-setup.service active -135254 A systemd-udev-trigger.service active -135255 R 27 systemd-udev-trigger.service done -135256 A systemd-udev-trigger.service active -139087 A systemd-udevd.service active -139088 R 16 systemd-udevd.service done -139090 A systemd-udevd-control.socket active -139248 A systemd-udevd-varlink.socket active -139467 A systemd-udevd-kernel.socket active -139766 A systemd-udevd.service active -139768 A sysinit.target inactive -139768 A sysinit.target active -139987 R 3 sysinit.target done -140711 A fstrim.timer inactive -140712 A fstrim.timer active -140712 R 44 fstrim.timer done -140713 A systemd-tmpfiles-clean.timer inactive -140714 A systemd-tmpfiles-clean.timer active -140714 R 43 systemd-tmpfiles-clean.timer done -140715 A timers.target inactive -140715 A timers.target active -140715 R 42 timers.target done -140716 A containerd.socket inactive -140716 A containerd.socket activating -140717 A dbus.socket inactive -140717 A dbus.socket activating -140718 A dbus.socket active -140718 R 54 dbus.socket done -140719 A docker.socket inactive -141020 A docker.socket activating -141022 A ssh.socket inactive -141958 A ssh.socket activating -143273 A ssh.socket active -143274 R 51 ssh.socket done -143276 A sshd-unix-local.socket inactive -143276 A sshd-unix-local.socket activating -143277 A sshd-unix-local.socket active -143277 R 48 sshd-unix-local.socket done -143278 A systemd-hostnamed.socket inactive -143279 A systemd-hostnamed.socket activating -143279 A systemd-hostnamed.socket active -143279 R 55 systemd-hostnamed.socket done -145175 A systemd-logind-varlink.socket inactive -145177 A systemd-pcrphase-sysinit.service inactive -145178 R 29 systemd-pcrphase-sysinit.service done -145179 A systemd-pcrphase-sysinit.service inactive -145179 A systemd-logind-varlink.socket activating -145180 A systemd-hostnamed.socket active -145181 A sshd-unix-local.socket active -145182 A -.mount active -145183 A shutdown.target inactive -145184 A basic.target inactive -145184 A system-sshd.slice inactive -146625 A sshd-keygen.service inactive -146702 A auditd.service inactive -148174 A nss-user-lookup.target inactive -148176 A ssh.socket active -148177 A docker.socket activating -148178 A dbus.socket active -148179 A containerd.socket activating -148180 A timers.target active -148181 A systemd-tmpfiles-clean.timer active -148181 A fstrim.timer active -148182 A sysinit.target active -148182 S 57 running -148183 S 59 running -148183 S 61 running -148184 A containerd.socket active -148185 R 61 containerd.socket done -148186 A containerd.socket active -148186 A docker.socket active -151131 R 59 docker.socket done -151205 A docker.socket active -151277 A systemd-logind-varlink.socket activating -151278 A systemd-logind-varlink.socket activating -151354 A systemd-logind-varlink.socket active -151355 R 57 systemd-logind-varlink.socket done -151419 A systemd-logind-varlink.socket active -151484 A sockets.target inactive -151484 A sockets.target active -151485 R 47 sockets.target done -151634 A basic.target inactive -151635 A basic.target active -151635 R 2 basic.target done -151854 A getty-static.service inactive -151930 R 66 getty-static.service done -152161 A sshd-keygen.service inactive -152397 R 52 sshd-keygen.service done -152476 A systemd-pcrphase.service inactive -152618 R 10 systemd-pcrphase.service done -152761 A systemd-user-sessions.service inactive -153133 A systemd-user-sessions.service activating -153198 A systemd-pcrphase.service inactive -154174 A sshd-keygen.service inactive -154428 A getty-static.service inactive -154429 A basic.target active -154500 A sockets.target active -155090 S 64 running -155091 A systemd-user-sessions.service activating -156913 A systemd-user-sessions.service active -157762 R 64 systemd-user-sessions.service done -157764 A systemd-user-sessions.service active -157767 A getty@tty1.service inactive -157767 R 67 getty@tty1.service done -157768 A getty@tty1.service inactive -162125 A dev-ttyS0.device inactive -162127 A dev-ttyS0.device active -162127 R 73 dev-ttyS0.device done -162128 A dev-ttyS0.device active -164817 A serial-getty@ttyS0.service inactive -164819 A serial-getty@ttyS0.service active -164820 R 71 serial-getty@ttyS0.service done -164820 A getty.target inactive -164821 A getty.target active -164821 R 65 getty.target done -164822 A multi-user.target inactive -164822 A multi-user.target active -164823 R 1 multi-user.target done -167669 A spin-waits.service inactive -167671 A spin-waits.service active -167672 R 63 spin-waits.service done -167672 F -167674 A spin-waits.service active -167675 A multi-user.target active -167676 A getty.target active -167676 A serial-getty@ttyS0.service active -168521 A spin-waits.service active -170950 A dev-vda.device active -174370 A serial-getty@ttyS0.service active -496843 A spin-waits.service inactive diff --git a/boot/testdata/jobs-waits-2026-11-12.txt b/boot/testdata/jobs-waits-2026-11-12.txt deleted file mode 100644 index 6fdea1e..0000000 --- a/boot/testdata/jobs-waits-2026-11-12.txt +++ /dev/null @@ -1,1545 +0,0 @@ - -UserspaceTimestampMonotonic=41505 -FinishTimestampMonotonic=166958 -SecurityStartTimestampMonotonic=41781 -SecurityFinishTimestampMonotonic=42526 -GeneratorsStartTimestampMonotonic=69753 -GeneratorsFinishTimestampMonotonic=73517 -UnitsLoadStartTimestampMonotonic=73521 -UnitsLoadFinishTimestampMonotonic=75378 -SPIN-WAITS-UNITS -Id=proc-sys-fs-binfmt_misc.automount -Names=proc-sys-fs-binfmt_misc.automount -After=-.mount -ActiveState=active -InactiveExitTimestampMonotonic=95891 -ActiveEnterTimestampMonotonic=95891 -InactiveEnterTimestampMonotonic=0 - -Id=dev-disk-by\x2ddiskseq-9.device -Names="dev-disk-by\\x2ddiskseq-9.device" -After= -ActiveState=active -InactiveExitTimestampMonotonic=170246 -ActiveEnterTimestampMonotonic=170246 -InactiveEnterTimestampMonotonic=0 - -Id=dev-disk-by\x2dpath-pci\x2d0000:00:05.0.device -Names="dev-disk-by\\x2dpath-pci\\x2d0000:00:05.0.device" -After= -ActiveState=active -InactiveExitTimestampMonotonic=170248 -ActiveEnterTimestampMonotonic=170248 -InactiveEnterTimestampMonotonic=0 - -Id=dev-disk-by\x2dpath-virtio\x2dpci\x2d0000:00:05.0.device -Names="dev-disk-by\\x2dpath-virtio\\x2dpci\\x2d0000:00:05.0.device" -After= -ActiveState=active -InactiveExitTimestampMonotonic=170246 -ActiveEnterTimestampMonotonic=170246 -InactiveEnterTimestampMonotonic=0 - -Id=dev-tpm0.device -Names=dev-tpm0.device -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=dev-tpmrm0.device -Names=dev-tpmrm0.device -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=dev-ttyS0.device -Names=dev-ttyS0.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=161190 -ActiveEnterTimestampMonotonic=161190 -InactiveEnterTimestampMonotonic=0 - -Id=dev-ttyS1.device -Names=dev-ttyS1.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=175773 -ActiveEnterTimestampMonotonic=175773 -InactiveEnterTimestampMonotonic=0 - -Id=dev-ttyS2.device -Names=dev-ttyS2.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=175306 -ActiveEnterTimestampMonotonic=175306 -InactiveEnterTimestampMonotonic=0 - -Id=dev-ttyS3.device -Names=dev-ttyS3.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=170691 -ActiveEnterTimestampMonotonic=170691 -InactiveEnterTimestampMonotonic=0 - -Id=dev-vda.device -Names=dev-vda.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=75454 -ActiveEnterTimestampMonotonic=170247 -InactiveEnterTimestampMonotonic=0 - -Id=sys-devices-pci0000:00-0000:00:05.0-virtio2-block-vda.device -Names=sys-devices-pci0000:00-0000:00:05.0-virtio2-block-vda.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=170244 -ActiveEnterTimestampMonotonic=170244 -InactiveEnterTimestampMonotonic=0 - -Id=sys-devices-platform-serial8250-serial8250:0-serial8250:0.1-tty-ttyS1.device -Names=sys-devices-platform-serial8250-serial8250:0-serial8250:0.1-tty-ttyS1.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=175774 -ActiveEnterTimestampMonotonic=175774 -InactiveEnterTimestampMonotonic=0 - -Id=sys-devices-platform-serial8250-serial8250:0-serial8250:0.2-tty-ttyS2.device -Names=sys-devices-platform-serial8250-serial8250:0-serial8250:0.2-tty-ttyS2.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=175304 -ActiveEnterTimestampMonotonic=175304 -InactiveEnterTimestampMonotonic=0 - -Id=sys-devices-platform-serial8250-serial8250:0-serial8250:0.3-tty-ttyS3.device -Names=sys-devices-platform-serial8250-serial8250:0-serial8250:0.3-tty-ttyS3.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=170692 -ActiveEnterTimestampMonotonic=170692 -InactiveEnterTimestampMonotonic=0 - -Id=sys-devices-pnp0-00:02-00:02:0-00:02:0.0-tty-ttyS0.device -Names=sys-devices-pnp0-00:02-00:02:0-00:02:0.0-tty-ttyS0.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=159900 -ActiveEnterTimestampMonotonic=159900 -InactiveEnterTimestampMonotonic=0 - -Id=sys-devices-virtual-net-sit0.device -Names=sys-devices-virtual-net-sit0.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=161623 -ActiveEnterTimestampMonotonic=161623 -InactiveEnterTimestampMonotonic=0 - -Id=sys-subsystem-net-devices-sit0.device -Names=sys-subsystem-net-devices-sit0.device -After= -ActiveState=active -InactiveExitTimestampMonotonic=161621 -ActiveEnterTimestampMonotonic=161621 -InactiveEnterTimestampMonotonic=0 - -Id=-.mount -Names=-.mount -After=-.slice -ActiveState=active -InactiveExitTimestampMonotonic=75445 -ActiveEnterTimestampMonotonic=75445 -InactiveEnterTimestampMonotonic=0 -Type=ext4 - -Id=dev-hugepages.mount -Names=dev-hugepages.mount -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=dev-mqueue.mount -Names=dev-mqueue.mount -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=home.mount -Names=home.mount -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=proc-sys-fs-binfmt_misc.mount -Names=proc-sys-fs-binfmt_misc.mount -After=systemd-journald.socket -.slice -.mount proc-sys-fs-binfmt_misc.automount -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=binfmt_misc - -Id=sys-fs-fuse-connections.mount -Names=sys-fs-fuse-connections.mount -After=modprobe@fuse.service systemd-journald.socket -.slice -.mount -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=fusectl - -Id=sys-kernel-config.mount -Names=sys-kernel-config.mount -After=systemd-journald.socket -.mount modprobe@configfs.service -.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=configfs - -Id=sys-kernel-debug.mount -Names=sys-kernel-debug.mount -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=sys-kernel-tracing.mount -Names=sys-kernel-tracing.mount -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=tmp.mount -Names=tmp.mount -After=swap.target system.slice systemd-journald.socket -.mount -ActiveState=active -InactiveExitTimestampMonotonic=98299 -ActiveEnterTimestampMonotonic=105664 -InactiveEnterTimestampMonotonic=0 -Type=tmpfs - -Id=systemd-ask-password-console.path -Names=systemd-ask-password-console.path -After=-.mount plymouth-start.service -ActiveState=active -InactiveExitTimestampMonotonic=95826 -ActiveEnterTimestampMonotonic=95826 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-ask-password-wall.path -Names=systemd-ask-password-wall.path -After=-.mount -ActiveState=active -InactiveExitTimestampMonotonic=95838 -ActiveEnterTimestampMonotonic=95838 -InactiveEnterTimestampMonotonic=0 - -Id=init.scope -Names=init.scope -After=-.slice -ActiveState=active -InactiveExitTimestampMonotonic=75443 -ActiveEnterTimestampMonotonic=75443 -InactiveEnterTimestampMonotonic=0 - -Id=apparmor.service -Names=apparmor.service -After=systemd-journald-audit.socket systemd-journald.socket -.mount system.slice systemd-sysctl.service local-fs.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=auditd.service -Names=auditd.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=containerd.service -Names=containerd.service -After=basic.target containerd.socket sysinit.target dbus-broker.service network.target systemd-journald.socket system.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=notify - -Id=dbus-broker.service -Names=dbus-broker.service dbus.service -After=-.mount systemd-journald.socket dbus.socket system.slice systemd-tmpfiles-setup.service tmp.mount -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=notify-reload - -Id=docker.service -Names=docker.service -After=basic.target time-set.target sysinit.target network-online.target containerd.service nss-lookup.target systemd-journald.socket firewalld.service system.slice docker.socket -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=notify - -Id=emergency.service -Names=emergency.service -After=-.mount systemd-ask-password-wall.path systemd-ask-password-console.path system.slice sysinit.target systemd-ask-password-console.service syslog.socket -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=idle - -Id=firewalld.service -Names=firewalld.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=fstrim.service -Names=fstrim.service -After=systemd-journald.socket sysinit.target system.slice basic.target fstrim.timer -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=getty-static.service -Names=getty-static.service -After=systemd-journald.socket system.slice basic.target sysinit.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=getty@tty1.service -Names=getty@tty1.service autovt@tty1.service -After=system-getty.slice basic.target getty-pre.target plymouth-quit-wait.service systemd-user-sessions.service rc-local.service sysinit.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=idle - -Id=initrd-cleanup.service -Names=initrd-cleanup.service -After=system.slice initrd-fs.target initrd.target initrd-root-fs.target systemd-journald.socket -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=initrd-parse-etc.service -Names=initrd-parse-etc.service -After=initrd-root-fs.target system.slice systemd-journald.socket -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=initrd-switch-root.service -Names=initrd-switch-root.service -After=system.slice initrd-switch-root.target systemd-journald.socket systemd-udevd.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=initrd-udevadm-cleanup-db.service -Names=initrd-udevadm-cleanup-db.service -After=systemd-udev-settle.service systemd-udev-trigger.service systemd-udevd.service system.slice systemd-journald.socket -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=kmod-static-nodes.service -Names=kmod-static-nodes.service -After=system.slice systemd-journald.socket -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=ldconfig.service -Names=ldconfig.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=modprobe@configfs.service -Names=modprobe@configfs.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=modprobe@dm_mod.service -Names=modprobe@dm_mod.service -After=system-modprobe.slice systemd-journald.socket -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=modprobe@drm.service -Names=modprobe@drm.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=modprobe@fuse.service -Names=modprobe@fuse.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=modprobe@loop.service -Names=modprobe@loop.service -After=system-modprobe.slice systemd-journald.socket -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=plymouth-quit-wait.service -Names=plymouth-quit-wait.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=plymouth-start.service -Names=plymouth-start.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=rc-local.service -Names=rc-local.service -After=basic.target sysinit.target systemd-journald.socket system.slice network.target network-online.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=forking - -Id=rescue.service -Names=rescue.service -After=sysinit.target system.slice getty@tty1.service serial-getty@ttyS0.service plymouth-start.service emergency.service -.mount -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=idle - -Id=serial-getty@ttyS0.service -Names=serial-getty@ttyS0.service -After=systemd-user-sessions.service dev-ttyS0.device basic.target plymouth-quit-wait.service rc-local.service getty-pre.target "system-serial\\x2dgetty.slice" sysinit.target -ActiveState=active -InactiveExitTimestampMonotonic=164226 -ActiveEnterTimestampMonotonic=164226 -InactiveEnterTimestampMonotonic=0 -Type=idle - -Id=spin-jobwatch.service -Names=spin-jobwatch.service -After=system.slice systemd-journald.socket -ActiveState=active -InactiveExitTimestampMonotonic=101750 -ActiveEnterTimestampMonotonic=101750 -InactiveEnterTimestampMonotonic=0 -Type=simple - -Id=spin-machine-sshd-keygen.service -Names=spin-machine-sshd-keygen.service -After=basic.target systemd-journald.socket system.slice sysinit.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=spin-waits.service -Names=spin-waits.service -After=sysinit.target basic.target multi-user.target system.slice -ActiveState=active -InactiveExitTimestampMonotonic=165411 -ActiveEnterTimestampMonotonic=165411 -InactiveEnterTimestampMonotonic=0 -Type=simple - -Id=ssh.service -Names=ssh.service sshd.service -After=sysinit.target basic.target nss-user-lookup.target network.target ssh.socket sshd-keygen.service auditd.service spin-machine-sshd-keygen.service systemd-journald.socket -.mount system.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=notify - -Id=sshd-keygen.service -Names=sshd-keygen.service -After=systemd-journald.socket system.slice basic.target sysinit.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=sshd@sshd-keygen.service -Names=sshd@sshd-keygen.service sshd-unix-local@sshd-keygen.service -After=basic.target nss-user-lookup.target system-sshd.slice -.mount sysinit.target sshd-keygen.service auditd.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=exec - -Id=syslog.service -Names=syslog.service -After=syslog.socket -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-ask-password-console.service -Names=systemd-ask-password-console.service -After=system.slice systemd-ask-password-console.path plymouth-start.service systemd-vconsole-setup.service systemd-journald.socket -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=notify - -Id=systemd-ask-password-wall.service -Names=systemd-ask-password-wall.service -After=system.slice systemd-journald.socket sysinit.target basic.target systemd-ask-password-wall.path systemd-user-sessions.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=notify - -Id=systemd-battery-check.service -Names=systemd-battery-check.service -After=systemd-journald.socket plymouth-start.service system.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-binfmt.service -Names=systemd-binfmt.service -After=system.slice systemd-journald.socket proc-sys-fs-binfmt_misc.mount proc-sys-fs-binfmt_misc.automount local-fs.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-bsod.service -Names=systemd-bsod.service -After=systemd-journald.socket systemd-battery-check.service system.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=simple - -Id=systemd-confext-initrd.service -Names=systemd-confext-initrd.service -After=modprobe@dm_mod.service system.slice modprobe@loop.service systemd-journald.socket -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-firstboot.service -Names=systemd-firstboot.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-fsck-root.service -Names=systemd-fsck-root.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-hibernate-clear.service -Names=systemd-hibernate-clear.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-hibernate-resume.service -Names=systemd-hibernate-resume.service -After=system.slice systemd-journald.socket systemd-battery-check.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-hostnamed.service -Names=systemd-hostnamed.service dbus-org.freedesktop.hostname1.service -After=systemd-tmpfiles-setup.service tmp.mount sysinit.target systemd-hostnamed.socket -.mount system.slice systemd-journald.socket basic.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=notify - -Id=systemd-hwdb-update.service -Names=systemd-hwdb-update.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-journal-catalog-update.service -Names=systemd-journal-catalog-update.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-journal-flush.service -Names=systemd-journal-flush.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-journald.service -Names=systemd-journald.service -After=system.slice systemd-journald.socket syslog.socket systemd-journald-audit.socket systemd-journald-dev-log.socket -.mount -ActiveState=active -InactiveExitTimestampMonotonic=99676 -ActiveEnterTimestampMonotonic=121726 -InactiveEnterTimestampMonotonic=0 -Type=notify-reload - -Id=systemd-logind.service -Names=systemd-logind.service dbus-org.freedesktop.login1.service -After=user.slice systemd-tmpfiles-setup.service systemd-logind-varlink.socket system.slice -.mount systemd-remount-fs.service nss-user-lookup.target dbus.socket basic.target modprobe@drm.service systemd-journald.socket sysinit.target tmp.mount -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=notify-reload - -Id=systemd-machine-id-commit.service -Names=systemd-machine-id-commit.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-modules-load.service -Names=systemd-modules-load.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-pcrmachine.service -Names=systemd-pcrmachine.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-pcrnvdone.service -Names=systemd-pcrnvdone.service -After=tpm2.target system.slice systemd-journald.socket systemd-tpm2-setup-early.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-pcrphase-initrd.service -Names=systemd-pcrphase-initrd.service -After=system.slice systemd-journald.socket tpm2.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-pcrphase-sysinit.service -Names=systemd-pcrphase-sysinit.service -After=system.slice systemd-journald.socket tpm2.target sysinit.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-pcrphase.service -Names=systemd-pcrphase.service -After=remote-cryptsetup.target systemd-journald.socket sysinit.target remote-fs.target basic.target system.slice tpm2.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-pcrproduct.service -Names=systemd-pcrproduct.service -After=systemd-pcrnvdone.service system.slice systemd-journald.socket -.mount tpm2.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-pstore.service -Names=systemd-pstore.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-random-seed.service -Names=systemd-random-seed.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-remount-fs.service -Names=systemd-remount-fs.service -After=systemd-fsck-root.service systemd-journald.socket system.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-soft-reboot.service -Names=systemd-soft-reboot.service -After=systemd-journald.socket shutdown.target systemd-udevd.service systemd-journald.service system.slice final.target umount.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-sysctl.service -Names=systemd-sysctl.service procps.service -After=system.slice systemd-modules-load.service systemd-journald.socket -ActiveState=active -InactiveExitTimestampMonotonic=102191 -ActiveEnterTimestampMonotonic=113211 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-sysext-initrd.service -Names=systemd-sysext-initrd.service -After=modprobe@dm_mod.service systemd-journald.socket modprobe@loop.service system.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-sysext.service -Names=systemd-sysext.service -After=local-fs.target systemd-journald.socket system.slice systemd-pcrphase-initrd.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-sysusers.service -Names=systemd-sysusers.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-tmpfiles-clean.service -Names=systemd-tmpfiles-clean.service -After=time-set.target systemd-journald.socket system.slice local-fs.target systemd-tmpfiles-clean.timer -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-tmpfiles-setup-dev-early.service -Names=systemd-tmpfiles-setup-dev-early.service -After=kmod-static-nodes.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-tmpfiles-setup-dev.service -Names=systemd-tmpfiles-setup-dev.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-tmpfiles-setup.service -Names=systemd-tmpfiles-setup.service -After=local-fs.target systemd-sysext.service systemd-sysusers.service systemd-journald.service systemd-confext-initrd.service systemd-journald.socket systemd-sysext-initrd.service system.slice -ActiveState=active -InactiveExitTimestampMonotonic=123430 -ActiveEnterTimestampMonotonic=132995 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-tpm2-setup-early.service -Names=systemd-tpm2-setup-early.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-tpm2-setup.service -Names=systemd-tpm2-setup.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-udev-load-credentials.service -Names=systemd-udev-load-credentials.service -After=system.slice systemd-journald.socket -ActiveState=active -InactiveExitTimestampMonotonic=104573 -ActiveEnterTimestampMonotonic=110996 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-udev-settle.service -Names=systemd-udev-settle.service -After=system.slice systemd-journald.socket systemd-udev-trigger.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-udev-trigger.service -Names=systemd-udev-trigger.service -After=systemd-udevd-control.socket systemd-journald.socket systemd-udevd-kernel.socket system.slice systemd-udevd-varlink.socket -ActiveState=active -InactiveExitTimestampMonotonic=105040 -ActiveEnterTimestampMonotonic=134912 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-udevd.service -Names=systemd-udevd.service -After=systemd-udevd-kernel.socket systemd-udevd-control.socket systemd-journald.socket systemd-sysusers.service systemd-udevd-varlink.socket systemd-hwdb-update.service system.slice systemd-udev-load-credentials.service -ActiveState=active -InactiveExitTimestampMonotonic=111932 -ActiveEnterTimestampMonotonic=138437 -InactiveEnterTimestampMonotonic=0 -Type=notify-reload - -Id=systemd-update-done.service -Names=systemd-update-done.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=systemd-user-sessions.service -Names=systemd-user-sessions.service -After=network.target home.mount nss-user-lookup.target systemd-journald.socket sysinit.target system.slice systemd-pcrphase.service remote-fs.target basic.target -ActiveState=active -InactiveExitTimestampMonotonic=150821 -ActiveEnterTimestampMonotonic=156771 -InactiveEnterTimestampMonotonic=0 -Type=oneshot - -Id=systemd-vconsole-setup.service -Names=systemd-vconsole-setup.service -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 -Type= - -Id=-.slice -Names=-.slice -After= -ActiveState=active -InactiveExitTimestampMonotonic=75438 -ActiveEnterTimestampMonotonic=75438 -InactiveEnterTimestampMonotonic=0 - -Id=system-getty.slice -Names=system-getty.slice -After=system.slice -ActiveState=active -InactiveExitTimestampMonotonic=95672 -ActiveEnterTimestampMonotonic=95672 -InactiveEnterTimestampMonotonic=0 - -Id=system-modprobe.slice -Names=system-modprobe.slice -After=system.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=system-serial\x2dgetty.slice -Names="system-serial\\x2dgetty.slice" -After=system.slice -ActiveState=active -InactiveExitTimestampMonotonic=95804 -ActiveEnterTimestampMonotonic=95804 -InactiveEnterTimestampMonotonic=0 - -Id=system-sshd.slice -Names=system-sshd.slice -After=system.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=system.slice -Names=system.slice -After=-.slice -ActiveState=active -InactiveExitTimestampMonotonic=75444 -ActiveEnterTimestampMonotonic=75444 -InactiveEnterTimestampMonotonic=0 - -Id=user.slice -Names=user.slice -After=-.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=containerd.socket -Names=containerd.socket -After=sysinit.target system.slice -.mount -ActiveState=active -InactiveExitTimestampMonotonic=138978 -ActiveEnterTimestampMonotonic=143828 -InactiveEnterTimestampMonotonic=0 - -Id=dbus.socket -Names=dbus.socket -After=system.slice -.mount sysinit.target -ActiveState=active -InactiveExitTimestampMonotonic=139703 -ActiveEnterTimestampMonotonic=139740 -InactiveEnterTimestampMonotonic=0 - -Id=docker.socket -Names=docker.socket -After=-.mount system.slice sysinit.target -ActiveState=active -InactiveExitTimestampMonotonic=139811 -ActiveEnterTimestampMonotonic=143886 -InactiveEnterTimestampMonotonic=0 - -Id=ssh.socket -Names=ssh.socket -After=system.slice sysinit.target -ActiveState=active -InactiveExitTimestampMonotonic=140835 -ActiveEnterTimestampMonotonic=141970 -InactiveEnterTimestampMonotonic=0 - -Id=sshd-unix-local.socket -Names=sshd-unix-local.socket -After=system.slice -.mount sysinit.target -ActiveState=active -InactiveExitTimestampMonotonic=142077 -ActiveEnterTimestampMonotonic=142546 -InactiveEnterTimestampMonotonic=0 - -Id=syslog.socket -Names=syslog.socket -After=system.slice -.mount -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-ask-password.socket -Names=systemd-ask-password.socket -After=system.slice -.mount -ActiveState=active -InactiveExitTimestampMonotonic=95952 -ActiveEnterTimestampMonotonic=96413 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-creds.socket -Names=systemd-creds.socket -After=system.slice -.mount -ActiveState=active -InactiveExitTimestampMonotonic=96426 -ActiveEnterTimestampMonotonic=96734 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-factory-reset.socket -Names=systemd-factory-reset.socket -After=system.slice -.mount -ActiveState=active -InactiveExitTimestampMonotonic=96743 -ActiveEnterTimestampMonotonic=97147 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-hostnamed.socket -Names=systemd-hostnamed.socket -After=sysinit.target -.mount system.slice -ActiveState=active -InactiveExitTimestampMonotonic=142595 -ActiveEnterTimestampMonotonic=142619 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-journald-audit.socket -Names=systemd-journald-audit.socket -After=system.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-journald-dev-log.socket -Names=systemd-journald-dev-log.socket -After=system.slice -.mount -ActiveState=active -InactiveExitTimestampMonotonic=97159 -ActiveEnterTimestampMonotonic=97181 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-journald.socket -Names=systemd-journald.socket -After=system.slice -.mount -ActiveState=active -InactiveExitTimestampMonotonic=97192 -ActiveEnterTimestampMonotonic=97203 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-logind-varlink.socket -Names=systemd-logind-varlink.socket -After=-.mount system.slice sysinit.target systemd-journald.socket -ActiveState=active -InactiveExitTimestampMonotonic=143326 -ActiveEnterTimestampMonotonic=149296 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-mute-console.socket -Names=systemd-mute-console.socket -After=system.slice -.mount -ActiveState=active -InactiveExitTimestampMonotonic=97215 -ActiveEnterTimestampMonotonic=97677 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-pcrextend.socket -Names=systemd-pcrextend.socket -After=-.mount tpm2.target system.slice -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-pcrlock.socket -Names=systemd-pcrlock.socket -After=system.slice -.mount tpm2.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-sysext.socket -Names=systemd-sysext.socket -After=local-fs.target -.mount system.slice -ActiveState=active -InactiveExitTimestampMonotonic=105730 -ActiveEnterTimestampMonotonic=106061 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-udevd-control.socket -Names=systemd-udevd-control.socket -After=system.slice -.mount -ActiveState=active -InactiveExitTimestampMonotonic=97700 -ActiveEnterTimestampMonotonic=97709 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-udevd-kernel.socket -Names=systemd-udevd-kernel.socket -After=system.slice -ActiveState=active -InactiveExitTimestampMonotonic=97720 -ActiveEnterTimestampMonotonic=97724 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-udevd-varlink.socket -Names=systemd-udevd-varlink.socket -After=system.slice -.mount -ActiveState=active -InactiveExitTimestampMonotonic=97734 -ActiveEnterTimestampMonotonic=97738 -InactiveEnterTimestampMonotonic=0 - -Id=basic.target -Names=basic.target -After=systemd-pcrphase-sysinit.service tmp.mount -.mount paths.target sysinit.target sockets.target slices.target dbus-broker.service -ActiveState=active -InactiveExitTimestampMonotonic=149510 -ActiveEnterTimestampMonotonic=149510 -InactiveEnterTimestampMonotonic=0 - -Id=cryptsetup-pre.target -Names=cryptsetup-pre.target -After=systemd-pcrphase-initrd.service systemd-pcrnvdone.service systemd-sysext-initrd.service systemd-confext-initrd.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=cryptsetup.target -Names=cryptsetup.target -After=systemd-pcrnvdone.service systemd-ask-password-console.path systemd-ask-password-wall.path systemd-pcrphase-initrd.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=emergency.target -Names=emergency.target -After=emergency.service sysinit.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=final.target -Names=final.target -After=shutdown.target umount.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=getty-pre.target -Names=getty-pre.target -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=getty.target -Names=getty.target -After=serial-getty@ttyS0.service getty@tty1.service getty-static.service -ActiveState=active -InactiveExitTimestampMonotonic=164297 -ActiveEnterTimestampMonotonic=164297 -InactiveEnterTimestampMonotonic=0 - -Id=imports.target -Names=imports.target -After= -ActiveState=active -InactiveExitTimestampMonotonic=95903 -ActiveEnterTimestampMonotonic=95903 -InactiveEnterTimestampMonotonic=0 - -Id=initrd-fs.target -Names=initrd-fs.target -After=initrd-parse-etc.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=initrd-root-device.target -Names=initrd-root-device.target -After=systemd-battery-check.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=initrd-root-fs.target -Names=initrd-root-fs.target -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=initrd-switch-root.target -Names=initrd-switch-root.target -After=systemd-pcrphase-initrd.service systemd-udevd.service initrd-root-fs.target emergency.target systemd-udev-load-credentials.service initrd-udevadm-cleanup-db.service systemd-pcrnvdone.service systemd-tmpfiles-clean.service initrd-cleanup.service emergency.service systemd-tmpfiles-setup.service initrd-fs.target systemd-confext-initrd.service systemd-sysext-initrd.service systemd-ask-password-console.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=initrd-usr-fs.target -Names=initrd-usr-fs.target -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=initrd.target -Names=initrd.target -After=rescue.service initrd-usr-fs.target initrd-root-device.target initrd-fs.target rescue.target initrd-root-fs.target basic.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=local-fs-pre.target -Names=local-fs-pre.target -After=systemd-hibernate-resume.service systemd-sysext-initrd.service systemd-confext-initrd.service systemd-remount-fs.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=local-fs.target -Names=local-fs.target -After=local-fs-pre.target systemd-remount-fs.service tmp.mount -ActiveState=active -InactiveExitTimestampMonotonic=105696 -ActiveEnterTimestampMonotonic=105696 -InactiveEnterTimestampMonotonic=0 - -Id=multi-user.target -Names=multi-user.target default.target -After=getty.target rescue.service basic.target rescue.target systemd-user-sessions.service -ActiveState=active -InactiveExitTimestampMonotonic=164333 -ActiveEnterTimestampMonotonic=164333 -InactiveEnterTimestampMonotonic=0 - -Id=network-online.target -Names=network-online.target -After=network.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=network-pre.target -Names=network-pre.target -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=network.target -Names=network.target -After=network-pre.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=nss-lookup.target -Names=nss-lookup.target -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=nss-user-lookup.target -Names=nss-user-lookup.target -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=paths.target -Names=paths.target -After=systemd-ask-password-console.path systemd-ask-password-wall.path -ActiveState=active -InactiveExitTimestampMonotonic=95907 -ActiveEnterTimestampMonotonic=95907 -InactiveEnterTimestampMonotonic=0 - -Id=remote-cryptsetup.target -Names=remote-cryptsetup.target -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=remote-fs-pre.target -Names=remote-fs-pre.target -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=remote-fs.target -Names=remote-fs.target -After=remote-fs-pre.target -ActiveState=active -InactiveExitTimestampMonotonic=95913 -ActiveEnterTimestampMonotonic=95913 -InactiveEnterTimestampMonotonic=0 - -Id=rescue.target -Names=rescue.target -After=rescue.service sysinit.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=shutdown.target -Names=shutdown.target -After=systemd-pcrphase.service systemd-sysext.service sshd@sshd-keygen.service swap.target sshd-unix-local.socket sockets.target systemd-pcrproduct.service proc-sys-fs-binfmt_misc.automount systemd-tmpfiles-clean.timer systemd-remount-fs.service systemd-pcrphase-initrd.service sysinit.target systemd-ask-password-console.service ssh.socket fstrim.service systemd-tmpfiles-setup.service getty.target systemd-ask-password-console.path systemd-hostnamed.service time-set.target getty-static.service syslog.socket systemd-ask-password-wall.path containerd.service systemd-logind.service rescue.service systemd-user-sessions.service systemd-logind-varlink.socket network-online.target emergency.service time-sync.target emergency.target user.slice paths.target slices.target systemd-bsod.service systemd-ask-password-wall.service basic.target systemd-pcrnvdone.service system-getty.slice systemd-tmpfiles-clean.service docker.service systemd-hostnamed.socket tpm2.target spin-waits.service sshd-keygen.service getty-pre.target rescue.target fstrim.timer containerd.socket network-pre.target getty@tty1.service docker.socket network.target remote-fs-pre.target multi-user.target local-fs-pre.target "system-serial\\x2dgetty.slice" nss-user-lookup.target systemd-udev-load-credentials.service nss-lookup.target initrd.target spin-machine-sshd-keygen.service systemd-mute-console.socket dbus-broker.service systemd-binfmt.service serial-getty@ttyS0.service imports.target rc-local.service ssh.service system-sshd.slice system-modprobe.slice systemd-pcrphase-sysinit.service systemd-sysctl.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=slices.target -Names=slices.target -After=user.slice -.slice system.slice -ActiveState=active -InactiveExitTimestampMonotonic=95916 -ActiveEnterTimestampMonotonic=95916 -InactiveEnterTimestampMonotonic=0 - -Id=sockets.target -Names=sockets.target -After=systemd-udevd-kernel.socket syslog.socket systemd-logind-varlink.socket systemd-mute-console.socket systemd-journald.socket systemd-hostnamed.socket systemd-udevd-varlink.socket systemd-pcrextend.socket systemd-udevd-control.socket ssh.socket systemd-pcrlock.socket systemd-creds.socket systemd-factory-reset.socket systemd-journald-dev-log.socket containerd.socket docker.socket systemd-sysext.socket systemd-journald-audit.socket systemd-ask-password.socket sshd-unix-local.socket dbus.socket -ActiveState=active -InactiveExitTimestampMonotonic=149468 -ActiveEnterTimestampMonotonic=149468 -InactiveEnterTimestampMonotonic=0 - -Id=soft-reboot.target -Names=soft-reboot.target -After=systemd-udevd.service systemd-soft-reboot.service systemd-journald.service -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=swap.target -Names=swap.target -After= -ActiveState=active -InactiveExitTimestampMonotonic=95929 -ActiveEnterTimestampMonotonic=95929 -InactiveEnterTimestampMonotonic=0 - -Id=sysinit.target -Names=sysinit.target -After=local-fs.target proc-sys-fs-binfmt_misc.automount apparmor.service swap.target systemd-udev-settle.service kmod-static-nodes.service systemd-pcrphase-initrd.service systemd-sysext.service sys-kernel-config.mount systemd-udev-trigger.service imports.target modprobe@loop.service sys-fs-fuse-connections.mount systemd-sysctl.service systemd-journald.service systemd-tmpfiles-setup.service modprobe@dm_mod.service systemd-pcrnvdone.service systemd-pcrproduct.service systemd-binfmt.service systemd-udevd.service -ActiveState=active -InactiveExitTimestampMonotonic=138596 -ActiveEnterTimestampMonotonic=138596 -InactiveEnterTimestampMonotonic=0 - -Id=time-set.target -Names=time-set.target -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=time-sync.target -Names=time-sync.target -After=time-set.target -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=timers.target -Names=timers.target -After=systemd-tmpfiles-clean.timer fstrim.timer -ActiveState=active -InactiveExitTimestampMonotonic=138931 -ActiveEnterTimestampMonotonic=138931 -InactiveEnterTimestampMonotonic=0 - -Id=tpm2.target -Names=tpm2.target -After=dev-tpm0.device dev-tpmrm0.device -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=umount.target -Names=umount.target -After=tmp.mount -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=apt-daily-upgrade.timer -Names=apt-daily-upgrade.timer -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=apt-daily.timer -Names=apt-daily.timer -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=dpkg-db-backup.timer -Names=dpkg-db-backup.timer -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=fstrim.timer -Names=fstrim.timer -After=time-set.target time-sync.target sysinit.target -.mount -ActiveState=active -InactiveExitTimestampMonotonic=138857 -ActiveEnterTimestampMonotonic=138857 -InactiveEnterTimestampMonotonic=0 - -Id=motd-news.timer -Names=motd-news.timer -After= -ActiveState=inactive -InactiveExitTimestampMonotonic=0 -ActiveEnterTimestampMonotonic=0 -InactiveEnterTimestampMonotonic=0 - -Id=systemd-tmpfiles-clean.timer -Names=systemd-tmpfiles-clean.timer -After=sysinit.target -ActiveState=active -InactiveExitTimestampMonotonic=138892 -ActiveEnterTimestampMonotonic=138892 -InactiveEnterTimestampMonotonic=0 diff --git a/boot/waits_probe_test.go b/boot/waits_probe_test.go index 6428f3a..3471d34 100644 --- a/boot/waits_probe_test.go +++ b/boot/waits_probe_test.go @@ -133,7 +133,7 @@ func (x waitsBoot) target() boot.Unit { u, _ := x.w.Unit(x.login); return u } // machineCommand is `spin-machine boot` with args, or, for a variant that takes devices out // of the machine, the release's QEMU run with the command line `spin-machine args` prints for -// the same arguments, less those devices - as boot:firmware-stages and boot:mmio run it to add +// the same arguments, less those devices - as boot:firmware-stages runs it to add // QEMU's trace flags. A machine with a device fewer has another fingerprint, which is a // fleet-wide decision, so spin-machine has no flag for it on purpose: an experiment does not // belong in the release's path. Everything else the line holds is the definition's. diff --git a/go.mod b/go.mod index a22f815..a88dee9 100644 --- a/go.mod +++ b/go.mod @@ -5,7 +5,6 @@ go 1.27.0 toolchain go1.27.3 require ( - github.com/godbus/dbus/v5 v5.1.0 github.com/spin-stack/go-tools v0.0.0-20261109214710-b4b5f4a78a45 golang.org/x/crypto v0.58.0 golang.org/x/sys v0.49.0 diff --git a/go.sum b/go.sum index cd8748b..8f5cf3f 100644 --- a/go.sum +++ b/go.sum @@ -1,5 +1,3 @@ -github.com/godbus/dbus/v5 v5.1.0 h1:4KLkAxT3aOY8Li4FRJe/KvhoNFFxo0m6fNuFUO8QJUk= -github.com/godbus/dbus/v5 v5.1.0/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/spin-stack/go-tools v0.0.0-20261109214710-b4b5f4a78a45 h1:P+LTBxUd9tGz6qRNVF3izCagBQdxyy0hll4fjISYsV8= github.com/spin-stack/go-tools v0.0.0-20261109214710-b4b5f4a78a45/go.mod h1:69hWhQD1NPsnFEF6BhVAprRGO4f/CMLlPs4z/b6bkyg= github.com/stretchr/testify v1.12.1 h1:EuwCh5fleGS7H32xRwO3wRGT7DxrDhLAT6FF8MpWDWE= diff --git a/image/build.sh b/image/build.sh index 8f02091..d149cce 100755 --- a/image/build.sh +++ b/image/build.sh @@ -299,12 +299,6 @@ for f in /etc/systemd/system/serial-getty@.service.d/term.conf \ in_image "$f" || { echo "ERROR: the image has no $f; a login would inherit TERM=dumb" >&2; exit 1; } done -# The serial getty is started Type=simple: Type=idle holds it until the boot's job queue -# drains, which with spin lingering is 77 ms of a login prompt (serial-getty@.service.d/type.conf). -"$bin/debugfs" -R "cat /etc/systemd/system/serial-getty@.service.d/type.conf" /work/base.raw 2>/dev/null | - grep -qx 'Type=simple' || { - echo "ERROR: the serial getty is not Type=simple; its prompt waits for the job queue to drain" >&2 - exit 1; } # A boot optimization that is invisible in a file listing and expensive when it regresses: # a masked unit is a symlink to /dev/null, and a package upgrade replacing one turns it diff --git a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/serial-getty@.service.d/type.conf b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/serial-getty@.service.d/type.conf deleted file mode 100644 index ffbdb7d..0000000 --- a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/serial-getty@.service.d/type.conf +++ /dev/null @@ -1,14 +0,0 @@ -# The serial login prompt as soon as its getty is started, not once the boot's job queue drains. -# -# The template is Type=idle: systemd forks the getty and holds it until no job is left running. -# That cost nothing while the queue was empty by then, and Type=simple measured within noise of -# it (2026-09-10). Since spin lingers, logind starts user@1000.service and its chain inside the -# boot transaction, and the getty waited for them: 91.8 ms between its fork and its exec in the -# median boot of v20261113.01 (task boot:waits, lab run 43361486792), against 3-5 before. -# Type=simple gives the prompt 77 ms back - 346/358 against 423/441 ms p50/p95 to a login -# prompt, 20 boots interleaved on the bench fleet (task boot:bench, lab run 43362067503). -# -# What Type=idle is for is a prompt not overwritten by the boot's own status lines, and this -# machine's console prints none: the kernel is quiet and systemd shows no status. -[Service] -Type=simple diff --git a/kernel/Dockerfile b/kernel/Dockerfile index b8adf15..bea2616 100644 --- a/kernel/Dockerfile +++ b/kernel/Dockerfile @@ -290,10 +290,9 @@ RUN < 78.5 ms; with # patches/0004 (PCI configuration through ECAM, one trap an access), 73.7. - # patches/0005 has each device's capability list walked once rather than per search: ECAM - # accesses per boot 1,032 -> 680 (task boot:mmio) and the kernel 95.1 -> 88.9 ms, 20 boots - # interleaved on the bench fleet, nested under KVM on a c8i.4xlarge (lab run 43327612594, - # 2026-11-12) - a baseline of that day, not comparable with the 73.7 above. + # A patch that walked each device's capability list once rather than per search took the + # kernel 95.1 -> 88.9 ms (lab run 43327612594, 2026-11-12) and was dropped on 2026-11-13: a + # first SSH login is ~470 ms, and 6 ms of it was not worth a local patch to carry. # Boot performance: the RAID6 PQ benchmark probes all SIMD implementations at boot to # pick the fastest. It must stay disabled. (RAID6_PQ itself is not selected today, so diff --git a/kernel/patches/0005-PCI-Remember-a-device-s-standard-capability-list.patch b/kernel/patches/0005-PCI-Remember-a-device-s-standard-capability-list.patch deleted file mode 100644 index ea0e9d2..0000000 --- a/kernel/patches/0005-PCI-Remember-a-device-s-standard-capability-list.patch +++ /dev/null @@ -1,169 +0,0 @@ -From: Manuel de Brito Fontes -Date: Thu, 12 Nov 2026 19:45:27 -0300 -Subject: [PATCH 5/5] PCI: Remember a device's standard capability list - -pci_find_capability() reads the status register and walks the -capability list from its start on every call, and -pci_find_next_capability() walks from where it is told. A device is -asked for its capabilities a dozen times or more while it is set up -(PM, MSI, MSI-X, VPD, EA, the reset methods, the PCIe port type) and -again by its driver: virtio-pci looks for four vendor capabilities, each -search a walk of its own. Each step of a walk is a configuration read. - -Under a hypervisor every configuration read is a trap. On this machine -each virtio-pci device took about 240 of them while it was set up, some -110 of which walked the same list again - the status register, the -pointer and six links, fourteen to sixteen times. - -Walk the list once in pci_setup_device(), keep each capability's ID and -offset in struct pci_dev, and answer both searches from there. A -position the list does not hold falls back to walking configuration -space, as does pci_bus_find_capability(), which has no pci_dev to keep -anything in. - -Measured on QEMU's q35 with three virtio-pci devices, nested under KVM -on an AWS c8i.4xlarge, 20 boots interleaved: ECAM accesses per boot -1,032 -> 680, kernel start to "Freeing unused kernel image" 95.1 -> -88.9 ms p50, acpi_init 14 -> 10 ms, virtio_pci_driver_init 6.5 -> 4.7 -ms; inet_init, which reads no configuration space, 7.50 -> 7.49 ms. -It costs 98 bytes in every struct pci_dev. - -The list is read before the early fixups run, so a quirk that changes -which capabilities a device shows would leave it stale. This kernel -runs only in a QEMU guest, where no such quirk applies. - -Local patch for this machine. Not upstream. - -Assisted-by: LLM ---- - drivers/pci/pci.c | 57 +++++++++++++++++++++++++++++++++++++++++++++ - drivers/pci/pci.h | 2 ++ - drivers/pci/probe.c | 1 + - include/linux/pci.h | 4 ++++ - 4 files changed, 64 insertions(+) - -diff --git a/drivers/pci/pci.c b/drivers/pci/pci.c -index f852564..691c73d 100644 ---- a/drivers/pci/pci.c -+++ b/drivers/pci/pci.c -@@ -420,6 +420,20 @@ static u8 __pci_find_next_cap(struct pci_bus *bus, unsigned int devfn, - - u8 pci_find_next_capability(struct pci_dev *dev, u8 pos, int cap) - { -+ int i; -+ -+ if (dev->cap_cached) { -+ for (i = 0; i < dev->cap_count && dev->cap_pos[i] != pos; i++) -+ ; -+ /* A position the list does not hold is the caller's own walk. */ -+ if (i < dev->cap_count) { -+ while (++i < dev->cap_count) -+ if (dev->cap_id[i] == cap) -+ return dev->cap_pos[i]; -+ return 0; -+ } -+ } -+ - return __pci_find_next_cap(dev->bus, dev->devfn, - pos + PCI_CAP_LIST_NEXT, cap); - } -@@ -467,6 +481,14 @@ static u8 __pci_bus_find_cap_start(struct pci_bus *bus, - u8 pci_find_capability(struct pci_dev *dev, int cap) - { - u8 pos; -+ int i; -+ -+ if (dev->cap_cached) { -+ for (i = 0; i < dev->cap_count; i++) -+ if (dev->cap_id[i] == cap) -+ return dev->cap_pos[i]; -+ return 0; -+ } - - pos = __pci_bus_find_cap_start(dev->bus, dev->devfn, dev->hdr_type); - if (pos) -@@ -503,6 +525,41 @@ u8 pci_bus_find_capability(struct pci_bus *bus, unsigned int devfn, int cap) - } - EXPORT_SYMBOL(pci_bus_find_capability); - -+/** -+ * pci_cache_capabilities - read a device's standard capability list once -+ * @dev: PCI device whose header type is known -+ * -+ * Walks the list the way PCI_FIND_NEXT_CAP() does - the same TTL, the same -+ * stop at an ID of 0xff - and keeps each capability's ID and offset, so that -+ * pci_find_capability() and pci_find_next_capability() answer from memory -+ * instead of walking configuration space again. -+ */ -+void pci_cache_capabilities(struct pci_dev *dev) -+{ -+ int ttl = PCI_FIND_CAP_TTL; -+ u8 pos, id; -+ u16 ent; -+ -+ dev->cap_count = 0; -+ pos = __pci_bus_find_cap_start(dev->bus, dev->devfn, dev->hdr_type); -+ if (pos) -+ pci_bus_read_config_byte(dev->bus, dev->devfn, pos, &pos); -+ -+ while (ttl-- && pos >= PCI_STD_HEADER_SIZEOF && -+ dev->cap_count < ARRAY_SIZE(dev->cap_id)) { -+ pos = ALIGN_DOWN(pos, 4); -+ pci_bus_read_config_word(dev->bus, dev->devfn, pos, &ent); -+ id = FIELD_GET(PCI_CAP_ID_MASK, ent); -+ if (id == 0xff) -+ break; -+ dev->cap_id[dev->cap_count] = id; -+ dev->cap_pos[dev->cap_count++] = pos; -+ pos = FIELD_GET(PCI_CAP_LIST_NEXT_MASK, ent); -+ } -+ -+ dev->cap_cached = true; -+} -+ - /** - * pci_find_next_ext_capability - Find an extended capability - * @dev: PCI device to query -diff --git a/drivers/pci/pci.h b/drivers/pci/pci.h -index ba3c3fd..f23ea45 100644 ---- a/drivers/pci/pci.h -+++ b/drivers/pci/pci.h -@@ -18,6 +18,8 @@ struct pcie_tlp_log; - - #define PCI_FIND_CAP_TTL 48 - -+void pci_cache_capabilities(struct pci_dev *dev); -+ - #define PCI_VSEC_ID_INTEL_TBT 0x1234 /* Thunderbolt */ - - #define PCIE_LINK_RETRAIN_TIMEOUT_MS 1000 -diff --git a/drivers/pci/probe.c b/drivers/pci/probe.c -index 52a79b0..a0e6232 100644 ---- a/drivers/pci/probe.c -+++ b/drivers/pci/probe.c -@@ -2031,6 +2031,7 @@ int pci_setup_device(struct pci_dev *dev) - dev->dev.bus = &pci_bus_type; - dev->hdr_type = FIELD_GET(PCI_HEADER_TYPE_MASK, hdr_type); - dev->multifunction = FIELD_GET(PCI_HEADER_TYPE_MFD, hdr_type); -+ pci_cache_capabilities(dev); - dev->error_state = pci_channel_io_normal; - set_pcie_port_type(dev); - -diff --git a/include/linux/pci.h b/include/linux/pci.h -index 272378d..fbaa2fc 100644 ---- a/include/linux/pci.h -+++ b/include/linux/pci.h -@@ -370,6 +370,10 @@ struct pci_dev { - unsigned int class; /* 3 bytes: (base,sub,prog-if) */ - u8 revision; /* PCI revision, low byte of class word */ - u8 hdr_type; /* PCI header type (`multi' flag masked out) */ -+ u8 cap_count; /* Entries in cap_id[] and cap_pos[] */ -+ bool cap_cached; /* The standard capability list is in cap_id[] */ -+ u8 cap_id[48]; /* Standard capability IDs, in list order */ -+ u8 cap_pos[48]; /* and their offsets in configuration space */ - #ifdef CONFIG_PCIEAER - u16 aer_cap; /* AER capability offset */ - struct aer_info *aer_info; /* AER info for this device */ --- -2.53.0 -