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..0d7476d --- /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 = f[3] + if f[5] == "running" { + j.Running = at + } + case "N": + j, err := job(f[2]) + if err != nil { + return JobLog{}, err + } + j.Unit, j.Queued = f[3], at + case "S": + j, err := job(f[2]) + if err != nil { + return JobLog{}, err + } + if f[3] == "running" && j.Running == 0 { + j.Running = at + } + case "R": + j, err := job(f[2]) + if err != nil { + return JobLog{}, err + } + j.Unit, j.Removed, j.Result = f[3], at, f[4] + case "A": + l.States = append(l.States, UnitState{At: at, Unit: f[2], State: f[3]}) + } + } + if l.Connected == 0 { + return JobLog{}, fmt.Errorf("no C line: jobwatch never subscribed") + } + // A job whose only trace is a state change or a removal was queued before jobwatch + // connected and finished before ListJobs answered: it was there, and nothing more is known. + for i := range l.Jobs { + j := &l.Jobs[i] + if j.Queued == 0 { + j.Initial = true + } + // systemd announces few of its jobs' state changes - 5 of 28 in a boot on 2026-11-12 - + // and a job that ran unannounced would read as waiting until it was removed. Its unit + // leaving inactive is the job running, and that is announced. + if j.Running == 0 { + from := max(j.Queued, l.Connected) + for _, s := range l.States { + if s.Unit == j.Unit && s.At >= from && (j.Removed == 0 || s.At <= j.Removed) && + (s.State == "activating" || s.State == "active") { + j.Running = s.At + break + } + } + } + } + return l, nil +} + +// Pending is the jobs in PID 1's queue at t, split by whether systemd was running them or +// they were waiting on another job. A job of the initial transaction counts from Connected, +// since nothing earlier was seen. +func (l JobLog) Pending(t time.Duration) (waiting, running []Job) { + for _, j := range l.Jobs { + from := j.Queued + if j.Initial { + from = l.Connected + } + if t < from || (j.Removed > 0 && t >= j.Removed) { // mutate-exempt: durations here are whole microseconds, so 0 and 1ns split them alike + continue + } + if j.Running > 0 && t >= j.Running { // mutate-exempt: durations here are whole microseconds, so 0 and 1ns split them alike + running = append(running, j) + } else { + waiting = append(waiting, j) + } + } + return waiting, running +} + +// Unfinished is every job that did not end done: a failure, a timeout, a job cancelled or +// skipped. A dependency result is a job that failed only because another did. +func (l JobLog) Unfinished() []Job { + var out []Job + for _, j := range l.Jobs { + if j.Result != "done" { + out = append(out, j) + } + } + slices.SortFunc(out, func(a, b Job) int { return cmp.Compare(a.ID, b.ID) }) + return out +} + +// Late is every job queued after jobwatch connected, by when. +func (l JobLog) Late() []Job { + var out []Job + for _, j := range l.Jobs { + if !j.Initial { + out = append(out, j) + } + } + slices.SortFunc(out, func(a, b Job) int { return cmp.Or(cmp.Compare(a.Queued, b.Queued), cmp.Compare(a.ID, b.ID)) }) + return out +} + +// Lag is how far behind systemd's own clock jobwatch heard a unit become active: the stamp +// of each ActiveState=active it received against the unit's ActiveEnterTimestampMonotonic, +// for every unit Waits has. It is what "live" means for this record. +// +// Only the first active a unit is heard to enter, and only for a unit that entered it after +// jobwatch subscribed: systemd sends ActiveState with every change to a unit's properties, so +// a unit already active is announced again and again, and counting those read a p95 of 42 ms +// that was a unit's age and not a delay (2026-11-12). +func (l JobLog) Lag(w Waits) []time.Duration { + var out []time.Duration + seen := map[string]bool{} + for _, s := range l.States { + if s.State != "active" || seen[s.Unit] { + continue + } + seen[s.Unit] = true + u, ok := w.Unit(s.Unit) + if !ok || u.Ready < l.Connected || s.At < u.Ready { + continue + } + out = append(out, s.At-u.Ready) + } + return out +} diff --git a/boot/jobs_test.go b/boot/jobs_test.go new file mode 100644 index 0000000..6806390 --- /dev/null +++ b/boot/jobs_test.go @@ -0,0 +1,229 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot + +import ( + "os" + "slices" + "strings" + "testing" + "time" +) + +// A real boot's record and the waits dump of the same boot: task boot:jobs RAW= on +// 2026-11-12, the release as it stood then. +func realJobs(t *testing.T) (JobLog, Waits) { + t.Helper() + b, err := os.ReadFile("testdata/jobs-2026-11-12.txt") + if err != nil { + t.Fatal(err) + } + l, err := ParseJobs(string(b)) + if err != nil { + t.Fatal(err) + } + b, err = os.ReadFile("testdata/jobs-waits-2026-11-12.txt") + if err != nil { + t.Fatal(err) + } + m, us, err := ParseWaits(string(b)) + if err != nil { + t.Fatal(err) + } + return l, NewWaits(m, us) +} + +func TestParseJobsReadsARealBoot(t *testing.T) { + l, w := realJobs(t) + if l.Connected == 0 || l.Finished <= l.Connected { + t.Fatalf("connected at %v, finished at %v", l.Connected, l.Finished) + } + if len(l.Jobs) == 0 { + t.Fatal("no jobs") + } + for _, j := range l.Jobs { + if j.Unit == "" { + t.Errorf("job %d has no unit", j.ID) + } + if j.Removed > 0 && j.Result == "" { + t.Errorf("job %d (%s) removed with no result", j.ID, j.Unit) + } + if j.Running > 0 && j.Removed > 0 && j.Running > j.Removed { + t.Errorf("job %d (%s) running at %v after it was removed at %v", j.ID, j.Unit, j.Running, j.Removed) + } + } + // The record and the timestamps are two accounts of one boot: jobwatch cannot have heard + // a unit become active before systemd stamped it, and should not be far behind. + lag := l.Lag(w) + if len(lag) == 0 { + t.Fatal("no unit heard becoming active") + } + for _, d := range lag { + if d < 0 || d > 100*time.Millisecond { + t.Errorf("a lag of %v", d) + } + } +} + +func TestPending(t *testing.T) { + l, err := ParseJobs(` +1000 C +1001 L 1 a.service start waiting +1002 L 2 b.service start running +1500 N 3 c.service +2000 A a.service activating +3000 R 2 b.service done +4000 R 1 a.service failed +5000 R 3 c.service done +`) + if err != nil { + t.Fatal(err) + } + for _, c := range []struct { + at int + waiting, running int + }{ + {999, 0, 0}, // before jobwatch connected, nothing was seen + {1500, 2, 1}, // a waiting, c just queued, b running since listed + {2500, 1, 2}, // a's unit activating is a running + {3500, 1, 1}, // b removed + {5000, 0, 0}, // c removed at that instant + } { + w, r := l.Pending(time.Duration(c.at) * time.Microsecond) + if len(w) != c.waiting || len(r) != c.running { + t.Errorf("at %dus: %d waiting, %d running; want %d, %d", c.at, len(w), len(r), c.waiting, c.running) + } + } + if u := l.Unfinished(); len(u) != 1 || u[0].Unit != "a.service" { + t.Errorf("unfinished = %+v", u) + } + if late := l.Late(); len(late) != 1 || late[0].Unit != "c.service" { + t.Errorf("late = %+v", late) + } +} + +// A record that ends in an error, or never subscribed, is that and not a boot with no jobs. +func TestParseJobsRefuses(t *testing.T) { + for name, rec := range map[string]string{ + "error": "1000 C\n2000 E subscribing to PID 1: timeout\n", + "no subscribe": "1001 L 1 a.service start waiting\n", + "short line": "1000 C\n1001 R 1 a.service\n", + "unknown event": "1000 C\n1001 Q 1\n", + } { + if _, err := ParseJobs(rec); err == nil { + t.Errorf("%s: parsed", name) + } + } +} + +// Every kind of event has its number of fields, and a line with fewer is an error, not an event +// read short; an E line is jobwatch's own error, said in its words. +func TestParseJobsHoldsEachEventToItsFields(t *testing.T) { + for _, short := range []string{ + "1001 L 1 a.service start", "1001 N 1", "1001 S 1", "1001 R 1 a.service", "1001 A a.service", + } { + if _, err := ParseJobs("1000 C\n" + short + "\n"); err == nil { + t.Errorf("%q: parsed", short) + } + } + _, err := ParseJobs("1000 C\n2000 E subscribing to PID 1: timeout\n") + if err == nil || !strings.Contains(err.Error(), "jobwatch stopped: subscribing to PID 1: timeout") { + t.Errorf("an E line read as %v", err) + } + if _, err := ParseJobs("1000 C\n2000 E\n"); err == nil || !strings.Contains(err.Error(), "jobwatch stopped") { + t.Errorf("a bare E line read as %v", err) + } + l, err := ParseJobs("1000 C\n1500 F\n9000 F already\n") + if err != nil || l.Finished != 1500*time.Microsecond { + t.Errorf("finished at %v (%v); want the plain F line's 1.5ms", l.Finished, err) + } +} + +// What jobwatch saw of each job: queued before it connected or after, when it ran - the first +// state change to running, or else its unit leaving inactive while the job was there - and the +// smallest timestamps, where a comparison with zero is off by one or not. +func TestParseJobsReadsEachJob(t *testing.T) { + l, err := ParseJobs(` +1 C +1 L 7 x.service start waiting +1 L 8 y.service start running +1 N 9 z.service +1 R 7 x.service done +2 S 10 running +3 S 10 running +3 R 10 seen-removed-only.service done +5 R 11 removed-only.service done +1500 N 20 c.service +1400 A c.service activating +1600 A other.service activating +1700 A c.service deactivating +1800 A c.service active +5000 R 20 c.service done +6000 A c.service activating +2000 N 21 pending.service +2100 A pending.service activating +`) + if err != nil { + t.Fatal(err) + } + job := map[string]Job{} + for _, j := range l.Jobs { + job[j.Unit] = j + } + if j := job["seen-removed-only.service"]; j.Running != us(2) { + t.Errorf("the first state change to running is at %v, want 2us", j.Running) + } + if j := job["c.service"]; j.Running != us(1800) { + t.Errorf("c.service ran from %v, want 1.8ms: its unit becoming active after it was queued", j.Running) + } + if j := job["pending.service"]; j.Running != us(2100) || j.Removed != 0 { + t.Errorf("a job still pending ran from %v, removed %v; want 2.1ms and not removed", j.Running, j.Removed) + } + var late []string + for _, j := range l.Late() { + late = append(late, j.Unit) + } + if want := []string{"z.service", "c.service", "pending.service"}; !slices.Equal(late, want) { + t.Errorf("late = %v, want %v: a job listed or seen only removed was queued before", late, want) + } + // At the first microsecond: x was removed, y was running since it was listed, z had just + // been queued, and the two seen only later were there from when jobwatch connected. + waiting, running := l.Pending(us(1)) + if len(running) != 1 || running[0].Unit != "y.service" { + t.Errorf("running at 1us: %v", running) + } + var w []string + for _, j := range waiting { + w = append(w, j.Unit) + } + slices.Sort(w) + if want := []string{"removed-only.service", "seen-removed-only.service", "z.service"}; !slices.Equal(w, want) { + t.Errorf("waiting at 1us: %v, want %v", w, want) + } +} + +// How far behind systemd jobwatch heard a unit become active: once per unit, only for a unit +// that became active after jobwatch subscribed, never a stamp before systemd's. +func TestLagCountsEachUnitOnce(t *testing.T) { + l, err := ParseJobs(` +1000 C +1600 A u.service active +1700 A u.service active +1400 A odd.service active +950 A early.service active +1200 A v.service activating +1300 A gone.service active +`) + if err != nil { + t.Fatal(err) + } + w := NewWaits(Manager{}, []Unit{ + unitAt("u.service", 1400, 1500), + unitAt("odd.service", 1400, 1500), + unitAt("early.service", 800, 900), + unitAt("v.service", 1100, 1150), + }) + if got := l.Lag(w); !slices.Equal(got, []time.Duration{us(100)}) { + t.Errorf("lag = %v, want [100us]", got) + } +} diff --git a/boot/jobwatch/main.go b/boot/jobwatch/main.go new file mode 100644 index 0000000..d36467b --- /dev/null +++ b/boot/jobwatch/main.go @@ -0,0 +1,189 @@ +// SPDX-License-Identifier: Apache-2.0 + +// jobwatch records what PID 1 says about its jobs while a guest boots, as they happen: the +// live half of task boot:waits, which reads systemd's timestamps after the fact. It is what +// bootvine (codeberg.org/wvhulle/bootvine) reads to draw its tree, without the tree. +// +// What it sees that the timestamps do not keep: when a job went from waiting to running +// (systemd dispatched it), how each job ended, and jobs queued after the initial transaction +// - socket and path activation, the first login's - with the moment they were queued. +// +// It talks to PID 1 on /run/systemd/private, which exists from PID 1's first moment and before +// any bus daemon; systemd sends every signal to every connection on that socket, Subscribe or +// not, and Subscribe is called anyway because a systemd that changed that would otherwise send +// nothing and this would report a boot with no jobs. Each event is stamped with +// CLOCK_MONOTONIC, systemd's own clock, when it is received, and kept in memory: writing to +// the serial console during the boot is a VM exit per byte inside what is being measured. The +// whole record is written once, after the boot. +// +// Diagnostic input, never part of a release: boot/jobwatch_probe_test.go builds it into a +// boot's own overlay. +// +// jobwatch +// +// writes the record to console once startup has finished, linger has passed since, and +// after-unit (another probe's writer, which shares the console) has gone inactive. +package main + +import ( + "fmt" + "os" + "strconv" + "strings" + "time" + + "github.com/godbus/dbus/v5" + "golang.org/x/sys/unix" +) + +// main is the binary a guest runs, and a guest is what holds it. +// +// mutate-lane: ./boot.TestBootJobs, which boots a guest with jobwatch in it and reads its record. +func main() { + if len(os.Args) != 4 { + fmt.Fprintln(os.Stderr, "usage: jobwatch ") + os.Exit(2) + } + linger, err := time.ParseDuration(os.Args[2]) + if err != nil { + fmt.Fprintf(os.Stderr, "jobwatch: linger %q: %v\n", os.Args[2], err) + os.Exit(2) + } + rec, err := watch(linger, os.Args[3]) + // What was recorded is written even when watching failed: a record that ends early says + // where it ended, and the error is its last line. + if err != nil { + rec = append(rec, fmt.Sprintf("%d E %v", now(), err)) + } + if err := os.WriteFile(os.Args[1], []byte("SPIN-JOBS-BEGIN\n"+strings.Join(rec, "\n")+"\nSPIN-JOBS-END\n"), 0); err != nil { + fmt.Fprintf(os.Stderr, "jobwatch: writing %s: %v\n", os.Args[1], err) + os.Exit(1) + } +} + +// now is CLOCK_MONOTONIC in microseconds, which is what systemd's *TimestampMonotonic are. +// +// mutate-lane: ./boot.TestBootJobs, whose Lag holds these stamps to systemd's own. +func now() int64 { + var ts unix.Timespec + _ = unix.ClockGettime(unix.CLOCK_MONOTONIC, &ts) + return ts.Nano() / 1000 +} + +// watch is the conversation with PID 1 over its private socket, which only a booted guest has. +// +// mutate-lane: ./boot.TestBootJobs, which parses what this recorded with boot.ParseJobs. +func watch(linger time.Duration, after string) ([]string, error) { + var rec []string + add := func(format string, a ...any) { rec = append(rec, fmt.Sprintf("%d ", now())+fmt.Sprintf(format, a...)) } + + conn, err := dbus.Dial("unix:path=/run/systemd/private") + if err != nil { + return rec, fmt.Errorf("connecting to /run/systemd/private: %w", err) + } + defer conn.Close() + // No Hello: there is no bus daemon on this socket to say it to. + if err := conn.Auth(nil); err != nil { + return rec, fmt.Errorf("authenticating to PID 1: %w", err) + } + // Large, because a channel godbus finds full is a signal lost, and a lost JobRemoved is a + // job that reads as never finished. + signals := make(chan *dbus.Signal, 1<<14) + conn.Signal(signals) + + manager := conn.Object("org.freedesktop.systemd1", "/org/freedesktop/systemd1") + // A message that arrives in the same read as the handshake's BEGIN is left unread by PID 1 + // until something else arrives on the socket, so the first message is a ping nobody waits + // for and the second is the one that matters. Without it Subscribe never returned and the + // boot finished around it (2026-11-12); bootvine works around the same thing with libdbus. + if err := manager. + Go("org.freedesktop.DBus.Peer.Ping", dbus.FlagNoReplyExpected, nil).Err; err != nil { + return rec, fmt.Errorf("pinging PID 1: %w", err) + } + if err := manager.Call("org.freedesktop.systemd1.Manager.Subscribe", 0).Err; err != nil { + return rec, fmt.Errorf("subscribing to PID 1: %w", err) + } + add("C") + + // The jobs queued before this connected, which is the initial transaction: when they were + // queued is not known, only that it was before now. + var jobs [][]any + if err := manager.Call("org.freedesktop.systemd1.Manager.ListJobs", 0).Store(&jobs); err != nil { + return rec, fmt.Errorf("listing PID 1's jobs: %w", err) + } + for _, j := range jobs { + add("L %v %v %v %v", j[0], j[1], j[2], j[3]) + } + var finish uint64 + if err := manager.Call("org.freedesktop.DBus.Properties.Get", 0, + "org.freedesktop.systemd1.Manager", "FinishTimestampMonotonic").Store(&finish); err != nil { + return rec, fmt.Errorf("reading FinishTimestampMonotonic: %w", err) + } + finished := finish != 0 + if finished { + add("F already") + } + var lingerUntil <-chan time.Time + if finished { + lingerUntil = time.After(linger) + } + lingered, afterDone := false, false + + for !(lingered && afterDone) { + select { + case <-lingerUntil: + lingered, lingerUntil = true, nil + case s, ok := <-signals: + if !ok { + return rec, fmt.Errorf("PID 1 closed the connection") + } + switch s.Name { + case "org.freedesktop.systemd1.Manager.JobNew": + add("N %v %v", s.Body[0], s.Body[2]) + case "org.freedesktop.systemd1.Manager.JobRemoved": + add("R %v %v %v", s.Body[0], s.Body[2], s.Body[3]) + case "org.freedesktop.systemd1.Manager.StartupFinished": + add("F") + if !finished { + finished, lingerUntil = true, time.After(linger) + } + case "org.freedesktop.DBus.Properties.PropertiesChanged": + iface, _ := s.Body[0].(string) + changed, _ := s.Body[1].(map[string]dbus.Variant) + p := string(s.Path) + switch { + case iface == "org.freedesktop.systemd1.Job": + if v, ok := changed["State"]; ok { + add("S %s %v", strings.TrimPrefix(p, "/org/freedesktop/systemd1/job/"), v.Value()) + } + case iface == "org.freedesktop.systemd1.Unit": + if v, ok := changed["ActiveState"]; ok { + unit := unescape(strings.TrimPrefix(p, "/org/freedesktop/systemd1/unit/")) + add("A %s %v", unit, v.Value()) + if unit == after && (v.Value() == "inactive" || v.Value() == "failed") { + afterDone = true + } + } + } + } + } + } + return rec, nil +} + +// unescape reads a unit's name back from its object path, where systemd writes every byte that +// is not a letter or a digit as _ and two hex digits: dev-vda.device is dev_2dvda_2edevice. +func unescape(s string) string { + var b strings.Builder + for i := 0; i < len(s); i++ { + if s[i] == '_' && i+2 < len(s) { + if n, err := strconv.ParseUint(s[i+1:i+3], 16, 8); err == nil { // mutate-exempt: two hex digits are at most 0xff, which every bit size from 8 up holds + b.WriteByte(byte(n)) + i += 2 + continue + } + } + b.WriteByte(s[i]) + } + return b.String() +} diff --git a/boot/jobwatch/main_test.go b/boot/jobwatch/main_test.go new file mode 100644 index 0000000..0cd33d5 --- /dev/null +++ b/boot/jobwatch/main_test.go @@ -0,0 +1,32 @@ +// SPDX-License-Identifier: Apache-2.0 + +package main + +import "testing" + +func TestUnescape(t *testing.T) { + for path, unit := range map[string]string{ + "dev_2dvda_2edevice": "dev-vda.device", + "system_2dserial_5cx2dgetty_2eslice": `system-serial\x2dgetty.slice`, + "serial_2dgetty_40ttyS0_2eservice": "serial-getty@ttyS0.service", + "_2d_2emount": "-.mount", + } { + if got := unescape(path); got != unit { + t.Errorf("unescape(%q) = %q, want %q", path, got, unit) + } + } +} + +// An escape at the very end of a path is read, and an escape cut short is left as it is: a path +// is systemd's, and a unit name may end in one. +func TestUnescapeAtTheEnd(t *testing.T) { + for path, unit := range map[string]string{ + "a_2e": "a.", + "a_2": "a_2", + "a_": "a_", + } { + if got := unescape(path); got != unit { + t.Errorf("unescape(%q) = %q, want %q", path, got, unit) + } + } +} diff --git a/boot/jobwatch_probe_test.go b/boot/jobwatch_probe_test.go 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/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/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..2b9f218 --- /dev/null +++ b/boot/vsockproxy/main.go @@ -0,0 +1,51 @@ +// 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" +) + +// 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 ") + 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..5a6a224 --- /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: // mutate-exempt: durations here are whole microseconds, so 0 and 1ns split them alike + u.Ready = active + 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) { // 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 + } + 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) // 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, "=") + 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..e561aed --- /dev/null +++ b/boot/waits_test.go @@ -0,0 +1,397 @@ +// 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", + "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", + } { + if _, _, err := ParseWaits(dump); err == nil { + t.Errorf("%s: parsed", name) + } + } +} + +// 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) + } + } +} 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= 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/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/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/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 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 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 +