fix: make the EKS control plane's disk latency observable, and give it room to run (#1009)

* 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>
This commit is contained in:
Josh Siviour
2026-09-07 21:53:41 +10:00
committed by GitHub
parent a1a46c6402
commit 8e11908dfb
17 changed files with 792 additions and 28 deletions
+31 -6
View File
@@ -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
+36
View File
@@ -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
+6
View File
@@ -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
@@ -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.<service.name>-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]
@@ -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
@@ -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
@@ -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"
@@ -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
@@ -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 <none> 1d v1.32.5\n')
NODES_LABELED_BODY=$(printf 'ip-1 Ready <none> 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
@@ -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.
+19
View File
@@ -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.
@@ -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")
}
+4
View File
@@ -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
}
+8 -1
View File
@@ -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
}
}
}
+8 -2
View File
@@ -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
}
+74 -6
View File
@@ -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"`
+90 -1
View File
@@ -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.