From a7421ab45316cd56990253e9b8c59a1f17d41c70 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Thu, 12 Nov 2026 21:00:00 -0300 Subject: [PATCH 1/5] waits, jobs (D-Bus), ssh-first, exits, mmio; tracing Signed-off-by: Manuel de Brito Fontes --- .github/workflows/lab.yml | 5 + Taskfile.yml | 2 +- boot/Taskfile.yml | 65 +- boot/bench_test.go | 19 +- boot/cpushare_test.go | 16 +- boot/exits_test.go | 244 ++++ boot/graph_test.go | 70 +- boot/jobs.go | 220 ++++ boot/jobs_test.go | 115 ++ boot/jobwatch/main.go | 181 +++ boot/jobwatch/main_test.go | 18 + boot/jobwatch_probe_test.go | 250 ++++ boot/mmio_test.go | 170 +++ boot/ssh_first_test.go | 242 ++++ boot/testdata/first-login.sh | 32 + boot/testdata/jobs-2026-11-12.txt | 173 +++ boot/testdata/jobs-waits-2026-11-12.txt | 1545 +++++++++++++++++++++++ boot/testdata/waits-2026-11-12.txt | 1536 ++++++++++++++++++++++ boot/vsockproxy/main.go | 48 + boot/waits.go | 407 ++++++ boot/waits_probe_test.go | 431 +++++++ boot/waits_test.go | 179 +++ go.mod | 5 +- go.sum | 2 + 24 files changed, 5961 insertions(+), 14 deletions(-) create mode 100644 boot/exits_test.go create mode 100644 boot/jobs.go create mode 100644 boot/jobs_test.go create mode 100644 boot/jobwatch/main.go create mode 100644 boot/jobwatch/main_test.go create mode 100644 boot/jobwatch_probe_test.go create mode 100644 boot/mmio_test.go create mode 100644 boot/ssh_first_test.go create mode 100644 boot/testdata/first-login.sh create mode 100644 boot/testdata/jobs-2026-11-12.txt create mode 100644 boot/testdata/jobs-waits-2026-11-12.txt create mode 100644 boot/testdata/waits-2026-11-12.txt create mode 100644 boot/vsockproxy/main.go create mode 100644 boot/waits.go create mode 100644 boot/waits_probe_test.go create mode 100644 boot/waits_test.go diff --git a/.github/workflows/lab.yml b/.github/workflows/lab.yml index 45a8a81..23d7c20 100644 --- a/.github/workflows/lab.yml +++ b/.github/workflows/lab.yml @@ -35,6 +35,11 @@ on: - boot:initcalls - 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/Taskfile.yml b/Taskfile.yml index ca41328..c9232c9 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -701,7 +701,7 @@ tasks: pair="${pair%"${pair##*[![:space:]]}"}" [ -z "$pair" ] && continue key="${pair%%=*}" - [[ "$pair" == *=* && "$key" =~ ^(REPS|TOP|GAP|ONLY|FLAGS|CPUS|MEMORY_MIB|DEBUG|FILE_MB|CACHE_TIMEOUT_S|GRAPH_[A-Z_]+|SHARE_[A-Z_]+|SPIN_[A-Z0-9_]+)$ ]] || + [[ "$pair" == *=* && "$key" =~ ^(REPS|TOP|GAP|ONLY|FLAGS|CPUS|TARGET|BUCKET|LINGER|MEMORY_MIB|DEBUG|FILE_MB|CACHE_TIMEOUT_S|GRAPH_[A-Z_]+|SHARE_[A-Z_]+|SPIN_[A-Z0-9_]+)$ ]] || { echo "::error::not a variable this workflow passes on: $pair"; exit 1; } case "$key" in SPIN_MACHINE_OUTPUT|SPIN_MACHINE_OUTPUT_B|SPIN_KERNEL_B|SPIN_KERNEL_C) echo "::error::$key is set by this workflow"; exit 1 ;; diff --git a/boot/Taskfile.yml b/boot/Taskfile.yml index f41be33..5707cb7 100644 --- a/boot/Taskfile.yml +++ b/boot/Taskfile.yml @@ -134,9 +134,10 @@ tasks: desc: >- Check first SSH login, reconnect, user services and logout in a disposable guest. Needs a built release; uses KVM when available, otherwise TCG. - The image does not start logind at boot, so this checks the thing that makes that - safe: that the first login activates it and gets a real session. SPIN_LOGIND_NO_SEATS=1 - removes the drop-in that allows it and is expected to fail, not to measure anything. + The image starts logind at boot, for spin's lingering manager, and this checks that + logins get a real session. SPIN_LOGIND_NO_SEATS=1 holds logind back from the boot and + removes the drop-in that lets an early login still activate it, and is expected to + fail, not to measure anything. deps: [':tools'] cmds: - SPIN_LOGIND_TEST=1 go test ./boot/ -run '^TestLogindSessions$' -count=1 -v -timeout 5m @@ -180,6 +181,64 @@ tasks: cmds: - SPIN_SYSTEMD_DEBUG=1 go test ./boot/ -run TestSystemdDebug -count=1 -v -timeout 15m + waits: + desc: >- + What waited on what between the kernel handing over and a login prompt, on the host's + clock: each unit's own time against the lag before it started, the critical path to the + login that accounts for every millisecond of it, the intervals no unit was working, and + what is still starting behind the prompt. Read after the boot from systemd's timestamps. + Needs KVM, a built release and sudo. REPS= boots, TARGET= the login unit, TOP= rows, + GAP= the shortest idle interval in ms, RAW= keeps each boot's dump. + deps: [':tools'] + 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 + vsock: sshd accepting, the first login done, a second login's cost, and the console + prompt beside them. Needs KVM, /dev/vhost-vsock (task vsock), a built release, sudo + and ssh. REPS= boots. + deps: [':tools'] + 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 9a13729..67a8230 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -34,6 +34,10 @@ type variant struct { profile bool // boot with `--profile`: initcall profiling, console silent setup string // shell run with the overlay mounted, $MNT its root flags []string // spin-machine boot flags after the rest: the feature matrix's axes + // -device entries taken out of the machine, by prefix ("virtio-rng-pci"): a diagnostic row + // of a machine with another fingerprint, which spin-machine deliberately has no flag for. + // Only bootWaits honours it; see machineCommand. + without []string } // A drop-in on the instance beats one on the template, which is where the image's own TERM @@ -89,6 +93,10 @@ func without(units ...string) variant { // - 300 more unit files nothing wants: 236 against 246, 12 boots, 2026-09-26. systemd's unit // cache holds names and modification times, so this measures the scan, which is free; it // does not measure parsing, which only units something pulls in pay for. +// - the serial getty without BindsTo= and After= on dev-ttyS0.device, which boot:waits found +// its start waiting on in 16 of 20 boots: 342/349 against 345/365, 20 boots on the bench +// fleet, 2026-11-12 (lab run 43303190733). The prompt does not come sooner when the getty +// stops waiting for udev to announce the port; a laptop had read 16 ms of it, which was noise. var variants = []variant{ // The image as it is, with a real agetty rather than the echo every row below uses. It // reads about a second slower and that is agetty's own sleep, not a fault to hunt: the @@ -210,6 +218,11 @@ func TestBootTrace(t *testing.T) { // waits separates the two in one boot: // // SPIN_GETTY_EXEC="/bin/sh -c 'echo SPIN-READY-login: ; sleep infinity'" + // + // SPIN_TRACE_APPEND is added to the kernel command line, after this probe's own, so a later + // parameter wins: systemd.log_level=debug times PID 1's start-up line by line, which on + // 2026-11-12 was how the ~45 ms between "Hostname set" and "Queued start job" was split. + // Every line is a VM exit, so the gaps between lines are the work and the lines are not. if x := os.Getenv("SPIN_GETTY_EXEC"); x != "" { body += "ExecStart=\nExecStart=-" + x + "\n" } @@ -227,8 +240,10 @@ func TestBootTrace(t *testing.T) { cmd := exec.Command(filepath.Join(out, "bin", "spin-machine"), "boot", "--release", out, "--disk", overlay, "--memory", v.memory, "--cpus", v.cpus, "--console", "file:/dev/stdout", - "--append", "init=/sbin/init loglevel=7 systemd.show_status=true "+ - "systemd.log_level=info systemd.log_target=console") + "--append", strings.TrimSpace("init=/sbin/init loglevel=7 systemd.show_status=true "+ + "systemd.log_level=info systemd.log_target=console "+os.Getenv("SPIN_TRACE_APPEND"))) + // FLAGS, as the other probes take it: spin-machine boot flags after the rest. + cmd.Args = append(cmd.Args, strings.Fields(os.Getenv("FLAGS"))...) cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} stdout, err := cmd.StdoutPipe() if err != nil { diff --git a/boot/cpushare_test.go b/boot/cpushare_test.go index afc37c1..d51c256 100644 --- a/boot/cpushare_test.go +++ b/boot/cpushare_test.go @@ -35,7 +35,7 @@ After=multi-user.target [Service] Type=oneshot StandardOutput=null -ExecStart=/bin/sh -c "mount -t tracefs none /sys/kernel/tracing 2>/dev/null; echo 0 > /sys/kernel/tracing/tracing_on; { echo SPIN-TRACE-BEGIN; sed -n '1,/initcall_finish: func=FN+/p' /sys/kernel/tracing/trace | grep -E 'sched_switch|workqueue_execute|initcall_(start|finish): func=FN[+]'; echo SPIN-TRACE-END; echo SPIN-DMESG-END; } > /dev/ttyS0" +ExecStart=/bin/sh -c "mount -t tracefs none /sys/kernel/tracing 2>/dev/null; echo 0 > /sys/kernel/tracing/tracing_on; { ` + traceAccess + ` echo SPIN-TRACE-BEGIN; sed -n '1,/initcall_finish: func=FN+/p' /sys/kernel/tracing/trace | grep -E 'sched_switch|workqueue_execute|initcall_(start|finish): func=FN[+]'; echo SPIN-TRACE-END; echo SPIN-DMESG-END; } > /dev/ttyS0" [Install] WantedBy=multi-user.target ` @@ -52,9 +52,23 @@ WantedBy=multi-user.target kernels = append(kernels, struct{ label, path string }{"kernel B", k}) } shares := map[string][]map[string]float64{} + // The release's kernel cannot be traced (untraceable), so with a kernel B it is left out + // after its first boot says so, and without one the probe stops and says what to build. + locked := map[string]bool{} for range reps { for _, k := range kernels { + if locked[k.label] { + continue + } console := bootUntil(t, out, v, k.path, "SPIN-DMESG-END", 180*time.Second) + if why := untraceable(console); why != "" { + if k.label == "release" && len(kernels) > 1 { + t.Logf("the release's kernel is left out: %s", why) + locked[k.label] = true + continue + } + t.Fatalf("nothing can be traced on the %s kernel: %s", k.label, why) + } begin, end := strings.Index(console, "SPIN-TRACE-BEGIN"), strings.Index(console, "SPIN-TRACE-END") if begin < 0 || end < begin { t.Fatalf("no trace in the console:\n%s", tail([]byte(console), 2000)) diff --git a/boot/exits_test.go b/boot/exits_test.go new file mode 100644 index 0000000..e62cc20 --- /dev/null +++ b/boot/exits_test.go @@ -0,0 +1,244 @@ +// 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/graph_test.go b/boot/graph_test.go index 49f6de7..c291ff7 100644 --- a/boot/graph_test.go +++ b/boot/graph_test.go @@ -29,6 +29,45 @@ import ( // It also cannot see what runs before ftrace_init, which is most of start_kernel's memory // setup: a root has to be a function entered after tracing is on. +// traceAccess goes into the unit of each probe that reads tracefs, before its trace: the +// guest's lockdown level and what reading tracefs answered. Both, because a locked-down kernel +// gives an empty trace and an empty trace has other causes: from the commit that forced +// lockdown (1400f6a) these probes answered "the trace is empty: is each a function entered +// after ftrace_init?" for acpi_init, which they had traced before (found 2026-11-12). +const traceAccess = `echo SPIN-LOCKDOWN $$(cat /sys/kernel/security/lockdown 2>&1); echo SPIN-TRACEFS $$(cat /sys/kernel/tracing/tracing_on 2>&1);` + +var ( + reLockdown = regexp.MustCompile(`SPIN-LOCKDOWN ([^\r\n]*)`) + reTracefs = regexp.MustCompile(`SPIN-TRACEFS ([^\r\n]*)`) +) + +// untraceable says why a kernel booted with traceAccess in its probe's unit could not be +// traced, with what to do instead, or "" when it could. +// +// The release's kernel never can: it runs lockdown at confidentiality from its first +// instruction (CONFIG_LOCK_DOWN_KERNEL_FORCE_CONFIDENTIALITY, kernel/README.md), which takes +// tracefs from root, and a lockdown= parameter only raises the level. So a trace is of a +// kernel B built without it, which is how lockdown's own cost was measured (2026-10-01). +func untraceable(console string) string { + const how = "trace a kernel built without it: on a branch, take " + + "CONFIG_LOCK_DOWN_KERNEL_FORCE_CONFIDENTIALITY out of kernel/config-* and out of " + + "kernel/Dockerfile's check of it, build it (task kernel:build there, or the Kernel workflow), " + + "and run this with SPIN_KERNEL_B= and GRAPH_KERNEL=b - in the lab, kernel_run=" + l := reLockdown.FindStringSubmatch(console) + f := reTracefs.FindStringSubmatch(console) + if l == nil || f == nil { + return "the probe's unit printed no SPIN-LOCKDOWN or SPIN-TRACEFS line, so it did not run" + } + if strings.Contains(l[1], "[confidentiality]") { + return "this kernel runs lockdown at confidentiality (" + strings.TrimSpace(l[1]) + + "), which closes tracefs to root; " + how + } + if v := strings.TrimSpace(f[1]); v != "0" && v != "1" { + return "tracefs answered " + strconv.Quote(v) + " (lockdown " + strings.TrimSpace(l[1]) + "); " + how + } + return "" +} + // graphReport boots reps machines with fns traced and prints the tree of p50 durations, on the // release's kernel or, with GRAPH_KERNEL=b, on SPIN_KERNEL_B's - which is also the check that a // kernel built differently still has a working function tracer: an empty tree fails. @@ -50,7 +89,7 @@ After=multi-user.target [Service] Type=oneshot StandardOutput=null -ExecStart=/bin/sh -c "mount -t tracefs none /sys/kernel/tracing 2>/dev/null; echo 0 > /sys/kernel/tracing/tracing_on; { echo SPIN-TRACE-BEGIN; grep -E '[{]$$|[}] /[*]|[+!#*@$$] +[0-9]' /sys/kernel/tracing/trace; echo SPIN-TRACE-END; echo SPIN-INVALID $$(grep -c __ftrace_invalid_address__ /sys/kernel/tracing/available_filter_functions); echo SPIN-DMESG-END; } > /dev/ttyS0" +ExecStart=/bin/sh -c "mount -t tracefs none /sys/kernel/tracing 2>/dev/null; echo 0 > /sys/kernel/tracing/tracing_on; { ` + traceAccess + ` echo SPIN-TRACE-BEGIN; grep -E '[{]$$|[}] /[*]|[+!#*@$$] +[0-9]' /sys/kernel/tracing/trace; echo SPIN-TRACE-END; echo SPIN-INVALID $$(grep -c __ftrace_invalid_address__ /sys/kernel/tracing/available_filter_functions); echo SPIN-DMESG-END; } > /dev/ttyS0" [Install] WantedBy=multi-user.target ` @@ -80,6 +119,9 @@ WantedBy=multi-user.target if m := regexp.MustCompile(`SPIN-INVALID (\d+)`).FindStringSubmatch(console); m != nil && m[1] != "0" { t.Errorf("available_filter_functions lists %s __ftrace_invalid_address__ records", m[1]) } + if why := untraceable(console); why != "" { + t.Fatalf("nothing can be traced on this kernel: %s", why) + } calls := parseGraph(console[begin:end]) if len(calls) == 0 { t.Fatalf("the trace of %s is empty: is each a function entered after ftrace_init?\n%s", @@ -112,14 +154,27 @@ func parseGraph(trace string) map[string]float64 { continue } if m := reGraphClose.FindStringSubmatch(line); m != nil { - st := stacks[m[1]] - if len(st) == 0 || st[len(st)-1] != m[3] { - // A close whose open was before the buffer began, or on another CPU. - continue + cpu := m[1] + if st := stacks[cpu]; len(st) == 0 || st[len(st)-1] != m[3] { + // Opened on another CPU: the task migrated while the function ran, which a + // function that sleeps does - acpi_init opened on CPU 1 and closed on CPU 0 in a + // boot on 2026-11-12, and the whole trace read as empty. Its open is the top of + // another CPU's stack. A close found nowhere opened before the buffer began. + cpu = "" + for c, other := range stacks { + if len(other) > 0 && other[len(other)-1] == m[3] { + cpu = c + break + } + } + if cpu == "" { + continue + } } + st := stacks[cpu] us, _ := strconv.ParseFloat(m[2], 64) total[strings.Join(st, "/")] += us / 1000 - stacks[m[1]] = st[:len(st)-1] + stacks[cpu] = st[:len(st)-1] continue } if m := reGraphLeaf.FindStringSubmatch(line); m != nil { @@ -207,6 +262,8 @@ func TestAGraphTraceIsSummedByCallPath(t *testing.T) { 0) + 12.000 us | acpi_ev_init(); 0) # 5000.000 us | } /* acpi_init */ 1) 3.000 us | } /* never_opened */ + 1) | migrates() { + 0) # 9913.509 us | } /* migrates */ ` got := parseGraph(trace) want := map[string]float64{ @@ -215,6 +272,7 @@ func TestAGraphTraceIsSummedByCallPath(t *testing.T) { "acpi_init/acpi_bus_scan/acpi_ns_walk": 0.002, "acpi_init/acpi_ev_init": 0.012, "other_cpu_leaf": 0.009, + "migrates": 9.913509, } if len(got) != len(want) { t.Fatalf("parsed %v, want %v", got, want) diff --git a/boot/jobs.go b/boot/jobs.go new file mode 100644 index 0000000..f2ba955 --- /dev/null +++ b/boot/jobs.go @@ -0,0 +1,220 @@ +// 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, j.Initial = f[3], true + 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) { + continue + } + if j.Running > 0 && t >= j.Running { + 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 new file mode 100644 index 0000000..219fc38 --- /dev/null +++ b/boot/jobs_test.go @@ -0,0 +1,115 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot + +import ( + "os" + "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) + } + } +} diff --git a/boot/jobwatch/main.go b/boot/jobwatch/main.go new file mode 100644 index 0000000..0fd021f --- /dev/null +++ b/boot/jobwatch/main.go @@ -0,0 +1,181 @@ +// 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" +) + +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. +func now() int64 { + var ts unix.Timespec + _ = unix.ClockGettime(unix.CLOCK_MONOTONIC, &ts) + return ts.Nano() / 1000 +} + +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 { + 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 new file mode 100644 index 0000000..26f9089 --- /dev/null +++ b/boot/jobwatch/main_test.go @@ -0,0 +1,18 @@ +// 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) + } + } +} diff --git a/boot/jobwatch_probe_test.go b/boot/jobwatch_probe_test.go new file mode 100644 index 0000000..a3abaae --- /dev/null +++ b/boot/jobwatch_probe_test.go @@ -0,0 +1,250 @@ +// 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 new file mode 100644 index 0000000..d977809 --- /dev/null +++ b/boot/mmio_test.go @@ -0,0 +1,170 @@ +// 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 new file mode 100644 index 0000000..5c0c84b --- /dev/null +++ b/boot/ssh_first_test.go @@ -0,0 +1,242 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot_test + +import ( + "bytes" + "cmp" + "fmt" + "math/rand/v2" + "os" + "os/exec" + "path/filepath" + "strings" + "sync" + "syscall" + "testing" + "time" + + "golang.org/x/sys/unix" + + "github.com/spin-stack/spin-machine/boot" +) + +// When a workspace can first be logged into, from the host, over SSH - the thing a workspace +// waits for, where boot:bench's `usable` is the serial console's prompt, which nothing a +// workspace does waits for. +// +// The machine gets a vsock device (--vsock-cid), and the image's systemd-ssh-generator binds +// sshd to AF_VSOCK port 22 when it finds one. From the moment before QEMU is exec'd the host +// tries to connect every few milliseconds; the first connection accepted is `listen`, and then +// one `ssh spin@ true` through boot/vsockproxy is `login`. The console's prompt is timed in the +// 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. +// +// SPIN_SSH_FIRST=1 run at all +// REPS= boots of each row (default 10) +// CPUS= vCPUs (default 2) +func TestFirstSSH(t *testing.T) { + if os.Getenv("SPIN_SSH_FIRST") == "" { + t.Skip("set SPIN_SSH_FIRST=1: boots VMs with a vsock device and logs into them") + } + out := releaseDir(t) + if !canSudo() { + t.Skip("this writes a key into the boot's own overlay through qemu-nbd, which needs sudo") + } + if _, err := os.Stat("/dev/vhost-vsock"); err != nil { + t.Skip("no /dev/vhost-vsock: run task vsock") + } + reps := envInt(t, "REPS", 10) + + dir := t.TempDir() + proxy := filepath.Join(dir, "vsockproxy") + build := exec.Command("go", "build", "-trimpath", "-o", proxy, "./vsockproxy") + if b, err := build.CombinedOutput(); err != nil { + t.Fatalf("building vsockproxy: %v\n%s", err, b) + } + key := filepath.Join(dir, "key") + mustRun(t, "ssh-keygen", "-q", "-t", "ed25519", "-N", "", "-f", key) + + // Every row has the key, the echo getty, and sshd@.service ordered after the image's host + // key generation. The image carries that drop-in itself since 2026-11-12; it is written + // here as well because the lab boots published releases, and one from before it cannot be + // logged into over vsock at all - the per-connection sshd finds no host keys. + keySetup := `ids=$(awk -F: '$1=="spin"{print $3":"$4}' "$MNT/etc/passwd"); test -n "$ids" +install -d -m 700 -o "${ids%:*}" -g "${ids#*:}" "$MNT/home/spin/.ssh" +install -m 600 -o "${ids%:*}" -g "${ids#*:}" ` + key + `.pub "$MNT/home/spin/.ssh/authorized_keys" +` + row := func(label, setup string) variant { + files := gettyDropin(gettyEcho) + files["/etc/systemd/system/sshd@.service.d/keygen.conf"] = "[Unit]\nWants=spin-machine-sshd-keygen.service\nAfter=spin-machine-sshd-keygen.service\n" + // The key in spin's own directory, owned by spin: sshd's StrictModes refuses one it + // cannot trust, and a refused key reads as a login that never comes. + return variant{label: label, cpus: cmp.Or(os.Getenv("CPUS"), "2"), memory: "2048", files: files, setup: keySetup + setup} + } + // Rows measured against "as built" and dropped once they had answered, on the bench fleet, + // 10 boots of each interleaved, lab run 43308825692 (2026-11-12), p50/p95 ms of the first + // login: as built then 570/626; pam_motd off 558/588; logind back in the boot 558/593; + // logind in the boot and spin lingering 510/525, with sshd accepting no later. The image + // now has no motd and lingers. Then, lab run 43312419007, 15 boots of each: the host keys + // generated in the boot (the keygen wanted by multi-user.target) 518/542 against 514/531 - + // nothing, so the keys stay with the first sshd that needs them. Each row's edit was checked in its setup, so a row that + // matched nothing failed rather than measuring the image under another name. + // + // The rows below are written so they hold on a release from before this branch as well as + // after it, because the lab boots published releases: each puts the image in the state this + // branch builds - logind in the boot, spin lingering - whether or not it already was. + const asThisBranch = `rm -f "$MNT/etc/systemd/system/multi-user.target.wants/systemd-logind.service" +test -e "$MNT/usr/lib/systemd/system/multi-user.target.wants/systemd-logind.service" +install -d "$MNT/var/lib/systemd/linger" && touch "$MNT/var/lib/systemd/linger/spin" +` + rows := []variant{ + row("as this branch", asThisBranch), + } + + type samples struct{ listen, login, again, prompt []time.Duration } + got := map[string]*samples{} + failed := map[string]int{} + for range reps { + for _, v := range rows { + r := firstSSH(t, out, v, proxy, key) + if got[v.label] == nil { + got[v.label] = &samples{} + } + if r.listen == 0 || r.login == 0 { + failed[v.label]++ + t.Logf("%s: a boot with no login: listen %v, login %v; %s", v.label, r.listen, r.login, r.why) + continue + } + g := got[v.label] + g.listen, g.login, g.again, g.prompt = append(g.listen, r.listen), append(g.login, r.login), append(g.again, r.again), append(g.prompt, r.prompt) + } + } + ms := func(ds []time.Duration, q float64) string { + d, ok := boot.Percentile(ds, q) + if !ok { + return "—" + } + return fmt.Sprintf("%.0f", float64(d)/float64(time.Millisecond)) + } + var b strings.Builder + fmt.Fprintf(&b, "\nms from the moment before QEMU is exec'd, p50/p95 over %d boots of each, interleaved, %s vCPUs\n\n", reps, rows[0].cpus) + fmt.Fprintf(&b, " %-16s %15s %15s %15s %15s %9s\n", "", "SSHD ACCEPTS", "FIRST LOGIN", "A SECOND TOOK", "CONSOLE PROMPT", "NO LOGIN") + for _, v := range rows { + g := got[v.label] + if g == nil { + g = &samples{} + } + fmt.Fprintf(&b, " %-16s %7s/%-7s %7s/%-7s %7s/%-7s %7s/%-7s %9d\n", v.label, + ms(g.listen, .5), ms(g.listen, .95), ms(g.login, .5), ms(g.login, .95), ms(g.again, .5), ms(g.again, .95), + ms(g.prompt, .5), ms(g.prompt, .95), failed[v.label]) + } + t.Log(b.String()) +} + +type firstSSHRun struct { + listen, login, prompt time.Duration + again time.Duration // a second login, right after the first: what any login costs + why string +} + +func firstSSH(t *testing.T, out string, v variant, proxy, key string) firstSSHRun { + t.Helper() + overlay := filepath.Join(t.TempDir(), "overlay.qcow2") + mustRun(t, filepath.Join(out, "bin", "qemu-img"), "create", "-f", "qcow2", + "-F", "qcow2", "-b", filepath.Join(out, "image", "rootfs.qcow2"), overlay) + editOverlay(t, overlay, v) + + // Context ids are the host's: two machines with one fail to start, so this one's is drawn + // from a range nothing else here uses. + cid := uint32(100000 + rand.IntN(1<<20)) + cmd := exec.Command(filepath.Join(out, "bin", "spin-machine"), "boot", "--release", out, + "--disk", overlay, "--memory", v.memory, "--cpus", v.cpus, + "--vsock-cid", fmt.Sprint(cid), + "--console", "file:/dev/stdout", "--append", "init=/sbin/init") + cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} + stdout, err := cmd.StdoutPipe() + if err != nil { + t.Fatalf("console pipe: %v", err) + } + var stderr bytes.Buffer + cmd.Stderr = &stderr + t0 := time.Now() + if err := cmd.Start(); err != nil { + t.Fatalf("launching the machine: %v", err) + } + defer func() { + if pgid, err := syscall.Getpgid(cmd.Process.Pid); err == nil { + _ = syscall.Kill(-pgid, syscall.SIGKILL) + } + _ = cmd.Wait() + }() + + var mu sync.Mutex + var r firstSSHRun + go func() { + run, _ := boot.Watch(stdout, t0, time.Now, boot.Usable) + mu.Lock() + r.prompt = run.At[boot.Usable] + mu.Unlock() + }() + + deadline := t0.Add(60 * time.Second) + for time.Now().Before(deadline) && r.listen == 0 { + if vsockAccepts(cid, 22) { + r.listen = time.Since(t0) + break + } + time.Sleep(2 * time.Millisecond) + } + if r.listen == 0 { + r.why = "sshd never accepted on vsock; QEMU: " + strings.TrimSpace(stderr.String()) + return r + } + ssh := []string{"-F", "/dev/null", "-i", key, "-o", "BatchMode=yes", + "-o", "StrictHostKeyChecking=no", "-o", "UserKnownHostsFile=/dev/null", "-o", "LogLevel=error", + "-o", "ConnectTimeout=10", "-o", fmt.Sprintf("ProxyCommand=%s %d 22", proxy, cid), "spin@vsock", "true"} + for time.Now().Before(deadline) { + b, err := exec.Command("ssh", ssh...).CombinedOutput() + if err == nil { + r.login = time.Since(t0) + break + } + r.why = fmt.Sprintf("ssh: %v: %s", err, strings.TrimSpace(string(b))) + time.Sleep(10 * time.Millisecond) + } + if r.login != 0 { + t1 := time.Now() + if exec.Command("ssh", ssh...).Run() == nil { + r.again = time.Since(t1) + } + } + // The prompt is usually there by now; it is waited for so the row is not empty. + for time.Now().Before(deadline) { + mu.Lock() + p := r.prompt + mu.Unlock() + if p != 0 { + break + } + time.Sleep(10 * time.Millisecond) + } + mu.Lock() + defer mu.Unlock() + return r +} + +// vsockAccepts says whether something accepts a connection on cid:port now. The connect +// timeout is short because a machine not yet started is the common answer, and the default +// is two seconds of not knowing. +func vsockAccepts(cid, port uint32) bool { + fd, err := unix.Socket(unix.AF_VSOCK, unix.SOCK_STREAM|unix.SOCK_CLOEXEC, 0) + if err != nil { + return false + } + defer unix.Close(fd) + tv := unix.NsecToTimeval((50 * time.Millisecond).Nanoseconds()) + _ = unix.SetsockoptTimeval(fd, unix.AF_VSOCK, unix.SO_VM_SOCKETS_CONNECT_TIMEOUT, &tv) + return unix.Connect(fd, &unix.SockaddrVM{CID: cid, Port: port}) == nil +} diff --git a/boot/testdata/first-login.sh b/boot/testdata/first-login.sh new file mode 100644 index 0000000..37d5c8f --- /dev/null +++ b/boot/testdata/first-login.sh @@ -0,0 +1,32 @@ +#!/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 new file mode 100644 index 0000000..85095e5 --- /dev/null +++ b/boot/testdata/jobs-2026-11-12.txt @@ -0,0 +1,173 @@ + +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 new file mode 100644 index 0000000..6fdea1e --- /dev/null +++ b/boot/testdata/jobs-waits-2026-11-12.txt @@ -0,0 +1,1545 @@ + +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/testdata/waits-2026-11-12.txt b/boot/testdata/waits-2026-11-12.txt new file mode 100644 index 0000000..ea4c4cb --- /dev/null +++ b/boot/testdata/waits-2026-11-12.txt @@ -0,0 +1,1536 @@ + +UserspaceTimestampMonotonic=47763 +FinishTimestampMonotonic=160902 +SecurityStartTimestampMonotonic=47988 +SecurityFinishTimestampMonotonic=48448 +GeneratorsStartTimestampMonotonic=74617 +GeneratorsFinishTimestampMonotonic=78154 +UnitsLoadStartTimestampMonotonic=78158 +UnitsLoadFinishTimestampMonotonic=79946 +SPIN-WAITS-UNITS +Id=proc-sys-fs-binfmt_misc.automount +Names=proc-sys-fs-binfmt_misc.automount +After=-.mount +ActiveState=active +InactiveExitTimestampMonotonic=102125 +ActiveEnterTimestampMonotonic=102125 +InactiveEnterTimestampMonotonic=0 + +Id=dev-disk-by\x2ddiskseq-9.device +Names="dev-disk-by\\x2ddiskseq-9.device" +After= +ActiveState=active +InactiveExitTimestampMonotonic=172881 +ActiveEnterTimestampMonotonic=172881 +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=172884 +ActiveEnterTimestampMonotonic=172884 +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=172884 +ActiveEnterTimestampMonotonic=172884 +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=157388 +ActiveEnterTimestampMonotonic=157388 +InactiveEnterTimestampMonotonic=0 + +Id=dev-ttyS1.device +Names=dev-ttyS1.device +After= +ActiveState=active +InactiveExitTimestampMonotonic=156730 +ActiveEnterTimestampMonotonic=156730 +InactiveEnterTimestampMonotonic=0 + +Id=dev-ttyS2.device +Names=dev-ttyS2.device +After= +ActiveState=active +InactiveExitTimestampMonotonic=162431 +ActiveEnterTimestampMonotonic=162431 +InactiveEnterTimestampMonotonic=0 + +Id=dev-ttyS3.device +Names=dev-ttyS3.device +After= +ActiveState=active +InactiveExitTimestampMonotonic=162887 +ActiveEnterTimestampMonotonic=162887 +InactiveEnterTimestampMonotonic=0 + +Id=dev-vda.device +Names=dev-vda.device +After= +ActiveState=active +InactiveExitTimestampMonotonic=80035 +ActiveEnterTimestampMonotonic=172886 +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=172885 +ActiveEnterTimestampMonotonic=172885 +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=156733 +ActiveEnterTimestampMonotonic=156733 +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=162428 +ActiveEnterTimestampMonotonic=162428 +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=162886 +ActiveEnterTimestampMonotonic=162886 +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=157380 +ActiveEnterTimestampMonotonic=157380 +InactiveEnterTimestampMonotonic=0 + +Id=sys-devices-virtual-net-sit0.device +Names=sys-devices-virtual-net-sit0.device +After= +ActiveState=active +InactiveExitTimestampMonotonic=153350 +ActiveEnterTimestampMonotonic=153350 +InactiveEnterTimestampMonotonic=0 + +Id=sys-subsystem-net-devices-sit0.device +Names=sys-subsystem-net-devices-sit0.device +After= +ActiveState=active +InactiveExitTimestampMonotonic=153352 +ActiveEnterTimestampMonotonic=153352 +InactiveEnterTimestampMonotonic=0 + +Id=-.mount +Names=-.mount +After=-.slice +ActiveState=active +InactiveExitTimestampMonotonic=80022 +ActiveEnterTimestampMonotonic=80022 +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=proc-sys-fs-binfmt_misc.automount systemd-journald.socket -.mount -.slice +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=binfmt_misc + +Id=sys-fs-fuse-connections.mount +Names=sys-fs-fuse-connections.mount +After=systemd-journald.socket -.mount -.slice modprobe@fuse.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=fusectl + +Id=sys-kernel-config.mount +Names=sys-kernel-config.mount +After=-.slice modprobe@configfs.service -.mount systemd-journald.socket +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=-.mount systemd-journald.socket system.slice swap.target +ActiveState=active +InactiveExitTimestampMonotonic=104208 +ActiveEnterTimestampMonotonic=109498 +InactiveEnterTimestampMonotonic=0 +Type=tmpfs + +Id=systemd-ask-password-console.path +Names=systemd-ask-password-console.path +After=plymouth-start.service -.mount +ActiveState=active +InactiveExitTimestampMonotonic=102062 +ActiveEnterTimestampMonotonic=102062 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-ask-password-wall.path +Names=systemd-ask-password-wall.path +After=-.mount +ActiveState=active +InactiveExitTimestampMonotonic=102074 +ActiveEnterTimestampMonotonic=102074 +InactiveEnterTimestampMonotonic=0 + +Id=init.scope +Names=init.scope +After=-.slice +ActiveState=active +InactiveExitTimestampMonotonic=80032 +ActiveEnterTimestampMonotonic=80032 +InactiveEnterTimestampMonotonic=0 + +Id=apparmor.service +Names=apparmor.service +After=systemd-journald-audit.socket system.slice local-fs.target systemd-sysctl.service -.mount systemd-journald.socket +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=containerd.socket system.slice sysinit.target basic.target network.target dbus-broker.service systemd-journald.socket +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=notify + +Id=dbus-broker.service +Names=dbus-broker.service dbus.service +After=tmp.mount systemd-tmpfiles-setup.service systemd-journald.socket dbus.socket system.slice -.mount +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=notify-reload + +Id=docker.service +Names=docker.service +After=basic.target time-set.target containerd.service docker.socket systemd-journald.socket network-online.target sysinit.target nss-lookup.target system.slice firewalld.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=notify + +Id=emergency.service +Names=emergency.service +After=systemd-ask-password-wall.path syslog.socket -.mount system.slice systemd-ask-password-console.service sysinit.target systemd-ask-password-console.path +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=fstrim.timer sysinit.target systemd-journald.socket basic.target system.slice +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=getty-static.service +Names=getty-static.service +After=basic.target systemd-journald.socket system.slice sysinit.target +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=getty@tty1.service +Names=getty@tty1.service autovt@tty1.service +After=sysinit.target systemd-user-sessions.service plymouth-quit-wait.service basic.target getty-pre.target rc-local.service system-getty.slice +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=idle + +Id=initrd-cleanup.service +Names=initrd-cleanup.service +After=systemd-journald.socket initrd.target initrd-fs.target initrd-root-fs.target system.slice +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=initrd-parse-etc.service +Names=initrd-parse-etc.service +After=systemd-journald.socket system.slice initrd-root-fs.target +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=initrd-switch-root.service +Names=initrd-switch-root.service +After=initrd-switch-root.target systemd-udevd.service system.slice systemd-journald.socket +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=initrd-udevadm-cleanup-db.service +Names=initrd-udevadm-cleanup-db.service +After=systemd-journald.socket systemd-udev-trigger.service systemd-udev-settle.service system.slice systemd-udevd.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=kmod-static-nodes.service +Names=kmod-static-nodes.service +After=systemd-journald.socket system.slice +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=systemd-journald.socket system-modprobe.slice +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=systemd-journald.socket system-modprobe.slice +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=systemd-journald.socket system.slice sysinit.target network.target basic.target network-online.target +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=forking + +Id=rescue.service +Names=rescue.service +After=plymouth-start.service system.slice -.mount getty@tty1.service emergency.service serial-getty@ttyS0.service sysinit.target +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=idle + +Id=serial-getty@ttyS0.service +Names=serial-getty@ttyS0.service +After="system-serial\\x2dgetty.slice" rc-local.service getty-pre.target basic.target sysinit.target systemd-user-sessions.service plymouth-quit-wait.service dev-ttyS0.device +ActiveState=active +InactiveExitTimestampMonotonic=158437 +ActiveEnterTimestampMonotonic=158437 +InactiveEnterTimestampMonotonic=0 +Type=idle + +Id=spin-machine-sshd-keygen.service +Names=spin-machine-sshd-keygen.service +After=system.slice sysinit.target basic.target systemd-journald.socket +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=spin-waits.service +Names=spin-waits.service +After=sysinit.target multi-user.target basic.target system.slice +ActiveState=active +InactiveExitTimestampMonotonic=160898 +ActiveEnterTimestampMonotonic=160898 +InactiveEnterTimestampMonotonic=0 +Type=simple + +Id=ssh.service +Names=ssh.service sshd.service +After=systemd-journald.socket network.target -.mount sshd-keygen.service spin-machine-sshd-keygen.service auditd.service basic.target system.slice ssh.socket sysinit.target nss-user-lookup.target +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=notify + +Id=sshd-keygen.service +Names=sshd-keygen.service +After=sysinit.target basic.target systemd-journald.socket system.slice +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=sshd-keygen.service sysinit.target auditd.service nss-user-lookup.target basic.target -.mount system-sshd.slice +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=plymouth-start.service system.slice systemd-ask-password-console.path systemd-journald.socket systemd-vconsole-setup.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=notify + +Id=systemd-ask-password-wall.service +Names=systemd-ask-password-wall.service +After=sysinit.target systemd-user-sessions.service systemd-ask-password-wall.path systemd-journald.socket basic.target system.slice +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=notify + +Id=systemd-battery-check.service +Names=systemd-battery-check.service +After=system.slice systemd-journald.socket plymouth-start.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-binfmt.service +Names=systemd-binfmt.service +After=local-fs.target system.slice proc-sys-fs-binfmt_misc.mount proc-sys-fs-binfmt_misc.automount systemd-journald.socket +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-bsod.service +Names=systemd-bsod.service +After=system.slice systemd-journald.socket systemd-battery-check.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=simple + +Id=systemd-confext-initrd.service +Names=systemd-confext-initrd.service +After=modprobe@loop.service system.slice modprobe@dm_mod.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=systemd-journald.socket systemd-battery-check.service system.slice +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-hostnamed.service +Names=systemd-hostnamed.service dbus-org.freedesktop.hostname1.service +After=tmp.mount systemd-tmpfiles-setup.service -.mount sysinit.target systemd-journald.socket system.slice basic.target systemd-hostnamed.socket +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=systemd-journald-audit.socket syslog.socket system.slice systemd-journald-dev-log.socket -.mount systemd-journald.socket +ActiveState=active +InactiveExitTimestampMonotonic=105587 +ActiveEnterTimestampMonotonic=129790 +InactiveEnterTimestampMonotonic=0 +Type=notify-reload + +Id=systemd-logind.service +Names=systemd-logind.service dbus-org.freedesktop.login1.service +After=systemd-journald.socket systemd-remount-fs.service system.slice systemd-logind-varlink.socket basic.target dbus.socket user.slice nss-user-lookup.target modprobe@drm.service -.mount systemd-tmpfiles-setup.service tmp.mount sysinit.target +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=system.slice tpm2.target systemd-tpm2-setup-early.service systemd-journald.socket +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-pcrphase-initrd.service +Names=systemd-pcrphase-initrd.service +After=tpm2.target system.slice systemd-journald.socket +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-pcrphase-sysinit.service +Names=systemd-pcrphase-sysinit.service +After=tpm2.target systemd-journald.socket sysinit.target system.slice +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-pcrphase.service +Names=systemd-pcrphase.service +After=basic.target tpm2.target sysinit.target remote-fs.target remote-cryptsetup.target systemd-journald.socket system.slice +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-pcrproduct.service +Names=systemd-pcrproduct.service +After=system.slice tpm2.target systemd-journald.socket systemd-pcrnvdone.service -.mount +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 system.slice systemd-journald.socket +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-soft-reboot.service +Names=systemd-soft-reboot.service +After=systemd-journald.service final.target system.slice systemd-journald.socket umount.target systemd-udevd.service shutdown.target +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-sysctl.service +Names=systemd-sysctl.service procps.service +After=systemd-modules-load.service systemd-journald.socket system.slice +ActiveState=active +InactiveExitTimestampMonotonic=106056 +ActiveEnterTimestampMonotonic=114601 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-sysext-initrd.service +Names=systemd-sysext-initrd.service +After=modprobe@dm_mod.service system.slice systemd-journald.socket modprobe@loop.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-sysext.service +Names=systemd-sysext.service +After=systemd-journald.socket system.slice local-fs.target 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=systemd-tmpfiles-clean.timer time-set.target systemd-journald.socket local-fs.target system.slice +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=systemd-sysext.service systemd-journald.socket systemd-journald.service systemd-confext-initrd.service local-fs.target systemd-sysusers.service system.slice systemd-sysext-initrd.service +ActiveState=active +InactiveExitTimestampMonotonic=131559 +ActiveEnterTimestampMonotonic=137984 +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=systemd-journald.socket system.slice +ActiveState=active +InactiveExitTimestampMonotonic=107813 +ActiveEnterTimestampMonotonic=112527 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-udev-settle.service +Names=systemd-udev-settle.service +After=systemd-udev-trigger.service system.slice systemd-journald.socket +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-udev-trigger.service +Names=systemd-udev-trigger.service +After=system.slice systemd-udevd-control.socket systemd-udevd-varlink.socket systemd-udevd-kernel.socket systemd-journald.socket +ActiveState=active +InactiveExitTimestampMonotonic=108277 +ActiveEnterTimestampMonotonic=131719 +InactiveEnterTimestampMonotonic=0 +Type=oneshot + +Id=systemd-udevd.service +Names=systemd-udevd.service +After=systemd-udevd-varlink.socket systemd-udev-load-credentials.service systemd-hwdb-update.service systemd-udevd-kernel.socket systemd-journald.socket system.slice systemd-sysusers.service systemd-udevd-control.socket +ActiveState=active +InactiveExitTimestampMonotonic=113953 +ActiveEnterTimestampMonotonic=142592 +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=basic.target remote-fs.target system.slice systemd-journald.socket systemd-pcrphase.service network.target nss-user-lookup.target home.mount sysinit.target +ActiveState=active +InactiveExitTimestampMonotonic=148648 +ActiveEnterTimestampMonotonic=151236 +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=80017 +ActiveEnterTimestampMonotonic=80017 +InactiveEnterTimestampMonotonic=0 + +Id=system-getty.slice +Names=system-getty.slice +After=system.slice +ActiveState=active +InactiveExitTimestampMonotonic=101907 +ActiveEnterTimestampMonotonic=101907 +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=102041 +ActiveEnterTimestampMonotonic=102041 +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=80020 +ActiveEnterTimestampMonotonic=80020 +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 -.mount system.slice +ActiveState=active +InactiveExitTimestampMonotonic=142906 +ActiveEnterTimestampMonotonic=145955 +InactiveEnterTimestampMonotonic=0 + +Id=dbus.socket +Names=dbus.socket +After=-.mount system.slice sysinit.target +ActiveState=active +InactiveExitTimestampMonotonic=143174 +ActiveEnterTimestampMonotonic=143189 +InactiveEnterTimestampMonotonic=0 + +Id=docker.socket +Names=docker.socket +After=system.slice -.mount sysinit.target +ActiveState=active +InactiveExitTimestampMonotonic=143205 +ActiveEnterTimestampMonotonic=145970 +InactiveEnterTimestampMonotonic=0 + +Id=ssh.socket +Names=ssh.socket +After=sysinit.target system.slice +ActiveState=active +InactiveExitTimestampMonotonic=143432 +ActiveEnterTimestampMonotonic=144428 +InactiveEnterTimestampMonotonic=0 + +Id=sshd-unix-local.socket +Names=sshd-unix-local.socket +After=-.mount system.slice sysinit.target +ActiveState=active +InactiveExitTimestampMonotonic=144450 +ActiveEnterTimestampMonotonic=144865 +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=102176 +ActiveEnterTimestampMonotonic=102631 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-creds.socket +Names=systemd-creds.socket +After=system.slice -.mount +ActiveState=active +InactiveExitTimestampMonotonic=102645 +ActiveEnterTimestampMonotonic=102904 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-factory-reset.socket +Names=systemd-factory-reset.socket +After=system.slice -.mount +ActiveState=active +InactiveExitTimestampMonotonic=102914 +ActiveEnterTimestampMonotonic=103290 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-hostnamed.socket +Names=systemd-hostnamed.socket +After=-.mount sysinit.target system.slice +ActiveState=active +InactiveExitTimestampMonotonic=144878 +ActiveEnterTimestampMonotonic=144884 +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=103300 +ActiveEnterTimestampMonotonic=103316 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-journald.socket +Names=systemd-journald.socket +After=system.slice -.mount +ActiveState=active +InactiveExitTimestampMonotonic=103326 +ActiveEnterTimestampMonotonic=103335 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-logind-varlink.socket +Names=systemd-logind-varlink.socket +After=sysinit.target systemd-journald.socket -.mount system.slice +ActiveState=active +InactiveExitTimestampMonotonic=145823 +ActiveEnterTimestampMonotonic=147621 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-mute-console.socket +Names=systemd-mute-console.socket +After=system.slice -.mount +ActiveState=active +InactiveExitTimestampMonotonic=103348 +ActiveEnterTimestampMonotonic=103797 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-pcrextend.socket +Names=systemd-pcrextend.socket +After=-.mount system.slice tpm2.target +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-pcrlock.socket +Names=systemd-pcrlock.socket +After=-.mount system.slice tpm2.target +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-sysext.socket +Names=systemd-sysext.socket +After=-.mount system.slice local-fs.target +ActiveState=active +InactiveExitTimestampMonotonic=109551 +ActiveEnterTimestampMonotonic=110731 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-udevd-control.socket +Names=systemd-udevd-control.socket +After=system.slice -.mount +ActiveState=active +InactiveExitTimestampMonotonic=103817 +ActiveEnterTimestampMonotonic=103826 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-udevd-kernel.socket +Names=systemd-udevd-kernel.socket +After=system.slice +ActiveState=active +InactiveExitTimestampMonotonic=103834 +ActiveEnterTimestampMonotonic=103839 +InactiveEnterTimestampMonotonic=0 + +Id=systemd-udevd-varlink.socket +Names=systemd-udevd-varlink.socket +After=system.slice -.mount +ActiveState=active +InactiveExitTimestampMonotonic=103847 +ActiveEnterTimestampMonotonic=103851 +InactiveEnterTimestampMonotonic=0 + +Id=basic.target +Names=basic.target +After=paths.target systemd-pcrphase-sysinit.service -.mount slices.target sockets.target tmp.mount dbus-broker.service sysinit.target +ActiveState=active +InactiveExitTimestampMonotonic=147647 +ActiveEnterTimestampMonotonic=147647 +InactiveEnterTimestampMonotonic=0 + +Id=cryptsetup-pre.target +Names=cryptsetup-pre.target +After=systemd-sysext-initrd.service systemd-pcrphase-initrd.service systemd-pcrnvdone.service systemd-confext-initrd.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 + +Id=cryptsetup.target +Names=cryptsetup.target +After=systemd-ask-password-wall.path systemd-pcrphase-initrd.service systemd-pcrnvdone.service systemd-ask-password-console.path +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 + +Id=emergency.target +Names=emergency.target +After=sysinit.target emergency.service +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=getty@tty1.service getty-static.service serial-getty@ttyS0.service +ActiveState=active +InactiveExitTimestampMonotonic=158477 +ActiveEnterTimestampMonotonic=158477 +InactiveEnterTimestampMonotonic=0 + +Id=imports.target +Names=imports.target +After= +ActiveState=active +InactiveExitTimestampMonotonic=102136 +ActiveEnterTimestampMonotonic=102136 +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-pcrnvdone.service systemd-tmpfiles-setup.service initrd-fs.target emergency.target emergency.service systemd-tmpfiles-clean.service initrd-cleanup.service systemd-ask-password-console.service systemd-confext-initrd.service systemd-udevd.service systemd-udev-load-credentials.service initrd-udevadm-cleanup-db.service systemd-sysext-initrd.service initrd-root-fs.target +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=initrd-fs.target initrd-root-device.target initrd-root-fs.target basic.target rescue.target rescue.service initrd-usr-fs.target +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 + +Id=local-fs-pre.target +Names=local-fs-pre.target +After=systemd-sysext-initrd.service systemd-hibernate-resume.service systemd-remount-fs.service systemd-confext-initrd.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 + +Id=local-fs.target +Names=local-fs.target +After=systemd-remount-fs.service local-fs-pre.target tmp.mount +ActiveState=active +InactiveExitTimestampMonotonic=109518 +ActiveEnterTimestampMonotonic=109518 +InactiveEnterTimestampMonotonic=0 + +Id=multi-user.target +Names=multi-user.target default.target +After=rescue.target rescue.service getty.target basic.target systemd-user-sessions.service +ActiveState=active +InactiveExitTimestampMonotonic=158481 +ActiveEnterTimestampMonotonic=158481 +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=102141 +ActiveEnterTimestampMonotonic=102141 +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=102145 +ActiveEnterTimestampMonotonic=102145 +InactiveEnterTimestampMonotonic=0 + +Id=rescue.target +Names=rescue.target +After=sysinit.target rescue.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 + +Id=shutdown.target +Names=shutdown.target +After=system-modprobe.slice systemd-ask-password-console.service rc-local.service emergency.service systemd-sysctl.service getty-static.service sockets.target user.slice systemd-pcrproduct.service systemd-bsod.service network-online.target systemd-logind.service slices.target local-fs-pre.target dbus-broker.service initrd.target basic.target rescue.target systemd-tmpfiles-setup.service containerd.socket sshd-unix-local.socket systemd-binfmt.service systemd-ask-password-wall.service fstrim.service "system-serial\\x2dgetty.slice" systemd-mute-console.socket emergency.target docker.socket ssh.service systemd-udev-load-credentials.service remote-fs-pre.target rescue.service systemd-pcrnvdone.service getty-pre.target systemd-pcrphase.service system-sshd.slice imports.target systemd-ask-password-wall.path systemd-remount-fs.service serial-getty@ttyS0.service ssh.socket network-pre.target getty.target systemd-pcrphase-initrd.service sshd@sshd-keygen.service systemd-hostnamed.socket swap.target nss-lookup.target systemd-pcrphase-sysinit.service spin-waits.service time-sync.target syslog.socket sysinit.target systemd-tmpfiles-clean.timer paths.target systemd-ask-password-console.path getty@tty1.service docker.service spin-machine-sshd-keygen.service multi-user.target proc-sys-fs-binfmt_misc.automount nss-user-lookup.target systemd-hostnamed.service systemd-user-sessions.service tpm2.target systemd-tmpfiles-clean.service systemd-logind-varlink.socket time-set.target containerd.service network.target system-getty.slice fstrim.timer systemd-sysext.service sshd-keygen.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 + +Id=slices.target +Names=slices.target +After=user.slice system.slice -.slice +ActiveState=active +InactiveExitTimestampMonotonic=102149 +ActiveEnterTimestampMonotonic=102149 +InactiveEnterTimestampMonotonic=0 + +Id=sockets.target +Names=sockets.target +After=dbus.socket systemd-creds.socket systemd-mute-console.socket systemd-journald-dev-log.socket systemd-pcrlock.socket ssh.socket systemd-udevd-control.socket systemd-journald.socket systemd-udevd-varlink.socket syslog.socket systemd-journald-audit.socket docker.socket systemd-ask-password.socket containerd.socket systemd-udevd-kernel.socket systemd-factory-reset.socket systemd-logind-varlink.socket systemd-sysext.socket sshd-unix-local.socket systemd-hostnamed.socket systemd-pcrextend.socket +ActiveState=active +InactiveExitTimestampMonotonic=147639 +ActiveEnterTimestampMonotonic=147639 +InactiveEnterTimestampMonotonic=0 + +Id=soft-reboot.target +Names=soft-reboot.target +After=systemd-soft-reboot.service systemd-journald.service systemd-udevd.service +ActiveState=inactive +InactiveExitTimestampMonotonic=0 +ActiveEnterTimestampMonotonic=0 +InactiveEnterTimestampMonotonic=0 + +Id=swap.target +Names=swap.target +After= +ActiveState=active +InactiveExitTimestampMonotonic=102155 +ActiveEnterTimestampMonotonic=102155 +InactiveEnterTimestampMonotonic=0 + +Id=sysinit.target +Names=sysinit.target +After=systemd-udev-settle.service local-fs.target modprobe@dm_mod.service imports.target systemd-sysext.service systemd-udevd.service systemd-sysctl.service proc-sys-fs-binfmt_misc.automount modprobe@loop.service kmod-static-nodes.service systemd-pcrphase-initrd.service systemd-journald.service systemd-tmpfiles-setup.service apparmor.service sys-fs-fuse-connections.mount systemd-udev-trigger.service swap.target sys-kernel-config.mount systemd-pcrnvdone.service systemd-binfmt.service systemd-pcrproduct.service +ActiveState=active +InactiveExitTimestampMonotonic=142651 +ActiveEnterTimestampMonotonic=142651 +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=142895 +ActiveEnterTimestampMonotonic=142895 +InactiveEnterTimestampMonotonic=0 + +Id=tpm2.target +Names=tpm2.target +After=dev-tpmrm0.device dev-tpm0.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-sync.target time-set.target sysinit.target -.mount +ActiveState=active +InactiveExitTimestampMonotonic=142879 +ActiveEnterTimestampMonotonic=142879 +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=142889 +ActiveEnterTimestampMonotonic=142889 +InactiveEnterTimestampMonotonic=0 diff --git a/boot/vsockproxy/main.go b/boot/vsockproxy/main.go new file mode 100644 index 0000000..701f8d9 --- /dev/null +++ b/boot/vsockproxy/main.go @@ -0,0 +1,48 @@ +// SPDX-License-Identifier: Apache-2.0 + +// vsockproxy is ssh's ProxyCommand for a guest reached over vsock: it connects to a context +// id and port and copies stdin to the connection and the connection to stdout. task +// boot:ssh-first builds it, because the host that runs the probe is not guaranteed a +// systemd-ssh-proxy or a socat that speaks AF_VSOCK. +// +// Diagnostic, never part of a release. +// +// vsockproxy +package main + +import ( + "fmt" + "io" + "os" + "strconv" + + "golang.org/x/sys/unix" +) + +func main() { + if len(os.Args) != 3 { + fmt.Fprintln(os.Stderr, "usage: vsockproxy ") + os.Exit(2) + } + cid, err1 := strconv.ParseUint(os.Args[1], 10, 32) + port, err2 := strconv.ParseUint(os.Args[2], 10, 32) + if err1 != nil || err2 != nil { + fmt.Fprintf(os.Stderr, "vsockproxy: cid %q and port %q must be numbers\n", os.Args[1], os.Args[2]) + os.Exit(2) + } + fd, err := unix.Socket(unix.AF_VSOCK, unix.SOCK_STREAM|unix.SOCK_CLOEXEC, 0) + if err != nil { + fmt.Fprintf(os.Stderr, "vsockproxy: a vsock socket: %v\n", err) + os.Exit(1) + } + if err := unix.Connect(fd, &unix.SockaddrVM{CID: uint32(cid), Port: uint32(port)}); err != nil { + fmt.Fprintf(os.Stderr, "vsockproxy: connecting to vsock %d:%d: %v\n", cid, port, err) + os.Exit(1) + } + conn := os.NewFile(uintptr(fd), "vsock") + go func() { + _, _ = io.Copy(conn, os.Stdin) + _ = unix.Shutdown(fd, unix.SHUT_WR) + }() + _, _ = io.Copy(os.Stdout, conn) +} diff --git a/boot/waits.go b/boot/waits.go new file mode 100644 index 0000000..0d1186d --- /dev/null +++ b/boot/waits.go @@ -0,0 +1,407 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot + +import ( + "bufio" + "cmp" + "fmt" + "slices" + "strconv" + "strings" + "time" +) + +// What waited on what, in early userspace. +// +// `systemd-analyze critical-chain` lists, for each unit, the After= dependency that finished +// last. That is a list of what finished last, not of what was waiting: it does not separate a +// unit's own run time from the time it spent queued behind another one, and it does not say +// when nothing was running at all. bootvine (codeberg.org/wvhulle/bootvine) draws the live +// version of the answer on a console - a unit nested under the After= dependency that still +// has a job pending - and this is the same rule applied after the fact, from the timestamps +// systemd keeps for every unit, so that it can be read without a screen and repeated. +// +// After the fact rather than live because a live listener is a process on the guest's vCPUs +// during exactly the phase being measured; the price is that a job's queue time is not kept, +// so a unit's wait is measured from the moment its last ordering dependency was ready, not +// from the moment its job was queued. Every job of the initial transaction is queued at once, +// so the two only differ for a job queued later (socket or path activation), which this does +// not follow. + +// Manager is PID 1's own timeline, as guest CLOCK_MONOTONIC: what systemd did before it ran +// its first job. +type Manager struct { + Userspace time.Duration // PID 1 exec'd: the kernel handed over + SecurityStart time.Duration + SecurityFinish time.Duration + GeneratorsStart time.Duration + GeneratorsFinish time.Duration + UnitsLoadStart time.Duration + UnitsLoadFinish time.Duration + Finish time.Duration // the initial transaction's last job completed +} + +// Unit is one unit's activation in a boot, as guest CLOCK_MONOTONIC. +type Unit struct { + ID string + // Names is every name it answers to; After= may use any of them. + Names []string + State string // ActiveState when it was read + // Idle is a service of Type=idle, whose process systemd forks and then holds until the + // job queue is empty: its Ready is when it was forked, and what it waited for after that + // is in no unit's timestamps. + Idle bool + After []string + // Start is when it left inactive; Ready is when a unit ordered after it could start: when + // it became active, or, for a oneshot that does not remain, when it was done. Zero Ready + // is a unit that never got there. + Start, Ready time.Duration +} + +// Name is the unit's shortest name, which is the one to report and to compare across boots: a +// device's Id changes from boot to boot and dev-vda.device does not. +func (u Unit) Name() string { + n := u.ID + for _, m := range u.Names { + if len(m) < len(n) || (len(m) == len(n) && m < n) { + n = m + } + } + return n +} + +// Own is what a unit took itself, from starting to ready. +func (u Unit) Own() time.Duration { return u.Ready - u.Start } + +// ParseWaits reads what the probe's unit prints: `systemctl show` of the manager, a line +// "SPIN-WAITS-UNITS", then `systemctl show '*'` - one block of Key=Value lines per unit, +// separated by blank lines. Units that were never started in this boot are left out. +func ParseWaits(s string) (Manager, []Unit, error) { + head, units, ok := strings.Cut(s, "SPIN-WAITS-UNITS") + if !ok { + return Manager{}, nil, fmt.Errorf("no SPIN-WAITS-UNITS line between the manager and the units") + } + mb := blocks(head) + if len(mb) != 1 { + return Manager{}, nil, fmt.Errorf("want one block of manager properties, found %d", len(mb)) + } + var m Manager + var err error + for _, f := range []struct { + key string + dst *time.Duration + }{ + {"UserspaceTimestampMonotonic", &m.Userspace}, + {"SecurityStartTimestampMonotonic", &m.SecurityStart}, + {"SecurityFinishTimestampMonotonic", &m.SecurityFinish}, + {"GeneratorsStartTimestampMonotonic", &m.GeneratorsStart}, + {"GeneratorsFinishTimestampMonotonic", &m.GeneratorsFinish}, + {"UnitsLoadStartTimestampMonotonic", &m.UnitsLoadStart}, + {"UnitsLoadFinishTimestampMonotonic", &m.UnitsLoadFinish}, + {"FinishTimestampMonotonic", &m.Finish}, + } { + if *f.dst, err = usec(mb[0], f.key); err != nil { + return Manager{}, nil, fmt.Errorf("reading the manager: %w", err) + } + } + // A boot that has not finished has no answer to how it finished, and the probe waits for + // this; zero here is the probe reading too early, not a fast boot. + if m.Userspace == 0 || m.Finish == 0 { + return Manager{}, nil, fmt.Errorf("the manager's userspace or finish timestamp is zero: the boot had not finished") + } + + var us []Unit + for _, b := range blocks(units) { + u := Unit{ID: b["Id"], Names: names(b["Names"]), State: b["ActiveState"]} + if u.ID == "" { + return Manager{}, nil, fmt.Errorf("a unit block with no Id: %v", b) + } + // Type is the filesystem on a mount and the service type only on a service. + u.Idle = strings.HasSuffix(u.ID, ".service") && b["Type"] == "idle" + u.After = names(b["After"]) + var exit, active, inactive time.Duration + for _, f := range []struct { + key string + dst *time.Duration + }{ + {"InactiveExitTimestampMonotonic", &exit}, + {"ActiveEnterTimestampMonotonic", &active}, + {"InactiveEnterTimestampMonotonic", &inactive}, + } { + if *f.dst, err = usec(b, f.key); err != nil { + return Manager{}, nil, fmt.Errorf("reading %s: %w", u.ID, err) + } + } + switch { + case active > 0: + u.Ready = active + case inactive > exit && exit > 0: + // A oneshot that does not remain active goes activating -> inactive, and a unit + // ordered after it starts when it is done; a failed unit lands here too. + u.Ready = inactive + } + u.Start = exit + if u.Start == 0 || (u.Ready > 0 && u.Start > u.Ready) { + // Active without ever leaving inactive in this boot - a device, the root mount, a + // slice - or left inactive again since; either way it was ready when it said so. + u.Start = u.Ready + } + if u.Start == 0 && u.Ready == 0 { + continue + } + us = append(us, u) + } + if len(us) == 0 { + return Manager{}, nil, fmt.Errorf("no unit was started in this boot") + } + return m, us, nil +} + +// names splits a list of unit names as systemctl prints it: a name with a backslash in it is +// quoted and the backslash doubled - "system-serial\\x2dgetty.slice" - and has to be read back +// to match the unit's own Names. +func names(s string) []string { + f := strings.Fields(s) + for i, n := range f { + if u, err := strconv.Unquote(n); err == nil { + f[i] = u + } + } + return f +} + +func blocks(s string) []map[string]string { + var out []map[string]string + var cur map[string]string + sc := bufio.NewScanner(strings.NewReader(s)) + sc.Buffer(make([]byte, 1<<20), 1<<20) + for sc.Scan() { + line := strings.TrimRight(sc.Text(), "\r") + k, v, ok := strings.Cut(line, "=") + if !ok || k == "" || strings.ContainsAny(k, " \t") { + // A blank line ends a block; anything else that is not Key=Value is the console + // around the dump, and ends nothing. + if strings.TrimSpace(line) == "" && cur != nil { + out = append(out, cur) + cur = nil + } + continue + } + if cur == nil { + cur = map[string]string{} + } + cur[k] = v + } + if cur != nil { + out = append(out, cur) + } + return out +} + +// usec reads a *TimestampMonotonic property. A missing one is an error rather than zero: a +// systemd that renamed it would otherwise report every unit as never started. +func usec(b map[string]string, key string) (time.Duration, error) { + v, ok := b[key] + if !ok { + return 0, fmt.Errorf("no %s", key) + } + n, err := strconv.ParseInt(v, 10, 64) + if err != nil { + return 0, fmt.Errorf("%s=%q: %w", key, v, err) + } + return time.Duration(n) * time.Microsecond, nil +} + +// Waits is one boot's units, indexed, with the questions this file asks of them. +type Waits struct { + Manager Manager + // Units is every unit by its Id. byName finds one by any of its names, which is how + // After= refers to it. + Units map[string]Unit + byName map[string]Unit +} + +// NewWaits indexes a boot's units by Id and by every other name they have. +func NewWaits(m Manager, us []Unit) Waits { + w := Waits{Manager: m, Units: make(map[string]Unit, len(us)), byName: map[string]Unit{}} + for _, u := range us { + w.Units[u.ID] = u + w.byName[u.ID] = u + for _, n := range u.Names { + w.byName[n] = u + } + } + return w +} + +// Unit finds a unit by any of its names. +func (w Waits) Unit(name string) (Unit, bool) { u, ok := w.byName[name]; return u, ok } + +// Blocker is the unit a unit was waiting on: of its After= dependencies that were ready by +// the time it started, the one that was ready last. A unit none of whose After= dependencies +// ran in this boot has none, and its start is the manager's doing. +// +// A dependency that was ready only after the unit started was not ordered against it in this +// boot's transaction - After= orders two jobs only when both have one - and is ignored. +func (w Waits) Blocker(u Unit) (Unit, bool) { + var best Unit + var found bool + for _, id := range u.After { + d, ok := w.byName[id] + if !ok || d.ID == u.ID || d.Ready == 0 || d.Ready > u.Start { + continue + } + // Ties go to the unit that took longer itself, then by name: a target is ready the + // microsecond its last dependency is, and naming the dependency says more. + if !found || d.Ready > best.Ready || + (d.Ready == best.Ready && (d.Own() > best.Own() || (d.Own() == best.Own() && d.ID < best.ID))) { + best, found = d, true + } + } + return best, found +} + +// Hop is one unit on a critical path. Lag is the time between its blocker being ready and it +// starting: systemd dispatching it, or waiting on something that is not a unit. The first hop +// has no blocker, and its Lag is from the end of the manager's unit load. +type Hop struct { + Unit Unit + Blocker string + Lag time.Duration +} + +// CriticalPath walks back from target through each unit's Blocker and returns the chain from +// its root to target. Along it, the root's Start plus every hop's Own and every later hop's Lag +// is target's Ready, so nothing between the end of the unit load and target is unaccounted +// for. +func (w Waits) CriticalPath(target string) ([]Hop, error) { + u, ok := w.byName[target] + if !ok { + return nil, fmt.Errorf("%s was not started in this boot", target) + } + var rev []Hop + seen := map[string]bool{} + for { + if seen[u.ID] { + return nil, fmt.Errorf("%s is its own blocker: ordering cycle in the timestamps", u.ID) + } + seen[u.ID] = true + b, ok := w.Blocker(u) + if !ok { + rev = append(rev, Hop{Unit: u, Lag: u.Start - w.Manager.UnitsLoadFinish}) + break + } + rev = append(rev, Hop{Unit: u, Blocker: b.Name(), Lag: u.Start - b.Ready}) + u = b + } + slices.Reverse(rev) + return rev, nil +} + +// Gap is an interval in which no unit was activating: systemd was waiting for something that +// is not a unit's process - the kernel announcing a device, its own dispatch - or for nothing. +// Next is the unit whose start ended it, and NextBlocker what that unit had been waiting on. +type Gap struct { + From, To time.Duration + Next string + NextBlocker string +} + +// Gaps is every interval of at least min between the end of the unit load and until in which +// no unit was between starting and ready. +// +// A device is not busy while it is activating: its job is waiting for the kernel and udev to +// announce it, which is the thing a gap is for. Counted as busy, dev-vda.device's 109 ms +// covered every gap in the boot and the first version of this reported none (2026-11-12). +func (w Waits) Gaps(until, min time.Duration) []Gap { + type span struct{ from, to time.Duration } + var busy []span + for _, u := range w.Units { + if strings.HasSuffix(u.ID, ".device") { + continue + } + end := u.Ready + if end == 0 { + end = until // still activating when it was read + } + if end > u.Start { + busy = append(busy, span{u.Start, end}) + } + } + slices.SortFunc(busy, func(a, b span) int { return cmp.Compare(a.from, b.from) }) + + var gaps []Gap + cursor := w.Manager.UnitsLoadFinish + add := func(to time.Duration) { + if to-cursor < min { + return + } + g := Gap{From: cursor, To: to} + if n, ok := w.startingAt(to); ok { + g.Next = n.Name() + if b, ok := w.Blocker(n); ok { + g.NextBlocker = b.Name() + } + } + gaps = append(gaps, g) + } + for _, s := range busy { + if s.from >= until { + break + } + if s.from > cursor { + add(s.from) + } + cursor = max(cursor, s.to) + } + if until > cursor { + add(until) + } + return gaps +} + +// startingAt is the unit that starts first at or after t: the one that ended a gap there. One +// that takes time beats one that does not at the same instant, and a device is never one, for +// the reason Gaps gives. +func (w Waits) startingAt(t time.Duration) (Unit, bool) { + var best Unit + var found bool + for _, u := range w.Units { + if u.Start < t || strings.HasSuffix(u.ID, ".device") { + continue + } + if !found || u.Start < best.Start || + (u.Start == best.Start && (u.Own() > best.Own() || (u.Own() == best.Own() && u.ID < best.ID))) { + best, found = u, true + } + } + return best, found +} + +// After is every unit that was not ready by t - the boot still going on behind a login prompt, +// competing for the vCPUs with whatever the first login does - ordered by when it was ready, +// with the units still not ready last. Devices are left out: they cost the guest nothing by +// being late. +func (w Waits) After(t time.Duration) []Unit { + var out []Unit + for _, u := range w.Units { + if strings.HasSuffix(u.ID, ".device") { + continue + } + if u.Ready == 0 || u.Ready > t { + out = append(out, u) + } + } + slices.SortFunc(out, func(a, b Unit) int { + ra, rb := a.Ready, b.Ready + if ra == 0 { + ra = 1 << 62 + } + if rb == 0 { + rb = 1 << 62 + } + return cmp.Or(cmp.Compare(ra, rb), cmp.Compare(a.ID, b.ID)) + }) + return out +} diff --git a/boot/waits_probe_test.go b/boot/waits_probe_test.go new file mode 100644 index 0000000..1c6dba8 --- /dev/null +++ b/boot/waits_probe_test.go @@ -0,0 +1,431 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot_test + +import ( + "bytes" + "cmp" + "fmt" + "maps" + "os" + "os/exec" + "path/filepath" + "slices" + "strconv" + "strings" + "syscall" + "testing" + "time" + + "github.com/spin-stack/spin-machine/boot" +) + +// What waited on what between the kernel handing over and a login prompt, on one axis with +// the host's clock: boot.Waits applied to REPS boots. See boot/waits.go for the rule. +// +// The guest and the host share no clock, so the two are joined at one event both see: the +// probe's unit writes SPIN-WAITS-ANCHOR as its first act, the host stamps the read it arrives +// in, and systemd keeps the unit's exec as InactiveExitTimestampMonotonic. The difference is +// where guest CLOCK_MONOTONIC zero - the kernel's start - sits on the host's clock, and it is +// late by the fork-to-echo of one shell and a serial write. That error is a few milliseconds: +// on a laptop on 2026-11-12 the echo'd login prompt landed 2.5 ms before the getty's fork in +// one boot of five, which it cannot have. Read a difference smaller than that as none. What is +// before that zero is QEMU and the firmware; task boot:firmware-stages splits it. +// +// The login is serial-getty@ttyS0 replaced by an echo (gettyEcho), as task boot:bench's +// baseline does, so agetty's own second is not in it. The getty keeps Type=idle, so what is +// between its fork and the prompt is it waiting for the job queue to drain, and that is +// printed as its own row because it is in no unit's timestamps. +// +// SPIN_BOOT_WAITS=1 run at all +// REPS= boots (default 5) +// CPUS= vCPUs (default 2, the machine's) +// TARGET= the unit whose start is the login (default serial-getty@ttyS0.service) +// TOP= rows per table (default 15) +// GAP= the shortest idle interval printed (default 1) +// RAW= also write each boot's dump there, which is how testdata is made +func TestBootWaits(t *testing.T) { + if os.Getenv("SPIN_BOOT_WAITS") == "" { + t.Skip("set SPIN_BOOT_WAITS=1: boots a VM and needs sudo to write into its overlay") + } + out := releaseDir(t) + if !canSudo() { + t.Skip("this writes a unit 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 + target := cmp.Or(os.Getenv("TARGET"), "serial-getty@ttyS0.service") + raw := os.Getenv("RAW") + + v := waitsVariant(cmp.Or(os.Getenv("CPUS"), "2")) + + var boots []waitsBoot + for rep := range reps { + b := bootWaits(t, out, v, target, "SPIN-WAITS-END") + if raw != "" { + name := filepath.Join(raw, fmt.Sprintf("waits-%02d.txt", rep+1)) + if err := os.WriteFile(name, []byte(b.dump), 0o644); err != nil { + t.Fatalf("writing %s: %v", name, err) + } + } + boots = append(boots, b) + } + t.Log(waitsReport(boots, target, top, minGap)) +} + +// waitsVariant is the boot both probes take: the getty an echo, and spin-waits.service printing +// every unit's timestamps once startup has finished. +func waitsVariant(cpus string) variant { + // Type=simple and a loop on FinishTimestampMonotonic, for the reason TestUserspaceCost + // gives: this unit is one of the initial transaction's jobs. + // + // The units are list-units --all and not `systemctl show '*'`: the pattern matches only + // the units still loaded and active, 57 of them on 2026-11-12, and drops every oneshot + // that ran and finished. --all is more than ran; ParseWaits drops the ones that did not. + // Names is there because a device's Id is whichever of its aliases systemd met first - the + // sysfs path in one boot, dev-vda.device in the next - and After= names the alias. The + // names go through a command substitution and not xargs, which reads a backslash as an + // escape and asked for system-serialx2dgetty.slice, a unit that does not exist. $$ is a + // literal $ in a unit file. + const props = "Id,Names,Type,ActiveState,After,InactiveExitTimestampMonotonic,ActiveEnterTimestampMonotonic,InactiveEnterTimestampMonotonic" + const manager = "UserspaceTimestampMonotonic,SecurityStartTimestampMonotonic,SecurityFinishTimestampMonotonic,GeneratorsStartTimestampMonotonic,GeneratorsFinishTimestampMonotonic,UnitsLoadStartTimestampMonotonic,UnitsLoadFinishTimestampMonotonic,FinishTimestampMonotonic" + dump := `[Unit] +Description=Print every unit's activation timestamps +After=multi-user.target +[Service] +Type=simple +StandardOutput=null +ExecStart=/bin/sh -c "echo SPIN-WAITS-ANCHOR > /dev/ttyS0; i=0; while [ \"$$(systemctl show -p FinishTimestampMonotonic --value)\" = 0 ] && [ $$i -lt 100 ]; do i=$$((i+1)); sleep 0.05; done; { echo SPIN-WAITS-BEGIN; systemctl show -p ` + manager + `; echo SPIN-WAITS-UNITS; systemctl show -p ` + props + ` -- $$(systemctl list-units --all --plain --no-legend --no-pager | awk '{print $$1}'); echo SPIN-WAITS-END; } > /dev/ttyS0 2>&1" +[Install] +WantedBy=multi-user.target +` + files := gettyDropin(gettyEcho) + files["/etc/systemd/system/spin-waits.service"] = dump + return variant{ + label: "waits", cpus: cpus, memory: "2048", files: files, + links: map[string]string{ + "/etc/systemd/system/multi-user.target.wants/spin-waits.service": "/etc/systemd/system/spin-waits.service", + }, + } +} + +// waitsBoot is one boot, with its two clocks joined: kernel is guest monotonic zero on the +// host's clock, and usable is the login prompt on the guest's. +type waitsBoot struct { + w boot.Waits + dump string + console string + kernel, usable time.Duration + login string // the unit whose start is the login + start time.Time // the moment before the machine was launched + ram hostRAM // the guest's RAM as the host holds it at the end +} + +// hostRAM is guestRAM's answer at the end of a boot: MB of the guest's RAM resident on the +// host, and how much of that is in transparent huge pages - KVM can map a guest page 2M at a +// time only where the host has it in a huge page. +type hostRAM struct{ residentMB, hugeMB float64 } + +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 +// 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. +func machineCommand(t *testing.T, out string, v variant, args ...string) *exec.Cmd { + t.Helper() + bin := filepath.Join(out, "bin", "spin-machine") + if len(v.without) == 0 { + return exec.Command(bin, append([]string{"boot", "--release", out}, args...)...) + } + line := machineArgs(t, bin, out, args) + removed := 0 + for i := 0; i+1 < len(line); i++ { + if line[i] != "-device" { + continue + } + for _, d := range v.without { + if strings.HasPrefix(line[i+1], d) { + line = slices.Delete(line, i, i+2) + i-- + removed++ + break + } + } + } + if removed != len(v.without) { + t.Fatalf("took %d devices out of %v; the command line has:\n%s", removed, v.without, strings.Join(line, "\n")) + } + return exec.Command(line[0], line[1:]...) +} + +// bootWaits boots once and reads the console until end, which is SPIN-WAITS-END or the marker +// of a probe that writes after it. +func bootWaits(t *testing.T, out string, v variant, target, end string) waitsBoot { + t.Helper() + overlay := filepath.Join(t.TempDir(), "overlay.qcow2") + mustRun(t, filepath.Join(out, "bin", "qemu-img"), "create", "-f", "qcow2", + "-F", "qcow2", "-b", filepath.Join(out, "image", "rootfs.qcow2"), overlay) + editOverlay(t, overlay, v) + + cmd := machineCommand(t, out, v, "--disk", overlay, "--memory", v.memory, "--cpus", v.cpus, + "--console", "file:/dev/stdout", "--append", "init=/sbin/init") + cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} + r, w, err := os.Pipe() + if err != nil { + t.Fatalf("console pipe: %v", err) + } + cmd.Stdout, cmd.Stderr = w, w + t0 := time.Now() + if err := cmd.Start(); err != nil { + t.Fatalf("launching the machine: %v", err) + } + _ = w.Close() + defer func() { + if pgid, err := syscall.Getpgid(cmd.Process.Pid); err == nil { + _ = syscall.Kill(-pgid, syscall.SIGKILL) + } + _ = cmd.Wait() + _ = r.Close() + }() + + // Stamped per read, as boot.Watch does and for its reason: a harness that stamps lines + // slows the serial port it is timing. + stamps := map[string]time.Duration{} + marks := []string{"login:", "SPIN-WAITS-ANCHOR", "SPIN-WAITS-END", end} + var console []byte + buf := make([]byte, 65536) + deadline := time.Now().Add(90 * time.Second) + for _, done := stamps[end]; !done; _, done = stamps[end] { + if err := r.SetReadDeadline(deadline); err != nil { + t.Fatalf("setting the console deadline: %v", err) + } + n, err := r.Read(buf) + at := time.Since(t0) + // A marker can straddle two reads; it is searched in what has arrived, from a little + // before this read, and stamped with the read that completed it. + from := max(0, len(console)-32) + console = append(console, buf[:n]...) + for _, m := range marks { + if _, ok := stamps[m]; !ok && bytes.Contains(console[from:], []byte(m)) { + stamps[m] = at + } + } + if _, done := stamps[end]; err != nil && !done { + t.Fatalf("never saw %s; console tail:\n%s", end, tail(console, 2000)) + } + } + // What the host holds of the guest's memory, read while the machine still runs. + var ram hostRAM + if mb, err := strconv.Atoi(v.memory); err == nil { + ram.residentMB, ram.hugeMB, _ = guestRAM(cmd.Process.Pid, mb) + } + for _, m := range marks[:3] { + if _, ok := stamps[m]; !ok { + t.Fatalf("no %q on the console; tail:\n%s", m, tail(console, 2000)) + } + } + + s := string(console) + begin := strings.Index(s, "SPIN-WAITS-BEGIN") + stop := strings.Index(s, "SPIN-WAITS-END") + if begin < 0 || stop < begin { + t.Fatalf("no dump between SPIN-WAITS-BEGIN and -END; tail:\n%s", tail(console, 2000)) + } + dump := s[begin+len("SPIN-WAITS-BEGIN") : stop] + m, us, err := boot.ParseWaits(dump) + if err != nil { + t.Fatalf("reading the dump: %v\n%s", err, tail([]byte(dump), 1500)) + } + wt := boot.NewWaits(m, us) + probe, ok := wt.Units["spin-waits.service"] + if !ok || probe.Start == 0 { + t.Fatalf("spin-waits.service has no start in its own dump") + } + if _, ok := wt.Unit(target); !ok { + t.Fatalf("%s was not started in this boot: TARGET names a unit this image does not start", target) + } + kernel := stamps["SPIN-WAITS-ANCHOR"] - probe.Start + return waitsBoot{w: wt, dump: dump, console: s, start: t0, ram: ram, kernel: kernel, usable: stamps["login:"] - kernel, login: target} +} + +// waitsReport prints the boots as p50s, then the median boot verbatim: a critical path or a +// set of gaps averaged across boots would be a path no boot took. +func waitsReport(boots []waitsBoot, target string, top int, minGap time.Duration) string { + ms := func(d time.Duration) string { return fmt.Sprintf("%.1f", float64(d)/float64(time.Millisecond)) } + p50 := func(ds []time.Duration) time.Duration { d, _ := boot.Percentile(ds, 0.5); return d } + p95 := func(ds []time.Duration) time.Duration { d, _ := boot.Percentile(ds, 0.95); return d } + + var b strings.Builder + fmt.Fprintf(&b, "\nms on the host's clock from the moment before QEMU is exec'd, p50/p95 over %d boots\n\n", len(boots)) + + // The boot as consecutive phases; each row's value is where it ends, and the column + // beside it what the phase itself took. + type phase struct { + name string + at func(waitsBoot) time.Duration + } + phases := []phase{ + {"kernel starts (QEMU, firmware)", func(x waitsBoot) time.Duration { return x.kernel }}, + {"PID 1 exec'd (kernel)", func(x waitsBoot) time.Duration { return x.kernel + x.w.Manager.Userspace }}, + {"security setup done", func(x waitsBoot) time.Duration { return x.kernel + x.w.Manager.SecurityFinish }}, + {"generators start (PID 1 setup)", func(x waitsBoot) time.Duration { return x.kernel + x.w.Manager.GeneratorsStart }}, + {"generators done", func(x waitsBoot) time.Duration { return x.kernel + x.w.Manager.GeneratorsFinish }}, + {"units loaded", func(x waitsBoot) time.Duration { return x.kernel + x.w.Manager.UnitsLoadFinish }}, + {target + " forked (jobs)", func(x waitsBoot) time.Duration { return x.kernel + x.target().Start }}, + {"login prompt (Type=idle, exec)", func(x waitsBoot) time.Duration { return x.kernel + x.usable }}, + } + fmt.Fprintf(&b, " %-46s %15s %15s\n", "PHASE ENDS AT", "AT", "TOOK") + var prev []time.Duration + for _, p := range phases { + var at, took []time.Duration + for i, x := range boots { + at = append(at, p.at(x)) + if prev != nil { + took = append(took, at[i]-prev[i]) + } else { + took = append(took, at[i]) + } + } + fmt.Fprintf(&b, " %-46s %7s/%-7s %7s/%-7s\n", p.name, ms(p50(at)), ms(p95(at)), ms(p50(took)), ms(p95(took))) + prev = at + } + // Not a phase of the login: the transaction finishes on its own schedule, before or after + // the getty's exec, and is here to be set beside systemd-analyze's number. + var finish []time.Duration + for _, x := range boots { + finish = append(finish, x.kernel+x.w.Manager.Finish) + } + fmt.Fprintf(&b, " %-46s %7s/%-7s\n", "(startup finished)", ms(p50(finish)), ms(p95(finish))) + + // Units, across boots: how often each was on the path to the login, and what it cost there. + type agg struct { + onPath int + own, lag []time.Duration + blockers map[string]int + ownAnyway []time.Duration + } + units := map[string]*agg{} + get := func(id string) *agg { + if units[id] == nil { + units[id] = &agg{blockers: map[string]int{}} + } + return units[id] + } + for _, x := range boots { + for _, u := range x.w.Units { + get(u.Name()).ownAnyway = append(get(u.Name()).ownAnyway, u.Own()) + } + path, err := x.w.CriticalPath(target) + if err != nil { + fmt.Fprintf(&b, "\n a boot with no critical path to %s: %v\n", target, err) + continue + } + for _, h := range path { + a := get(h.Unit.Name()) + a.onPath++ + a.own = append(a.own, h.Unit.Own()) + a.lag = append(a.lag, h.Lag) + a.blockers[cmp.Or(h.Blocker, "(unit load)")]++ + } + } + + fmt.Fprintf(&b, "\nON THE PATH TO %s: a unit's own time and the lag before it started, p50 where it was on it\n\n", target) + fmt.Fprintf(&b, " %-44s %6s %8s %8s %s\n", "UNIT", "BOOTS", "OWN", "LAG", "WAITED ON") + ids := slices.Collect(maps.Keys(units)) + slices.SortFunc(ids, func(a, c string) int { + return cmp.Or(cmp.Compare(units[c].onPath, units[a].onPath), + cmp.Compare(p50(units[c].own)+p50(units[c].lag), p50(units[a].own)+p50(units[a].lag)), cmp.Compare(a, c)) + }) + n := 0 + for _, id := range ids { + a := units[id] + if a.onPath == 0 || n == top { + continue + } + n++ + fmt.Fprintf(&b, " %-44s %3d/%-2d %8s %8s %s\n", clipUnit(id), a.onPath, len(boots), + ms(p50(a.own)), ms(p50(a.lag)), mostOften(a.blockers, a.onPath)) + } + + fmt.Fprintf(&b, "\nSLOWEST UNITS, on the path or not: p50 of their own time\n\n") + slices.SortFunc(ids, func(a, c string) int { + return cmp.Or(cmp.Compare(p50(units[c].ownAnyway), p50(units[a].ownAnyway)), cmp.Compare(a, c)) + }) + for _, id := range ids[:min(top, len(ids))] { + a := units[id] + fmt.Fprintf(&b, " %-44s %8s in %d/%d boots, on the path in %d\n", clipUnit(id), + ms(p50(a.ownAnyway)), len(a.ownAnyway), len(boots), a.onPath) + } + + // The median boot, by its login, in its own words. + med := slices.Clone(boots) + slices.SortFunc(med, func(a, c waitsBoot) int { return cmp.Compare(a.kernel+a.usable, c.kernel+c.usable) }) + x := med[len(med)/2] + fmt.Fprintf(&b, "\nTHE MEDIAN BOOT, login at %s ms; guest ms from the kernel's start\n", ms(x.kernel+x.usable)) + if path, err := x.w.CriticalPath(target); err == nil { + fmt.Fprintf(&b, "\n critical path, from the end of the unit load at %s\n\n", ms(x.w.Manager.UnitsLoadFinish)) + fmt.Fprintf(&b, " %8s %8s %7s %7s %s\n", "START", "READY", "OWN", "LAG", "UNIT") + for _, h := range path { + fmt.Fprintf(&b, " %8s %8s %7s %7s %s\n", ms(h.Unit.Start), ms(h.Unit.Ready), ms(h.Unit.Own()), ms(h.Lag), h.Unit.Name()) + } + // A device has no After= to follow: it is ready when udev announces it. What announced + // it is the coldplug, so its window is the next thing to read. + if root := path[0].Unit; strings.HasSuffix(root.ID, ".device") { + for _, id := range []string{"systemd-udevd.service", "systemd-udev-trigger.service"} { + if u, ok := x.w.Unit(id); ok { + fmt.Fprintf(&b, " %8s %8s %7s %7s (%s, which announces %s)\n", ms(u.Start), ms(u.Ready), ms(u.Own()), "", id, root.Name()) + } + } + } + if u := x.target(); u.Idle { + fmt.Fprintf(&b, " %8s %8s %7s %7s %s\n", ms(u.Ready), ms(x.usable), ms(x.usable-u.Ready), "", "(Type=idle: the job queue draining, then exec)") + } + } + gaps := x.w.Gaps(x.target().Start, minGap) + fmt.Fprintf(&b, "\n no unit activating, for at least %s ms: systemd waiting on the kernel, or on itself\n\n", ms(minGap)) + var idle time.Duration + for _, g := range gaps { + idle += g.To - g.From + ended := g.Next + if g.NextBlocker != "" { + ended += " after " + g.NextBlocker + } + fmt.Fprintf(&b, " %8s %8s %7s then %s\n", ms(g.From), ms(g.To), ms(g.To-g.From), cmp.Or(ended, "(nothing)")) + } + fmt.Fprintf(&b, " %8s %8s %7s in all\n", "", "", ms(idle)) + + late := x.w.After(max(x.usable, x.target().Ready)) + fmt.Fprintf(&b, "\n still starting behind the login prompt: %d units\n\n", len(late)) + for _, u := range late[:min(top, len(late))] { + ready := "never" + if u.Ready > 0 { + ready = "+" + ms(u.Ready-x.usable) + } + fmt.Fprintf(&b, " %8s %7s %s (%s)\n", ready, ms(max(0, u.Own())), u.Name(), u.State) + } + return b.String() +} + +func mostOften(m map[string]int, of int) string { + var best string + for k, v := range m { + if best == "" || v > m[best] || (v == m[best] && k < best) { + best = k + } + } + if len(m) > 1 { + return fmt.Sprintf("%s (%d of %d)", best, m[best], of) + } + return best +} + +func clipUnit(s string) string { + if len(s) > 44 { + return s[:41] + "..." + } + return s +} diff --git a/boot/waits_test.go b/boot/waits_test.go new file mode 100644 index 0000000..6222612 --- /dev/null +++ b/boot/waits_test.go @@ -0,0 +1,179 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot + +import ( + "os" + "slices" + "strconv" + "strings" + "testing" + "time" +) + +// A real boot's dump, as the console carried it (\r\n and all): task boot:waits RAW= on +// 2026-11-12, the release as it stood then. +func realWaits(t *testing.T) Waits { + t.Helper() + b, err := os.ReadFile("testdata/waits-2026-11-12.txt") + if err != nil { + t.Fatal(err) + } + m, us, err := ParseWaits(string(b)) + if err != nil { + t.Fatal(err) + } + return NewWaits(m, us) +} + +func TestParseWaitsReadsARealBoot(t *testing.T) { + w := realWaits(t) + if w.Manager.Userspace == 0 || w.Manager.UnitsLoadFinish <= w.Manager.Userspace || w.Manager.Finish <= w.Manager.UnitsLoadFinish { + t.Fatalf("manager timeline out of order: %+v", w.Manager) + } + // The getty is the login; it must have been read with its Type and its ordering intact. + g, ok := w.Unit("serial-getty@ttyS0.service") + if !ok || !g.Idle || g.Start == 0 { + t.Fatalf("serial-getty@ttyS0.service = %+v, %v", g, ok) + } + // A quoted, escaped name in After= is read back to the name the slice has. + if !slices.Contains(g.After, `system-serial\x2dgetty.slice`) { + t.Errorf("After= of the getty did not unquote the slice: %q", g.After) + } + if _, ok := w.Unit(`system-serial\x2dgetty.slice`); !ok { + t.Errorf("the getty's slice is not found by the name After= uses") + } + for _, u := range w.Units { + if u.Ready > 0 && u.Start > u.Ready { + t.Errorf("%s starts at %v after it is ready at %v", u.ID, u.Start, u.Ready) + } + } +} + +// The property the report rests on: from the end of the unit load to the login, a critical +// path accounts for every microsecond, and each hop waits on a unit it is really ordered after. +func TestCriticalPathAccountsForTheWholeWait(t *testing.T) { + w := realWaits(t) + const target = "serial-getty@ttyS0.service" + path, err := w.CriticalPath(target) + if err != nil { + t.Fatal(err) + } + if path[len(path)-1].Unit.ID != target { + t.Fatalf("path ends at %s", path[len(path)-1].Unit.ID) + } + sum := w.Manager.UnitsLoadFinish + for i, h := range path { + sum += h.Lag + h.Unit.Own() + if i == 0 { + if h.Blocker != "" { + t.Errorf("the root %s has a blocker %s", h.Unit.ID, h.Blocker) + } + continue + } + prev := path[i-1].Unit + if h.Blocker != prev.Name() { + t.Errorf("hop %s names %s as its blocker, the path has %s before it", h.Unit.ID, h.Blocker, prev.Name()) + } + if !slices.ContainsFunc(h.Unit.After, func(n string) bool { return n == prev.ID || slices.Contains(prev.Names, n) }) { + t.Errorf("%s waits on %s, which is not in its After=", h.Unit.ID, prev.ID) + } + if h.Lag < 0 { + t.Errorf("%s started %v before %s was ready", h.Unit.ID, -h.Lag, prev.ID) + } + } + if got := w.Units[target].Ready; sum != got { + t.Errorf("unit load + lags + own times = %v, the target is ready at %v", sum, got) + } +} + +// A gap is a time no unit's process was working; one that overlaps a unit's activation is a +// gap that is not there. +func TestGapsOverlapNoActivation(t *testing.T) { + w := realWaits(t) + until := w.Units["serial-getty@ttyS0.service"].Start + gaps := w.Gaps(until, 0) + if len(gaps) == 0 { + t.Fatal("no gaps in a boot with devices to wait for") + } + for _, g := range gaps { + if g.From < w.Manager.UnitsLoadFinish || g.To > until || g.To <= g.From { + t.Errorf("gap %v-%v outside %v-%v", g.From, g.To, w.Manager.UnitsLoadFinish, until) + } + for _, u := range w.Units { + if strings.HasSuffix(u.ID, ".device") || u.Ready <= u.Start { + continue + } + if u.Start < g.To && u.Ready > g.From { + t.Errorf("gap %v-%v overlaps %s activating %v-%v", g.From, g.To, u.ID, u.Start, u.Ready) + } + } + } +} + +func unitBlock(id, after string, exit, active, inactive int) string { + return "Id=" + id + "\nNames=" + id + "\nAfter=" + after + + "\nActiveState=active" + + "\nInactiveExitTimestampMonotonic=" + strconv.Itoa(exit) + + "\nActiveEnterTimestampMonotonic=" + strconv.Itoa(active) + + "\nInactiveEnterTimestampMonotonic=" + strconv.Itoa(inactive) + "\n\n" +} + +const manager = "UserspaceTimestampMonotonic=100\nSecurityStartTimestampMonotonic=110\nSecurityFinishTimestampMonotonic=120\n" + + "GeneratorsStartTimestampMonotonic=130\nGeneratorsFinishTimestampMonotonic=140\n" + + "UnitsLoadStartTimestampMonotonic=150\nUnitsLoadFinishTimestampMonotonic=1000\nFinishTimestampMonotonic=9000\n\n" + +// The blocker is the dependency ready last before the unit started; a oneshot that finished is +// ready when it finished; a dependency ready only after the unit started was not ordered against +// it and is not its blocker. +func TestBlocker(t *testing.T) { + dump := manager + "SPIN-WAITS-UNITS\n" + + unitBlock("early.service", "", 1000, 1500, 0) + + unitBlock("oneshot.service", "", 1000, 0, 2500) + // ran 1000-2500, did not remain + unitBlock("later.service", "", 1000, 5000, 0) + // ready after the unit below started + unitBlock("never.service", "", 0, 0, 0) + // loaded, never started: dropped + unitBlock("unit.service", "early.service oneshot.service later.service never.service", 3000, 3200, 0) + m, us, err := ParseWaits(dump) + if err != nil { + t.Fatal(err) + } + w := NewWaits(m, us) + if _, ok := w.Units["never.service"]; ok { + t.Error("a unit that never started was kept") + } + if got := w.Units["oneshot.service"].Ready; got != 2500*time.Microsecond { + t.Errorf("a finished oneshot is ready at %v, want 2.5ms", got) + } + b, ok := w.Blocker(w.Units["unit.service"]) + if !ok || b.ID != "oneshot.service" { + t.Errorf("blocker = %s, %v; want oneshot.service", b.ID, ok) + } + path, err := w.CriticalPath("unit.service") + if err != nil { + t.Fatal(err) + } + if len(path) != 2 || path[0].Lag != 0 || path[1].Lag != 500*time.Microsecond { + t.Errorf("path = %+v; want oneshot from the unit load, then unit 0.5ms after it", path) + } + late := w.After(3100 * time.Microsecond) + if len(late) != 2 || late[0].ID != "unit.service" || late[1].ID != "later.service" { + t.Errorf("after 3.1ms: %v; want unit then later", late) + } +} + +// A dump that is not one is an error that says so, never an empty boot: the probe reading too +// early, or a systemd that renamed a property, would otherwise report a boot in which nothing +// waited. +func TestParseWaitsRefuses(t *testing.T) { + for name, dump := range map[string]string{ + "no separator": manager, + "unfinished": strings.Replace(manager, "FinishTimestampMonotonic=9000", "FinishTimestampMonotonic=0", 1) + "SPIN-WAITS-UNITS\n" + unitBlock("a.service", "", 1, 2, 0), + "renamed property": manager + "SPIN-WAITS-UNITS\nId=a.service\nInactiveExitTimestampMonotonic=1\nActiveEnterTimestampMonotonic=2\n", + "nothing started": manager + "SPIN-WAITS-UNITS\n" + unitBlock("a.service", "", 0, 0, 0), + "systemctl refused": manager + "SPIN-WAITS-UNITS\nsystemctl: invalid option -- '.'\n", + } { + if _, _, err := ParseWaits(dump); err == nil { + t.Errorf("%s: parsed", name) + } + } +} diff --git a/go.mod b/go.mod index f79c560..7221772 100644 --- a/go.mod +++ b/go.mod @@ -9,6 +9,9 @@ require ( golang.org/x/sys v0.49.0 ) -require go.yaml.in/yaml/v3 v3.0.6 // indirect +require ( + github.com/godbus/dbus/v5 v5.1.0 // indirect + go.yaml.in/yaml/v3 v3.0.6 // indirect +) tool github.com/spin-stack/go-tools/cmd/task diff --git a/go.sum b/go.sum index c5f0cd7..828a205 100644 --- a/go.sum +++ b/go.sum @@ -1,3 +1,5 @@ +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= From 7be2af210ca21b30fba118f3b78173fecf83ad1d Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Thu, 12 Nov 2026 21:01:22 -0300 Subject: [PATCH 2/5] PCI Remember a device standard capability list Signed-off-by: Manuel de Brito Fontes --- kernel/Dockerfile | 4 + kernel/README.md | 7 + ...-a-device-s-standard-capability-list.patch | 169 ++++++++++++++++++ 3 files changed, 180 insertions(+) create mode 100644 kernel/patches/0005-PCI-Remember-a-device-s-standard-capability-list.patch diff --git a/kernel/Dockerfile b/kernel/Dockerfile index c8b8e46..b8adf15 100644 --- a/kernel/Dockerfile +++ b/kernel/Dockerfile @@ -290,6 +290,10 @@ 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. # 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/README.md b/kernel/README.md index 09a2aba..7a4837a 100644 --- a/kernel/README.md +++ b/kernel/README.md @@ -62,6 +62,13 @@ Lockdown at confidentiality also takes away the tenant's kernel tracing: kprobes `bpf_probe_read_kernel` and perf on the kernel. User-space tracing and networking eBPF are untouched, and so is a BPF LSM program that reads no kernel memory. +It takes tracefs too, and with it this repository's own kernel tracing: `task boot:initcalls` +with `SPIN_GRAPH` (function_graph) or `SPIN_CPU_SHARE` (scheduler events) cannot trace the +release's kernel, and says so. They trace a kernel B built with +`CONFIG_LOCK_DOWN_KERNEL_FORCE_NONE=y` instead - that option swapped in this config and taken out +of `Dockerfile`'s check, on a branch or in a scratch worktree, never in a release. The rest of +the boot probes read the ring buffer and systemd, which lockdown leaves alone. + systemd notices at boot, and the console shows two lines that read like missing protection and are lockdown working: 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 new file mode 100644 index 0000000..ea0e9d2 --- /dev/null +++ b/kernel/patches/0005-PCI-Remember-a-device-s-standard-capability-list.patch @@ -0,0 +1,169 @@ +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 + From 4b40c2ba3ba73b79c4932a1a415151e15ce13be1 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Thu, 12 Nov 2026 21:02:10 -0300 Subject: [PATCH 3/5] sshd wait host keys Signed-off-by: Manuel de Brito Fontes --- image/README.md | 4 +++- .../etc/systemd/system/sshd@.service.d/keygen.conf | 14 ++++++++++++++ .../system/spin-machine-sshd-keygen.service | 3 ++- 3 files changed, 19 insertions(+), 2 deletions(-) create mode 100644 image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/sshd@.service.d/keygen.conf diff --git a/image/README.md b/image/README.md index 89bf40e..b5b99ab 100644 --- a/image/README.md +++ b/image/README.md @@ -73,7 +73,9 @@ from outside: not run before `sshd` is asked to validate a configuration with no keys, and `ssh.service` fails five times and gives up. `spin-machine-sshd-keygen.service` generates them instead: every boot here *is* a first boot, since the root filesystem is a fresh - overlay, so the keys live exactly as long as the VM does. + overlay, so the keys live exactly as long as the VM does. Every sshd waits for it, + including the per-connection `sshd@.service` that `systemd-ssh-generator` starts for vsock + and `ssh .host`: without that, those connections found no host keys and were dropped. - **Two thirds of the boot was systemd asking the console questions.** The kernel execs `/sbin/init` at 59 ms and systemd's first log line arrived at 852, with nothing running in between. It was a terminfo query and a terminal reset, 334 ms of timeout each, waiting for diff --git a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/sshd@.service.d/keygen.conf b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/sshd@.service.d/keygen.conf new file mode 100644 index 0000000..8f3d61c --- /dev/null +++ b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/sshd@.service.d/keygen.conf @@ -0,0 +1,14 @@ +# The per-connection sshd waits for the host keys too, not only ssh.service. +# +# systemd-ssh-generator listens on AF_VSOCK port 22 when the machine has a vsock device, and on +# /run/ssh-unix-local/socket (`ssh .host`) always, and both start sshd@.service for each +# connection. spin-machine-sshd-keygen.service was wanted by ssh.service alone, so until +# something had connected over TCP there were no host keys, and the per-connection sshd +# dropped every connection: over vsock the image could not be logged into at all +# (task boot:ssh-first, 2026-11-12). +# +# A drop-in on the template, because an ordering against a template name in the keygen unit +# (Before=sshd@.service) orders nothing: it applies to no instance. +[Unit] +Wants=spin-machine-sshd-keygen.service +After=spin-machine-sshd-keygen.service diff --git a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-sshd-keygen.service b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-sshd-keygen.service index 8507b12..7cf86d4 100644 --- a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-sshd-keygen.service +++ b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-sshd-keygen.service @@ -26,7 +26,8 @@ Description=Generate SSH host keys for this VM # after spin-machine-sshd-keygen.service/start after basic.target/start # # Socket activation still works: the socket starts ssh.service, and ssh.service waits for -# this. +# this. The per-connection sshd@.service that systemd-ssh-generator's vsock and AF_UNIX +# sockets start waits for it through a drop-in of its own (sshd@.service.d/keygen.conf). Before=ssh.service sshd.service ConditionPathExists=/usr/bin/ssh-keygen From 43a9fb3d065dc9082b41558ccdf3f9d739ab4b1d Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Thu, 12 Nov 2026 21:02:37 -0300 Subject: [PATCH 4/5] Remove motd Signed-off-by: Manuel de Brito Fontes --- boot/logind_test.go | 23 +++--- image/build.sh | 71 +++++++++++-------- .../local/lib/spin-base/configure-system.sh | 48 +++++-------- .../local/lib/spin-base/optimize-systemd.sh | 22 +++--- .../10-seats.conf | 7 +- 5 files changed, 88 insertions(+), 83 deletions(-) diff --git a/boot/logind_test.go b/boot/logind_test.go index c519805..c86ed4c 100644 --- a/boot/logind_test.go +++ b/boot/logind_test.go @@ -25,19 +25,22 @@ func TestLogindSessions(t *testing.T) { t.Fatal(err) } root := newRawRoot(t, out, base) - // The shipped image does not start logind at boot: the first login activates it over - // the Varlink socket, which is worth 18 ms (see the 10-seats.conf drop-in). So the - // state this asserts before any login is `inactive`, and a machine that answers - // `active` has put logind back into the boot transaction. + // The shipped image starts logind at boot, because spin lingers and logind is what starts + // a lingering user's manager (optimize-systemd.sh). So the state this asserts before any + // login is `active`, and a machine that answers `inactive` has taken logind out of the boot + // again and moved spin's manager back into the first login. // - // SPIN_LOGIND_NO_SEATS=1 removes the drop-in and nothing else. It is the experiment - // that says what the drop-in does, and it is expected to fail: without - // /run/systemd/seats, pam_systemd never asks logind for a session and never activates - // it, so every login — SSH and console alike — comes up with XDG_RUNTIME_DIR unset and - // no error anywhere (2026-09-12). - expectedState := "inactive" + // SPIN_LOGIND_NO_SEATS=1 removes the 10-seats.conf drop-in and nothing else, and logind is + // then held back from the boot as it once was: that is the case the drop-in exists for - a + // login that arrives before logind has run - and it is expected to fail. Without + // /run/systemd/seats, pam_systemd never asks logind for a session and never activates it, + // so every login - SSH and console alike - comes up with XDG_RUNTIME_DIR unset and no + // error anywhere (2026-09-12). + expectedState := "active" if os.Getenv("SPIN_LOGIND_NO_SEATS") == "1" { root.remove("/etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf") + root.link("/etc/systemd/system/multi-user.target.wants/systemd-logind.service", "/dev/null") + expectedState = "inactive" } content, err := os.ReadFile("testdata/logind-session.sh") if err != nil { diff --git a/image/build.sh b/image/build.sh index 2478b34..daae0e8 100755 --- a/image/build.sh +++ b/image/build.sh @@ -320,29 +320,39 @@ for u in tmp.mount systemd-tmpfiles-setup.service; do fi done -# logind is deferred rather than masked, and the two halves of that only work together. -# The drop-in makes pam_systemd's guard — access("/run/systemd/seats/") — true before -# logind has run, so the first login activates it over Varlink instead of being handed a -# session with no XDG_RUNTIME_DIR and no user manager. The overridden want is what keeps -# the 24 ms. Either half alone is a silent failure: without the drop-in every login comes -# up session-less and nothing logs an error, and a re-enabled want costs the boot time back -# while everything still works, so neither shows up anywhere but here. -in_image /etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf || { - echo "ERROR: the image has no logind seats drop-in; every login would lose its session" >&2 - exit 1; } -# The want is overridden, not deleted: the package ships it in /usr, so the /etc path must -# hold a symlink to /dev/null. Asserting its *absence* is the version of this check that -# passed while the image still started logind at boot, because the /etc path was never -# there to remove (2026-09-12). -if ! stat_in_image /etc/systemd/system/multi-user.target.wants/systemd-logind.service | +# logind starts in the boot, because spin lingers and logind is what starts a lingering +# user's manager: the first SSH login comes 60 ms sooner for both together (the numbers are +# in optimize-systemd.sh). Each half alone is silent - the want overridden leaves the linger +# file doing nothing until the first login starts logind, and the file gone leaves logind in +# the boot buying nothing - so both are asserted here. The want is the package's, in /usr; an +# override would be a /dev/null symlink at the /etc path, which is how it was done before +# (2026-09-12) and what a stale configure step would bring back. +if stat_in_image /etc/systemd/system/multi-user.target.wants/systemd-logind.service | grep -q '/dev/null'; then - echo "ERROR: the want for systemd-logind is not overridden; the package ships one in" \ - "/usr and logind is back in the boot transaction" >&2 + echo "ERROR: the want for systemd-logind is overridden; spin's manager would start in" \ + "the first login instead of the boot" >&2 exit 1 fi +in_image /usr/lib/systemd/system/multi-user.target.wants/systemd-logind.service || { + echo "ERROR: the package no longer wants systemd-logind from multi-user.target" >&2 + exit 1; } +in_image /var/lib/systemd/linger/spin || { + echo "ERROR: spin does not linger; its manager starts inside the first login" >&2 + exit 1; } +# The drop-in still matters with logind in the boot: a login can arrive before logind has +# run, and without it pam_systemd hands that login no session and says nothing. +in_image /etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf || { + echo "ERROR: the image has no logind seats drop-in; an early login would lose its session" >&2 + exit 1; } +# The per-connection sshd that systemd-ssh-generator's vsock and AF_UNIX sockets start must +# wait for the host keys: without the drop-in, nothing can log in over vsock at all. +"$bin/debugfs" -R "cat /etc/systemd/system/sshd@.service.d/keygen.conf" /work/base.raw 2>/dev/null | + grep -qx 'After=spin-machine-sshd-keygen.service' || { + echo "ERROR: sshd@.service does not wait for spin-machine-sshd-keygen.service" >&2 + exit 1; } if stat_in_image /etc/systemd/system/systemd-logind.service | grep -q '/dev/null'; then - echo "ERROR: systemd-logind.service is masked - deferring it means it still starts" \ - "on demand, and masked means it never starts at all" >&2 + echo "ERROR: systemd-logind.service is masked - it never starts, no login gets a" \ + "session, and spin's manager never starts either" >&2 exit 1 fi @@ -365,17 +375,18 @@ in_image /etc/systemd/system/timers.target.wants/fstrim.timer || { echo "ERROR: fstrim.timer is not enabled" >&2 exit 1; } -# The login banner is this image's own, and pam_motd is enabled for ssh to print it — so -# whatever is in /etc/update-motd.d now runs on every login. That is the reason to assert -# both halves rather than only the one that was added: the distribution's scripts reach the -# network (50-motd-news), print an advertisement, and were deleted, and a package upgrade -# that restores one restores it into a path that is now read. -in_image /etc/update-motd.d/00-spin-boot || { - echo "ERROR: the image has no /etc/update-motd.d/00-spin-boot to print the boot time" >&2 - exit 1; } -for f in /etc/update-motd.d/10-help-text /etc/update-motd.d/50-motd-news; do - if in_image "$f"; then - echo "ERROR: $f is back, and pam_motd now runs it at every login" >&2 +# No login runs a MOTD: pam_motd is off in every stack the distribution enables it in, so +# whatever a package upgrade restores into /etc/update-motd.d - 50-motd-news reaches the +# network - is never run. Read from the finished filesystem, and the file is checked to be a +# PAM stack before its lines are: debugfs prints nothing for a file that is not there, and +# nothing has no pam_motd line in it. +for f in /etc/pam.d/sshd /etc/pam.d/login; do + stack=$("$bin/debugfs" -R "cat $f" /work/base.raw 2>/dev/null) + printf '%s\n' "$stack" | grep -q 'pam_unix\|common-session' || { + echo "ERROR: $f is missing or is not a PAM stack" >&2 + exit 1; } + if printf '%s\n' "$stack" | grep -q '^[[:space:]]*session.*pam_motd\.so'; then + echo "ERROR: pam_motd is enabled in $f, and runs /etc/update-motd.d at every login" >&2 exit 1 fi done diff --git a/image/mkosi.extra/usr/local/lib/spin-base/configure-system.sh b/image/mkosi.extra/usr/local/lib/spin-base/configure-system.sh index 74c2bf7..ffb3148 100755 --- a/image/mkosi.extra/usr/local/lib/spin-base/configure-system.sh +++ b/image/mkosi.extra/usr/local/lib/spin-base/configure-system.sh @@ -60,6 +60,14 @@ useradd --create-home --shell /bin/bash --uid 1000 --groups sudo,docker spin passwd --lock root passwd --lock spin +# spin lingers: logind starts spin's user manager (user@1000.service) during the boot rather +# than inside the first login, which is the one thing a workspace waits for. The first SSH +# login came 60 ms sooner for it; the numbers are in optimize-systemd.sh, beside logind being +# kept in the boot for the same reason. What `loginctl enable-linger` writes, without a logind +# to ask - this runs in mkosi's chroot. It names a user, not a machine: no identity. +install -d -m 0755 /var/lib/systemd/linger +touch /var/lib/systemd/linger/spin + # Sudo without a password, because there is no password. The boundary this machine relies # on is the VM, not the difference between two accounts inside it — but a workload that # expects not to be root by default gets what it expects. @@ -67,38 +75,20 @@ install -m 0440 /dev/stdin /etc/sudoers.d/spin <<'EOF' spin ALL=(ALL) NOPASSWD: ALL EOF -# The MOTD is this image's own. The distribution's goes, all of it: scripts that check for available updates, count -# reboots and advertise a support subscription — network calls and package queries in a -# machine that is started, does one piece of work and is thrown away. -# -# What replaces it is one line that says how long this machine took to boot. +# No MOTD, and no pam_motd to run one. The distribution's scripts check for updates, count +# reboots and advertise a subscription - network calls and package queries in a machine that +# is started, does one piece of work and is thrown away. This image's own replacement, a line +# saying how long the boot took, ran systemd-analyze inside every login, which is the one +# thing a workspace waits for; a boot time belongs to task boot:bench and boot:ssh-first, +# which measure it on purpose, not to a greeting nobody acts on (removed 2026-11-12). # -# It is there because a number nobody sees is a number nobody defends. A cold boot is 853ms -# (measured 2026-09-10, `task boot:bench`) and it took a harness to find that out. Printing -# it at every login means the next regression is noticed by whoever logs in next, rather -# than by whoever thinks to measure. -echo "Replacing the distribution MOTD..." +# pam_motd goes from every PAM stack that has it, not only ssh's: with it enabled, whatever a +# package upgrade restores into /etc/update-motd.d runs at the next login, and image/build.sh +# asserts the lines are off rather than that the directory is empty. +echo "Removing the MOTD..." rm -rf /etc/update-motd.d/* truncate -s 0 /etc/motd - -install -d -m 0755 /etc/update-motd.d -cat > /etc/update-motd.d/00-spin-boot <<'MOTD' -#!/bin/sh -# How long this machine took to boot, printed by pam_motd at every login. -# -# `|| true` and a silent exit: a motd script that fails prints its error to somebody's -# terminal instead of a greeting, and this is a greeting. systemd-analyze answers "Bootup is -# not yet finished" if a login somehow arrives before the boot does. -analysis=$(systemd-analyze 2>/dev/null | head -1) || true -case "$analysis" in - Startup*) printf '\n%s\n\n' "$analysis" ;; -esac -MOTD -chmod 0755 /etc/update-motd.d/00-spin-boot - -# pam_motd stays enabled, including for ssh, where the distribution ships it commented -# out. There is something worth printing. -sed -i 's/^#\(session.*pam_motd.so\)/\1/' /etc/pam.d/sshd +sed -i 's/^\(session.*pam_motd\.so\)/#\1/' /etc/pam.d/sshd /etc/pam.d/login # The distribution's background maintenance. Ubuntu ships five timers enabled. Four of them have no business in a machine that is diff --git a/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh b/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh index 73ca092..509be5c 100755 --- a/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh +++ b/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh @@ -214,19 +214,15 @@ rm -f /etc/systemd/system/multi-user.target.wants/ssh.service 2>/dev/null || tru mkdir -p /etc/systemd/system/sockets.target.wants ln -sf /lib/systemd/system/ssh.socket /etc/systemd/system/sockets.target.wants/ssh.socket -# logind out of the boot transaction, worth 24 ms. Not masked: masked means never started, -# and a login needs it. It stays enabled in every other sense and is started by the first -# thing that asks for a session over its Varlink socket — see the 10-seats.conf drop-in -# shipped beside it, which is what makes pam_systemd get as far as asking. -# -# A symlink to /dev/null and not `rm`, because the want is not in /etc to begin with: the -# package ships it at /usr/lib/systemd/system/multi-user.target.wants/systemd-logind.service. -# An `rm` of the /etc path is what this said first, and it removed nothing at all — the -# build passed, the image shipped, and logind started at boot exactly as before (2026-09-12). -# The /dev/null symlink in /etc overrides the want in /usr and nothing else: the unit itself -# is untouched, which is why it can still be activated on demand. -mkdir -p /etc/systemd/system/multi-user.target.wants -ln -sf /dev/null /etc/systemd/system/multi-user.target.wants/systemd-logind.service +# logind stays in the boot transaction, as the package wants it +# (/usr/lib/systemd/system/multi-user.target.wants/systemd-logind.service), because spin +# lingers - configure-system.sh - and it is logind that starts a lingering user's manager. +# Taking it out of the boot was worth 24 ms to a console prompt (2026-09-12) and moved logind, +# dbus-broker and user@1000.service into the first login instead, which is what a workspace +# waits for: with logind in the boot and spin lingering, the first SSH login over vsock came +# 60 ms sooner, 510/525 against 570/626 ms p50/p95, and sshd accepted no later (321 against +# 324), 10 boots of each interleaved on the bench fleet (task boot:ssh-first, lab run +# 43308825692, 2026-11-12). image/build.sh asserts the want is not overridden. log "Setting default target to multi-user..." ln -sf /lib/systemd/system/multi-user.target /etc/systemd/system/default.target diff --git a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf index 550546d..d1c9439 100644 --- a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf +++ b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf @@ -1,4 +1,9 @@ -# Why logind is not started at boot, and why this file is what allows that. +# What lets a login that arrives before logind has run still get a session. +# +# logind is in the boot again (spin lingers; see optimize-systemd.sh), but a login can still +# arrive before it has started - sshd accepts on vsock while the boot is going - and this is +# what makes that login activate logind instead of landing without a session. The history +# below is from when logind was deferred to the first login, which is when it was found. # # pam_systemd decides whether to register a session by calling logind_running(), which is # access("/run/systemd/seats/"). That is a test for "is this a system with logind", not for From 2c5dcddf9a075af0a3306f9f12d33d1785c2f80e Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Thu, 12 Nov 2026 23:05:43 -0300 Subject: [PATCH 5/5] boot: tests that refuse every edit mutate makes to waits, jobs and jobwatch The pull request's gate failed on 130 mutations no test refused. The library code now has a test for each edge it decides on: a unit's name, each way a unit sits in the dump, console noise between its blocks, what a unit waited on and the ties between candidates, where a gap begins and ends and which unit ended it, the order behind the prompt, every event's fields, when a job ran, and Lag's cut-offs. startingAt and After answer from a map, so their tests ask 64 times, through many orders. jobwatch's main, watch and now and vsockproxy's main are held by the lanes that run them in a guest (mutate-lane: ./boot.TestBootJobs, ./boot.TestFirstSSH). Exempted with the reason on the line: comparisons of a duration with zero, where every duration is whole microseconds, and the scanner buffer's size and ParseUint's bit size, past what any input reaches. ParseJobs loses an assignment the loop after it already made. task mutate against origin/main: 181 refused, 0 survived. Signed-off-by: Manuel de Brito Fontes Co-Authored-By: Claude Opus 5.5 --- boot/jobs.go | 6 +- boot/jobs_test.go | 114 +++++++++++++++++++ boot/jobwatch/main.go | 10 +- boot/jobwatch/main_test.go | 14 +++ boot/vsockproxy/main.go | 3 + boot/waits.go | 8 +- boot/waits_test.go | 218 +++++++++++++++++++++++++++++++++++++ 7 files changed, 365 insertions(+), 8 deletions(-) diff --git a/boot/jobs.go b/boot/jobs.go index f2ba955..0d7476d 100644 --- a/boot/jobs.go +++ b/boot/jobs.go @@ -93,7 +93,7 @@ func ParseJobs(s string) (JobLog, error) { if err != nil { return JobLog{}, err } - j.Unit, j.Initial = f[3], true + j.Unit = f[3] if f[5] == "running" { j.Running = at } @@ -157,10 +157,10 @@ func (l JobLog) Pending(t time.Duration) (waiting, running []Job) { if j.Initial { from = l.Connected } - if t < from || (j.Removed > 0 && t >= j.Removed) { + 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 { + 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) diff --git a/boot/jobs_test.go b/boot/jobs_test.go index 219fc38..6806390 100644 --- a/boot/jobs_test.go +++ b/boot/jobs_test.go @@ -4,6 +4,8 @@ package boot import ( "os" + "slices" + "strings" "testing" "time" ) @@ -113,3 +115,115 @@ func TestParseJobsRefuses(t *testing.T) { } } } + +// 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 index 0fd021f..d36467b 100644 --- a/boot/jobwatch/main.go +++ b/boot/jobwatch/main.go @@ -36,6 +36,9 @@ import ( "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 ") @@ -59,12 +62,17 @@ func main() { } // 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...)) } @@ -169,7 +177,7 @@ 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 { + 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 diff --git a/boot/jobwatch/main_test.go b/boot/jobwatch/main_test.go index 26f9089..0cd33d5 100644 --- a/boot/jobwatch/main_test.go +++ b/boot/jobwatch/main_test.go @@ -16,3 +16,17 @@ func TestUnescape(t *testing.T) { } } } + +// 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/vsockproxy/main.go b/boot/vsockproxy/main.go index 701f8d9..2b9f218 100644 --- a/boot/vsockproxy/main.go +++ b/boot/vsockproxy/main.go @@ -19,6 +19,9 @@ import ( "golang.org/x/sys/unix" ) +// main is ssh's ProxyCommand, and only ssh running against a guest calls it. +// +// mutate-lane: ./boot.TestFirstSSH, whose every login goes through it. func main() { if len(os.Args) != 3 { fmt.Fprintln(os.Stderr, "usage: vsockproxy ") diff --git a/boot/waits.go b/boot/waits.go index 0d1186d..5a6a224 100644 --- a/boot/waits.go +++ b/boot/waits.go @@ -134,15 +134,15 @@ func ParseWaits(s string) (Manager, []Unit, error) { } } switch { - case active > 0: + case active > 0: // mutate-exempt: durations here are whole microseconds, so 0 and 1ns split them alike u.Ready = active - case inactive > exit && exit > 0: + case inactive > exit && exit > 0: // mutate-exempt: durations here are whole microseconds, so 0 and 1ns split them alike // A oneshot that does not remain active goes activating -> inactive, and a unit // ordered after it starts when it is done; a failed unit lands here too. u.Ready = inactive } u.Start = exit - if u.Start == 0 || (u.Ready > 0 && u.Start > u.Ready) { + if u.Start == 0 || (u.Ready > 0 && u.Start > u.Ready) { // mutate-exempt: durations here are whole microseconds, so 0 and 1ns split them alike // Active without ever leaving inactive in this boot - a device, the root mount, a // slice - or left inactive again since; either way it was ready when it said so. u.Start = u.Ready @@ -175,7 +175,7 @@ func blocks(s string) []map[string]string { var out []map[string]string var cur map[string]string sc := bufio.NewScanner(strings.NewReader(s)) - sc.Buffer(make([]byte, 1<<20), 1<<20) + sc.Buffer(make([]byte, 1<<20), 1<<20) // mutate-exempt: any size past the longest line - a target's After=, a few KB - reads the dump alike for sc.Scan() { line := strings.TrimRight(sc.Text(), "\r") k, v, ok := strings.Cut(line, "=") diff --git a/boot/waits_test.go b/boot/waits_test.go index 6222612..e561aed 100644 --- a/boot/waits_test.go +++ b/boot/waits_test.go @@ -169,6 +169,7 @@ func TestParseWaitsRefuses(t *testing.T) { "no separator": manager, "unfinished": strings.Replace(manager, "FinishTimestampMonotonic=9000", "FinishTimestampMonotonic=0", 1) + "SPIN-WAITS-UNITS\n" + unitBlock("a.service", "", 1, 2, 0), "renamed property": manager + "SPIN-WAITS-UNITS\nId=a.service\nInactiveExitTimestampMonotonic=1\nActiveEnterTimestampMonotonic=2\n", + "no userspace": strings.Replace(manager, "UserspaceTimestampMonotonic=100", "UserspaceTimestampMonotonic=0", 1) + "SPIN-WAITS-UNITS\n" + unitBlock("a.service", "", 1, 2, 0), "nothing started": manager + "SPIN-WAITS-UNITS\n" + unitBlock("a.service", "", 0, 0, 0), "systemctl refused": manager + "SPIN-WAITS-UNITS\nsystemctl: invalid option -- '.'\n", } { @@ -177,3 +178,220 @@ func TestParseWaitsRefuses(t *testing.T) { } } } + +// The name a unit is reported and compared by is its shortest, and of two as short the first in +// order: a device's Id is whichever alias systemd met first. +func TestUnitNameIsTheShortest(t *testing.T) { + for _, c := range []struct { + u Unit + want string + }{ + {Unit{ID: "sys-devices-virtio2-block-vda.device", Names: []string{"sys-devices-virtio2-block-vda.device", "dev-vda.device", "dev-disk-by-path-x.device"}}, "dev-vda.device"}, + {Unit{ID: "b.device", Names: []string{"b.device", "a.device"}}, "a.device"}, + {Unit{ID: "a.device", Names: []string{"b.device", "a.device"}}, "a.device"}, + {Unit{ID: "a.service", Names: []string{"longer.service"}}, "a.service"}, + {Unit{ID: "a.service"}, "a.service"}, + } { + if got := c.u.Name(); got != c.want { + t.Errorf("%v: Name() = %q, want %q", c.u.Names, got, c.want) + } + } +} + +func us(n int) time.Duration { return time.Duration(n) * time.Microsecond } + +// Each way a unit can be in the dump, read to the start and readiness the rest of this file +// rests on - at the smallest values, where an off-by-one in a comparison with zero shows. +func TestParseWaitsReadsEachKindOfUnit(t *testing.T) { + typed := func(id, typ string, exit, active, inactive int) string { + b := unitBlock(id, "", exit, active, inactive) + return strings.TrimSuffix(b, "\n") + "Type=" + typ + "\n\n" + } + dump := manager + "SPIN-WAITS-UNITS\n" + + unitBlock("dev.device", "", 0, 5, 0) + // plugged: no exit, ready when active + unitBlock("restarted.service", "", 9, 4, 0) + // left inactive again after it was ready + unitBlock("oneshot.service", "", 2, 0, 7) + // ran and did not remain + unitBlock("tiny.service", "", 1, 1, 0) + // active at the first microsecond + unitBlock("short.service", "", 1, 0, 3) + // a oneshot that started at the first + unitBlock("early.service", "", 1, 5, 0) + + unitBlock("activating.service", "", 1, 0, 0) + // started, not ready when read + unitBlock("stopped.service", "", 0, 0, 3) + // inactive, never started: not this boot's + typed("idle.service", "idle", 2, 3, 0) + + typed("simple.service", "simple", 2, 3, 0) + + typed("tmp.mount", "idle", 2, 3, 0) // a mount's Type is its filesystem + m, us0, err := ParseWaits(dump) + if err != nil { + t.Fatal(err) + } + w := NewWaits(m, us0) + for _, c := range []struct { + id string + start, ready int + idle bool + }{ + {"dev.device", 5, 5, false}, + {"restarted.service", 4, 4, false}, + {"oneshot.service", 2, 7, false}, + {"tiny.service", 1, 1, false}, + {"short.service", 1, 3, false}, + {"early.service", 1, 5, false}, + {"activating.service", 1, 0, false}, + {"idle.service", 2, 3, true}, + {"simple.service", 2, 3, false}, + {"tmp.mount", 2, 3, false}, + } { + u, ok := w.Units[c.id] + if !ok { + t.Errorf("%s: dropped", c.id) + continue + } + if u.Start != us(c.start) || u.Ready != us(c.ready) || u.Idle != c.idle { + t.Errorf("%s: start %v ready %v idle %v; want %v %v %v", c.id, u.Start, u.Ready, u.Idle, us(c.start), us(c.ready), c.idle) + } + } + if _, ok := w.Units["stopped.service"]; ok { + t.Error("a unit that never left inactive in this boot was kept") + } +} + +// The dump arrives through a console: a line that is not Key=Value is noise that neither ends a +// block nor starts one, and only a blank line ends one. +func TestBlocksReadKeyValueLinesOnly(t *testing.T) { + got := blocks("Id=a\r\n kernel noise\nnot a key=1\n=empty\nAfter=x y\n\n\nId=b\nAfter=\n") + if len(got) != 2 || got[0]["Id"] != "a" || got[0]["After"] != "x y" || got[1]["Id"] != "b" { + t.Fatalf("blocks = %v", got) + } + if _, ok := got[0]["not a key"]; ok { + t.Error("a line with a space before its = was read as a key") + } + if _, ok := got[0][""]; ok { + t.Error("a line starting with = was read as a key") + } + if v, ok := got[1]["After"]; !ok || v != "" { + t.Errorf("an empty value was not kept: %q, %v", v, ok) + } +} + +func unitAt(id string, start, ready int, after ...string) Unit { + return Unit{ID: id, Start: us(start), Ready: us(ready), After: after} +} + +// What a unit waited on: the After= dependency ready last by the time it started - itself, a +// unit never ready, and one ready only later excluded - with ties to the one that took longer, +// then by name. +func TestBlockerRules(t *testing.T) { + w := NewWaits(Manager{}, []Unit{ + unitAt("aa.target", 100, 100, "aa.target", "late.service", "activating.service", "edge.service", "early.service"), + unitAt("late.service", 120, 150), + unitAt("activating.service", 50, 0), + unitAt("edge.service", 100, 100), + unitAt("early.service", 40, 50), + unitAt("waits-on-nothing.service", 100, 110, "activating.service"), + unitAt("first.service", 100, 110, "one.service"), + unitAt("one.service", 1, 1), + unitAt("tied.service", 200, 210, "c.service", "a.service", "b.service"), + // A name earlier in order does not beat a dependency that took longer. + unitAt("tied-by-own.service", 200, 210, "c.service", "a.service"), + unitAt("a.service", 145, 150), + unitAt("b.service", 130, 150), + unitAt("c.service", 130, 150), + }) + for _, c := range []struct{ unit, want string }{ + {"aa.target", "edge.service"}, + {"waits-on-nothing.service", ""}, + {"first.service", "one.service"}, + {"tied.service", "b.service"}, + {"tied-by-own.service", "c.service"}, + } { + b, ok := w.Blocker(w.Units[c.unit]) + if got := map[bool]string{true: b.ID}[ok]; got != c.want { + t.Errorf("%s waited on %q, want %q", c.unit, got, c.want) + } + } +} + +// Gaps are the intervals no unit was activating: a device's activation is not work, a unit still +// activating is busy to the end, a gap shorter than the minimum is left out and one exactly as +// long is kept, and each says which unit ended it and what that unit had waited on. +func TestGapsBoundaries(t *testing.T) { + ms := func(n int) time.Duration { return time.Duration(n) * time.Millisecond } + at := func(id string, start, ready int, after ...string) Unit { + return Unit{ID: id, Start: ms(start), Ready: ms(ready), After: after} + } + units := []Unit{ + {ID: "before.service", Start: 0, Ready: us(1)}, // ended before the unit load did + at("s1.service", 10, 20), + at("vda.device", 12, 60), + at("dep.target", 29, 29), + at("s2.service", 30, 40, "dep.target"), + at("blip.service", 42, 43), + at("act.service", 48, 0), + } + w := NewWaits(Manager{UnitsLoadFinish: ms(10)}, units) + got := w.Gaps(ms(60), ms(5)) + want := []Gap{ + {From: ms(20), To: ms(30), Next: "s2.service", NextBlocker: "dep.target"}, + {From: ms(43), To: ms(48), Next: "act.service"}, + } + if !slices.Equal(got, want) { + t.Fatalf("gaps = %+v\nwant %+v", got, want) + } + // Without the unit still activating, the boot ends idle, and that is a gap to until. + w = NewWaits(Manager{UnitsLoadFinish: ms(10)}, units[:len(units)-1]) + got = w.Gaps(ms(60), ms(5)) + if last := got[len(got)-1]; last.From != ms(43) || last.To != ms(60) || last.Next != "" { + t.Errorf("the last gap is %+v, want 43ms to 60ms ended by nothing", last) + } +} + +// The unit that ended a gap: the first to start at or after it, one that took time before one +// that did not, then by name; never a device. +func TestStartingAt(t *testing.T) { + w := NewWaits(Manager{}, []Unit{ + unitAt("before.service", 5, 50), + unitAt("z.device", 10, 30), + unitAt("instant.target", 10, 10), + unitAt("0-instant.target", 10, 10), + unitAt("b.service", 10, 20), + unitAt("a.service", 10, 20), + unitAt("later.service", 11, 12), + }) + // The units are a map, and which of the tied ones is met first changes from call to call: the + // answer may not. + for range 64 { + if u, ok := w.startingAt(us(10)); !ok || u.ID != "a.service" { + t.Fatalf("startingAt(10us) = %s, %v; want a.service", u.ID, ok) + } + } + if u, ok := w.startingAt(us(11)); !ok || u.ID != "later.service" { + t.Errorf("startingAt(11us) = %s, %v; want later.service", u.ID, ok) + } + if _, ok := w.startingAt(us(12)); ok { + t.Error("startingAt past every start found one") + } +} + +// Behind the prompt: every unit not ready by t, by when it was, the ones never ready last and +// by name; devices left out, and a unit ready exactly at t is not behind. +func TestAfterOrder(t *testing.T) { + w := NewWaits(Manager{}, []Unit{ + unitAt("ready.service", 1, 5), + unitAt("at.service", 1, 10), + unitAt("b-never.service", 1, 0), + unitAt("a-never.service", 1, 0), + unitAt("one.service", 1, 11), + unitAt("late.service", 1, 30), + unitAt("late.device", 1, 40), + }) + want := []string{"one.service", "late.service", "a-never.service", "b-never.service"} + // From a map: the order the sort meets them in changes from call to call, and the answer may not. + for range 64 { + var got []string + for _, u := range w.After(us(10)) { + got = append(got, u.ID) + } + if !slices.Equal(got, want) { + t.Fatalf("After(10us) = %v, want %v", got, want) + } + } +}