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.