From bf33c63101228083d879be8cb42b11cc8a9458c6 Mon Sep 17 00:00:00 2001 From: William Grzybowski Date: Mon, 12 Oct 2026 15:49:54 -0300 Subject: [PATCH 1/3] truenas-appliance-runner: the boot's milestones and its console on one clock, and boot-report for where its time went --- .../truenas-appliance-runner/action.yml | 5 + .../truenas-appliance-runner/appliance.sh | 72 +++++++++++- .../truenas-appliance-runner/test_tnctl.py | 35 +++++- .../actions/truenas-appliance-runner/tnctl.py | 104 ++++++++++++++++-- README.md | 9 +- 5 files changed, 209 insertions(+), 16 deletions(-) diff --git a/.github/actions/truenas-appliance-runner/action.yml b/.github/actions/truenas-appliance-runner/action.yml index b00d59b..beeea25 100644 --- a/.github/actions/truenas-appliance-runner/action.yml +++ b/.github/actions/truenas-appliance-runner/action.yml @@ -110,6 +110,11 @@ runs: ln -sf "$lib/appliance.sh" "$RUNNER_TEMP/truenas-appliance-bin/truenas-appliance" echo "$RUNNER_TEMP/truenas-appliance-bin" >> "$GITHUB_PATH" out="$("$lib/appliance.sh" start)" + # Folded: the boot as the appliance's console saw it, on the same + # clock as the milestones logged above. + echo "::group::The appliance's console during its boot (seconds since qemu started)" + cat "$APPLIANCE_DIR/console.ts.log" 2>/dev/null || echo "(no console)" + echo "::endgroup::" get() { sed -n "s/^$1=//p" <<<"$out"; } { echo "host=$(get TN_HOST)" diff --git a/.github/actions/truenas-appliance-runner/appliance.sh b/.github/actions/truenas-appliance-runner/appliance.sh index 8b4a30f..e616d06 100755 --- a/.github/actions/truenas-appliance-runner/appliance.sh +++ b/.github/actions/truenas-appliance-runner/appliance.sh @@ -14,6 +14,11 @@ # disks, as # appliance.sh revert back to , in seconds, no boot # appliance.sh probe [baseline] change it, revert, check the change went +# appliance.sh boot-report where the boot's time went: systemd's +# critical chain and slowest units, and +# middleware's start, over ssh. Leaves ssh +# on, with a key and sudo for the admin: +# revert afterwards if that matters # appliance.sh call [params...] # a middleware API call, as the admin, its # result as JSON on stdout @@ -131,8 +136,9 @@ start() { -device "virtio-blk-pci,drive=data$i,serial=data$i") done - local booted + local booted t0 say "booting $disk as $name: ${memory} MB, $vcpus vCPUs, $ndata data disks of ${datagb}G" + t0=$(date +%s.%N) qemu-system-x86_64 -name "$name" -machine "q35,accel=$accel" -cpu "$cpu" -smp "$vcpus" -m "$memory" \ -smbios "type=1,serial=$name" \ -drive "if=pflash,format=raw,readonly=on,file=$OVMF_CODE" \ @@ -145,11 +151,15 @@ start() { -qmp "unix:$QMP,server=on,wait=off" \ -display none -serial "file:$DIR/console.log" \ -daemonize -pidfile "$DIR/qemu.pid" + # The console, each line with the seconds since qemu started, for as + # long as qemu runs: the boot's milestones below are on the same clock. + nohup "${TNCTL[@]}" tail-ts "$DIR/console.log" "$DIR/console.ts.log" \ + --since "$t0" --pid "$(cat "$DIR/qemu.pid")" >/dev/null 2>&1 & if ! booted=$("${TNCTL[@]}" wait "$(url)" "$APPLIANCE_USER" "$APPLIANCE_TEMPLATE_PASSWORD" \ - --timeout "${APPLIANCE_BOOT_TIMEOUT:-900}"); then + --since "$t0" --timeout "${APPLIANCE_BOOT_TIMEOUT:-900}"); then say "--- its console, last 60 lines" - tail -n 60 "$DIR/console.log" >&2 || true + console 60 >&2 || true die "the appliance's API never came up" fi say "API up ${booted}s after qemu started" @@ -161,6 +171,7 @@ start() { { echo "APPLIANCE_PASSWORD_NOW=$(printf %q "$password")" echo "APPLIANCE_HTTP_PORT=$http" + echo "APPLIANCE_SSH_PORT=$sshp" } > "$STATE" local snapped="" @@ -217,6 +228,56 @@ revert() { awk -v a="$t0" -v b="$(date +%s.%N)" 'BEGIN {printf "%.1f\n", b - a}' } +# console [lines]: the end of its serial console, timed when it can be. +console() { + if [ -s "$DIR/console.ts.log" ]; then + tail -n "${1:-100}" "$DIR/console.ts.log" + else + tail -n "${1:-100}" "$DIR/console.log" + fi +} + +# boot_report: where the boot's time went, from inside: systemd's own +# account of it, the chain of units middleware waited on, the slowest +# units, and middleware's log of its own start. Over ssh, as the admin with +# a key made here and sudo; those, and ssh, stay on afterwards. +boot_report() { + running || die "no appliance running" + state + needs ssh openssh-client ssh-keygen openssh-client + local key="$DIR/report_key" + [ -f "$key" ] || ssh-keygen -q -t ed25519 -N '' -C appliance-boot-report -f "$key" + "${TNCTL[@]}" enable-ssh "$(url)" "$APPLIANCE_USER" "$APPLIANCE_PASSWORD_NOW" --pubkey "$(cat "$key.pub")" >&2 + local port="${APPLIANCE_SSH_PORT:-2222}" + local -a ssh_ + ssh_=(ssh -i "$key" -p "$port" -o BatchMode=yes -o ConnectTimeout=5 + -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o LogLevel=ERROR + "$APPLIANCE_USER@127.0.0.1") + local i + for i in $(seq 1 30); do + "${ssh_[@]}" true 2>/dev/null && break + [ "$i" = 30 ] && die "no ssh into the appliance on 127.0.0.1:$port" + sleep 2 + done + "${ssh_[@]}" 'bash -s' <<'REPORT' +section() { printf '\n=== %s\n' "$*"; } +section "systemd-analyze" +systemd-analyze || true +section "the critical chain to middlewared" +systemd-analyze critical-chain middlewared.service --no-pager || true +section "the critical chain to the default target" +systemd-analyze critical-chain --no-pager || true +section "the 30 slowest units" +systemd-analyze blame --no-pager | head -n 30 || true +section "middlewared's unit, from the journal" +sudo -n journalctl -b -o short-monotonic -u middlewared --no-pager | head -n 40 || true +section "middlewared's log of its start" +sudo -n head -n 150 /var/log/middlewared.log || true +section "the kernel's command line" +cat /proc/cmdline +REPORT +} + # probe : that revert works and what it costs. A group is made # over the API, the appliance reverted to , and the group must # be gone; KEY=value on stdout. @@ -242,7 +303,8 @@ probe) shift; probe "$@" ;; snapshot) shift; snapshot "$@" ;; revert) shift; revert "$@" ;; snapshots) running || die "no appliance running"; hmp info snapshots ;; -console) tail -n "${2:-100}" "$DIR/console.log" ;; +console) console "${2:-100}" ;; +boot-report) boot_report ;; stop) if running; then "${TNCTL[@]}" qmp "$QMP" quit >/dev/null || true; fi ;; -*) die "usage: appliance.sh start | snapshot | revert | probe [baseline] | call [params...] | snapshots | console [lines] | stop" ;; +*) die "usage: appliance.sh start | snapshot | revert | probe [baseline] | call [params...] | boot-report | snapshots | console [lines] | stop" ;; esac diff --git a/.github/actions/truenas-appliance-runner/test_tnctl.py b/.github/actions/truenas-appliance-runner/test_tnctl.py index ffe7708..99c8844 100644 --- a/.github/actions/truenas-appliance-runner/test_tnctl.py +++ b/.github/actions/truenas-appliance-runner/test_tnctl.py @@ -2,6 +2,8 @@ test_tnctl.py. Standard library only, like tnctl.""" import base64 +import contextlib +import io import hashlib import json import os @@ -10,6 +12,7 @@ import sys import tempfile import threading +import time import unittest from types import SimpleNamespace @@ -122,11 +125,19 @@ def test_wait_until_ready(self): "auth.login_ex": lambda creds, notify: {"response_type": "SUCCESS" if creds["password"] == "pw" else "AUTH_ERR"}, "system.ready": lambda notify: next(ready), # Bigger than one short frame length can say, and than two. - "system.info": lambda notify: {"blob": "x" * 70000}, + "system.info": lambda notify: {"blob": "x" * 70000, "uptime_seconds": 12.5}, }) self.addCleanup(srv.close) - tnctl.cmd_wait(args(url=srv.url, user="truenas_admin", password="pw")) - self.assertEqual([m for m, _ in srv.calls], ["auth.login_ex", "system.ready", "system.ready", "system.ready"]) + err = io.StringIO() + with contextlib.redirect_stderr(err): + tnctl.cmd_wait(args(url=srv.url, user="truenas_admin", password="pw", since=time.time())) + self.assertEqual([m for m, _ in srv.calls], + ["auth.login_ex", "system.ready", "system.ready", "system.ready", "system.info"]) + # Each milestone once, in the order they happen. + milestones = [line.split(" ", 2)[2] for line in err.getvalue().splitlines() if line.startswith("tnctl: +")] + self.assertEqual(milestones[:4], [f"port {srv.url.rsplit(':', 1)[1]} accepts connections", + "the API's websocket answers", "login accepted", "system.ready"]) + self.assertIn("the guest's kernel started (it has been up 12.5s)", milestones[4]) self.assertEqual(srv.paths, ["/api/current"]) c = tnctl.login(srv.url, "truenas_admin", "pw") self.assertEqual(len(c.call("system.info")["blob"]), 70000) @@ -191,5 +202,23 @@ def serve(): self.assertEqual(e.exception.code, 1) +class TestTailTs(unittest.TestCase): + def test_lines_are_timed_and_cleaned(self): + d = tempfile.mkdtemp() + src, out = os.path.join(d, "console.log"), os.path.join(d, "console.ts.log") + with open(src, "wb") as f: + f.write(b"\x1b[1;32m[ OK ]\x1b[0m Started middlewared\r\n\r\nhalf") + # A pid that has exited: copy what is there, then stop. + dead = os.fork() + if dead == 0: + os._exit(0) + os.waitpid(dead, 0) + tnctl.cmd_tail_ts(args(file=src, out=out, since=time.time() - 5, pid=dead)) + with open(out) as f: + lines = f.read().splitlines() + self.assertEqual([line.split(None, 1)[1] for line in lines], ["[ OK ] Started middlewared", "half"]) + self.assertTrue(all(4.5 < float(line.split()[0]) < 30 for line in lines), lines) + + if __name__ == "__main__": unittest.main() diff --git a/.github/actions/truenas-appliance-runner/tnctl.py b/.github/actions/truenas-appliance-runner/tnctl.py index 6cc6a2e..1a9a812 100755 --- a/.github/actions/truenas-appliance-runner/tnctl.py +++ b/.github/actions/truenas-appliance-runner/tnctl.py @@ -14,11 +14,20 @@ Once the installed system is up: create its admin. Only a system with no admin yet allows this, unauthenticated. - tnctl.py wait URL USER PASSWORD [--timeout S] + tnctl.py wait URL USER PASSWORD [--timeout S] [--since EPOCH] Until USER can log in and system.ready is true; prints the seconds. + With --since, a boot's: logs each milestone on the way in seconds + since EPOCH (qemu's start): the port accepting connections, the API's + websocket answering, the login accepted, system.ready, and when the + guest's kernel started (from its uptime). + + tnctl.py tail-ts FILE OUT [--since EPOCH] [--pid PID] + Copy the lines FILE grows by into OUT, each prefixed with the seconds + since EPOCH, until PID exits: the serial console, timed. tnctl.py rotate URL USER PASSWORD NEW - tnctl.py enable-ssh URL USER PASSWORD + tnctl.py enable-ssh URL USER PASSWORD [--pubkey KEY] + ssh for USER with its password, or with KEY and sudo without one. tnctl.py call URL USER PASSWORD METHOD [JSON-PARAMS...] One call as USER, its result as JSON on stdout. tnctl.py wait-verify URL USER PASSWORD [--timeout S] @@ -39,6 +48,7 @@ import hashlib import json import os +import re import socket import struct import sys @@ -266,18 +276,90 @@ def setup(): def cmd_wait(a): start = time.monotonic() - c = retry("a login", a.timeout, lambda: login(a.url, a.user, a.password), every=2) + t0 = a.since + host, port = urllib.parse.urlsplit(a.url).hostname, urllib.parse.urlsplit(a.url).port or 80 + seen = set() + + def mark(what): + if t0 is not None and what not in seen: + seen.add(what) + log(f"+{time.time() - t0:.1f}s {what}") + + def attempt(): + with socket.create_connection((host, port), timeout=2): + pass + mark(f"port {port} accepts connections") + c = RPC(api(a.url), 30) + try: + mark("the API's websocket answers") + r = c.call("auth.login_ex", {"mechanism": "PASSWORD_PLAIN", "username": a.user, "password": a.password}) + if (r or {}).get("response_type") != "SUCCESS": + raise RPCError("auth.login_ex", r) + except BaseException: + c.close() + raise + mark("login accepted") + return c + + c = retry("a login", a.timeout, attempt, every=1) + def ready(): if not c.call("system.ready"): raise ValueError("not ready yet") try: - retry("system.ready", max(10, a.timeout - (time.monotonic() - start)), ready, every=2) + retry("system.ready", max(10, a.timeout - (time.monotonic() - start)), ready, every=1) + mark("system.ready") + if t0 is not None: + try: + uptime = float(c.call("system.info")["uptime_seconds"]) + log(f"+{time.time() - t0 - uptime:.1f}s the guest's kernel started (it has been up {uptime:.1f}s)") + except (RPCError, KeyError, TypeError, ValueError) as e: + log("no uptime from system.info:", e) finally: c.close() print(f"{time.monotonic() - start:.1f}") +ANSI = re.compile(rb"\x1b\[[0-9;?]*[ -/]*[@-~]|\x1b[()][A-Za-z0-9]|\r") + + +def alive(pid): + try: + os.kill(pid, 0) + except ProcessLookupError: + return False + except PermissionError: + pass + return True + + +def cmd_tail_ts(a): + t0 = a.since if a.since is not None else time.time() + while not os.path.exists(a.file): + if a.pid and not alive(a.pid): + return + time.sleep(0.2) + buf = b"" + with open(a.file, "rb") as f, open(a.out, "ab", buffering=0) as out: + while True: + data = f.read(65536) + if not data: + if a.pid and not alive(a.pid): + break + time.sleep(0.2) + continue + buf += data + *lines, buf = buf.split(b"\n") + stamp = f"{time.time() - t0:7.1f} ".encode() + for line in lines: + line = ANSI.sub(b"", line).rstrip() + if line: + out.write(stamp + line + b"\n") + if buf.strip(): + out.write(f"{time.time() - t0:7.1f} ".encode() + ANSI.sub(b"", buf).rstrip() + b"\n") + + def cmd_wait_verify(a): c = login(a.url, a.user, a.password) try: @@ -303,7 +385,12 @@ def cmd_enable_ssh(a): c = login(a.url, a.user, a.password) try: uid = c.call("user.query", [["username", "=", a.user]], {"get": True})["id"] - c.call("user.update", uid, {"ssh_password_enabled": True}) + if a.pubkey: + # A key, and sudo without a password, for a script to log in + # with and read what only root can. + c.call("user.update", uid, {"sshpubkey": a.pubkey, "sudo_commands_nopasswd": ["ALL"]}) + else: + c.call("user.update", uid, {"ssh_password_enabled": True}) c.call("service.update", "ssh", {"enable": True}) c.job("service.control", "START", "ssh", {"silent": False}) finally: @@ -377,10 +464,13 @@ def p(name, fn, *args, timeout=600): p("install", cmd_install, "url", timeout=3600).add_argument("--disk", default="") p("setup-admin", cmd_setup_admin, "url", "user", "password") - p("wait", cmd_wait, "url", "user", "password") + p("wait", cmd_wait, "url", "user", "password").add_argument("--since", type=float) + tail = p("tail-ts", cmd_tail_ts, "file", "out") + tail.add_argument("--since", type=float) + tail.add_argument("--pid", type=int) p("wait-verify", cmd_wait_verify, "url", "user", "password", timeout=300) p("rotate", cmd_rotate, "url", "user", "password", "new") - p("enable-ssh", cmd_enable_ssh, "url", "user", "password") + p("enable-ssh", cmd_enable_ssh, "url", "user", "password").add_argument("--pubkey", default="") p("call", cmd_call, "url", "user", "password", "method", timeout=120).add_argument("params", nargs="*") p("qmp", cmd_qmp, "socket", "command").add_argument("args", nargs="?") p("hmp", cmd_hmp, "socket", "line") diff --git a/README.md b/README.md index 048062c..fb9b51a 100644 --- a/README.md +++ b/README.md @@ -561,7 +561,14 @@ jobs: Outputs: `host`, `host-http`, `username`, `password` (masked), `ssh`, `boot-seconds`, `snapshot-seconds`. `truenas-appliance` is put on `PATH`: `snapshot `, `revert `, `call [params...]`, -`snapshots`, `console [lines]`, `probe`. +`snapshots`, `console [lines]`, `probe`, and `boot-report`: where the boot's +time went, from systemd and middleware's own log, over ssh (it leaves ssh on +with a key and sudo for the admin, so revert afterwards if that matters). + +The step's log has the boot's milestones, in seconds since qemu started (the +port accepting connections, the API's websocket answering, the login, +`system.ready`, and when the guest's kernel started), and the console of the +boot on the same clock, folded. These scripts are the one copy. github-truenas-runner's image pipeline fetches them from here, at the last commit that changed this directory, to From bb4125e9e5664659c817c1468d6e96dd79a37e71 Mon Sep 17 00:00:00 2001 From: William Grzybowski Date: Mon, 12 Oct 2026 16:15:07 -0300 Subject: [PATCH 2/3] truenas-appliance-runner: press Enter at GRUB's menu instead of waiting ten seconds for it; boot-report shows this boot's middleware log and the journal's pauses --- .../truenas-appliance-runner/appliance.sh | 11 +++++++++-- .github/actions/truenas-appliance-runner/lib.sh | 16 ++++++++++++++++ 2 files changed, 25 insertions(+), 2 deletions(-) diff --git a/.github/actions/truenas-appliance-runner/appliance.sh b/.github/actions/truenas-appliance-runner/appliance.sh index e616d06..8e1e207 100755 --- a/.github/actions/truenas-appliance-runner/appliance.sh +++ b/.github/actions/truenas-appliance-runner/appliance.sh @@ -155,6 +155,7 @@ start() { # long as qemu runs: the boot's milestones below are on the same clock. nohup "${TNCTL[@]}" tail-ts "$DIR/console.log" "$DIR/console.ts.log" \ --since "$t0" --pid "$(cat "$DIR/qemu.pid")" >/dev/null 2>&1 & + skip_grub "$DIR/console.log" "$QMP" if ! booted=$("${TNCTL[@]}" wait "$(url)" "$APPLIANCE_USER" "$APPLIANCE_TEMPLATE_PASSWORD" \ --since "$t0" --timeout "${APPLIANCE_BOOT_TIMEOUT:-900}"); then @@ -271,8 +272,14 @@ section "the 30 slowest units" systemd-analyze blame --no-pager | head -n 30 || true section "middlewared's unit, from the journal" sudo -n journalctl -b -o short-monotonic -u middlewared --no-pager | head -n 40 || true -section "middlewared's log of its start" -sudo -n head -n 150 /var/log/middlewared.log || true +section "middlewared's log of this boot's start" +sudo -n awk '/ - Starting TrueNAS/ {n = 0; delete buf} {buf[++n] = $0} END {for (i = 1; i <= n && i <= 120; i++) print buf[i]}' /var/log/middlewared.log || true +section "the journal's pauses over a second (kernel, initrd, userspace)" +sudo -n journalctl -b -o short-monotonic --no-pager | + awk -F'[][]' 'NF > 2 {t = $2 + 0; if (seen && t - p >= 1) printf "%6.1fs before [%8.3f] %s\n", t - p, t, substr($3, 1, 150); p = t; seen = 1}' || true +section "the kernel's own pauses over half a second" +sudo -n dmesg | + awk -F'[][]' 'NF > 2 {t = $2 + 0; if (seen && t - p >= 0.5) printf "%6.1fs before [%8.3f] %s\n", t - p, t, substr($3, 1, 150); p = t; seen = 1}' || true section "the kernel's command line" cat /proc/cmdline REPORT diff --git a/.github/actions/truenas-appliance-runner/lib.sh b/.github/actions/truenas-appliance-runner/lib.sh index c1be3ec..e8d6233 100644 --- a/.github/actions/truenas-appliance-runner/lib.sh +++ b/.github/actions/truenas-appliance-runner/lib.sh @@ -56,6 +56,22 @@ vars_qcow2() { qemu-img convert -q -f raw -O qcow2 "$OVMF_VARS" "$1" } +# skip_grub : TrueNAS's GRUB menu waits ten +# seconds for a key on every boot, a sixth of the whole boot. This is the +# key: Enter, through qemu's monitor, once the menu is on the console. In +# the background, for up to a minute; the boot goes on regardless. +skip_grub() { + ( + for _ in $(seq 1 300); do + if grep -aq "Press enter to boot" "$1" 2>/dev/null; then + "${TNCTL[@]}" qmp "$2" send-key '{"keys": [{"type": "qcode", "data": "ret"}]}' >/dev/null 2>&1 + exit 0 + fi + sleep 0.2 + done + ) >/dev/null 2>&1 & +} + # binds: where the appliance's forwarded ports listen. This machine's # loopback, and Docker's bridge when there is one, so that a container # reaches it as host.docker.internal; never the runner's network. From 90c0fa7f87f5f99b9ca46213bddd9aa31560cd26 Mon Sep 17 00:00:00 2001 From: William Grzybowski Date: Mon, 12 Oct 2026 16:38:22 -0300 Subject: [PATCH 3/3] truenas-appliance-runner: boot-report shows CPU steal and iowait in the appliance and on the runner, and the guest's clocksource --- .../truenas-appliance-runner/appliance.sh | 20 +++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/.github/actions/truenas-appliance-runner/appliance.sh b/.github/actions/truenas-appliance-runner/appliance.sh index 8e1e207..237d41f 100755 --- a/.github/actions/truenas-appliance-runner/appliance.sh +++ b/.github/actions/truenas-appliance-runner/appliance.sh @@ -262,6 +262,9 @@ boot_report() { done "${ssh_[@]}" 'bash -s' <<'REPORT' section() { printf '\n=== %s\n' "$*"; } +cpu_seconds() { + awk -v hz="$(getconf CLK_TCK)" '/^cpu / {printf "user %.0f system %.0f idle %.0f iowait %.0f steal %.0f\n", ($2 + $3) / hz, $4 / hz, $5 / hz, $6 / hz, $9 / hz}' /proc/stat +} section "systemd-analyze" systemd-analyze || true section "the critical chain to middlewared" @@ -282,7 +285,24 @@ sudo -n dmesg | awk -F'[][]' 'NF > 2 {t = $2 + 0; if (seen && t - p >= 0.5) printf "%6.1fs before [%8.3f] %s\n", t - p, t, substr($3, 1, 150); p = t; seen = 1}' || true section "the kernel's command line" cat /proc/cmdline +section "where the guest's CPU time went since boot, in seconds" +cpu_seconds +section "the guest's clocksource" +cat /sys/devices/system/clocksource/clocksource0/current_clocksource REPORT + echo + echo "=== the runner the appliance runs on" + echo "$(nproc) vCPUs, load $(cut -d' ' -f1-3 /proc/loadavg), $(free -m | awk '/^Mem:/ {print $2 " MB, " $7 " MB available"}')" + echo "Its CPU time since it booted, in seconds (steal is time its own host held its vCPUs back):" + cpu_seconds +} + +# cpu_seconds: /proc/stat's CPU line in seconds. Steal is time the +# hypervisor kept this machine's vCPUs from running; iowait is time spent +# waiting for disks. Defined here and in the report's script on the +# appliance alike. +cpu_seconds() { + awk -v hz="$(getconf CLK_TCK)" '/^cpu / {printf "user %.0f system %.0f idle %.0f iowait %.0f steal %.0f\n", ($2 + $3) / hz, $4 / hz, $5 / hz, $6 / hz, $9 / hz}' /proc/stat } # probe : that revert works and what it costs. A group is made