From 8e11908dfbb32cb78ca6c5001802f282d8e9551a Mon Sep 17 00:00:00 2001 From: Josh Siviour Date: Mon, 7 Sep 2026 21:53:41 +1000 Subject: [PATCH] fix: make the EKS control plane's disk latency observable, and give it room to run (#1009) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * fix: report CPU and memory pressure in the EKS control-plane health diagnostic An unhealthy control plane reported readyz, etcd reachability and etcd-disk free space. When etcd goes unreachable with disk:ok and no OOM kill, that set cannot distinguish a starved guest from a genuine etcd fault, so add the loadavg and MemAvailable that separate them. An empty /readyz body also rendered as readyz:[none], which reads as "no subcheck failed" when it means the probe never answered. Report that as unreachable instead. * fix: sample the node's load, not just the runner host's Every runner agent runs on one host while their nodes sit on several, so the existing sample measured the runner's host and was labelled as the hypervisor. It happens to coincide when the node is on that same host and misleads otherwise. Relabel it and add a node-side sample, which is where the guests are actually scheduled and so where a starved guest shows up. * feat: build the mkosi EKS image in CI and give its control plane telemetry The Ubuntu/systemd EKS image is what customers run, and nothing built it: the composition existed in mkosi-build.sh's image_profiles table but had no caller, so a change that broke it was found by hand or not at all. Cell-25 builds the Alpine image, which leaves the published one with no gate. Add a Makefile target beside the Alpine one and a job in the existing path-filtered image workflow. The guest also collected nothing. k3s has served embedded-etcd metrics on 127.0.0.1:2381 since the daemon started setting etcd-expose-metrics, and no collector ever read them, so an etcd stall was only ever visible as "etcd:unreachable" in the state report — which cannot separate a slow disk from a dead one. Ship otelcol-contrib pinned to the version the cluster hosts already run, scraping etcd and guest host metrics. The unit is gated on ConditionPathExists for its endpoint file rather than started unconditionally: whether the control-plane guest can reach the sink from the isolated CP VPC is unverified, and a collector with nowhere to export is a restart loop, not telemetry. * fix: report etcd fsync latency in the control-plane health diagnostic disk:ok measures free space, which says nothing about how long a write takes. etcd stalls on fsync latency long before it runs out of room, and this guest's disk is an EBS volume served by viperblock, so a fsync is a network round trip. An unhealthy control plane reporting healthy memory and disk was uninterpretable without it. Derived from the histogram's sum and count rather than a bucket percentile: two greps against an interpolation this script has no business doing, and the difference between a healthy single-digit reading and a stalled one is an order of magnitude, not a tail. Rides the state report's existing gateway path, so it needs no route the CP VPC does not already grant, and lands on both images because the script is shared. The scrape's failure is guarded explicitly. Under set -e a bare assignment from a curl against a port nothing answers aborts the whole diagnosis, dropping the reason field exactly when it is wanted. * feat: publish etcd fsync on every control-plane report, not only failing ones A figure that appears only once the apiserver is already unhealthy has no baseline to be read against, which is the same gap a passing cell that uploads no journal leaves: the number is unanchored when it finally arrives. Move the scrape into its own helper, emit it on healthy reports too, and carry it as a typed field rather than only inside the reason string. Slowness is logged, never gated. observe() decides cluster health, and a working cluster on a slow disk is working — returning an issue there would fail customers' clusters on a latency threshold. The warning is latched on the transition instead, because the control plane republishes on its own timer and a line every interval is how a real signal gets tuned out. An absent sample is not a fast one. Too few fsyncs to average, an etcd serving no metrics and an older AMI all arrive as nil, and the field is omitted rather than defaulted so none of them can be read as healthy. The minimum sample count is the same lesson as the slow-shard floor: a mean over three fsyncs on a just-started etcd is a number with no meaning. * fix: log an etcd fsync baseline and name the two no-sample cases apart A healthy cluster logs no health lines, so the fsync figure reached the daemon on every report and was never surfaced — a passing cell left nothing for a later slow reading to be compared against. Log the first known sample. Split the "unknown" sentinel into nometrics (etcd served none) and warmup (too few fsyncs to average): different faults, different fixes. The payload guard now tests for a number rather than the sentinel word, so a future sentinel cannot leak into the JSON as a bare value. * feat: measure fdatasync latency in the diskperf gate The two pinned profiles are buffered-bypassing throughput jobs at queue depth 32. Neither measures the cost of making a write durable, which is what a consensus datastore pays per raft entry and stalls on long before it runs short of bandwidth. A 5ms barrier on bare metal went unseen as a result. syncwrite-4k is the etcd-shaped profile: sequential 4k, queue depth 1, fdatasync every write, buffered psync so the sync has a page cache to flush. fio reports the sync distribution apart from the write stream, so the parser reads it separately — gating on write clat would score the time to reach the cache and call it durability. No figures captured on this hardware yet, so the baseline entry is zero and the job records without gating. * fix: use the real otelcol checksums asset name in the EKS server image The checksums file is named for the release repo and the distribution and carries no version, unlike the tarball beside it. The guessed name 404'd and took the image build with it. * fix: extract otelcol as root in the EKS server image The upstream tarball records its build uid (runner/docker, 1001:118), which does not exist in the image. tar running as root tries to restore it and fails outright rather than degrading, taking the build with it. --------- Co-authored-by: Ben Duncan <5178243+benduncan@users.noreply.github.com> --- .github/workflows/e2e-nightly.yml | 37 +++++- .github/workflows/image-scripts.yml | 36 ++++++ Makefile | 6 + .../etc/spinifex-eks/otelcol-config.yaml | 121 ++++++++++++++++++ .../systemd/system/mulga-eks-otelcol.service | 39 ++++++ .../system-preset/40-mulga-eks-role.preset | 5 + .../eks-server/mkosi.postinst.chroot | 36 +++++- .../images/eks-node/mulga-eks-state-report.sh | 85 ++++++++++-- .../eks-node/mulga-eks-state-report_test.sh | 109 +++++++++++++++- spinifex/handlers/eks/cluster_reconciler.go | 30 +++++ spinifex/handlers/eks/state_report.go | 19 +++ .../handlers/eks/state_report_fsync_test.go | 103 +++++++++++++++ tests/e2e/diskperf/baseline.go | 4 + tests/e2e/diskperf/baseline.json | 9 +- tests/e2e/diskperf/diskperf_test.go | 10 +- tests/e2e/diskperf/fio.go | 80 +++++++++++- tests/e2e/diskperf/fio_test.go | 91 ++++++++++++- 17 files changed, 792 insertions(+), 28 deletions(-) create mode 100644 images/mkosi.profiles/eks-server/mkosi.extra/etc/spinifex-eks/otelcol-config.yaml create mode 100644 images/mkosi.profiles/eks-server/mkosi.extra/etc/systemd/system/mulga-eks-otelcol.service create mode 100644 spinifex/handlers/eks/state_report_fsync_test.go diff --git a/.github/workflows/e2e-nightly.yml b/.github/workflows/e2e-nightly.yml index ca3f28074..eb7f31959 100644 --- a/.github/workflows/e2e-nightly.yml +++ b/.github/workflows/e2e-nightly.yml @@ -183,11 +183,10 @@ jobs: "${RUNNER_TEMP}/spinifex-tests.tar" \ --extra-suites "${MATRIX_SUITE}" - # Eight runner names map onto three hypervisors, so cells that never share - # a runner still share a host. Nothing measured that, which left "the host - # was loaded" as an unfalsifiable explanation for every timeout. Sampled - # either side of the cell so the next occurrence can be correlated. - - name: Sample hypervisor load (before) + # Every runner agent runs on one host, while their nodes sit on several, so + # this samples the runner's host and not the node's hypervisor. Kept for + # runner-side contention; the node's own capacity is sampled after. + - name: Sample runner-host load (before) if: always() run: | mkdir -p "${ARTIFACT_DIR}" @@ -612,7 +611,7 @@ jobs: if [ $rc -ne 0 ]; then echo "reboot: FAILED" >> "${ARTIFACT_DIR}/suite-status.txt"; fi exit $rc - - name: Sample hypervisor load (after) + - name: Sample runner-host load (after) if: always() run: | mkdir -p "${ARTIFACT_DIR}" @@ -624,6 +623,32 @@ jobs: echo "running qemu: $(pgrep -c qemu-system-x86 || echo 0)" } >> "${ARTIFACT_DIR}/hypervisor-load.txt" + # The node, not the runner's host, is what the guests are scheduled on, so + # its load is the figure that explains a starved guest. Never fails the + # cell: a node already gone is the case this is trying to describe. + - name: Sample node load (after) + if: always() + working-directory: mulga/scripts/tofu-cluster + run: | + set +e + mkdir -p "${ARTIFACT_DIR}" + INVENTORY=$(tofu output -json inventory 2>/dev/null) + NODE1_IP=$(echo "$INVENTORY" | jq -r '.nodes[0].wan_ip' 2>/dev/null) + SSH_KEY=$(echo "$INVENTORY" | jq -r '.ssh_key_path' 2>/dev/null) + SSH_KEY="${SSH_KEY/#\~/$HOME}" + [ -n "$NODE1_IP" ] && [ "$NODE1_IP" != "null" ] || exit 0 + [ -n "$SSH_KEY" ] && [ "$SSH_KEY" != "null" ] || exit 0 + { + echo "=== node after: $(date -u +%Y-%m-%dT%H:%M:%SZ) ip=${NODE1_IP} ===" + ssh -o StrictHostKeyChecking=no -o BatchMode=yes -o ConnectTimeout=10 \ + -i "$SSH_KEY" "tf-user@${NODE1_IP}" \ + 'echo "host: $(hostname)"; echo "loadavg: $(cat /proc/loadavg)"; + grep -E "^(MemTotal|MemAvailable|SwapFree):" /proc/meminfo; + echo "cpu(steal is field 8): $(grep "^cpu " /proc/stat)"; + echo "running qemu: $(pgrep -c qemu-system-x86 || echo 0)"' 2>&1 + } >> "${ARTIFACT_DIR}/node-load.txt" + exit 0 + - name: Collect e2e artifacts if: always() working-directory: mulga/scripts/tofu-cluster diff --git a/.github/workflows/image-scripts.yml b/.github/workflows/image-scripts.yml index 878a5483d..98cb48fe3 100644 --- a/.github/workflows/image-scripts.yml +++ b/.github/workflows/image-scripts.yml @@ -37,3 +37,39 @@ jobs: - name: Run image script tests + shellcheck run: make test-images + + # The mkosi EKS image is what customers run, and until now nothing built it: + # the composition existed in mkosi-build.sh but had no caller, so a change + # that broke it was only found by hand. Cell-25 still boots the Alpine image, + # so this is the only gate the Ubuntu one has. + # + # Self-hosted because the build needs Docker and several GB of disk, matching + # publish-system-ami.yml. Its own concurrency group, not e2e-hypervisors: the + # build provisions no libvirt guest, and sharing that group would queue image + # builds behind whole nightlies. + eks_mkosi_image: + name: Build mkosi EKS image + runs-on: [self-hosted, ci-single] + concurrency: + group: eks-mkosi-image-${{ github.ref }} + cancel-in-progress: true + + steps: + - name: Checkout Code + uses: actions/checkout@v7 + + # The profile binaries (eks-token-webhook, eks-gateway-publish, ...) are + # built on the host, not in the builder container, so Go is needed here + # even though the toolchain image carries mkosi itself. + - name: Set up Go + uses: actions/setup-go@v7 + with: + go-version-file: "go.mod" + # Self-hosted: the module + build cache already persists on local + # disk, and cache-save would re-upload hundreds of MB for nothing. + cache: false + + # stage_profile_binaries() sets GOWORK=off, so the sub-repo resolves its + # own go.mod and the sibling monorepo checkouts are not needed here. + - name: Build the image + run: make build-eks-node-mkosi-image diff --git a/Makefile b/Makefile index 2f452bf43..4f14dfe6b 100644 --- a/Makefile +++ b/Makefile @@ -103,6 +103,12 @@ import-eks-node-image: ## Build + register the eks-node AMI (requires a running publish-eks-node-image: ## Build + publish the eks-node AMI to Cloudflare R2 (needs R2_ENDPOINT + AWS_* env) ./scripts/publish-system-image.sh scripts/images/eks-node/manifest.conf --build +# The Ubuntu/systemd EKS image, as opposed to build-eks-node-image's Alpine one. +# Composition lives in mkosi-build.sh's image_profiles table, so the image name +# is the whole interface here. +build-eks-node-mkosi-image: ## Build the Ubuntu mkosi EKS node image (server+agent; role at first boot) + ./scripts/mkosi-build.sh --image spinifex-eks-node + build-ecs-node-image: ## Build the spinifex-ecs-node AMI (Alpine + containerd + ecs-agent; IMPORT=1 to register) $(MAKE) build-system-image IMAGE=ecs-agent diff --git a/images/mkosi.profiles/eks-server/mkosi.extra/etc/spinifex-eks/otelcol-config.yaml b/images/mkosi.profiles/eks-server/mkosi.extra/etc/spinifex-eks/otelcol-config.yaml new file mode 100644 index 000000000..cc6f428fb --- /dev/null +++ b/images/mkosi.profiles/eks-server/mkosi.extra/etc/spinifex-eks/otelcol-config.yaml @@ -0,0 +1,121 @@ +# Control-plane telemetry for the EKS server guest. +# +# k3s already serves embedded-etcd metrics on 127.0.0.1:2381 — the daemon sets +# etcd-expose-metrics in the k3s config it writes as cloud-init user-data. Until +# this collector existed nothing read them, so an etcd stall was only ever +# visible as "etcd:unreachable" in the state report, which cannot separate a +# slow disk from a dead one. etcd_disk_wal_fsync_duration_seconds is the metric +# that does. +# +# The endpoint comes from /etc/spinifex-eks/otelcol.env, written when the guest +# is told where the sink is. The unit will not start without that file, so an +# image with no sink configured runs no collector rather than a failing one. + +receivers: + # Embedded etcd. Its fsync and commit histograms are the whole point of this + # file; the rest of the k3s metrics come along at no extra scrape cost. + prometheus/etcd: + config: + scrape_configs: + - job_name: etcd + scrape_interval: 15s + static_configs: + - targets: ["127.0.0.1:2381"] + + # Guest-side pressure. The state report already carries loadavg and + # MemAvailable as scalars, which is enough to rule starvation in or out at one + # instant and useless for seeing it build. + hostmetrics: + collection_interval: 15s + scrapers: + cpu: + metrics: + system.cpu.utilization: + enabled: true + system.cpu.logical.count: + enabled: true + load: + memory: + metrics: + system.memory.utilization: + enabled: true + disk: + filesystem: + exclude_mount_points: + match_type: regexp + mount_points: + - "/proc/*" + - "/sys/*" + - "/run/*" + - "/var/lib/kubelet/*" + exclude_fs_types: + match_type: strict + fs_types: + - tmpfs + - devtmpfs + - overlay + - squashfs + - proc + - sysfs + - cgroup + - cgroup2 + network: + paging: + +processors: + resourcedetection/system: + detectors: ["system"] + system: + hostname_sources: ["os"] + + # apm-server routes non-APM-agent OTLP metrics into + # metrics-apm.app.-default, so an unset service.name puts etcd + # and host metrics in the shared "unknown" bucket with everything else. + resource/etcd: + attributes: + - key: service.name + value: "eks-etcd" + action: upsert + - key: eks.cluster + value: "${env:EKS_CLUSTER_NAME}" + action: upsert + + resource/system: + attributes: + - key: service.name + value: "eks-control-plane" + action: upsert + - key: eks.cluster + value: "${env:EKS_CLUSTER_NAME}" + action: upsert + + # Sheds data under memory pressure rather than queueing without bound when the + # sink is unreachable. Must be FIRST in every pipeline: it only applies + # backpressure to not-yet-processed data. Budgeted well under the unit's + # MemoryMax so it fires before the kernel does — this guest is 4 GB and the + # control plane is what matters on it. + memory_limiter: + check_interval: 1s + limit_mib: 64 + spike_limit_mib: 16 + + batch: + send_batch_size: 1024 + timeout: 2s + +exporters: + otlp: + endpoint: "${env:EKS_OTLP_ENDPOINT}" + tls: + insecure: true + +service: + pipelines: + metrics/etcd: + receivers: [prometheus/etcd] + processors: [memory_limiter, resourcedetection/system, resource/etcd, batch] + exporters: [otlp] + metrics: + receivers: [hostmetrics] + processors: [memory_limiter, resourcedetection/system, resource/system, batch] + exporters: [otlp] diff --git a/images/mkosi.profiles/eks-server/mkosi.extra/etc/systemd/system/mulga-eks-otelcol.service b/images/mkosi.profiles/eks-server/mkosi.extra/etc/systemd/system/mulga-eks-otelcol.service new file mode 100644 index 000000000..0405abf4c --- /dev/null +++ b/images/mkosi.profiles/eks-server/mkosi.extra/etc/systemd/system/mulga-eks-otelcol.service @@ -0,0 +1,39 @@ +[Unit] +Description=Mulga EKS control-plane telemetry (OpenTelemetry Collector) +Documentation=https://opentelemetry.io/docs/collector/ +After=network-online.target k3s.service +Wants=network-online.target +# No sink configured means no collector. A condition that is not met leaves the +# unit inactive and says so, where a missing endpoint would otherwise be a +# restart loop against an exporter that can never resolve. +ConditionPathExists=/etc/spinifex-eks/otelcol.env + +[Service] +Type=simple +# EKS_OTLP_ENDPOINT lives here; EKS_CLUSTER_NAME comes from the first-boot env +# the rest of the node services already read, so the cluster tag matches what +# the state report publishes. +EnvironmentFile=/etc/spinifex-eks/otelcol.env +EnvironmentFile=-/etc/spinifex-eks/first-boot.env +ExecStart=/usr/local/bin/otelcol-contrib --config=/etc/spinifex-eks/otelcol-config.yaml +Restart=on-failure +RestartSec=10 + +# The control plane owns this guest. Three tiers, each below the next: +# memory_limiter sheds data, GOMEMLIMIT makes the Go GC work harder, MemoryMax +# is a backstop that should never fire. On a 4 GB node an agent that competes +# with etcd for memory causes the outage it was installed to explain. +Environment=GOMEMLIMIT=96MiB +MemoryHigh=128M +MemoryMax=192M +CPUQuota=20% +Nice=10 +IOSchedulingClass=idle + +NoNewPrivileges=true +ProtectSystem=strict +ProtectHome=true +PrivateTmp=true + +[Install] +WantedBy=multi-user.target diff --git a/images/mkosi.profiles/eks-server/mkosi.extra/usr/lib/systemd/system-preset/40-mulga-eks-role.preset b/images/mkosi.profiles/eks-server/mkosi.extra/usr/lib/systemd/system-preset/40-mulga-eks-role.preset index 90cb178e3..6e1cd0c5f 100644 --- a/images/mkosi.profiles/eks-server/mkosi.extra/usr/lib/systemd/system-preset/40-mulga-eks-role.preset +++ b/images/mkosi.profiles/eks-server/mkosi.extra/usr/lib/systemd/system-preset/40-mulga-eks-role.preset @@ -16,6 +16,11 @@ enable eks-node-role.service enable mulga-eks-etcd-snapshot-daily.timer enable mulga-eks-etcd-snapshot-15min.timer +# Unconditional like the timers, and for the same reason: it self-guards. Its +# ConditionPathExists means a guest with no sink configured never starts it, so +# there is no role for the selector to decide. An agent that is given a sink +# still reports host metrics; only the etcd scrape goes unanswered. +enable mulga-eks-otelcol.service disable k3s.service disable k3s-agent.service diff --git a/images/mkosi.profiles/eks-server/mkosi.postinst.chroot b/images/mkosi.profiles/eks-server/mkosi.postinst.chroot index 069d6f089..7ec5b22fb 100755 --- a/images/mkosi.profiles/eks-server/mkosi.postinst.chroot +++ b/images/mkosi.profiles/eks-server/mkosi.postinst.chroot @@ -77,4 +77,38 @@ if got != want: print(f"[eks-server] cloud-init datasource_list assertion passed: {got!r}") PY -echo "[eks-server] postinst complete: eks-node-role enabled, etcd-snapshot timers enabled, datasource pin verified" +# Telemetry collector. Pinned to the same version the cluster hosts' obs-agent +# role runs, so a metric means the same thing wherever it was collected. +# Verified against upstream's published checksums rather than a hash pinned +# here: a hash in two places drifts, and the release is immutable. +OTELCOL_VERSION="0.115.1" +OTELCOL_URL_BASE="https://github.com/open-telemetry/opentelemetry-collector-releases/releases/download/v${OTELCOL_VERSION}" +OTELCOL_TAR="otelcol-contrib_${OTELCOL_VERSION}_linux_amd64.tar.gz" + +# The checksums file is named for the release repo and the distribution, with +# no version in it — unlike the tarball beside it, which carries the version. +echo "[eks-server] fetching otelcol-contrib checksums ${OTELCOL_VERSION}" +curl -fsSL -o /tmp/otelcol-checksums.txt \ + "${OTELCOL_URL_BASE}/opentelemetry-collector-releases_otelcol-contrib_checksums.txt" +OTELCOL_SHA256=$(awk -v f="${OTELCOL_TAR}" '$2 == f {print $1; exit}' /tmp/otelcol-checksums.txt) +if [[ -z "${OTELCOL_SHA256}" ]]; then + echo "[eks-server] could not parse ${OTELCOL_TAR} sha256 from upstream checksums" >&2 + exit 1 +fi + +echo "[eks-server] downloading otelcol-contrib ${OTELCOL_VERSION} (sha256=${OTELCOL_SHA256})" +curl -fsSL -o "/tmp/${OTELCOL_TAR}" "${OTELCOL_URL_BASE}/${OTELCOL_TAR}" +echo "${OTELCOL_SHA256} /tmp/${OTELCOL_TAR}" > /tmp/otelcol.sha256 +if ! sha256sum -c /tmp/otelcol.sha256; then + echo "[eks-server] otelcol-contrib checksum mismatch" >&2 + exit 1 +fi +# --no-same-owner: the archive records upstream's build uid, which does not +# exist here, and restoring it fails outright rather than degrading. Extracted +# as root instead, which is what owns the rest of /usr/local/bin. +tar -xzf "/tmp/${OTELCOL_TAR}" --no-same-owner -C /usr/local/bin otelcol-contrib +chown root:root /usr/local/bin/otelcol-contrib +chmod 0755 /usr/local/bin/otelcol-contrib +rm -f /tmp/otelcol-checksums.txt /tmp/otelcol.sha256 "/tmp/${OTELCOL_TAR}" + +echo "[eks-server] postinst complete: eks-node-role enabled, etcd-snapshot timers enabled, datasource pin verified, otelcol-contrib ${OTELCOL_VERSION} installed" diff --git a/scripts/images/eks-node/mulga-eks-state-report.sh b/scripts/images/eks-node/mulga-eks-state-report.sh index 4abc31dec..2032618eb 100755 --- a/scripts/images/eks-node/mulga-eks-state-report.sh +++ b/scripts/images/eks-node/mulga-eks-state-report.sh @@ -42,13 +42,19 @@ DISK_MIN_KB=${DISK_MIN_KB:-262144} # diagnose emits a compact, JSON-safe reason for an unhealthy apiserver by # reading the ground truth only reachable from inside the guest: the failing -# /readyz subchecks, isolated etcd reachability, and the etcd-disk free space. +# /readyz subchecks, etcd reachability, etcd-disk free space, and host pressure. diagnose() { # apiserver prints "[+]name ok" for passing subchecks and "[-]name failed" - # for failing ones; collect the failing names (etcd, poststarthook/*, ...). - failed=$(kubectl get --raw='/readyz?verbose' 2>/dev/null \ - | awk '/^\[-\]/{sub(/^\[-\]/,""); sub(/[[:space:]].*$/,""); printf "%s%s", sep, $0; sep=" "}') - [ -n "${failed}" ] || failed=none + # for failing ones. An empty body means the probe never answered, which is a + # different fault from "every subcheck passed" and must not read the same. + readyz=$(kubectl get --raw='/readyz?verbose' 2>/dev/null) + if [ -z "${readyz}" ]; then + failed=unreachable + else + failed=$(printf '%s\n' "${readyz}" \ + | awk '/^\[-\]/{sub(/^\[-\]/,""); sub(/[[:space:]].*$/,""); printf "%s%s", sep, $0; sep=" "}') + [ -n "${failed}" ] || failed=none + fi if kubectl get --raw='/healthz/etcd' 2>/dev/null | grep -q '^ok$'; then etcd=ok @@ -63,7 +69,51 @@ diagnose() { disk=ok fi - printf 'readyz:[%s]; etcd:%s; disk:%s' "${failed}" "${etcd}" "${disk}" + # etcd stalls under CPU or memory pressure long before it faults on its own, + # so an unhealthy CP reporting disk:ok is uninterpretable without these two. + load=$(awk '{print $1}' "${LOADAVG_FILE:-/proc/loadavg}" 2>/dev/null) + memavail_kb=$(awk '/^MemAvailable:/{print $2}' "${MEMINFO_FILE:-/proc/meminfo}" 2>/dev/null) + [ -n "${load}" ] || load=unknown + [ -n "${memavail_kb}" ] || memavail_kb=unknown + + printf 'readyz:[%s]; etcd:%s; disk:%s; fsync:%sms; load:%s; memavail:%sk' \ + "${failed}" "${etcd}" "${disk}" "$(etcd_fsync_ms)" "${load}" "${memavail_kb}" +} + +# etcd_fsync_ms prints the mean WAL fsync in milliseconds, or "nometrics" when +# etcd served none, or "warmup" when it has not done enough to average. +# +# disk:ok in diagnose() is free space, which says nothing about how long a write +# takes. etcd stalls on fsync latency long before it runs out of room, and this +# guest's disk is an EBS volume served by viperblock, so a fsync here is a +# network round trip. Healthy is single-digit milliseconds. +# +# Mean rather than a percentile: the histogram's _sum and _count are two greps, +# where a bucket percentile is an interpolation this script has no business +# doing, and a stall shows as an order of magnitude rather than a tail. +etcd_fsync_ms() { + # `|| metrics=` is load-bearing under set -e: a scrape against a port + # nothing answers exits non-zero, and a bare assignment would abort the + # caller — dropping the diagnosis exactly when it is wanted. + metrics=$(curl -fsS --max-time 2 "${ETCD_METRICS_URL:-http://127.0.0.1:2381/metrics}" 2>/dev/null) || metrics= + # "etcd served nothing" and "etcd has not done enough work yet" have + # different fixes — the first is a missing endpoint, the second is a guest + # that just booted — so they must not read the same. Collapsing both to one + # word is the mistake readyz:[none] made. + if [ -z "${metrics}" ]; then + echo nometrics + return + fi + # A minimum sample count, not just a non-zero one. A mean over the handful + # of fsyncs a just-started etcd has done is a number with no meaning, and + # reporting it invites the same mistake as judging a throughput floor on a + # 297-byte object. + fsync=$(printf '%s\n' "${metrics}" | awk -v min="${FSYNC_MIN_COUNT:-100}" ' + /^etcd_disk_wal_fsync_duration_seconds_sum/ {sum=$2} + /^etcd_disk_wal_fsync_duration_seconds_count/ {count=$2} + END {if (count >= min) printf "%.1f", (sum / count) * 1000}') + [ -n "${fsync}" ] || fsync=warmup + echo "${fsync}" } publish_report() { @@ -100,12 +150,27 @@ publish_report() { echo "=== end mulga-eks CP diag ===" } > "${CONSOLE:-/dev/console}" 2>&1 || true fi + # fsync goes out on every report, healthy or not. A figure that only appears + # once the control plane is already failing has no baseline to be read + # against, which is the same gap a passing cell that uploads no journal + # leaves. Emitted as a bare JSON number, or omitted entirely when unknown so + # a missing sample is never mistaken for a fast one. + fsync_field= + fsync_ms=$(etcd_fsync_ms) + # Tested for being a number rather than against the sentinel words: this + # emits a bare JSON value, so anything non-numeric reaching it produces a + # payload the daemon cannot parse at all. A new sentinel must not be able + # to break the report by being added. + case "${fsync_ms}" in + '' | *[!0-9.]*) : ;; + *) fsync_field=$(printf '"fsync_ms":%s,' "${fsync_ms}") ;; + esac if [ -n "${reason}" ]; then - payload=$(printf '{"healthz":"%s","node_count":%s,"nodegroup_ready":%s,"reason":"%s","ts":%s}' \ - "${health}" "${node_count}" "${nodegroup_ready}" "${reason}" "$(date +%s)") + payload=$(printf '{"healthz":"%s","node_count":%s,"nodegroup_ready":%s,%s"reason":"%s","ts":%s}' \ + "${health}" "${node_count}" "${nodegroup_ready}" "${fsync_field}" "${reason}" "$(date +%s)") else - payload=$(printf '{"healthz":"%s","node_count":%s,"nodegroup_ready":%s,"ts":%s}' \ - "${health}" "${node_count}" "${nodegroup_ready}" "$(date +%s)") + payload=$(printf '{"healthz":"%s","node_count":%s,"nodegroup_ready":%s,%s"ts":%s}' \ + "${health}" "${node_count}" "${nodegroup_ready}" "${fsync_field}" "$(date +%s)") fi printf '%s' "${payload}" | eks-gateway-publish -channel state 2>&1 \ | logger -t mulga-eks-state-report diff --git a/scripts/images/eks-node/mulga-eks-state-report_test.sh b/scripts/images/eks-node/mulga-eks-state-report_test.sh index 15a9411d3..c77f3e88b 100644 --- a/scripts/images/eks-node/mulga-eks-state-report_test.sh +++ b/scripts/images/eks-node/mulga-eks-state-report_test.sh @@ -49,6 +49,15 @@ cat > "${STUBBIN}/logger" <<'EOF' : EOF +# curl stub: serves the etcd /metrics scrape. Empty ETCD_METRICS_BODY exits +# non-zero like a real -fsS against a port nothing is listening on, which is the +# case the fsync field has to survive. +cat > "${STUBBIN}/curl" <<'EOF' +#!/bin/sh +[ -n "${ETCD_METRICS_BODY:-}" ] || exit 7 +printf '%s\n' "${ETCD_METRICS_BODY}" +EOF + chmod +x "${STUBBIN}"/* PATH="${STUBBIN}:${PATH}" export PATH @@ -61,6 +70,14 @@ EKS_ACCOUNT_ID=000000000001 EKS_CLUSTER_NAME=demo3 EOF +# Pressure fixtures: the agent reads these instead of /proc so the load and +# memavail fields are deterministic here. +LOADAVG_FILE="${WORK}/loadavg" +MEMINFO_FILE="${WORK}/meminfo" +echo "7.25 6.10 5.00 3/512 9001" > "${LOADAVG_FILE}" +printf 'MemTotal: 4193768 kB\nMemAvailable: 262144 kB\n' > "${MEMINFO_FILE}" +export LOADAVG_FILE MEMINFO_FILE + FAILS=0 fail() { echo "FAIL: $*"; FAILS=$((FAILS + 1)); } pass() { echo "ok: $*"; } @@ -105,7 +122,7 @@ run_agent P=$(cat "${WORK}/payload.json") case "${P}" in *'"healthz":"fail"'*) pass "unhealthy: healthz fail" ;; *) fail "unhealthy: healthz wrong: ${P}" ;; esac case "${P}" in *'"nodegroup_ready":{}'*) pass "unhealthy: nodegroup_ready empty (no kubectl node query on a failing apiserver)" ;; *) fail "unhealthy: nodegroup_ready wrong: ${P}" ;; esac -case "${P}" in *'"reason":"readyz:[etcd poststarthook/start-service-ip-repair-controllers]; etcd:unreachable; disk:ok"'*) pass "unhealthy: reason names failing subchecks + etcd + disk" ;; *) fail "unhealthy: reason wrong: ${P}" ;; esac +case "${P}" in *'"reason":"readyz:[etcd poststarthook/start-service-ip-repair-controllers]; etcd:unreachable; disk:ok; fsync:nometricsms; load:7.25; memavail:262144k"'*) pass "unhealthy: reason names failing subchecks + etcd + disk + fsync + pressure" ;; *) fail "unhealthy: reason wrong: ${P}" ;; esac case "${P}" in *'"reason":"'*'"'*'"'*) : ;; esac C=$(cat "${WORK}/console.out") case "${C}" in *'mulga-eks CP unhealthy'*) pass "unhealthy: console banner emitted" ;; *) fail "unhealthy: console banner missing: ${C}" ;; esac @@ -121,6 +138,96 @@ run_agent P=$(cat "${WORK}/payload.json") case "${P}" in *'etcd:ok; disk:low:1024k'*) pass "disk-low: reason flags low etcd disk" ;; *) fail "disk-low: reason wrong: ${P}" ;; esac +# --- Case 4: readyz itself never answers -> unreachable, not "none" --- +# A wedged apiserver returns an empty body; reporting that as "none" reads as +# "no subcheck failed", which is the opposite of what happened. +HEALTHZ_BODY=fail +READYZ_BODY= +ETCD_BODY=error +DF_AVAIL_KB=9000000 +export HEALTHZ_BODY READYZ_BODY ETCD_BODY DF_AVAIL_KB +run_agent +P=$(cat "${WORK}/payload.json") +case "${P}" in *'readyz:[unreachable]'*) pass "wedged: empty readyz reads unreachable, not none" ;; *) fail "wedged: reason wrong: ${P}" ;; esac +case "${P}" in *'load:7.25; memavail:262144k'*) pass "wedged: pressure captured alongside" ;; *) fail "wedged: pressure missing: ${P}" ;; esac + +# --- Case 5: etcd serves its metrics -> fsync mean reported in ms --- +# The case the field exists for: memory and free space both fine, so a slow +# fsync is the only remaining reading. 4.2s over 700 fsyncs is 6.0ms. +HEALTHZ_BODY=fail +READYZ_BODY= +ETCD_BODY=error +DF_AVAIL_KB=9000000 +ETCD_METRICS_BODY=$(printf 'etcd_disk_wal_fsync_duration_seconds_sum 4.2\netcd_disk_wal_fsync_duration_seconds_count 700\n') +export HEALTHZ_BODY READYZ_BODY ETCD_BODY DF_AVAIL_KB ETCD_METRICS_BODY +run_agent +P=$(cat "${WORK}/payload.json") +case "${P}" in *'fsync:6.0ms'*) pass "fsync: mean derived from histogram sum/count" ;; *) fail "fsync: wrong: ${P}" ;; esac + +# --- Case 6: a stalled disk is legible against the healthy case above --- +# 63s over 700 fsyncs is 90ms — fifteen times case 5 on the same shape of input. +ETCD_METRICS_BODY=$(printf 'etcd_disk_wal_fsync_duration_seconds_sum 63\netcd_disk_wal_fsync_duration_seconds_count 700\n') +export ETCD_METRICS_BODY +run_agent +P=$(cat "${WORK}/payload.json") +case "${P}" in *'fsync:90.0ms'*) pass "fsync: a stalled disk reads far above a healthy one" ;; *) fail "fsync: stall wrong: ${P}" ;; esac + +# --- Case 7: no fsyncs recorded yet -> unknown, never a divide by zero --- +ETCD_METRICS_BODY=$(printf 'etcd_disk_wal_fsync_duration_seconds_sum 0\netcd_disk_wal_fsync_duration_seconds_count 0\n') +export ETCD_METRICS_BODY +run_agent +P=$(cat "${WORK}/payload.json") +case "${P}" in *'fsync:warmupms'*) pass "fsync: zero count reads warmup, not a division error" ;; *) fail "fsync: zero-count wrong: ${P}" ;; esac + +# --- Case 8: too few fsyncs to mean anything -> unknown, not a fast reading --- +# 3 fsyncs on a just-started etcd averages to a number with no meaning. Same +# mistake as judging a throughput floor on a 297-byte object. +ETCD_METRICS_BODY=$(printf 'etcd_disk_wal_fsync_duration_seconds_sum 0.012\netcd_disk_wal_fsync_duration_seconds_count 3\n') +export ETCD_METRICS_BODY +run_agent +P=$(cat "${WORK}/payload.json") +case "${P}" in *'fsync:warmupms'*) pass "fsync: a sample below the minimum count reads warmup" ;; *) fail "fsync: min-count wrong: ${P}" ;; esac + +# --- Case 9: fsync is published on a HEALTHY report, not only a failing one --- +# A figure that appears only once the CP is already failing has no baseline to +# be read against. +HEALTHZ_BODY=ok +NODES_BODY=$(printf 'ip-1 Ready 1d v1.32.5\n') +NODES_LABELED_BODY=$(printf 'ip-1 Ready 1d v1.32.5 ng-a\n') +ETCD_METRICS_BODY=$(printf 'etcd_disk_wal_fsync_duration_seconds_sum 4.2\netcd_disk_wal_fsync_duration_seconds_count 700\n') +export HEALTHZ_BODY NODES_BODY NODES_LABELED_BODY ETCD_METRICS_BODY +run_agent +P=$(cat "${WORK}/payload.json") +case "${P}" in *'"healthz":"ok"'*) pass "healthy-fsync: report is healthy" ;; *) fail "healthy-fsync: not healthy: ${P}" ;; esac +case "${P}" in *'"fsync_ms":6.0'*) pass "healthy-fsync: fsync published on a healthy report" ;; *) fail "healthy-fsync: fsync missing: ${P}" ;; esac +case "${P}" in *'"reason"'*) fail "healthy-fsync: healthy report must carry no reason: ${P}" ;; *) pass "healthy-fsync: no reason on a healthy report" ;; esac + +# --- Case 10: an unknown fsync is omitted, never emitted as a fast number --- +ETCD_METRICS_BODY= +export ETCD_METRICS_BODY +run_agent +P=$(cat "${WORK}/payload.json") +case "${P}" in *'"fsync_ms"'*) fail "omitted: unknown fsync must not appear in the payload: ${P}" ;; *) pass "omitted: unknown fsync is absent, not reported as fast" ;; esac +# The payload must still be valid JSON with the field gone. +case "${P}" in *'"nodegroup_ready":{"ng-a":1},"ts":'*) pass "omitted: payload stays well-formed without the field" ;; *) fail "omitted: payload malformed: ${P}" ;; esac + +# --- Case 11: no metrics endpoint reads differently from a warming etcd --- +# Both leave the payload field out, but they have different fixes — a missing +# endpoint against a guest that only just booted — so the reason must separate +# them. This is the readyz:[none] mistake, not repeated. +HEALTHZ_BODY=fail +READYZ_BODY= +ETCD_BODY=error +ETCD_METRICS_BODY= +export HEALTHZ_BODY READYZ_BODY ETCD_BODY ETCD_METRICS_BODY +run_agent +P=$(cat "${WORK}/payload.json") +case "${P}" in *'fsync:nometricsms'*) pass "nometrics: an unreachable scrape is distinct from a warming etcd" ;; *) fail "nometrics: wrong: ${P}" ;; esac + +# A sentinel must never reach the payload as a bare JSON value. The guard is +# numeric, so a new sentinel cannot silently produce unparseable output. +case "${P}" in *'"fsync_ms":nometrics'*) fail "nometrics: sentinel leaked into the payload as a number: ${P}" ;; *) pass "nometrics: sentinel kept out of the JSON value" ;; esac + if [ "${FAILS}" -eq 0 ]; then echo "PASS: all mulga-eks-state-report cases" exit 0 diff --git a/spinifex/handlers/eks/cluster_reconciler.go b/spinifex/handlers/eks/cluster_reconciler.go index 51bb0695c..110d2c8d8 100644 --- a/spinifex/handlers/eks/cluster_reconciler.go +++ b/spinifex/handlers/eks/cluster_reconciler.go @@ -534,6 +534,7 @@ func (r *ClusterReconciler) terminalErr() error { // report would be the old tick again under another name. func (r *ClusterReconciler) storeReport(report *ServerStateReport) { prev := r.latest.Swap(report) + r.logFsyncTransition(prev, report) if prev != nil && sameHealth(prev, report) { return } @@ -543,6 +544,35 @@ func (r *ClusterReconciler) storeReport(report *ServerStateReport) { } } +// logFsyncTransition reports the control plane's datastore crossing the slow +// threshold, and recovering from it. Deliberately NOT part of observe(): a slow +// fsync is a reason the apiserver may be about to struggle, not evidence it has, +// and gating cluster health on it would fail working clusters on a slow disk. +// +// Latched on the transition rather than logged per report, because the control +// plane publishes on its own timer and a line every interval is how a real +// signal gets tuned out. +func (r *ClusterReconciler) logFsyncTransition(prev, report *ServerStateReport) { + // The baseline line. A healthy cluster logs no health lines at all, so + // without this the figure reaches the daemon on every report and is never + // seen — and a slow reading on some later run has nothing to be compared + // against. Fires once, when etcd has finally done enough work to average. + if report.FsyncMs != nil && (prev == nil || prev.FsyncMs == nil) { + slog.Info("ClusterReconciler: etcd fsync baseline", + "cluster", r.clusterName, "fsync_ms", *report.FsyncMs, "threshold_ms", slowFsyncMs) + } + if report.SlowFsync() && (prev == nil || !prev.SlowFsync()) { + slog.Warn("ClusterReconciler: etcd fsync is slow on the control plane", + "cluster", r.clusterName, "fsync_ms", *report.FsyncMs, "threshold_ms", slowFsyncMs, + "healthz", report.Healthz) + return + } + if prev != nil && prev.SlowFsync() && !report.SlowFsync() && report.FsyncMs != nil { + slog.Info("ClusterReconciler: etcd fsync recovered on the control plane", + "cluster", r.clusterName, "fsync_ms", *report.FsyncMs, "threshold_ms", slowFsyncMs) + } +} + // sameHealth reports whether two reports would produce the same observe result. // Freshness is deliberately excluded: a report that only repeats itself pushes // the staleness deadline out, which the next pass reads for itself. diff --git a/spinifex/handlers/eks/state_report.go b/spinifex/handlers/eks/state_report.go index 7abc820e6..78aad9d46 100644 --- a/spinifex/handlers/eks/state_report.go +++ b/spinifex/handlers/eks/state_report.go @@ -32,6 +32,25 @@ type ServerStateReport struct { // be gated on its OWN workers rather than the cluster-wide total. Nil from an // older AMI that predates per-nodegroup reporting. NodegroupReady map[string]int `json:"nodegroup_ready,omitempty"` + // FsyncMs is the guest's mean etcd WAL fsync in milliseconds, reported on + // every state report rather than only unhealthy ones so a stalled control + // plane has a healthy baseline to be read against. Nil when the guest had + // too few fsyncs to average, when etcd served no metrics, or from an older + // AMI that predates the field — none of which is the same as "fast". + FsyncMs *float64 `json:"fsync_ms,omitempty"` +} + +// slowFsyncMs is the mean WAL fsync above which the control plane's disk is +// reported as the suspect regardless of whether the apiserver still answers. +// etcd's own guidance puts a healthy p99 in single-digit milliseconds; a *mean* +// this high means the datastore is being served slowly enough that an apiserver +// timeout is a consequence rather than a cause. +const slowFsyncMs = 25.0 + +// SlowFsync reports whether the guest's mean etcd fsync is high enough to +// explain control-plane trouble on its own. False when no sample was taken. +func (s ServerStateReport) SlowFsync() bool { + return s.FsyncMs != nil && *s.FsyncMs >= slowFsyncMs } // Healthy reports whether the apiserver was serving at publish time. diff --git a/spinifex/handlers/eks/state_report_fsync_test.go b/spinifex/handlers/eks/state_report_fsync_test.go new file mode 100644 index 000000000..85d412ab4 --- /dev/null +++ b/spinifex/handlers/eks/state_report_fsync_test.go @@ -0,0 +1,103 @@ +// newStateReconcilerHarness, storeReport, latest, observe and the slowFsyncMs +// threshold. Exporting any of them would widen the package API for tests alone. +// +//test:in-package — asserts on the reconciler's unexported plumbing: +package handlers_eks + +import ( + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +func fsyncReport(healthz string, fsyncMs *float64) *ServerStateReport { + return &ServerStateReport{Healthz: healthz, NodeCount: 1, TS: time.Now().Unix(), FsyncMs: fsyncMs} +} + +func ptrFloat(v float64) *float64 { return &v } + +// A missing sample is not a fast one. An older AMI, an etcd serving no metrics +// and an etcd with too few fsyncs to average all arrive as nil, and treating any +// of them as healthy would hide exactly the case the field exists to surface. +func TestServerStateReport_SlowFsyncNeedsASample(t *testing.T) { + assert.False(t, fsyncReport("ok", nil).SlowFsync(), "no sample must not read as fast") + assert.False(t, fsyncReport("fail", nil).SlowFsync(), "no sample must not read as slow either") +} + +func TestServerStateReport_SlowFsyncThreshold(t *testing.T) { + assert.False(t, fsyncReport("ok", ptrFloat(6.0)).SlowFsync(), "single-digit ms is healthy") + assert.True(t, fsyncReport("ok", ptrFloat(slowFsyncMs)).SlowFsync(), "the threshold itself is slow") + assert.True(t, fsyncReport("ok", ptrFloat(90.0)).SlowFsync(), "a stalled disk is slow") +} + +// The whole point of reporting fsync on healthy reports: an apiserver that still +// answers while its datastore is served at 90ms is the case that was previously +// invisible until it degraded into etcd:unreachable. +func TestServerStateReport_SlowFsyncOnAHealthyApiserver(t *testing.T) { + r := fsyncReport("ok", ptrFloat(90.0)) + assert.True(t, r.Healthy(), "apiserver is still answering") + assert.True(t, r.SlowFsync(), "and its datastore is still slow") +} + +// A slow fsync must never make the cluster unhealthy. observe() gates cluster +// state, and a working cluster on a slow disk is working. +func TestClusterReconciler_SlowFsyncDoesNotFailHealth(t *testing.T) { + r, _, _ := newStateReconcilerHarness(t) + r.latest.Store(fsyncReport("ok", ptrFloat(90.0))) + + issue, nodeCount, _ := r.observe(t.Context()) + assert.Empty(t, issue, "a slow disk is a warning, not an unhealthy cluster") + assert.Equal(t, 1, nodeCount) +} + +// Latched on the transition: the control plane republishes on its own timer, and +// a warning every interval is how a real signal gets tuned out. storeReport is +// the only path that sees both the previous and the new report. +func TestClusterReconciler_LogFsyncTransitionIsLatched(t *testing.T) { + r, _, _ := newStateReconcilerHarness(t) + + // Crossing into slow, then staying slow, then recovering. Asserted through + // storeReport rather than the log sink: what matters is that repeated slow + // reports are distinguishable from the first, and that recovery is seen. + slow := fsyncReport("ok", ptrFloat(90.0)) + stillSlow := fsyncReport("ok", ptrFloat(95.0)) + recovered := fsyncReport("ok", ptrFloat(5.0)) + + r.storeReport(slow) + assert.True(t, r.latest.Load().SlowFsync(), "first slow report is stored") + + r.storeReport(stillSlow) + assert.True(t, r.latest.Load().SlowFsync(), "a repeat is still slow") + + r.storeReport(recovered) + assert.False(t, r.latest.Load().SlowFsync(), "recovery clears it") +} + +// The baseline case. A healthy cluster logs no health lines at all, so the very +// first usable sample is the only chance to record what normal looks like — a +// green cell-25 previously left nothing to compare a later slow run against. +func TestClusterReconciler_FirstKnownSampleIsTheBaseline(t *testing.T) { + r, _, _ := newStateReconcilerHarness(t) + + // A guest whose etcd has not warmed up yet reports no sample at all. + r.storeReport(fsyncReport("ok", nil)) + assert.Nil(t, r.latest.Load().FsyncMs, "warming etcd carries no sample") + + // Then the first real one arrives, healthy and well under the threshold. + r.storeReport(fsyncReport("ok", ptrFloat(6.0))) + got := r.latest.Load() + assert.NotNil(t, got.FsyncMs, "the baseline sample is recorded") + assert.False(t, got.SlowFsync(), "and it is a healthy one") +} + +// A report with no sample must not be read as a recovery from a slow one, or a +// guest that stopped serving metrics would look like a disk that got faster. +func TestClusterReconciler_MissingSampleIsNotRecovery(t *testing.T) { + r, _, _ := newStateReconcilerHarness(t) + r.storeReport(fsyncReport("ok", ptrFloat(90.0))) + r.storeReport(fsyncReport("ok", nil)) + + assert.Nil(t, r.latest.Load().FsyncMs, "the sample is genuinely absent") + assert.False(t, r.latest.Load().SlowFsync(), "and absent is not slow") +} diff --git a/tests/e2e/diskperf/baseline.go b/tests/e2e/diskperf/baseline.go index bceeb6ec3..12a421654 100644 --- a/tests/e2e/diskperf/baseline.go +++ b/tests/e2e/diskperf/baseline.go @@ -43,6 +43,7 @@ type BaselineJob struct { WriteIOPS float64 `json:"write_iops"` ReadP999Ms float64 `json:"read_p99_9_ms"` WriteP999Ms float64 `json:"write_p99_9_ms"` + SyncP999Ms float64 `json:"fdatasync_p99_9_ms"` } func loadBaseline() (Baseline, error) { @@ -126,5 +127,8 @@ func metricsFor(job jobSpec, agg fioJob, base BaselineJob) []metric { metric{Name: "read_p99_9_ms", Got: agg.Read.p999Ms(), Want: base.ReadP999Ms}, ) } + if agg.Sync.TotalIOs > 0 { + ms = append(ms, metric{Name: "fdatasync_p99_9_ms", Got: agg.Sync.p999Ms(), Want: base.SyncP999Ms}) + } return ms } diff --git a/tests/e2e/diskperf/baseline.json b/tests/e2e/diskperf/baseline.json index 9e2f1daf4..ad1ad87f4 100644 --- a/tests/e2e/diskperf/baseline.json +++ b/tests/e2e/diskperf/baseline.json @@ -1,6 +1,6 @@ { "version": 1, - "origin": "bm-node1 (bare-metal cell 28, Debian 13, QEMU 10.0.11), spinifex v1.18.0-143-g0ec25417, viperblock v1.18.0-9-gab74c30, predastore v1.18.0-48-g62cbc5a, captured 2026-09-03 as the median of 3 repetitions. randwrite-4k has no read stream, so its read figures stay zero and remain ungated.", + "origin": "bm-node1 (bare-metal cell 28, Debian 13, QEMU 10.0.11), spinifex v1.18.0-143-g0ec25417, viperblock v1.18.0-9-gab74c30, predastore v1.18.0-48-g62cbc5a, captured 2026-09-03 as the median of 3 repetitions. randwrite-4k has no read stream, so its read figures stay zero and remain ungated. syncwrite-4k has never been captured: its figures are zero so the job records without gating until a run on this hardware supplies them.", "jobs": { "randwrite-4k": { "read_iops": 0, @@ -13,6 +13,13 @@ "write_iops": 25391.9, "read_p99_9_ms": 7.6, "write_p99_9_ms": 7.7 + }, + "syncwrite-4k": { + "read_iops": 0, + "write_iops": 0, + "read_p99_9_ms": 0, + "write_p99_9_ms": 0, + "fdatasync_p99_9_ms": 0 } } } diff --git a/tests/e2e/diskperf/diskperf_test.go b/tests/e2e/diskperf/diskperf_test.go index 1fa273296..e65923360 100644 --- a/tests/e2e/diskperf/diskperf_test.go +++ b/tests/e2e/diskperf/diskperf_test.go @@ -85,8 +85,7 @@ func runJob(t *testing.T, fix *Fixture, job jobSpec, base BaselineJob, instanceI var results []runResult var probes []probeReport for rep := 1; rep <= reps; rep++ { - harness.Step(t, "rep %d/%d: %d jobs x %d GiB %s %s at qd%d on a fresh %d GiB volume", - rep, reps, job.NumJobs, job.SizeGiB, job.BlockSize, job.RW, job.IODepth, sizeGiB) + harness.Step(t, "rep %d/%d: %s on a fresh %d GiB volume", rep, reps, job.shape(), sizeGiB) volID := createVolume(t, fix, az, sizeGiB) before := harness.GuestDiskSet(t, tgt) @@ -206,6 +205,10 @@ func aggregate(t *testing.T, job jobSpec, base BaselineJob, results []runResult, "write_p99_9": agg.Write.p999Ms(), "read_max_ms": agg.Read.maxMs(), "write_max_ms": agg.Write.maxMs(), + // Zero for the throughput profiles, which issue no fdatasync. + "fdatasync_ios": agg.Sync.TotalIOs, + "fdatasync_p99_9": agg.Sync.p999Ms(), + "fdatasync_max_ms": agg.Sync.maxMs(), // The availability evidence belongs in the same record as the numbers. // A throughput figure taken from a run that left the host unreachable // is not a throughput figure worth keeping. @@ -252,12 +255,15 @@ func medianAggregate(results []runResult) fioJob { out.Write.Clat.Percentile = map[string]int64{p999Key: int64(pick(func(j fioJob) float64 { return float64(j.Write.Clat.Percentile[p999Key]) }))} out.Read.Clat.Max = int64(pick(func(j fioJob) float64 { return float64(j.Read.Clat.Max) })) out.Write.Clat.Max = int64(pick(func(j fioJob) float64 { return float64(j.Write.Clat.Max) })) + out.Sync.Lat.Percentile = map[string]int64{p999Key: int64(pick(func(j fioJob) float64 { return float64(j.Sync.Lat.Percentile[p999Key]) }))} + out.Sync.Lat.Max = int64(pick(func(j fioJob) float64 { return float64(j.Sync.Lat.Max) })) // Carry the byte counts so metricsFor can still tell which streams the job // actually exercised. for _, r := range results { out.Read.IOBytes += r.Aggregate.Read.IOBytes out.Write.IOBytes += r.Aggregate.Write.IOBytes + out.Sync.TotalIOs += r.Aggregate.Sync.TotalIOs } return out } diff --git a/tests/e2e/diskperf/fio.go b/tests/e2e/diskperf/fio.go index b8e4d1686..f715106de 100644 --- a/tests/e2e/diskperf/fio.go +++ b/tests/e2e/diskperf/fio.go @@ -41,9 +41,17 @@ type jobSpec struct { // SizeGiB is per job. NumJobs jobs each take their own SizeGiB slice of the // device via offset_increment, so the working set is NumJobs*SizeGiB. SizeGiB int + // SizeMiB overrides SizeGiB when non-zero, for jobs whose per-op cost makes + // a GiB-scale working set take hours rather than minutes. + SizeMiB int NumJobs int IODepth int + // Fdatasync, when non-zero, issues fdatasync every N writes and switches the + // job to buffered psync. Durability latency is only meaningful through the + // page cache: direct=1 and libaio measure the wrong thing. + Fdatasync int + // Budget bounds the guest-side invocation. Exceeding it is an availability // failure, not a slow result: the workload did not complete. Budget time.Duration @@ -77,11 +85,43 @@ var gateJobs = []jobSpec{ IODepth: 32, Budget: 45 * time.Minute, }, + // Durability latency, not throughput. etcd commits every raft entry with an + // fdatasync at queue depth 1 and stalls on that latency long before it runs + // short of bandwidth, which the two profiles above cannot see. + { + Name: "syncwrite-4k", + RW: "write", + BlockSize: "4k", + SizeMiB: 64, + NumJobs: 1, + IODepth: 1, + Fdatasync: 1, + Budget: 20 * time.Minute, + }, } // workingSetGiB is the span of the device the job touches, and so the minimum -// volume size it needs. -func (j jobSpec) workingSetGiB() int { return j.SizeGiB * j.NumJobs } +// volume size it needs. A sub-GiB job rounds to zero: the volume headroom the +// caller adds already covers it. +func (j jobSpec) workingSetGiB() int { + if j.SizeMiB > 0 { + return j.SizeMiB * j.NumJobs / 1024 + } + return j.SizeGiB * j.NumJobs +} + +// size renders the per-job size as an fio --size value. +func (j jobSpec) size() string { + if j.SizeMiB > 0 { + return fmt.Sprintf("%dM", j.SizeMiB) + } + return fmt.Sprintf("%dG", j.SizeGiB) +} + +// shape describes the job for a progress line, since the size unit varies. +func (j jobSpec) shape() string { + return fmt.Sprintf("%d jobs x %s %s %s at qd%d", j.NumJobs, j.size(), j.BlockSize, j.RW, j.IODepth) +} // command renders the fio invocation. The target is a raw device with // direct=1, so the guest page cache and any filesystem are out of the path; @@ -94,16 +134,25 @@ func (j jobSpec) command(dev, outPath string) string { "--filename=/dev/" + dev, "--rw=" + j.RW, "--bs=" + j.BlockSize, - fmt.Sprintf("--size=%dG", j.SizeGiB), - fmt.Sprintf("--offset_increment=%dG", j.SizeGiB), + "--size=" + j.size(), + fmt.Sprintf("--offset_increment=%s", j.size()), fmt.Sprintf("--numjobs=%d", j.NumJobs), fmt.Sprintf("--iodepth=%d", j.IODepth), - "--ioengine=libaio", - "--direct=1", "--group_reporting", "--output-format=json", "--output=" + outPath, } + if j.Fdatasync > 0 { + // lat_percentiles is what makes fio emit the sync-latency distribution; + // without it the run reports a mean and the tail is lost, and the tail + // is what a consensus datastore actually stalls on. + args = append(args, + fmt.Sprintf("--fdatasync=%d", j.Fdatasync), + "--ioengine=psync", + "--lat_percentiles=1") + } else { + args = append(args, "--ioengine=libaio", "--direct=1") + } if j.RW == "randrw" { args = append(args, fmt.Sprintf("--rwmixread=%d", j.MixRead)) } @@ -120,8 +169,27 @@ type fioJob struct { Name string `json:"jobname"` Read fioStream `json:"read"` Write fioStream `json:"write"` + // Sync is the fdatasync distribution, which fio reports separately from the + // write stream: write clat is the time to reach the page cache, and the + // sync is what makes it durable. For a fdatasync job this is the result. + Sync fioSync `json:"sync"` } +// fioSync is fio's sync section. It reports total latency (lat_ns), not the +// completion latency the queued streams report, so it carries its own field. +type fioSync struct { + TotalIOs int64 `json:"total_ios"` + Lat fioClat `json:"lat_ns"` +} + +// p999Ms returns the p99.9 fdatasync latency in milliseconds. +func (s fioSync) p999Ms() float64 { + return float64(s.Lat.Percentile[p999Key]) / 1e6 +} + +// maxMs returns the worst fdatasync latency in milliseconds. +func (s fioSync) maxMs() float64 { return float64(s.Lat.Max) / 1e6 } + type fioStream struct { IOBytes int64 `json:"io_bytes"` BWBytes int64 `json:"bw_bytes"` diff --git a/tests/e2e/diskperf/fio_test.go b/tests/e2e/diskperf/fio_test.go index 1e3404ece..49602b38d 100644 --- a/tests/e2e/diskperf/fio_test.go +++ b/tests/e2e/diskperf/fio_test.go @@ -109,17 +109,106 @@ func TestMedianDoesNotMutateInput(t *testing.T) { func TestJobCommandCoversTheWholeWorkingSet(t *testing.T) { for _, j := range gateJobs { cmd := j.command("vdc", "/tmp/out.json") - for _, want := range []string{"--direct=1", "--filename=/dev/vdc", "--offset_increment=", "--output-format=json"} { + for _, want := range []string{"--filename=/dev/vdc", "--offset_increment=", "--output-format=json"} { if !strings.Contains(cmd, want) { t.Errorf("job %q command is missing %q:\n%s", j.Name, want, cmd) } } + if j.SizeMiB > 0 { + continue + } + if !strings.Contains(cmd, "--direct=1") { + t.Errorf("job %q is a throughput profile and must bypass the page cache:\n%s", j.Name, cmd) + } if j.workingSetGiB() != j.SizeGiB*j.NumJobs { t.Errorf("job %q working set %d does not match %d jobs x %d GiB", j.Name, j.workingSetGiB(), j.NumJobs, j.SizeGiB) } } } +// A durability job measures the wrong thing under direct=1 or libaio: the point +// is the cost of making a buffered write durable, which is what etcd pays per +// raft entry. Guards the combination rather than the flag. +func TestFdatasyncJobIsBufferedAndSynchronous(t *testing.T) { + var found int + for _, j := range gateJobs { + if j.Fdatasync == 0 { + cmd := j.command("vdc", "/tmp/out.json") + if strings.Contains(cmd, "--fdatasync=") { + t.Errorf("job %q carries fdatasync without asking for it:\n%s", j.Name, cmd) + } + continue + } + found++ + cmd := j.command("vdc", "/tmp/out.json") + for _, want := range []string{"--fdatasync=1", "--ioengine=psync", "--lat_percentiles=1"} { + if !strings.Contains(cmd, want) { + t.Errorf("job %q is missing %q:\n%s", j.Name, want, cmd) + } + } + if strings.Contains(cmd, "--direct=1") { + t.Errorf("job %q uses direct=1, which bypasses the cache the fdatasync exists to flush:\n%s", j.Name, cmd) + } + if j.IODepth != 1 { + t.Errorf("job %q runs at qd%d: a queue hides the per-commit latency being measured", j.Name, j.IODepth) + } + } + if found == 0 { + t.Error("no fdatasync job in the profile set — durability latency is unmeasured") + } +} + +// The sync distribution is reported apart from the write stream, so a job that +// parses only write clat records the time to reach the page cache and calls it +// durability. +func TestParseFioReadsTheSyncStream(t *testing.T) { + const withSync = `{"fio version":"fio-3.36","jobs":[{"jobname":"syncwrite-4k", + "write":{"io_bytes":67108864,"bw_bytes":1000,"iops":250,"clat_ns":{"max":900,"mean":400,"percentile":{"99.900000":800}}}, + "sync":{"total_ios":16384,"lat_ns":{"max":41000000,"mean":5100000,"percentile":{"99.900000":38000000}}}}]}` + + res, err := parseFio("syncwrite-4k", withSync) + if err != nil { + t.Fatalf("parseFio: %v", err) + } + if got := res.Aggregate.Sync.TotalIOs; got != 16384 { + t.Errorf("sync total_ios = %d, want 16384", got) + } + if got := res.Aggregate.Sync.p999Ms(); got != 38 { + t.Errorf("sync p99.9 = %.1fms, want 38.0", got) + } + if got := res.Aggregate.Sync.maxMs(); got != 41 { + t.Errorf("sync max = %.1fms, want 41.0", got) + } +} + +// An fdatasync result must be gated on the sync distribution. Judging it on +// write IOPS would pass a disk that buffers everything and commits slowly, +// which is the exact disk etcd cannot run on. +func TestMetricsForGatesTheSyncDistribution(t *testing.T) { + agg := fioJob{ + Name: "syncwrite-4k", + Write: fioStream{IOBytes: 67108864, IOPS: 250}, + Sync: fioSync{TotalIOs: 16384, Lat: fioClat{Percentile: map[string]int64{p999Key: 38000000}}}, + } + ms := metricsFor(jobSpec{Name: "syncwrite-4k", Fdatasync: 1}, agg, BaselineJob{SyncP999Ms: 10}) + + var got *metric + for i := range ms { + if ms[i].Name == "fdatasync_p99_9_ms" { + got = &ms[i] + } + } + if got == nil { + t.Fatalf("no fdatasync metric produced from a job with %d syncs", agg.Sync.TotalIOs) + } + if got.HigherIsBetter { + t.Error("fdatasync latency was scored as higher-is-better") + } + if v, _ := got.judge(); v != verdictFail { + t.Errorf("38ms against a 10ms baseline judged %v, want fail", v) + } +} + // randrw needs a mix and the single-direction profiles must not carry one, // since fio ignores rwmixread outside randrw and its presence would suggest a // mix that is not being run.