ci(test): add 64 MB fresh-memory probe and per-sample compaction/THP counters

- stall_probe.c: a pinned spinner (gap without an involuntary context
  switch = the vCPU itself was not running) and a 10 ms sleeper (timer
  wake-up latency, the parent heartbeat's situation).
- hv_info.c: hypervisor signature and KVM feature bits (steal time,
  realtime hint).
- Sampler records per-CPU jiffies so lost ticks can be attributed to
  all vCPUs or a subset.
- Idle observation step after the build to see whether stalls need load.

.github/scripts/ci-probe/hv_info.c

@@ -0,0 +1,34 @@
+// [TEST PR] Print hypervisor identification and KVM paravirt feature bits.
+#include <cpuid.h>
+#include <stdio.h>
+#include <string.h>
+
+int
+main(void)
+{
+    unsigned a = 0, b = 0, c = 0, d = 0;
+    char sig[13] = {0};
+    __cpuid(0x40000000, a, b, c, d);
+    memcpy(sig, &b, 4);
+    memcpy(sig + 4, &c, 4);
+    memcpy(sig + 8, &d, 4);
+    printf("hv_signature=%s hv_max_leaf=0x%x\n", sig, a);
+    if (strcmp(sig, "KVMKVMKVM") == 0 && a >= 0x40000001)
+    {
+        __cpuid(0x40000001, a, b, c, d);
+        printf(
+            "kvm_features=0x%x clocksource2=%u async_pf=%u steal_time=%u "
+            "pv_eoi=%u pv_unhalt=%u pv_tlb_flush=%u pv_sched_yield=%u "
+            "hints_realtime=%u\n",
+            a,
+            (a >> 3) & 1,
+            (a >> 4) & 1,
+            (a >> 5) & 1,
+            (a >> 6) & 1,
+            (a >> 7) & 1,
+            (a >> 9) & 1,
+            (a >> 13) & 1,
+            d & 1);
+    }
+    return 0;
+}

.github/scripts/ci-probe/memfresh.c

@@ -0,0 +1,89 @@
+// [TEST PR] Host first-touch latency probe.
+//   memfresh <MB> <interval_sec>
+// Every <interval_sec>: mmap <MB> of fresh anonymous memory, touch each page
+// while timing it, munmap. Fresh guest pages that the host has never backed
+// need a host-side allocation (EPT fault); on a host under memory pressure or
+// doing hugepage compaction that costs milliseconds to seconds per page
+// instead of about a microsecond.
+#define _GNU_SOURCE
+#include <stdio.h>
+#include <stdlib.h>
+#include <sys/mman.h>
+#include <time.h>
+#include <unistd.h>
+
+static double
+now_ms(void)
+{
+    struct timespec ts;
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    return ts.tv_sec * 1e3 + ts.tv_nsec / 1e6;
+}
+
+static void
+utc(char* buf, size_t n)
+{
+    struct timespec ts;
+    struct tm tm;
+    clock_gettime(CLOCK_REALTIME, &ts);
+    gmtime_r(&ts.tv_sec, &tm);
+    size_t l = strftime(buf, n, "%FT%T", &tm);
+    snprintf(buf + l, n - l, ".%03ldZ", ts.tv_nsec / 1000000);
+}
+
+int
+main(int argc, char** argv)
+{
+    if (argc < 3)
+        return 2;
+    size_t const mb = (size_t)atoi(argv[1]);
+    int const interval = atoi(argv[2]);
+    size_t const len = mb << 20, page = 4096;
+    setvbuf(stdout, NULL, _IOLBF, 0);
+    char b[48];
+    for (;;)
+    {
+        volatile unsigned char* buf = mmap(
+            NULL,
+            len,
+            PROT_READ | PROT_WRITE,
+            MAP_PRIVATE | MAP_ANONYMOUS,
+            -1,
+            0);
+        if (buf == MAP_FAILED)
+        {
+            perror("mmap");
+            return 1;
+        }
+        double const t0 = now_ms();
+        double max = 0, sum_slow = 0;
+        long slow = 0;
+        for (size_t off = 0; off < len; off += page)
+        {
+            double const a = now_ms();
+            buf[off] = 1;
+            double const d = now_ms() - a;
+            if (d > 1.0)
+            {
+                ++slow;
+                sum_slow += d;
+            }
+            if (d > max)
+                max = d;
+        }
+        double const total = now_ms() - t0;
+        munmap((void*)buf, len);
+        utc(b, sizeof b);
+        printf(
+            "%s memfresh mb=%zu total=%.0fms us_per_page=%.2f pages_over_1ms=%ld "
+            "slow_sum=%.0fms max_page=%.1fms\n",
+            b,
+            mb,
+            total,
+            total * 1000.0 / (double)(len / page),
+            slow,
+            sum_slow,
+            max);
+        sleep(interval);
+    }
+}

.github/scripts/ci-probe/memtouch.c

@@ -0,0 +1,85 @@
+// [TEST PR] Host-swap / page-residency probe.
+//   memtouch <MB> <idle_sec>
+// Allocates and touches <MB> of memory, then repeatedly sleeps <idle_sec> and
+// re-touches every page while timing each touch. Guest-resident memory costs
+// well under a microsecond per page; pages the host has swapped out or
+// reclaimed cost milliseconds each (a host page-in per page). A re-touch of a
+// 512 MB buffer that takes seconds, with many pages over 1 ms, means the host
+// is paging this VM's memory.
+#define _GNU_SOURCE
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <sys/mman.h>
+#include <time.h>
+#include <unistd.h>
+
+static double
+now_ms(void)
+{
+    struct timespec ts;
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    return ts.tv_sec * 1e3 + ts.tv_nsec / 1e6;
+}
+
+static void
+utc(char* buf, size_t n)
+{
+    struct timespec ts;
+    struct tm tm;
+    clock_gettime(CLOCK_REALTIME, &ts);
+    gmtime_r(&ts.tv_sec, &tm);
+    size_t l = strftime(buf, n, "%FT%T", &tm);
+    snprintf(buf + l, n - l, ".%03ldZ", ts.tv_nsec / 1000000);
+}
+
+int
+main(int argc, char** argv)
+{
+    if (argc < 3)
+        return 2;
+    size_t const mb = (size_t)atoi(argv[1]);
+    int const idle = atoi(argv[2]);
+    size_t const len = mb << 20, page = 4096;
+    setvbuf(stdout, NULL, _IOLBF, 0);
+    volatile unsigned char* buf = mmap(
+        NULL, len, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS, -1, 0);
+    if (buf == MAP_FAILED)
+    {
+        perror("mmap");
+        return 1;
+    }
+    memset((void*)buf, 1, len);
+    char b[48];
+    for (;;)
+    {
+        sleep(idle);
+        double const t0 = now_ms();
+        double max = 0, sum_slow = 0;
+        long slow = 0;
+        for (size_t off = 0; off < len; off += page)
+        {
+            double const a = now_ms();
+            buf[off] += 1;
+            double const d = now_ms() - a;
+            if (d > 1.0)
+            {
+                ++slow;
+                sum_slow += d;
+            }
+            if (d > max)
+                max = d;
+        }
+        utc(b, sizeof b);
+        printf(
+            "%s memtouch mb=%zu idle=%ds total=%.0fms pages_over_1ms=%ld "
+            "slow_sum=%.0fms max_page=%.1fms\n",
+            b,
+            mb,
+            idle,
+            now_ms() - t0,
+            slow,
+            sum_slow,
+            max);
+    }
+}

.github/scripts/ci-probe/stall_probe.c

@@ -0,0 +1,187 @@
+// [TEST PR] Stall probe for the coverage runner VM.
+//   stall_probe spin <cpu> <threshold_ms>   pin to <cpu>, spin, report gaps
+//   between
+//                                           consecutive clock reads above
+//                                           threshold
+//   stall_probe sleep <ms> <threshold_ms>   nanosleep(<ms>) in a loop, report
+//   wake-ups
+//                                           late by more than threshold
+//   stall_probe exit <cpu> <threshold_ms>   pin, execute cpuid (an
+//   unconditional VM
+//                                           exit) once per ms; a gap whose
+//                                           work= equals the gap is a vCPU
+//                                           stuck in the hypervisor
+//   stall_probe fault <cpu> <threshold_ms>  pin, map+touch+unmap 2 MB of fresh
+//   pages
+//                                           every 5 ms; work= equal to the gap
+//                                           means the stall is in the
+//                                           page-fault/EPT path
+// Each gap line carries the thread's voluntary/involuntary context switch
+// deltas: a spin gap with nivcsw+=0 means the thread stayed on its CPU from the
+// guest's point of view, i.e. the vCPU itself was not running (hypervisor),
+// while nivcsw>0 is ordinary in-guest preemption. Counters are read every
+// iteration so the deltas cover exactly the reported gap.
+#define _GNU_SOURCE
+#include <cpuid.h>
+#include <sched.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <sys/mman.h>
+#include <sys/resource.h>
+#include <time.h>
+#include <unistd.h>
+
+static double
+now_ms(void)
+{
+    struct timespec ts;
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    return ts.tv_sec * 1e3 + ts.tv_nsec / 1e6;
+}
+
+static void
+utc(char* buf, size_t n)
+{
+    struct timespec ts;
+    struct tm tm;
+    clock_gettime(CLOCK_REALTIME, &ts);
+    gmtime_r(&ts.tv_sec, &tm);
+    size_t l = strftime(buf, n, "%FT%T", &tm);
+    snprintf(buf + l, n - l, ".%03ldZ", ts.tv_nsec / 1000000);
+}
+
+enum mode { SPIN, SLEEP, EXIT, FAULT, BIG };
+
+// One unit of work for the exit/fault modes; returns its duration in ms.
+// For fault mode the three phases are timed separately so a slow unit can
+// be attributed to mmap (guest VMA work), the touches (guest page fault +
+// EPT fault in the host) or munmap (TLB shootdown / PV flush).
+static double g_map, g_touch, g_unmap;
+
+static double
+work(enum mode m)
+{
+    double const t0 = now_ms();
+    if (m == EXIT)
+    {
+        unsigned a, b, c, d;
+        __cpuid(0, a, b, c, d);
+    }
+    else if (m == FAULT || m == BIG)
+    {
+        size_t const n = m == BIG ? 64u << 20 : 2u << 20;
+        char* p = mmap(
+            NULL,
+            n,
+            PROT_READ | PROT_WRITE,
+            MAP_PRIVATE | MAP_ANONYMOUS,
+            -1,
+            0);
+        double const t1 = now_ms();
+        if (p != MAP_FAILED)
+        {
+            for (size_t i = 0; i < n; i += 4096)
+                p[i] = 1;
+        }
+        double const t2 = now_ms();
+        if (p != MAP_FAILED)
+            munmap(p, n);
+        double const t3 = now_ms();
+        g_map = t1 - t0;
+        g_touch = t2 - t1;
+        g_unmap = t3 - t2;
+    }
+    return now_ms() - t0;
+}
+
+int
+main(int argc, char** argv)
+{
+    if (argc < 4)
+        return 2;
+    enum mode const m = strcmp(argv[1], "spin") == 0 ? SPIN
+        : strcmp(argv[1], "sleep") == 0              ? SLEEP
+        : strcmp(argv[1], "exit") == 0               ? EXIT
+        : strcmp(argv[1], "fault") == 0              ? FAULT
+                                                     : BIG;
+    int const spin = m != SLEEP;
+    double const pace = m == EXIT ? 1 : m == FAULT ? 5 : m == BIG ? 1000 : 0;
+    int const arg = atoi(argv[2]);
+    double const thr = atof(argv[3]);
+    setvbuf(stdout, NULL, _IOLBF, 0);
+    if (spin)
+    {
+        cpu_set_t s;
+        CPU_ZERO(&s);
+        CPU_SET(arg, &s);
+        if (sched_setaffinity(0, sizeof s, &s) != 0)
+            perror("sched_setaffinity");
+    }
+    struct rusage ru;
+    getrusage(RUSAGE_THREAD, &ru);
+    long pv = ru.ru_nvcsw, pi = ru.ru_nivcsw;
+    double prev = now_ms(), last_report = prev, maxgap = 0;
+    long gaps = 0, gaps_no_switch = 0;
+    char b[48];
+    for (;;)
+    {
+        double w = 0;
+        if (!spin)
+        {
+            struct timespec r = {arg / 1000, (arg % 1000) * 1000000L};
+            nanosleep(&r, NULL);
+        }
+        else if (pace > 0)
+        {
+            w = work(m);
+            while (now_ms() - prev < pace)
+                ;
+        }
+        double const t = now_ms();
+        double const gap = t - prev - (spin ? 0 : arg);
+        // Track the switch counters continuously so a gap's delta covers
+        // only that gap (a syscall per iteration is fine for a probe).
+        getrusage(RUSAGE_THREAD, &ru);
+        long const dv = ru.ru_nvcsw - pv, di = ru.ru_nivcsw - pi;
+        pv = ru.ru_nvcsw;
+        pi = ru.ru_nivcsw;
+        if (gap > thr)
+        {
+            utc(b, sizeof b);
+            printf(
+                "%s %s gap=%.0fms cpu=%d nvcsw+=%ld nivcsw+=%ld work=%.0fms "
+                "map/touch/unmap=%.0f/%.0f/%.0f\n",
+                b,
+                argv[1],
+                gap,
+                sched_getcpu(),
+                dv,
+                di,
+                w,
+                g_map,
+                g_touch,
+                g_unmap);
+            ++gaps;
+            if (spin && di == 0)
+                ++gaps_no_switch;
+            if (gap > maxgap)
+                maxgap = gap;
+        }
+        if (t - last_report > 60000)
+        {
+            utc(b, sizeof b);
+            printf(
+                "%s %s alive cpu=%d gaps=%ld gaps_without_switch=%ld "
+                "maxgap=%.0fms\n",
+                b,
+                argv[1],
+                sched_getcpu(),
+                gaps,
+                gaps_no_switch,
+                maxgap);
+            last_report = t;
+        }
+        prev = t;
+    }
+}

.github/workflows/xahau-ga-nix.yml

@@ -286,6 +286,110 @@ jobs:
           clang_gcc_toolchain: ${{ matrix.clang_gcc_toolchain || '' }}
           ccache_max_size: '100G'
 
+      # [TEST PR] Host sampler: every 20s record load, PSI, steal time, cgroup
+      # CPU throttling and the number of rippled processes for the whole
+      # coverage build+test run, so a multi_runner stall report can be
+      # correlated with host state. Detached; printed by the step after Build.
+      - name: Start host sampler (coverage)
+        if: matrix.job_type == 'coverage'
+        shell: bash
+        run: |
+          cat > "$RUNNER_TEMP/sampler.sh" <<'EOF'
+          #!/bin/bash
+          out="$1"
+          prev_total=0; prev_steal=0; prev_up=""
+          while true; do
+            read -r _ u n s i w q sq st _ < /proc/stat
+            total=$((u+n+s+i+w+q+sq+st))
+            dt=$((total-prev_total)); ds=$((st-prev_steal))
+            steal_pct=0
+            [ "$prev_total" -gt 0 ] && [ "$dt" -gt 0 ] && steal_pct=$((100*ds/dt))
+            # Fraction of guest CPU time actually accounted over the interval:
+            # jiffies delta / (wall delta * ncpu * HZ). Well below 100% with
+            # steal%=0 means the vCPUs were not running (hypervisor), which the
+            # guest cannot see as steal on this VM.
+            now_up=$(cut -d' ' -f1 /proc/uptime)
+            delivered="n/a"
+            if [ -n "$prev_up" ]; then
+              delivered=$(awk -v dj="$dt" -v du="$(awk -v a="$now_up" -v b="$prev_up" 'BEGIN{print a-b}')" -v n="$(nproc)" 'BEGIN{ if (du>0) printf "%d%%", 100*dj/(du*n*100); else print "n/a"}')
+            fi
+            prev_up=$now_up
+            prev_total=$total; prev_steal=$st
+            nr=0; nl=0
+            for c in /proc/[0-9]*/comm; do
+              read -r name < "$c" 2>/dev/null || continue
+              [ "$name" = rippled ] && nr=$((nr+1))
+              case "$name" in llvm*) nl=$((nl+1));; esac
+            done
+            # block I/O: sectors written and ms spent doing I/O, summed over whole disks
+            disk=$(awk '$3 ~ /^(sd[a-z]+|vd[a-z]+|nvme[0-9]+n[0-9]+)$/ {w+=$10; t+=$13} END{printf "wr_sectors=%d io_ms=%d", w, t}' /proc/diskstats)
+            vm=$(awk '/^(pgpgout|nr_dirty|nr_writeback|pgfault|thp_fault_alloc|thp_fault_fallback|compact_stall|compact_fail|pgmigrate_success|pgalloc_normal|pgfree|nr_free_pages|balloon_inflate|balloon_deflate) /{printf "%s=%s ", $1, $2}' /proc/vmstat)
+            thr=$(grep -E '^(nr_throttled|throttled_usec)' /sys/fs/cgroup/cpu.stat 2>/dev/null | tr '\n' ' ')
+            # the multi_runner parent: the rippled whose cmdline has --unittest but not --unittest-child
+            pp=""
+            for d in /proc/[0-9]*; do
+              read -r name < "$d/comm" 2>/dev/null && [ "$name" = rippled ] || continue
+              cl=$(tr '\0' ' ' < "$d/cmdline" 2>/dev/null) || continue
+              case "$cl" in
+                *--unittest-child*) ;;
+                *--unittest*) pp=${d#/proc/}; break ;;
+              esac
+            done
+            parent=""
+            if [ -n "$pp" ] && [ -r "/proc/$pp/schedstat" ]; then
+              # schedstat: on-cpu ns, runqueue-wait ns, timeslices; thread states (R/S/D counts)
+              parent="parent_pid=$pp schedstat=[$(cat /proc/$pp/schedstat)] threads=[$(awk '{print $3}' /proc/$pp/task/*/stat 2>/dev/null | sort | uniq -c | tr -s ' \n' ' ')] ctxsw=[$(awk '/ctxt_switches/{printf "%s ", $2}' /proc/$pp/status)]"
+            fi
+            percpu=$(awk '/^cpu[0-9]/{printf "%d,", $2+$3+$4+$5+$6+$7+$8+$9}' /proc/stat)
+            echo "$(date -u +%FT%TZ) up=$(cut -d' ' -f1 /proc/uptime) load=$(cut -d' ' -f1-3 /proc/loadavg) steal%=$steal_pct steal_total=$st cpu_delivered=$delivered jiffies=$total psi_cpu=$(awk '/^some/{print $2}' /proc/pressure/cpu 2>/dev/null) psi_mem=$(awk '/^full/{print $2}' /proc/pressure/memory 2>/dev/null) psi_io=$(awk '/^some/{print $2}' /proc/pressure/io 2>/dev/null) memavail_mb=$(awk '/MemAvailable/{print int($2/1024)}' /proc/meminfo) rippled_procs=$nr llvm_procs=$nl $disk $vm$thr$parent percpu_jiffies=$percpu" >> "$out"
+            sleep 5
+          done
+          EOF
+          chmod +x "$RUNNER_TEMP/sampler.sh"
+          echo "nproc=$(nproc) cpu.max=$(cat /sys/fs/cgroup/cpu.max 2>/dev/null || echo n/a) cpuset=$(cat /sys/fs/cgroup/cpuset.cpus.effective 2>/dev/null || echo n/a)"
+          echo "kernel=$(uname -r) clocksource=$(cat /sys/devices/system/clocksource/clocksource0/current_clocksource 2>/dev/null) hypervisor_flag=$(grep -c -w hypervisor /proc/cpuinfo) dmi=$(cat /sys/class/dmi/id/sys_vendor /sys/class/dmi/id/product_name 2>/dev/null | tr '\n' ' ') dmesg_restrict=$(cat /proc/sys/kernel/dmesg_restrict 2>/dev/null)"
+          grep -E '^(model name|cpu MHz)' /proc/cpuinfo | sort | uniq -c | head -4
+          setsid nohup "$RUNNER_TEMP/sampler.sh" "$RUNNER_TEMP/host-samples.log" > /dev/null 2>&1 &
+          echo "sampler pid $!"
+          # Probes (see .github/scripts/ci-probe/*.c): hypervisor features once, then a
+          # 10ms sleeper (timer wake-up latency, the parent heartbeat's situation) and
+          # two spinners pinned to CPUs 3 and 17 (vCPU not running vs in-guest preemption),
+          # two cpuid loops pinned to CPUs 5 and 11 (is a vCPU stuck returning from a VM
+          # exit?) and a fresh-page toucher pinned to CPU 9 (is it the page-fault path?).
+          ${{ matrix.cc }} -O2 -o "$RUNNER_TEMP/hv_info" .github/scripts/ci-probe/hv_info.c && "$RUNNER_TEMP/hv_info" || echo "hv_info unavailable"
+          cat /sys/class/dmi/id/bios_vendor /sys/class/dmi/id/bios_version /sys/class/dmi/id/product_version 2>/dev/null | tr '\n' ' '; echo
+          if ${{ matrix.cc }} -O2 -o "$RUNNER_TEMP/stall_probe" .github/scripts/ci-probe/stall_probe.c; then
+            setsid nohup "$RUNNER_TEMP/stall_probe" sleep 10 100 > "$RUNNER_TEMP/probe-sleep.log" 2>&1 &
+            setsid nohup "$RUNNER_TEMP/stall_probe" spin 3 100 > "$RUNNER_TEMP/probe-spin3.log" 2>&1 &
+            setsid nohup "$RUNNER_TEMP/stall_probe" spin 17 100 > "$RUNNER_TEMP/probe-spin17.log" 2>&1 &
+            setsid nohup "$RUNNER_TEMP/stall_probe" exit 5 100 > "$RUNNER_TEMP/probe-exit5.log" 2>&1 &
+            setsid nohup "$RUNNER_TEMP/stall_probe" exit 11 100 > "$RUNNER_TEMP/probe-exit11.log" 2>&1 &
+            setsid nohup "$RUNNER_TEMP/stall_probe" fault 9 100 > "$RUNNER_TEMP/probe-fault9.log" 2>&1 &
+            setsid nohup "$RUNNER_TEMP/stall_probe" big 13 100 > "$RUNNER_TEMP/probe-big13.log" 2>&1 &
+            echo "probes started"
+          else
+            echo "stall_probe build failed; continuing without probes"
+          fi
+          # Host paging probe: 512 MB re-touched after 120 s idle, and 64 MB after 10 s (control).
+          if ${{ matrix.cc }} -O2 -o "$RUNNER_TEMP/memtouch" .github/scripts/ci-probe/memtouch.c; then
+            setsid nohup "$RUNNER_TEMP/memtouch" 512 120 > "$RUNNER_TEMP/probe-mem512.log" 2>&1 &
+            setsid nohup "$RUNNER_TEMP/memtouch" 64 10 > "$RUNNER_TEMP/probe-mem64.log" 2>&1 &
+          fi
+          if ${{ matrix.cc }} -O2 -o "$RUNNER_TEMP/memfresh" .github/scripts/ci-probe/memfresh.c; then
+            setsid nohup "$RUNNER_TEMP/memfresh" 512 90 > "$RUNNER_TEMP/probe-memfresh.log" 2>&1 &
+          fi
+          echo "clockevent=$(cat /sys/devices/system/clockevents/clockevent0/current_device 2>/dev/null) available_clocksource=$(cat /sys/devices/system/clocksource/clocksource0/available_clocksource 2>/dev/null) thp=$(cat /sys/kernel/mm/transparent_hugepage/enabled 2>/dev/null) virtio_drivers=$(ls /sys/bus/virtio/drivers 2>/dev/null | tr '\n' ',')"
+          # Is idle time in /proc/stat wall-clock based (NO_HZ idle) or tick based? Decides
+          # whether lost per-vCPU jiffies on an idle guest mean "halted vCPU not woken" or
+          # "vCPU frozen while running". Plus the TSC flags behind the missing tsc clocksource.
+          echo "cmdline=$(cat /proc/cmdline) nohz_full=$(cat /sys/devices/system/cpu/nohz_full 2>/dev/null) $(grep -E '^CONFIG_(NO_HZ|HZ=|VIRT_CPU_ACCOUNTING|TICK_CPU_ACCOUNTING|IRQ_TIME_ACCOUNTING)' /boot/config-$(uname -r) 2>/dev/null | tr '\n' ' ') tsc_flags=$(grep -m1 '^flags' /proc/cpuinfo | grep -o -w -E 'constant_tsc|nonstop_tsc|tsc_known_freq|tsc_reliable|rdtscp|tsc_adjust|hypervisor' | tr '\n' ',')"
+          grep -m2 -E "nohz_mode|hres_active|Clock Event Device" /proc/timer_list 2>/dev/null || echo "timer_list not readable"
+          # Are the guest's free pages handed back to the host (balloon / free page reporting)?
+          # If so every fresh page costs a host-side allocation, which is where the fault probe stalls.
+          for d in /sys/bus/virtio/drivers/virtio_balloon/virtio*; do echo "balloon $(basename $d) features=$(cat $d/features 2>/dev/null)"; done
+          grep -E "^(balloon_|thp_fault_alloc|thp_collapse_alloc|compact_stall|compact_fail|pgmigrate_success)" /proc/vmstat | tr '\n' ' '; echo
+          echo "page_reporting_order=$(cat /sys/module/page_reporting/parameters/page_reporting_order 2>/dev/null) thp_defrag=$(cat /sys/kernel/mm/transparent_hugepage/defrag 2>/dev/null) khugepaged_defrag=$(cat /sys/kernel/mm/transparent_hugepage/khugepaged/defrag 2>/dev/null) compaction_proactiveness=$(cat /proc/sys/vm/compaction_proactiveness 2>/dev/null) numa_balancing=$(cat /proc/sys/kernel/numa_balancing 2>/dev/null) nodes=$(ls -d /sys/devices/system/node/node* 2>/dev/null | wc -l)"
+
       - name: Build (Coverage)
         if: matrix.job_type == 'coverage'
         uses: ./.github/actions/xahau-ga-build
@@ -306,6 +410,48 @@ jobs:
           cmake-target: 'coverage'
           ccache_max_size: '100G'
 
+      # [TEST PR] Keep the slot for 12 more minutes with nothing but the sampler and
+      # probes running, to see whether the stalls also happen on an idle guest.
+      - name: Idle stall observation (coverage)
+        if: always() && matrix.job_type == 'coverage'
+        shell: bash
+        run: |
+          # 3 min quiet baseline, then a controlled 2 GB fdatasync write every 3 min
+          # (does a guest write burst coincide with vCPU stalls?), 12 min in total.
+          log="$RUNNER_TEMP/iotest.log"
+          sleep 180
+          for i in 1 2 3; do
+            s=$(date -u +%FT%T.%3NZ); t0=$SECONDS
+            dd if=/dev/zero of="$RUNNER_TEMP/iotest.bin" bs=1M count=2048 conv=fdatasync 2>/dev/null
+            echo "$s dd 2GB fdatasync start, took $((SECONDS-t0))s, ended $(date -u +%FT%T.%3NZ)" >> "$log"
+            rm -f "$RUNNER_TEMP/iotest.bin"
+            sleep 180
+          done
+
+      # [TEST PR] see "Start host sampler" above.
+      - name: Show host samples (coverage)
+        if: always() && matrix.job_type == 'coverage'
+        shell: bash
+        run: |
+          pkill -f sampler.sh || true
+          pkill -x stall_probe || true
+          for f in sleep spin3 spin17 exit5 exit11 fault9 big13; do
+            echo "---- probe-$f: $(grep -c ' gap=' "$RUNNER_TEMP/probe-$f.log" 2>/dev/null || true) gaps >100ms; gaps >=500ms or without a context switch:"
+            { grep -E ' gap=' "$RUNNER_TEMP/probe-$f.log" 2>/dev/null || true; } | awk '{g=$3; sub("gap=","",g); sub("ms","",g); if (g+0>=500 || $6=="nivcsw+=0") print}' | head -60 || true
+            { grep ' alive ' "$RUNNER_TEMP/probe-$f.log" 2>/dev/null || true; } | tail -1 || true
+          done
+          pkill -x memtouch || true
+          pkill -x memfresh || true
+          echo "---- controlled writes:"; cat "$RUNNER_TEMP/iotest.log" 2>/dev/null || true
+          for f in mem512 mem64 memfresh; do
+            echo "---- probe-$f (all lines):"
+            cat "$RUNNER_TEMP/probe-$f.log" 2>/dev/null || true
+          done
+          echo "---- host samples"
+          cat "$RUNNER_TEMP/host-samples.log" || echo "no samples recorded"
+          echo "---- kernel messages (if readable) mentioning timers/clock/lockups/kvm, last 40"
+          dmesg 2>&1 | grep -iE "hrtimer|clocksource|rcu|lockup|stall|kvm|hung task|steal" | tail -40 || true
+
       - name: Set artifact name
         if: matrix.job_type == 'build'
         id: set-artifact-name

src/test/unit_test/multi_runner.cpp

@@ -24,16 +24,86 @@
 #include <boost/lexical_cast.hpp>
 
 #include <algorithm>
+#include <ctime>
 #include <iomanip>
 #include <iostream>
 #include <sstream>
 #include <vector>
 
+#ifndef _WIN32
+#include <unistd.h>
+#endif
+
 namespace ripple {
 namespace test {
 
 namespace detail {
 
+// UTC wall clock, for correlating stall reports with CI/host logs.
+static std::string
+now_str()
+{
+    auto const t =
+        std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
+    std::tm tm{};
+#ifdef _WIN32
+    gmtime_s(&tm, &t);
+#else
+    gmtime_r(&t, &tm);
+#endif
+    std::stringstream ss;
+    ss << std::put_time(&tm, "%FT%TZ");
+    return ss.str();
+}
+
+static long
+parent_pid()
+{
+#ifdef _WIN32
+    return 0;
+#else
+    return static_cast<long>(getppid());
+#endif
+}
+
+// One line to stderr in a single write, so reports from the parent and
+// many children sharing the same pipe do not interleave mid-line.
+template <class... Ts>
+static void
+say(Ts const&... ts)
+{
+    std::ostringstream oss;
+    (oss << ... << ts) << '\n';
+    std::cerr << oss.str();
+}
+
+// Report when a step of a watchdog-relevant thread took longer than
+// `threshold`; returns the elapsed time.
+template <class F>
+static std::chrono::milliseconds
+timed(
+    char const* who,
+    char const* what,
+    F&& f,
+    std::chrono::milliseconds threshold)
+{
+    using namespace std::chrono;
+    auto const start = steady_clock::now();
+    f();
+    auto const elapsed =
+        duration_cast<milliseconds>(steady_clock::now() - start);
+    if (elapsed > threshold)
+        say(who,
+            ": ",
+            what,
+            " took ",
+            elapsed.count(),
+            "ms (ended ",
+            now_str(),
+            ")");
+    return elapsed;
+}
+
 std::string
 fmtdur(typename clock_type::duration const& d)
 {
@@ -392,20 +462,32 @@ multi_runner_base<IsParent>::add_failures(std::size_t failures)
 
 multi_runner_parent::multi_runner_parent() : os_(std::cout)
 {
+    // Heartbeat: a dedicated thread so the children only stop seeing
+    // increments when this process really is not running. A sleep that
+    // overran by more than a second is reported: that is the parent process
+    // itself being starved by the host, not a blocked I/O.
+    keep_alive_thread_ = std::thread([this] {
+        using namespace std::chrono;
+        while (this->continue_keep_alive_)
+        {
+            this->inc_keep_alive_count();
+            detail::timed(
+                "multi_runner_parent",
+                "heartbeat sleep(100ms)",
+                [] { std::this_thread::sleep_for(milliseconds(100)); },
+                milliseconds(1000));
+        }
+    });
+
     message_queue_thread_ = std::thread([this] {
+        using namespace std::chrono;
         std::vector<char> buf(1 << 20);
         while (this->continue_message_queue_ ||
                this->message_queue_->get_num_msg())
         {
-            // let children know the parent is still alive
-            this->inc_keep_alive_count();
             if (!this->message_queue_->get_num_msg())
             {
-                // If a child does not see the keep alive count incremented,
-                // it will assume the parent has died. This sleep time needs
-                // to be small enough so the child will see increments from
-                // a live parent.
-                std::this_thread::sleep_for(std::chrono::milliseconds(100));
+                std::this_thread::sleep_for(milliseconds(100));
                 continue;
             }
             try
@@ -419,16 +501,32 @@ multi_runner_parent::multi_runner_parent() : os_(std::cout)
                 assert(recvd_size == 1);
                 MessageType mt{*reinterpret_cast<MessageType*>(buf.data())};
 
-                this->message_queue_->receive(
-                    buf.data(), buf.size(), recvd_size, priority);
+                // Blocks until the sending child finishes its second send();
+                // report if that child was stalled for long.
+                detail::timed(
+                    "multi_runner_parent",
+                    "receive(body)",
+                    [&] {
+                        this->message_queue_->receive(
+                            buf.data(), buf.size(), recvd_size, priority);
+                    },
+                    milliseconds(1000));
                 if (recvd_size)
                 {
                     std::string s{buf.data(), recvd_size};
                     switch (mt)
                     {
                         case MessageType::log:
-                            this->os_ << s;
-                            this->os_.flush();
+                            // Blocks if whoever reads our stdout (e.g. ninja)
+                            // is not draining the pipe.
+                            detail::timed(
+                                "multi_runner_parent",
+                                "stdout write+flush",
+                                [&] {
+                                    this->os_ << s;
+                                    this->os_.flush();
+                                },
+                                milliseconds(1000));
                             break;
                         case MessageType::test_start:
                             running_suites_.insert(std::move(s));
@@ -462,6 +560,8 @@ multi_runner_parent::~multi_runner_parent()
 
     continue_message_queue_ = false;
     message_queue_thread_.join();
+    continue_keep_alive_ = false;
+    keep_alive_thread_.join();
 
     print_results(os_);
 
@@ -509,29 +609,82 @@ multi_runner_child::multi_runner_child(
 {
     if (num_jobs_ > 1)
     {
+        parent_pid_ = detail::parent_pid();
         keep_alive_thread_ = std::thread([this] {
-            std::size_t last_count = get_keep_alive_count();
+            using namespace std::chrono;
+            // A dead parent is detected within one tick through the ppid
+            // check. The heartbeat is the fallback for a parent that is alive
+            // but wedged (and for Windows, which has no ppid here), so its
+            // grace period must exceed any scheduling stall a loaded CI host
+            // can produce. The old 2.5s limit fired on live parents.
+            constexpr auto grace = seconds(60);
+            constexpr auto warn_after = milliseconds(2500);
+            auto last_count = this->get_keep_alive_count();
+            auto last_change = steady_clock::now();
+            bool warned = false;
             while (this->continue_keep_alive_)
             {
-                // Use a small sleep time so in the normal case the child
-                // process may shutdown quickly. However, to protect against
-                // false alarms, use a longer sleep time later on.
-                std::this_thread::sleep_for(std::chrono::milliseconds(500));
-                auto cur_count = this->get_keep_alive_count();
-                if (cur_count == last_count)
+                std::this_thread::sleep_for(milliseconds(500));
+
+                if (parent_pid_ != 0 && detail::parent_pid() != parent_pid_)
                 {
-                    // longer sleep time to protect against false alarms
-                    std::this_thread::sleep_for(std::chrono::seconds(2));
-                    cur_count = this->get_keep_alive_count();
-                    if (cur_count == last_count)
-                    {
-                        // assume parent process is no longer alive
-                        std::cerr << "multi_runner_child " << job_index_
-                                  << ": Assuming parent died, exiting.\n";
-                        std::exit(EXIT_FAILURE);
-                    }
+                    detail::say(
+                        "multi_runner_child ",
+                        job_index_,
+                        ": parent pid ",
+                        parent_pid_,
+                        " is gone (ppid now ",
+                        detail::parent_pid(),
+                        "), exiting. ",
+                        detail::now_str());
+                    std::exit(EXIT_FAILURE);
+                }
+
+                auto const cur_count = this->get_keep_alive_count();
+                auto const now = steady_clock::now();
+                if (cur_count != last_count)
+                {
+                    if (warned)
+                        detail::say(
+                            "multi_runner_child ",
+                            job_index_,
+                            ": keep-alive resumed after ",
+                            duration_cast<milliseconds>(now - last_change)
+                                .count(),
+                            "ms. ",
+                            detail::now_str());
+                    last_count = cur_count;
+                    last_change = now;
+                    warned = false;
+                    continue;
+                }
+
+                auto const stalled =
+                    duration_cast<milliseconds>(now - last_change);
+                if (!warned && stalled >= warn_after)
+                {
+                    detail::say(
+                        "multi_runner_child ",
+                        job_index_,
+                        ": no keep-alive from parent for ",
+                        stalled.count(),
+                        "ms",
+                        parent_pid_ ? " but its pid is still alive" : "",
+                        "; continuing. ",
+                        detail::now_str());
+                    warned = true;
+                }
+                if (stalled >= grace)
+                {
+                    detail::say(
+                        "multi_runner_child ",
+                        job_index_,
+                        ": Assuming parent died (no keep-alive for ",
+                        stalled.count(),
+                        "ms), exiting. ",
+                        detail::now_str());
+                    std::exit(EXIT_FAILURE);
                 }
-                last_count = cur_count;
             }
         });
     }

src/test/unit_test/multi_runner.h

@@ -223,6 +223,11 @@ private:
     std::ostream& os_;
     std::atomic<bool> continue_message_queue_{true};
     std::thread message_queue_thread_;
+    // Heartbeat for the children runs on its own thread so a blocking
+    // receive() or a blocked stdout write in message_queue_thread_ cannot
+    // make the children believe the parent died.
+    std::atomic<bool> continue_keep_alive_{true};
+    std::thread keep_alive_thread_;
     // track running suites so if a child crashes the culprit can be flagged
     std::set<std::string> running_suites_;
 
@@ -263,6 +268,8 @@ private:
     bool quiet_{false};
     bool print_log_{true};
 
+    // pid of the parent at construction; 0 where unavailable (Windows)
+    long parent_pid_{0};
     std::atomic<bool> continue_keep_alive_{true};
     std::thread keep_alive_thread_;