wait_event_timing — independent benchmark & testing (Hacking Postgres 2026-06-17)

[NikolayS]

wait_event_timing — independent benchmark & testing (tracking issue)

Tracking issue for the independent benchmarking / testing of the wait_event_timing patch series (Dmitry Fomin's PR: DmitryNFomin#2), started during a Hacking Postgres session on 2026-06-17 (Kirk Wolak, Dmitry Fomin, Nik). An AI agent ("Leo", via samograph) joined the call and drove the setup live.

Design brief (living doc, GitHub Pages): https://nikolays.github.io/wet-timing-bench-brief/

---

Feature under test

wait_event_timing — Oracle-style wait-event instrumentation. Compile-time gate --enable-wait-event-timing (meson -Dwait_event_timing=true); runtime GUC wait_event_capture = off | stats | trace.

• stats — per-(backend, event) count / total / max + 32-bucket log2 histogram (eager shmem; lazily DSA in later patch).
• trace — per-session DSA ring of individual waits (wait_event_trace_ring_size = 4 MB/backend, power-of-two, fixed at start) + query-attribution markers.
• Sizing GUCs: wait_event_trace_ring_size=4096kB, wait_event_timing_max_tranches=192.

Hardware / build

• Box: Hetzner CCX43 — 16 dedicated vCPU (AMD EPYC-Milan), 64 GB RAM, Ubuntu 24.04, Falkenstein. (ephemeral benchmark host, SSH-key-only, to be destroyed after.)
• Build: branch wet-series (PR Add comprehensive wait events coverage gap analysis #2 head, commit 983f0ec), base = upstream master 89eafad297a. ./configure --prefix=/opt/pg-wet --enable-wait-event-timing CC="ccache gcc" CFLAGS="-O2" (in-tree, gcc -O2). Baseline = wet-series-base (no flag).

Validity gate (the trap we hit & fixed)

A build configured without the flag still exposes the wait_event_capture GUC but silently downgrades stats/trace to off → off/stats/trace all equal baseline → a false ~0% overhead. Mitigation, run before every benchmark:

• start a server on the built binary, SET wait_event_capture=stats then SELECT current_setting('wait_event_capture') must return stats (and trace), and pg_stat_wait_event_timing view must exist. No gate pass ⇒ no benchmark.

Methodology (the ladder)

vanilla → patched-stub (flag off) → compiled+capture=off → stats → trace. Two cost concepts kept distinct: static overhead (constant cost of having it compiled/enabled) vs observer effect (dynamic, grows with sampling/reading frequency).

Canonical measured-run command (reused for all workloads)

pgbench -S -c 16 -j 16 -T 180 -P 15 -r -n postgres

-c=-j=16 (= cores; avoids pgbench co-location oversubscription) · -T 180 (3-min, stable) · -P 15 (progress every 15s) · -r (per-statement latency) · -n (no vacuum) · select-only. --log intentionally NOT used (it is itself an observer-effect source). 3 interleaved rounds (baseline→off→stats→trace), median.

Workloads

• W1 — read-only cached (shared_buffers=8GB, scale 100): inline-gate / CPU-bound cost.
• W2 — read-only wait-saturated (shared_buffers=256MB, scale 400): TPS + wait-event proof (top events + total transition count; confirms we actually exercise waits).
• W3 — same as W2 but -R <50% of W2 baseline TPS>: latency under headroom (regular load-test, not stress). + CPU-idle sampling to confirm headroom.
• Clusters: fsync=on, compute_query_id=on + track_activities=on (required for trace query-attribution; kept on for all variants = apples-to-apples).

Preliminary results (iteration 1, no pg_stat_statements — RUNNING)

W1 (read-only cached), early rounds, on the verified build:

variant	median TPS	Δ vs baseline
baseline	~222,900	—
off	~222,930	+0.01%
stats	~223,160	+0.12%
trace	~222,100	−0.36%

→ all within ±0.4% = statistically indistinguishable (virtualized-env noise). The discriminating numbers come from W2 (wait-saturated).

Iterations

• Round 1 (running): revised config, no pg_stat_statements — the without-pgss reference.
• Round 2 (staged, ready): + pg_stat_statements (shared_preload_libraries + CREATE EXTENSION on both clusters) to add realistic shared-hash/LWLock contention (more wait events); resets pgss before each run, cross-checks its call count (≈ TPS×180), dumps top queries alongside the wait events. Also CPU-idle headroom sampling.

Open questions / next steps

• Stub build (patched, compiled without the flag) — measures cost of the source changes when #ifdef'd out (expected ≈0). Not yet built.
• W4 (read-side observer effect): while one pgbench drives the workload, a second client polls the wait-event views at increasing frequency → measures how reading the instrumentation perturbs what it measures.
• Per-iteration results HTML pages (with Python charts) + a "what changed vs previous round" diff.
• ≥3 independent review agents post-completion (performance + correctness); re-run if anything is off.
• Store raw bench.log per round.

Artifacts

Scripts are in the collapsible sections below (live host IP redacted as <BENCH_HOST>). Raw bench.log per round will be attached as runs complete.

Scripts

run_bench.sh (Round 2 — current, with pg_stat_statements + CPU-headroom + top-queries)

#!/bin/bash
# REVISED benchmark (team spec 2026-06-17): select-only, -c16 -j16 -T180 -P15 -r -n, 3 rounds
#  W1 cached (SB=8GB, s100); W2 wait-saturated (SB=256MB, s400) + wait-event proof;
#  W3 = W2 but -R at 50% of W2 baseline median TPS (latency focus). No TPC-B.
BASELINE_BIN=/opt/pg-baseline/bin
WET_BIN=/opt/pg-wet/bin
BASELINE_DATA=/data/pg-baseline
WET_DATA=/data/pg-wet
BPORT=5440
WPORT=5441
LOG=/root/bench.log
DUR=180
mkdir -p /tmp/bench_results
exec > >(tee -a $LOG) 2>&1
log() { echo "[$(date '+%H:%M:%S')] $*"; }

stop_all() {
    su - pgbench -c "$BASELINE_BIN/pg_ctl -D $BASELINE_DATA stop -m fast 2>/dev/null; exit 0" 2>/dev/null || true
    su - pgbench -c "$WET_BIN/pg_ctl -D $WET_DATA stop -m fast 2>/dev/null; exit 0" 2>/dev/null || true
    sleep 3
}

set_conf() { # datadir key value
    python3 -c "
import re
p='$1/postgresql.conf'
c=open(p).read()
c=re.sub(r'^#?\s*$2\s*=.*', \"$2 = '$3'\", c, flags=re.M)
if '$2' not in c: c+=\"\n$2 = '$3'\n\"
open(p,'w').write(c)
"
}

start_baseline() { # sb
    stop_all
    set_conf "$BASELINE_DATA" shared_buffers "$1"
    set_conf "$BASELINE_DATA" shared_preload_libraries "pg_stat_statements"
    su - pgbench -c "$BASELINE_BIN/pg_ctl -D $BASELINE_DATA -l /tmp/baseline.log start"
    sleep 4
}
start_wet() { # sb capture
    stop_all
    set_conf "$WET_DATA" shared_buffers "$1"
    set_conf "$WET_DATA" shared_preload_libraries "pg_stat_statements"
    set_conf "$WET_DATA" wait_event_capture "$2"
    su - pgbench -c "$WET_BIN/pg_ctl -D $WET_DATA -l /tmp/wet.log start"
    sleep 4
    local actual
    actual=$(su - pgbench -c "$WET_BIN/psql -p $WPORT -tAc 'SHOW wait_event_capture;' postgres" 2>/dev/null | tr -d ' \n')
    log "    confirmed wait_event_capture=$actual"
}

# run_pgbench BIN PORT EXTRA  -> sets globals R_TPS R_LAT R_CALLS R_IDLE
run_pgbench() {
    local bin="$1" port="$2" extra="$3"
    # reset pg_stat_statements before the run (cross-check call count after)
    su - pgbench -c "$bin/psql -p $port -tAc 'SELECT pg_stat_statements_reset();' postgres" >/dev/null 2>&1
    # sample CPU during the run (vmstat 'id' = idle%); confirms saturation (W1/W2) vs headroom (W3)
    ( vmstat 30 7 >/tmp/last_vmstat.txt 2>&1 ) & local vmpid=$!
    su - pgbench -c "$bin/pgbench -p $port -S -c 16 -j 16 -T $DUR -P 15 -r -n $extra postgres 2>&1" | tee /tmp/last_pgbench.txt
    kill $vmpid 2>/dev/null
    R_TPS=$(grep -oP 'tps = \K[0-9.]+' /tmp/last_pgbench.txt | head -1)
    R_LAT=$(grep -oP 'latency average = \K[0-9.]+' /tmp/last_pgbench.txt | head -1)
    R_CALLS=$(su - pgbench -c "$bin/psql -p $port -tAc 'SELECT sum(calls) FROM pg_stat_statements;' postgres" 2>/dev/null | tr -d '[:space:]')
    R_IDLE=$(awk 'NR>2 && NF>=5 {sum+=$(NF-2); n++} END {if(n>0) printf "%.0f", sum/n}' /tmp/last_vmstat.txt 2>/dev/null)
    log "    cross-check: pgss_calls=$R_CALLS  avg_cpu_idle=${R_IDLE}%"
}

# median of 3 values (middle) ; or 2 -> avg
med3() { python3 -c "import sys; v=sorted(float(x) for x in sys.argv[1:]); print(v[len(v)//2] if len(v)%2 else (v[len(v)//2-1]+v[len(v)//2])/2)" "$@"; }

run_workload() { # NAME SB EXTRA  (EXTRA passed to pgbench, e.g. '-R 1234')  -> sets MED_BL MED_OFF MED_STA MED_TRA (TPS) and LAT_*
    local name="$1" sb="$2" extra="$3"
    local -a BL OFF STA TRA LBL LOF LST LTR
    for r in 1 2 3; do
        log "$name Round $r/3  (SB=$sb ${extra:+$extra})"
        start_baseline "$sb"; run_pgbench $BASELINE_BIN $BPORT "$extra"; BL[$r]=$R_TPS; LBL[$r]=$R_LAT; log "  BL tps=$R_TPS lat=${R_LAT}ms"
        start_wet "$sb" off;   run_pgbench $WET_BIN $WPORT "$extra";    OFF[$r]=$R_TPS; LOF[$r]=$R_LAT; log "  OFF tps=$R_TPS lat=${R_LAT}ms"
        start_wet "$sb" stats; run_pgbench $WET_BIN $WPORT "$extra";    STA[$r]=$R_TPS; LST[$r]=$R_LAT; log "  STA tps=$R_TPS lat=${R_LAT}ms"
        start_wet "$sb" trace; run_pgbench $WET_BIN $WPORT "$extra";    TRA[$r]=$R_TPS; LTR[$r]=$R_LAT; log "  TRA tps=$R_TPS lat=${R_LAT}ms"
    done
    MED_BL=$(med3 ${BL[1]} ${BL[2]} ${BL[3]}); MED_OFF=$(med3 ${OFF[1]} ${OFF[2]} ${OFF[3]})
    MED_STA=$(med3 ${STA[1]} ${STA[2]} ${STA[3]}); MED_TRA=$(med3 ${TRA[1]} ${TRA[2]} ${TRA[3]})
    LATMED_BL=$(med3 ${LBL[1]} ${LBL[2]} ${LBL[3]}); LATMED_OFF=$(med3 ${LOF[1]} ${LOF[2]} ${LOF[3]})
    LATMED_STA=$(med3 ${LST[1]} ${LST[2]} ${LST[3]}); LATMED_TRA=$(med3 ${LTR[1]} ${LTR[2]} ${LTR[3]})
    log "=== $name MEDIANS  TPS:  BL=$MED_BL OFF=$MED_OFF STA=$MED_STA TRA=$MED_TRA"
    log "=== $name MEDIANS  LAT(ms): BL=$LATMED_BL OFF=$LATMED_OFF STA=$LATMED_STA TRA=$LATMED_TRA"
    python3 -c "
bl=$MED_BL
for n,v in [('off',$MED_OFF),('stats',$MED_STA),('trace',$MED_TRA)]:
    print('  %-6s TPS %%vs baseline: %+.2f%%'%(n,(v-bl)/bl*100))
"
}

log "================ REVISED BENCHMARK START ================"
log "Spec: pgbench -S -c 16 -j 16 -T 180 -P 15 -r -n ; 3 rounds ; W1 cached / W2 wait-saturated / W3 = W2 -R 50%"

# ---- W1: cached, scale 100 ----
log "=== Init scale 100 (W1) on both clusters + CREATE EXTENSION pg_stat_statements ==="
start_baseline 8GB
su - pgbench -c "$BASELINE_BIN/psql -p $BPORT -c 'CREATE EXTENSION IF NOT EXISTS pg_stat_statements;' postgres" 2>&1 | tail -1
su - pgbench -c "$BASELINE_BIN/pgbench -p $BPORT -i -s 100 --no-vacuum postgres 2>&1 | tail -2"; stop_all
start_wet 8GB off
su - pgbench -c "$WET_BIN/psql -p $WPORT -c 'CREATE EXTENSION IF NOT EXISTS pg_stat_statements;' postgres" 2>&1 | tail -1
su - pgbench -c "$WET_BIN/pgbench -p $WPORT -i -s 100 --no-vacuum postgres 2>&1 | tail -2"; stop_all
log "=== W1: Read-only CACHED (SB=8GB, scale 100) ==="
run_workload W1 8GB ""

# ---- W2 + W3: wait-saturated, scale 400 ----
log "=== Init scale 400 (W2/W3) on both clusters ==="
start_baseline 256MB; su - pgbench -c "$BASELINE_BIN/pgbench -p $BPORT -i -s 400 --no-vacuum postgres 2>&1 | tail -2"; stop_all
start_wet 256MB off;  su - pgbench -c "$WET_BIN/pgbench -p $WPORT -i -s 400 --no-vacuum postgres 2>&1 | tail -2"; stop_all
log "=== W2: Read-only WAIT-SATURATED (SB=256MB, scale 400) ==="
run_workload W2 256MB ""
W2_BL_TPS=$MED_BL

# wait-event proof on W2 stats
log "=== W2 wait-event PROOF (stats, sampled) ==="
start_wet 256MB stats
su - pgbench -c "$WET_BIN/psql -p $WPORT -c 'SELECT pg_stat_reset_wait_event_timing_all();' postgres" 2>/dev/null
su - pgbench -c "$WET_BIN/pgbench -p $WPORT -S -c 16 -j 16 -T 90 -n --no-vacuum postgres" &
BENCH_PID=$!
sleep 30
log "--- pg_stat_activity sample (active backends by wait) ---"
su - pgbench -c "$WET_BIN/psql -p $WPORT -c \"SELECT coalesce(wait_event_type,'CPU') t, coalesce(wait_event,'running') e, count(*) FROM pg_stat_activity WHERE state='active' AND pid<>pg_backend_pid() GROUP BY 1,2 ORDER BY 3 DESC LIMIT 10;\" postgres" 2>/dev/null
wait $BENCH_PID
log "--- pg_stat_wait_event_timing top events (by count) ---"
su - pgbench -c "$WET_BIN/psql -p $WPORT -c \"SELECT wait_event_type, wait_event, sum(count) total_count, round((sum(total_wait_time_us)/1000.0)::numeric,1) total_wait_ms FROM pg_stat_wait_event_timing GROUP BY 1,2 ORDER BY 3 DESC LIMIT 12;\" postgres" 2>/dev/null
W2_TOTAL=$(su - pgbench -c "$WET_BIN/psql -p $WPORT -tAc 'SELECT sum(count) FROM pg_stat_wait_event_timing;' postgres" 2>/dev/null | tr -d ' \n')
log "W2 total wait-event transitions captured: $W2_TOTAL (over ~90s)"
log "--- pg_stat_statements top queries (the queries that generated the waits) ---"
su - pgbench -c "$WET_BIN/psql -p $WPORT -c \"SELECT calls, round(total_exec_time::numeric,1) total_ms, round(mean_exec_time::numeric,4) mean_ms, left(query,60) query FROM pg_stat_statements ORDER BY calls DESC LIMIT 8;\" postgres" 2>/dev/null
stop_all

# ---- W3: same as W2 but rate-limited to 50% of W2 baseline TPS (latency focus) ----
W3_RATE=$(python3 -c "print(int(0.5*$W2_BL_TPS))")
log "=== W3: LATENCY under 50% capacity (SB=256MB, scale 400, -R $W3_RATE = 50% of W2 baseline TPS $W2_BL_TPS) ==="
run_workload W3 256MB "-R $W3_RATE"

log "================ BENCHMARK COMPLETE ================"
log "SUMMARY (medians):"
log "W1 cached     TPS  BL=$MED_BL"  # note: globals hold last workload; full per-workload medians logged above
log "Done. Full per-workload medians + W2 wait events are in $LOG above. W3 headline = latency (LAT lines)."

rebuild_wet.sh (clean instrumented build + verification gate)

#!/bin/bash
# Rebuild the INSTRUMENTED postgres correctly (clean in-tree build), with verification gate.
set -uo pipefail
echo "[$(date +%H:%M:%S)] === Stopping any in-flight benchmark & clusters ==="
pkill -f run_bench.sh 2>/dev/null
pkill -f 'bin/pgbench' 2>/dev/null
pkill -f 'bin/postgres -D' 2>/dev/null
sleep 3

echo "[$(date +%H:%M:%S)] === Clean rebuild of /opt/pg-wet from wet-series WITH --enable-wait-event-timing ==="
cd /root/pg-src
git checkout -f wet-series
echo "[$(date +%H:%M:%S)] git clean -fdx (remove ALL prior build artifacts incl. ignored .o)..."
git clean -fdx -q
rm -rf /root/build-wet
echo "[$(date +%H:%M:%S)] configure (in-tree)..."
./configure --prefix=/opt/pg-wet --enable-wait-event-timing CC="ccache gcc" CFLAGS="-O2" > /root/wet-configure.log 2>&1
if grep -q -- '--enable-wait-event-timing' config.log; then
  echo "  configure OK: flag present"
else
  echo "  !!! configure did NOT record the flag — aborting"; tail -8 /root/wet-configure.log; exit 1
fi
echo "[$(date +%H:%M:%S)] make -j16 (few minutes)..."
make -j16 > /root/wet-make.log 2>&1 || { echo "MAKE FAILED"; tail -20 /root/wet-make.log; exit 1; }
rm -rf /opt/pg-wet
make install > /root/wet-install.log 2>&1 || { echo "INSTALL FAILED"; tail -20 /root/wet-install.log; exit 1; }
echo "[$(date +%H:%M:%S)] installed. configure line now:"
/opt/pg-wet/bin/pg_config --configure | tr ' ' '\n' | grep -i 'wait\|prefix'

echo "[$(date +%H:%M:%S)] === VERIFICATION GATE: does capture=stats/trace actually stick? ==="
P=/opt/pg-wet/bin
pkill -f 'D /tmp/guctest' 2>/dev/null; sleep 1; rm -rf /tmp/guctest
$P/initdb -D /tmp/guctest >/tmp/guctest_init.log 2>&1
$P/pg_ctl -D /tmp/guctest -o "-p 5999" -l /tmp/guctest.log start >/dev/null 2>&1
sleep 3
STATS=$($P/psql -p 5999 -d postgres -tAc "SET wait_event_capture=stats; SHOW wait_event_capture;" 2>&1 | tr -d '[:space:]')
TRACE=$($P/psql -p 5999 -d postgres -tAc "SET wait_event_capture=trace; SHOW wait_event_capture;" 2>&1 | tr -d '[:space:]')
$P/pg_ctl -D /tmp/guctest stop >/dev/null 2>&1
echo "  SET stats -> '$STATS'   SET trace -> '$TRACE'"
if [ "$STATS" = "stats" ] && [ "$TRACE" = "trace" ]; then
  echo "[$(date +%H:%M:%S)] VERIFIED: instrumented build accepts stats AND trace. Build is valid."
  touch /root/WET_BUILD_VERIFIED
else
  echo "[$(date +%H:%M:%S)] NOT VERIFIED: capture did not stick (stats='$STATS' trace='$TRACE'). Do NOT benchmark."
  rm -f /root/WET_BUILD_VERIFIED
  exit 1
fi

go.sh (re-init wet cluster + gate + run)

#!/bin/bash
# Re-init wet cluster with corrected binary -> verification gate (as pgbench) -> full benchmark
set -uo pipefail
WET=/opt/pg-wet/bin
BASE=/opt/pg-baseline/bin
log(){ echo "[$(date +%H:%M:%S)] $*"; }

log "=== Stopping everything ==="
su - pgbench -c "$WET/pg_ctl -D /data/pg-wet stop -m immediate 2>/dev/null; exit 0" 2>/dev/null || true
su - pgbench -c "$BASE/pg_ctl -D /data/pg-baseline stop -m immediate 2>/dev/null; exit 0" 2>/dev/null || true
pkill -f run_bench.sh 2>/dev/null || true
pkill -u pgbench pgbench 2>/dev/null || true
sleep 3

log "=== Re-initdb /data/pg-wet with the CORRECTED instrumented binary ==="
rm -rf /data/pg-wet
su - pgbench -c "$WET/initdb -D /data/pg-wet" >/root/wet-reinit.log 2>&1 || { echo "REINIT FAILED"; tail -8 /root/wet-reinit.log; exit 1; }
cat >> /data/pg-wet/postgresql.conf <<'EOF'
port = 5441
max_connections = 300
fsync = off
max_wal_size = 8GB
track_activities = on
compute_query_id = on
wait_event_capture = off
EOF
chown pgbench:pgbench /data/pg-wet/postgresql.conf

log "=== VERIFICATION GATE (as pgbench): capture=stats/trace must stick + view must exist ==="
su - pgbench -c "$WET/pg_ctl -D /data/pg-wet -l /tmp/wet_gate.log start"
for i in $(seq 1 25); do su - pgbench -c "$WET/pg_isready -p 5441 -q" && break; sleep 1; done
STATS=$(su - pgbench -c "$WET/psql -p 5441 -d postgres -tAc \"SET wait_event_capture=stats; SELECT current_setting('wait_event_capture');\"" 2>&1 | tail -1 | tr -d '[:space:]')
TRACE=$(su - pgbench -c "$WET/psql -p 5441 -d postgres -tAc \"SET wait_event_capture=trace; SELECT current_setting('wait_event_capture');\"" 2>&1 | tail -1 | tr -d '[:space:]')
VIEW=$(su - pgbench -c "$WET/psql -p 5441 -d postgres -tAc \"SELECT count(*) FROM pg_stat_wait_event_timing;\"" 2>&1 | tr -d '[:space:]')
su - pgbench -c "$WET/pg_ctl -D /data/pg-wet stop -m fast" 2>/dev/null || true
log "RESULT: SET stats -> '$STATS' ; SET trace -> '$TRACE' ; pg_stat_wait_event_timing rows -> '$VIEW'"
if [ "$STATS" = "stats" ] && [ "$TRACE" = "trace" ]; then
  log "✅ VERIFIED — build is genuinely instrumented (GUC accepts stats/trace; instrumentation view present). Proceeding."
  touch /root/WET_BUILD_VERIFIED
else
  log "❌ NOT VERIFIED (stats='$STATS' trace='$TRACE'). Aborting — will NOT produce misleading numbers."
  exit 1
fi

log "=== Launching full interleaved benchmark (baseline / off / stats / trace) ==="
bash /root/run_bench.sh

[NikolayS]

📹 Hacking Postgres session — call summary (2026-06-17)

Recording: https://www.youtube.com/watch?v=RLeB6rP5CA8
Participants: Kirk Wolak, Dmitry Fomin, Nik (postgres.ai) — plus an AI agent ("Leo", via samograph) that joined the Zoom as an active participant: it monitored the live transcript, answered questions in chat, provisioned the benchmark box, built/verified Postgres, ran the benchmark, and published the docs in real time.

Topic: independent review, testing, and benchmarking of Dmitry Fomin's wait_event_timing patch series — PR DmitryNFomin#2 (the reviewable 7-patch split of the original DmitryNFomin#1, restructured per Andrey Borodin's "send them all together but break into chewable parts" review).

Key technical points discussed

• Feature levels: wait_event_capture = off | stats | trace. stats (per-(backend,event) count/total/max + 32-bucket log2 histogram) is intended as the default-on mode; trace (per-session DSA ring of individual waits + query-attribution markers) is for targeted, short-duration diagnosis of specific backends. Changing levels is runtime (PGC_SUSET) — no restart needed. Without a fast clock source, stats still gives counts but not timing.
• Sampling vs this approach: today's pg_stat_activity sampling can't distinguish "one long wait" from "100 short waits" at the same average — this patch's counts + histogram resolve exactly that. Dmitry: spent that day hunting LWLock jumps in logs and "really wanted this tooling."
• Two cost concepts (kept distinct): static overhead (constant cost of compiled-in/enabled) vs observer effect (dynamic, grows with sampling/reading frequency; Kirk's pg_stat_statements-reset-under-load analogy).
• The measurement ladder: vanilla → patched-stub (flag off) → compiled+off → stats → trace, plus a "used/read frequency" axis.
• Validity gate (a real trap caught live): a build compiled without --enable-wait-event-timing still exposes the GUC but silently downgrades stats/trace to off → off/stats/trace all equal baseline → a false ~0% overhead. Fixed with a hard pre-benchmark gate (SET stats/trace must stick + view must exist).
• DSA trace ring: wait_event_trace_ring_size = 4 MB/backend (power-of-two, lazily allocated per trace session) → ~4 GB at 1000 trace backends ("Kirk's extra gig" concern). wait_event_timing_max_tranches=192.
• Trace verified genuinely working (temp-instance test): 49,791 ring records under trace incl. ExecStart/ExecEnd/QueryStart/QueryEnd query-attribution markers with per-query bracketing; empty ring under off.

Benchmark methodology agreed (evolved live)

• Hetzner CCX43 (16 dedicated AMD EPYC-Milan vCPU, 64 GB), wet-series @ 983f0ec, --enable-wait-event-timing, gcc -O2.
• Canonical command, reused everywhere: pgbench -S -c 16 -j 16 -T 180 -P 15 -r -n (3-min runs, clients=jobs=cores, progress + per-statement latency, no vacuum, select-only, --log deliberately avoided as an observer-effect source). 3 interleaved rounds, median.
• Workloads: W1 cached (SB=8GB) · W2 wait-saturated (SB=256MB, data≫SB) · W3 = W2 rate-limited -R at 50% of W2 baseline TPS (latency under headroom, regular load-test not stress; with a vmstat CPU-headroom check). fsync left at default (removed fsync=off as a red flag — moot for select-only).
• Preliminary W1 result: baseline/off/stats/trace all within ±0.4% (statistically indistinguishable) — expected for a cached (low-wait) workload.

Open methodology insight (end of call)

pgbench -S point lookups stay buffer-resident even with small shared_buffers → they under-generate wait events (~50k waits vs 200k+ TPS), so they can't reveal the per-wait-event cost. Next: bulk-read workloads (range/seq scans over data ≫ shared_buffers) to drive millions of wait-event transitions/sec — the real stress test.

Memorable

• Kirk's proposed blog title: "Which Butterfly Flapped Its Wings?" (the power of fine-grained wait attribution — was it one long wait or a storm of tiny ones?).
• Strategy advice (Nik → Dmitry): submit to pgsql-hackers early for community feedback rather than polishing one big silent shot; show the idea evolving across the thread. Jeremy Schneider is interested; potential game-changer for Postgres observability.

Deliverables / next steps (tracked in this issue)

• This tracking issue (wait_event_timing — independent benchmark & testing (Hacking Postgres 2026-06-17) #48), the design brief, per-round results HTML + charts, a comment on PR Add comprehensive wait events coverage gap analysis #2, a first-pass blog post.
• Future: W4 (read-side observer effect — second client polls the views at increasing frequency while a workload runs), the pg_stat_statements iteration, the bulk-read wait-saturated workload, and the patched-stub rung.
• Post-completion: ≥3 independent specialty review agents; re-run if anything is off.

[NikolayS]

⚠️ Correction: the "empty wait-event proof" was a query bug — the workload IS wait-heavy

The W2 wait-event proof came back empty, which looked like "the workload doesn't generate waits." That was a bug, not a result: the proof queried sum(count) but the column in pg_stat_wait_event_timing is calls (sum(count) errors → empty). Also, it queried after the pgbench backends exited — and stats live in per-backend slots that are freed on exit, so it undercounts; you must sample while the run is live.

Real measurement (live sampling, scale 200, SB=128MB, 8 clients, on /opt/pg-wet)

workload	TPS	wait-events/sec	wait-events/query	dominant waits
pgbench -S (point lookup)	72,035	~204,000	2.84	IO/DataFileRead, Client/ClientRead
bulk-read (50k-row range scan)	2,681	~264,000	98.3	IO/DataFileRead (≈all)

Implications

• The benchmark was already wait-event heavy. At the benchmark's 16 clients, W2 was pushing ~400k wait-event transitions/sec. So the observed ~0 overhead is a genuinely strong result — even at hundreds of thousands of transitions/sec, off/stats/trace stay within noise (the patch's design claim holds).
• Bulk vs point-lookup is similar on rate (~200k vs ~264k/sec) — the per-second rate is bounded by the IO/memory subsystem, not the query type. Bulk's value is shape: 98 IO-dominated waits/query (less ClientRead noise), a cleaner complementary signal — not a 10× increase. To push the rate higher: more clients or smaller shared_buffers (e.g. 16MB).

Fixes applied to the next-round script: sum(count)→sum(calls), total_wait_time_us→total_time_ms, and a live mid-run wait-event sample (the post-run query undercounts).

[NikolayS]

🔬 Independent 3-specialty review — verdict: promising preliminary result, NOT publishable as "negligible overhead" as-is

Three independent agents (benchmark-methodology/statistics · Postgres-internals/wait-event-correctness · adversarial-skeptic/reproducibility) reviewed the two-round results against the raw logs. All three: publishable: false. They verified the raw numbers faithfully back the reported medians, the build is genuinely instrumented (trace ring 1003 records + 16 markers + 9 real wait types), and the validity gate is a real, well-caught trap. But the headline overclaims. Consolidated blockers (where ≥2 reviewers independently converged):

1. Broken CPU-idle headroom gate (all 3 reviewers). awk '$(NF-2)' reads vmstat wa, not id, because a gu (guest) column shifted the layout → every avg_cpu_idle=0% in the logs is false; raw vmstat shows ~22–31% idle. The W3 "under headroom" premise was never validated by the harness (it's actually true per raw vmstat — but the gate proved nothing).

2. ±0.7–0.9% noise floor swamps the throughput claim (all 3). The flag-off instrumented binary beats baseline in 6/6 W2 sub-rounds (+0.6–0.9%) — physically impossible → a systematic binary/order bias larger than any trace cost being bounded. Variant order is fixed (BL→OFF→STA→TRA every round), confounding position with variant. So "overhead within ±1%" means "we couldn't see it," not "it's ~0."

3. W2 is NOT IO-bound — it's fully page-cached (reviewers 2 & 3). 6GB dataset in 24GB OS page cache; vmstat bi=0, wa=0, ~31% idle. The 412k "DataFileRead waits/sec" are sub-microsecond cache hits (post-run total_wait_ms=0.0) — the easy case. Under-states overhead vs the IO-bound / short-wait regime the feature targets.

4. Hard-case workloads untested (reviewers 2 & 3). No LWLock-contention/short-wait storm (Dmitry's motivating case — where per-transition fixed cost is the biggest fraction of the wait), no write workload, no W4 read-side observer-effect poller (the realistic risk for a default-on stats mode).

5. Stub/compile-out rung never built (reviewer 3). The rung that proves source changes cost ~0 when compiled out (#ifdef'd) was never run.

6. Stats arm's persisted evidence shows only aux processes (reviewer 2). Per-backend slots freed on exit → post-run table (646) shows background workers, not the workload's 12.37M; no preserved histogram from a workload backend.

The one genuine positive signal

W3 trace latency +1–2% is real — off ≤ stats ≤ trace monotonic in both rounds; pooled n=6 permutation test: trace-vs-OFF +2.09%, p=0.022. Worth reporting (but the original write-up under-argued it with eyeballed n=3 medians).

Mandatory caveats for any interim claim

Single virtualized 16-vCPU host; SELECT-only point lookups; fully page-cached (~80% sub-µs IO waits) = the easy case; throughput overhead "not resolvable above ~±1% noise floor" (NOT "~0"); compile-out cost unmeasured.

Corrected-run plan (Round 3, to actually pass review)

Fix vmstat (id by header name) · add A/A runs (BL-vs-BL, off-vs-off) to measure the true noise floor · randomize variant order · ≥5 rounds with mean±stddev + a pooled significance test for the W3 latency · build & run the stub rung · add an LWLock/short-wait contention workload (the hard case) · capture the stats histogram mid-run · report bi/wa/idle so saturation is visible. Write/W4 workloads loudly caveated as future.

[NikolayS]

✅ Corrected benchmark (v3) — results published

Full write-up + charts: https://nikolays.github.io/wet-timing-bench-brief/results.html

This addresses every blocker the independent review raised on the 2-round numbers. Reworked harness:
A/A noise floor (vanilla ×6 → CV 0.328%) · randomized variant order each round · 5 rounds with mean±stddev + exact permutation tests · the stub rung (patched source, --enable-wait-event-timing omitted) · CPU-idle fixed (vmstat id by header, not the wa off-by-one) · mid-run live histograms · three wait regimes incl. a short-wait storm.

Throughput — no resolvable overhead (within the same binary, runtime SET only)

regime (wait profile)	stats vs off	trace vs off	stub vs vanilla¹
W1 cached point-lookup (CPU-bound)	−0.07% (p=.82)	−0.55% (p=.18)	+0.36% (p=.29)
W2 ClientRead-saturated (−c64)	−0.74% (p=.18)	−0.34% (p=.56)	+0.96% (p=.06)
W3 buffer-miss short-wait (81% DataFileRead @ 3.9µs, 20M waits)	−0.27% (p=.38)	−0.26% (p=.31)	+1.21% (p=.008)

¹ The stub should cost zero. Its non-zero, sometimes-significant gap is binary code-layout variance (Mytkowicz effect) — larger than any capture cost. So the honest claim is throughput overhead < ~1%, build-variance-limited, not distinguishable from zero — measured even under 20M sub-4µs waits/run with full histogram capture.

OFF/STA/TRA are the same binary + same data cluster, differing only by SET wait_event_capture — no recompile, no re-initdb — so that comparison has no layout/cluster confound. The A/A floor (0.33%) applies, and every delta is inside it.

Latency under headroom — the one real signal

W4 (cached, rate-limited ~50%, idle≈30%): trace latency +1.49% vs off, p=0.008 — small but statistically clean, and it reproduces the direction of the earlier flagged result. stats: +0.50%, p=0.37 (n.s.). Throughput saturation hides this; rate-limited latency exposes it. Physically sensible: trace writes each wait into the DSA ring + emits query-attribution markers (more per-wait work than the stats histogram bump).

Instrumentation is genuinely exercised

~12M live client-backend wait transitions at W2 peak (65 backends); full 32-bucket log₂ histograms captured mid-run; trace ring filled to 131,072 records. The ~0 is at a high wait rate, not an idle feature.

Status: interim

• W5 (wait-heavy latency — the same probe on the buffer-miss workload) is running now and will sharpen the latency number.
• A fresh independent 3-specialty re-review of this corrected dataset is queued.
• Still future work (loudly caveated): a dedicated LWLock-contention storm, a write/WAL workload, and a true IO-bound (>RAM) regime. LWLock was <1% of waits here.

Raw per-run series, scripts, and logs to follow in this issue. Numbers + method are open for scrutiny — please poke holes.

[NikolayS]

Raw data, scripts & corrected analysis (v3)

Results page (corrected, reviewer-vetted): https://nikolays.github.io/wet-timing-bench-brief/results.html

Harness

Hetzner CCX43 (16 dedicated AMD EPYC-Milan vCPU, 64GB, Ubuntu 24.04). PG19beta1, wet-series @983f0ec (--enable-wait-event-timing) vs base wet-series-base; plus a stub built from the patched source with the flag omitted (/opt/pg-stub) as a Mytkowicz code-layout control. 5 variants: VAN vanilla · STB stub · OFF/STA/TRA instrumented w/ wait_event_capture=off/stats/trace. Each round runs all variants once in randomized order (randomized block); analysis uses the paired within-round sign-flip permutation test. A/A floor (vanilla ×6) CV=0.328%.

Raw per-run TPS (5 rounds each, round order)

W1 cached (SB8GB scale100 -c16):
 VAN 217419 217563 217042 218365 217215
 STB 219012 216819 217370 218095 220215
 OFF 216190 218557 217306 216454 219516
 STA 217004 217677 216044 218218 218278
 TRA 215080 216771 216175 217981 216053
W2 ClientRead-saturated (SB1GB scale10 -c64):
 VAN 243679 240495 244245 239289 242627
 STB 243993 245677 243016 245319 243954
 OFF 242072 244501 238935 238761 240678
 STA 239347 238588 239105 237794 241160
 TRA 239863 240669 241551 241324 237498
W3 buffer-miss short-wait (SB256MB scale400 -c16; 81% DataFileRead @3.9µs, 20.2M waits/run):
 VAN 184191 183317 183332 183516 183821
 STB 185669 185950 185592 185743 186333
 OFF 184366 184664 185160 183939 184809
 STA 183126 184754 183145 183626 185828
 TRA 183210 183493 183870 185026 184976

Raw per-run latency ms (under -R headroom, idle≈30%)

W4 cached -R108000:      OFF 0.364 0.362 0.363 0.363 0.361 | STA 0.365 0.360 0.363 0.369 0.365 | TRA 0.365 0.368 0.368 0.367 0.372
W6 cached -R108000 (rep):OFF 0.383 0.381 0.381 0.384 0.377 | STA 0.380 0.381 0.380 0.383 0.380 | TRA 0.385 0.390 0.385 0.389 0.386
W5 wait-heavy -R92000:   OFF 0.376 0.378 0.374 0.374 0.375 | STA 0.381 0.379 0.378 0.382 0.375 | TRA 0.381 0.384 0.384 0.385 0.374

Cached latency pooled n=10 (W4+W6, identical config): trace +5.6µs (+1.5%), 10/10 rounds positive, paired sign-flip p=0.0020; stats +0.7µs p=0.53. Percentiles (µs, 2% sample): OFF p50 299/p95 825/p99 1231; TRA p50 304/p95 847/p99 1258 (whole-distribution shift).

Scripts

run_bench_v3.sh (A/A + W1 + W2), run_w3.sh, run_w4.sh, run_w5.sh, run_w6.sh (percentiles via pgbench -l --sampling-rate), build_stub.sh. Key pattern: set_conf rewrites postgresql.conf, randomized variant order via shuf, idle parsed from vmstat by header name, mid-run live sampling of pg_stat_wait_event_timing (per-backend slots free on exit). Full scripts attached below / available on request.

Review process

Round 1 (3 specialties) rejected the original 2-round numbers (broken CPU-idle gate, no noise floor, fixed order, easy workload). Corrected harness fixed those. Round 2 (3 specialties) caught a real stats error (unblocked test → false p=0.008 floor artifact); all 6 fixes applied (paired test, multiple-comparison, n=10 latency, percentiles, stub-as-hypothesis, one-sided throughput bound). A 2-agent verification confirmed the fixes.

[NikolayS]

Benchmark scripts

Each run_*.sh shares the same structure (variant table, set_conf postgresql.conf rewrite, randomized shuf order, parse_idle via vmstat header, mid-run live sampling of pg_stat_wait_event_timing). Collapsed below.

run_bench_v3.sh — main harness: A/A noise floor + W1 cached + W2 ClientRead-saturated

#!/bin/bash
# Corrected benchmark v3 — addresses independent-review blockers:
#  - 5 variants incl STUB rung (patched source, flag OFF): VAN(vanilla) STB(stub) OFF STA TRA
#  - A/A noise floor (vanilla run 6x back-to-back) to quantify the real run-to-run/position noise
#  - RANDOMIZED variant order each round (breaks position<->variant confound)
#  - 5 rounds, report MEAN +/- STDDEV per variant (not median-of-3)
#  - FIXED vmstat idle parsing (locate 'id' by header, not NF offset)
#  - W2 = short-wait CONTENTION (small cached DB, high concurrency) -> LWLock/short non-IO waits (the hard case)
#  - mid-run stats histogram capture (per-backend slots freed on exit otherwise)
set -uo pipefail
BASE=/opt/pg-baseline/bin; STUB=/opt/pg-stub/bin; WET=/opt/pg-wet/bin
BASE_D=/data/pg-baseline; STUB_D=/data/pg-stub; WET_D=/data/pg-wet
BP=5440; SP=5442; WP=5441
LOG=/root/bench_v3.log; DUR=120; ROUNDS=5
mkdir -p /tmp/v3; chmod 777 /tmp/v3; : > $LOG
exec > >(tee -a $LOG) 2>&1
log(){ echo "[$(date '+%H:%M:%S')] $*"; }

declare -A VBIN VPORT VDD VCAP
VBIN[VAN]=$BASE; VPORT[VAN]=$BP; VDD[VAN]=$BASE_D; VCAP[VAN]="-"
VBIN[STB]=$STUB; VPORT[STB]=$SP; VDD[STB]=$STUB_D; VCAP[STB]="-"
VBIN[OFF]=$WET;  VPORT[OFF]=$WP; VDD[OFF]=$WET_D;  VCAP[OFF]="off"
VBIN[STA]=$WET;  VPORT[STA]=$WP; VDD[STA]=$WET_D;  VCAP[STA]="stats"
VBIN[TRA]=$WET;  VPORT[TRA]=$WP; VDD[TRA]=$WET_D;  VCAP[TRA]="trace"
VARIANTS=(VAN STB OFF STA TRA)

stop_all(){
  su - pgbench -c "$BASE/pg_ctl -D $BASE_D stop -m fast 2>/dev/null; exit 0" 2>/dev/null||true
  su - pgbench -c "$STUB/pg_ctl -D $STUB_D stop -m fast 2>/dev/null; exit 0" 2>/dev/null||true
  su - pgbench -c "$WET/pg_ctl  -D $WET_D  stop -m fast 2>/dev/null; exit 0" 2>/dev/null||true
  sleep 2
}
set_conf(){ python3 -c "
import re,sys
p='$1/postgresql.conf'; c=open(p).read()
c=re.sub(r'^#?\s*$2\s*=.*', \"$2 = '$3'\", c, flags=re.M)
if '$2' not in c: c+=\"\n$2 = '$3'\n\"
open(p,'w').write(c)"; }

# start_variant LABEL SB
start_variant(){
  local v=$1 sb=$2; stop_all
  set_conf "${VDD[$v]}" shared_buffers "$sb"
  [ "${VCAP[$v]}" != "-" ] && set_conf "${VDD[$v]}" wait_event_capture "${VCAP[$v]}"
  su - pgbench -c "${VBIN[$v]}/pg_ctl -D ${VDD[$v]} -l /tmp/v3/$v.log start" >/dev/null 2>&1
  sleep 4
}
# header is row 2 (find 'id' col); row 3 is the since-boot average -> skip it; average interval rows (NR>3)
parse_idle(){ awk 'NR==2{for(i=1;i<=NF;i++)if($i=="id")c=i} NR>3&&c{s+=$c;n++} END{if(n)printf "%.0f",s/n}' "$1"; }

# run_one LABEL PGBENCH_ARGS  -> echoes "tps lat idle"
run_one(){
  local v=$1; shift; local args="$*"
  ( vmstat 15 8 >/tmp/v3/vm.txt 2>&1 ) & local vp=$!
  # mid-run LIVE sampler for instrumented variants (slots freed on backend exit; must sample while alive)
  if [ "${VCAP[$v]}" = "stats" ] || [ "${VCAP[$v]}" = "trace" ]; then
    ( sleep $((DUR/2))
      local P=${VPORT[$v]} B=${VBIN[$v]} F=/tmp/v3/sample_${v}.txt
      echo "=== mid-run sample ($v) $(date '+%H:%M:%S') ===" >> $F
      su - pgbench -c "$B/psql -p $P -tAc \"SELECT 'LIVE_CLIENT_WAITS='||coalesce(sum(calls),0)||' over '||count(distinct pid)||' backends' FROM pg_stat_wait_event_timing WHERE backend_type='client backend';\" postgres" >> $F 2>&1
      su - pgbench -c "$B/psql -p $P -c \"SELECT wait_event_type,wait_event,sum(calls) calls,round(sum(total_time_ms)::numeric,1) tot_ms,round(sum(total_time_ms)/nullif(sum(calls),0)*1000,2) avg_us FROM pg_stat_wait_event_timing WHERE backend_type='client backend' GROUP BY 1,2 ORDER BY 3 DESC LIMIT 8;\" postgres" >> $F 2>&1
      [ "${VCAP[$v]}" = "stats" ] && su - pgbench -c "$B/psql -p $P -c \"SELECT wait_event,calls,total_time_ms,histogram FROM pg_stat_wait_event_timing WHERE backend_type='client backend' AND calls>0 ORDER BY calls DESC LIMIT 3;\" postgres" >> $F 2>&1
      [ "${VCAP[$v]}" = "trace" ] && su - pgbench -c "$B/psql -p $P -tAc \"SELECT 'TRACE_RING_RECORDS='||count(*) FROM pg_get_wait_event_trace((SELECT min(procnumber) FROM pg_stat_wait_event_timing WHERE backend_type='client backend'));\" postgres" >> $F 2>&1
    ) &
  fi
  su - pgbench -c "${VBIN[$v]}/pgbench -p ${VPORT[$v]} $args -T $DUR -n --no-vacuum postgres 2>&1" >/tmp/v3/pg.txt
  kill $vp 2>/dev/null
  local tps lat idle
  tps=$(grep -oP 'tps = \K[0-9.]+' /tmp/v3/pg.txt|head -1)
  lat=$(grep -oP 'latency average = \K[0-9.]+' /tmp/v3/pg.txt|head -1)
  idle=$(parse_idle /tmp/v3/vm.txt)
  echo "$tps $lat $idle"
}

# stats(list) -> "mean stddev cv%"
mstd(){ python3 -c "
import sys,statistics as s
v=[float(x) for x in sys.argv[1:] if x]
if len(v)<2: print('%.1f 0 0'%(v[0] if v else 0)); sys.exit()
m=s.mean(v); sd=s.pstdev(v); print('%.1f %.1f %.3f'%(m,sd,100*sd/m if m else 0))" "$@"; }

workload(){ # NAME SB PGARGS
  local name=$1 sb=$2 args=$3
  log "========== $name  (SB=$sb ; $args) =========="
  declare -A SER  # SER[label]="v1 v2 v3 v4 v5"  TPS series
  declare -A LAT IDL
  for v in "${VARIANTS[@]}"; do SER[$v]=""; LAT[$v]=""; IDL[$v]=""; done
  for r in $(seq 1 $ROUNDS); do
    local order=$(printf '%s\n' "${VARIANTS[@]}" | shuf | tr '\n' ' ')
    log "$name Round $r/$ROUNDS  order: $order"
    for v in $order; do
      start_variant "$v" "$sb"
      [ "${VCAP[$v]}" != "-" ] && { local act=$(su - pgbench -c "${VBIN[$v]}/psql -p ${VPORT[$v]} -tAc 'SHOW wait_event_capture;' postgres" 2>/dev/null|tr -d ' \n'); [ "$act" != "${VCAP[$v]}" ] && log "  !! $v capture mismatch: want ${VCAP[$v]} got $act"; }
      read t l i < <(run_one "$v" "$args")
      SER[$v]+="$t "; LAT[$v]+="$l "; IDL[$v]+="$i "
      log "  $v tps=$t lat=${l}ms cpu_idle=${i}%"
    done
  done
  log "--- $name SUMMARY (mean+-stddev over $ROUNDS rounds) ---"
  local van_mean=$(mstd ${SER[VAN]} | awk '{print $1}')
  for v in "${VARIANTS[@]}"; do
    read m sd cv < <(mstd ${SER[$v]})
    read lm lsd lcv < <(mstd ${LAT[$v]})
    local d=$(python3 -c "print('%+.2f'%((($m)-($van_mean))/($van_mean)*100)) if $van_mean else print('NA')")
    log "  $v  TPS mean=$m sd=$sd (cv=${cv}%)  vs VAN: ${d}%   LAT mean=${lm}ms sd=${lsd}  idle≈$(echo ${IDL[$v]}|awk '{print $1}')%"
  done
}

log "################ CORRECTED BENCHMARK v3 ################"
log "Variants: VAN(vanilla /opt/pg-baseline) STB(stub /opt/pg-stub, patched flag-off) OFF/STA/TRA(/opt/pg-wet). Randomized order, $ROUNDS rounds, ${DUR}s, mean+-stddev."

# ---- A/A noise floor: vanilla 6x back-to-back, same config ----
log "========== A/A NOISE FLOOR (vanilla x6, identical config) =========="
start_variant VAN 4GB
AA=""; for k in $(seq 1 6); do read t l i < <(run_one VAN "-S -c 16 -j 16 -P 30"); AA+="$t "; log "  A/A run $k: tps=$t idle=${i}%"; done
read aam aasd aacv < <(mstd $AA); log ">>> A/A noise floor: mean=$aam sd=$aasd CV=${aacv}%  (any cross-variant delta below ~${aacv}% is NOT resolvable)"

# init data on all three clusters for the given scale
init_scale(){ # scale
  local sc=$1
  for trip in "$BASE|$BP|$BASE_D" "$STUB|$SP|$STUB_D" "$WET|$WP|$WET_D"; do
    IFS='|' read -r bin port dd <<< "$trip"
    stop_all; set_conf "$dd" shared_buffers 1GB
    su - pgbench -c "$bin/pg_ctl -D $dd -l /tmp/v3/init.log start" >/dev/null 2>&1; sleep 3
    su - pgbench -c "$bin/psql -p $port -c 'CREATE EXTENSION IF NOT EXISTS pg_stat_statements;' postgres" >/dev/null 2>&1
    su - pgbench -c "$bin/pgbench -p $port -i -s $sc --no-vacuum postgres 2>&1 | tail -1"
  done; stop_all
}

log "=== init scale 100 (W1 cached) on all 3 clusters ==="; init_scale 100 2>&1 | tail -3
workload "W1_cached_pointlookup" 8GB "-S -c 16 -j 16 -P 30"

log "=== init scale 10 (W2 contention, small/hot) on all 3 clusters ==="; init_scale 10 2>&1 | tail -3
# small cached DB, OVERSUBSCRIBED concurrency -> LWLock/buffer-content + ClientRead short waits, ~no IO
workload "W2_shortwait_contention" 1GB "-S -c 64 -j 16 -P 30"

log "################ BENCHMARK v3 COMPLETE ################"
log "Done. Per-variant mean+-stddev + A/A noise floor above. STUB rung included; idle measured by header."

run_w3.sh — W3 buffer-miss short-wait (81% DataFileRead @3.9µs)

#!/bin/bash
# W3 add-on (corrected harness): buffer-miss SHORT-WAIT regime.
# 256MB shared_buffers vs ~6GB dataset (scale 400) -> high rate of short DataFileRead waits
# (served from OS page cache: sub-us..few-us). Stresses the per-transition fixed instrumentation cost.
# Same 5 variants incl STUB, randomized order, 5 rounds, mean+-stddev, mid-run histogram. idle by header.
set -uo pipefail
BASE=/opt/pg-baseline/bin; STUB=/opt/pg-stub/bin; WET=/opt/pg-wet/bin
BASE_D=/data/pg-baseline; STUB_D=/data/pg-stub; WET_D=/data/pg-wet
BP=5440; SP=5442; WP=5441
LOG=/root/bench_w3.log; DUR=120; ROUNDS=5
mkdir -p /tmp/v3; chmod 777 /tmp/v3; : > $LOG
exec > >(tee -a $LOG) 2>&1
log(){ echo "[$(date '+%H:%M:%S')] $*"; }

declare -A VBIN VPORT VDD VCAP
VBIN[VAN]=$BASE; VPORT[VAN]=$BP; VDD[VAN]=$BASE_D; VCAP[VAN]="-"
VBIN[STB]=$STUB; VPORT[STB]=$SP; VDD[STB]=$STUB_D; VCAP[STB]="-"
VBIN[OFF]=$WET;  VPORT[OFF]=$WP; VDD[OFF]=$WET_D;  VCAP[OFF]="off"
VBIN[STA]=$WET;  VPORT[STA]=$WP; VDD[STA]=$WET_D;  VCAP[STA]="stats"
VBIN[TRA]=$WET;  VPORT[TRA]=$WP; VDD[TRA]=$WET_D;  VCAP[TRA]="trace"
VARIANTS=(VAN STB OFF STA TRA)

stop_all(){
  for D in $BASE_D $STUB_D $WET_D; do su - pgbench -c "$WET/pg_ctl -D $D stop -m fast 2>/dev/null; exit 0" >/dev/null 2>&1||true; done
  pkill -9 -u pgbench postgres 2>/dev/null||true; sleep 3
}
set_conf(){ python3 - "$1" "$2" "$3" <<'PY'
import re,sys
p=sys.argv[1]+"/postgresql.conf"; k=sys.argv[2]; v=sys.argv[3]; c=open(p).read()
if re.search(r'^#?\s*'+k+r'\s*=', c, flags=re.M): c=re.sub(r'^#?\s*'+k+r'\s*=.*', f"{k} = '{v}'", c, flags=re.M)
else: c+=f"\n{k} = '{v}'\n"
open(p,"w").write(c)
PY
}
start_variant(){ local v=$1 sb=$2; stop_all
  set_conf "${VDD[$v]}" shared_buffers "$sb"
  [ "${VCAP[$v]}" != "-" ] && set_conf "${VDD[$v]}" wait_event_capture "${VCAP[$v]}"
  su - pgbench -c "${VBIN[$v]}/pg_ctl -D ${VDD[$v]} -l /tmp/v3/$v.log start" >/dev/null 2>&1; sleep 4
}
parse_idle(){ awk 'NR==2{for(i=1;i<=NF;i++)if($i=="id")c=i} NR>3&&c{s+=$c;n++} END{if(n)printf "%.0f",s/n}' "$1"; }
run_one(){ local v=$1; shift; local args="$*"
  ( vmstat 15 8 >/tmp/v3/vm.txt 2>&1 ) & local vp=$!
  if [ "${VCAP[$v]}" = "stats" ] || [ "${VCAP[$v]}" = "trace" ]; then
    ( sleep $((DUR/2)); local P=${VPORT[$v]} B=${VBIN[$v]} F=/tmp/v3/w3_sample_${v}.txt
      echo "=== W3 mid-run ($v) $(date '+%H:%M:%S') ===" >> $F
      su - pgbench -c "$B/psql -p $P -tAc \"SELECT 'LIVE_CLIENT_WAITS='||coalesce(sum(calls),0)||' over '||count(distinct pid)||' backends' FROM pg_stat_wait_event_timing WHERE backend_type='client backend';\" postgres" >> $F 2>&1
      su - pgbench -c "$B/psql -p $P -c \"SELECT wait_event_type,sum(calls) calls,round((100.0*sum(calls)/sum(sum(calls)) OVER ())::numeric,1) pct,round((sum(total_time_ms)/nullif(sum(calls),0)*1000)::numeric,2) avg_us FROM pg_stat_wait_event_timing WHERE backend_type='client backend' GROUP BY 1 ORDER BY 2 DESC;\" postgres" >> $F 2>&1
      [ "${VCAP[$v]}" = "stats" ] && su - pgbench -c "$B/psql -p $P -c \"SELECT wait_event,calls,total_time_ms,histogram FROM pg_stat_wait_event_timing WHERE backend_type='client backend' AND calls>0 ORDER BY calls DESC LIMIT 3;\" postgres" >> $F 2>&1
    ) &
  fi
  su - pgbench -c "${VBIN[$v]}/pgbench -p ${VPORT[$v]} $args -T $DUR -n --no-vacuum postgres 2>&1" >/tmp/v3/pg.txt
  kill $vp 2>/dev/null
  local tps lat idle
  tps=$(grep -oP 'tps = \K[0-9.]+' /tmp/v3/pg.txt|head -1)
  lat=$(grep -oP 'latency average = \K[0-9.]+' /tmp/v3/pg.txt|head -1)
  idle=$(parse_idle /tmp/v3/vm.txt)
  echo "$tps $lat $idle"
}
mstd(){ python3 -c "
import sys,statistics as s
v=[float(x) for x in sys.argv[1:] if x]
if len(v)<2: print('%.1f 0 0'%(v[0] if v else 0)); sys.exit()
m=s.mean(v); sd=s.pstdev(v); print('%.1f %.1f %.3f'%(m,sd,100*sd/m if m else 0))" "$@"; }
workload(){ local name=$1 sb=$2 args=$3
  log "========== $name  (SB=$sb ; $args) =========="
  declare -A SER LAT IDL; for v in "${VARIANTS[@]}"; do SER[$v]=""; LAT[$v]=""; IDL[$v]=""; done
  for r in $(seq 1 $ROUNDS); do
    local order=$(printf '%s\n' "${VARIANTS[@]}" | shuf | tr '\n' ' ')
    log "$name Round $r/$ROUNDS  order: $order"
    for v in $order; do
      start_variant "$v" "$sb"
      read t l i < <(run_one "$v" "$args")
      SER[$v]+="$t "; LAT[$v]+="$l "; IDL[$v]+="$i "
      log "  $v tps=$t lat=${l}ms cpu_idle=${i}%"
    done
  done
  log "--- $name SUMMARY (mean+-stddev over $ROUNDS rounds) ---"
  local van_mean=$(mstd ${SER[VAN]} | awk '{print $1}')
  for v in "${VARIANTS[@]}"; do
    read m sd cv < <(mstd ${SER[$v]}); read lm lsd lcv < <(mstd ${LAT[$v]})
    local d=$(python3 -c "print('%+.2f'%((($m)-($van_mean))/($van_mean)*100)) if $van_mean else print('NA')")
    log "  $v  TPS mean=$m sd=$sd (cv=${cv}%)  vs VAN: ${d}%   LAT mean=${lm}ms sd=${lsd}  idle≈$(echo ${IDL[$v]}|awk '{print $1}')%"
  done
  # raw series for offline significance testing
  for v in "${VARIANTS[@]}"; do log "  RAW $v TPS: ${SER[$v]}"; done
}
init_scale(){ local sc=$1
  for trip in "$BASE|$BP|$BASE_D" "$STUB|$SP|$STUB_D" "$WET|$WP|$WET_D"; do
    IFS='|' read -r bin port dd <<< "$trip"
    stop_all; set_conf "$dd" shared_buffers 2GB
    su - pgbench -c "$bin/pg_ctl -D $dd -l /tmp/v3/init.log start" >/dev/null 2>&1; sleep 3
    su - pgbench -c "$bin/pgbench -p $port -i -s $sc --no-vacuum postgres 2>&1 | tail -1"
  done; stop_all
}
log "################ W3 buffer-miss short-wait (corrected harness) ################"
log "=== init scale 400 (~6GB) on all 3 clusters ==="; init_scale 400 2>&1 | tail -3
workload "W3_buffermiss_shortwait" 256MB "-S -c 16 -j 16 -P 30"
log "################ W3 COMPLETE ################"

run_w4.sh — W4 cached latency under headroom (-R108000)

#!/bin/bash
# W3 add-on (corrected harness): buffer-miss SHORT-WAIT regime.
# 256MB shared_buffers vs ~6GB dataset (scale 400) -> high rate of short DataFileRead waits
# (served from OS page cache: sub-us..few-us). Stresses the per-transition fixed instrumentation cost.
# Same 5 variants incl STUB, randomized order, 5 rounds, mean+-stddev, mid-run histogram. idle by header.
set -uo pipefail
BASE=/opt/pg-baseline/bin; STUB=/opt/pg-stub/bin; WET=/opt/pg-wet/bin
BASE_D=/data/pg-baseline; STUB_D=/data/pg-stub; WET_D=/data/pg-wet
BP=5440; SP=5442; WP=5441
LOG=/root/bench_w4.log; DUR=120; ROUNDS=5
mkdir -p /tmp/v3; chmod 777 /tmp/v3; : > $LOG
exec > >(tee -a $LOG) 2>&1
log(){ echo "[$(date '+%H:%M:%S')] $*"; }

declare -A VBIN VPORT VDD VCAP
VBIN[VAN]=$BASE; VPORT[VAN]=$BP; VDD[VAN]=$BASE_D; VCAP[VAN]="-"
VBIN[STB]=$STUB; VPORT[STB]=$SP; VDD[STB]=$STUB_D; VCAP[STB]="-"
VBIN[OFF]=$WET;  VPORT[OFF]=$WP; VDD[OFF]=$WET_D;  VCAP[OFF]="off"
VBIN[STA]=$WET;  VPORT[STA]=$WP; VDD[STA]=$WET_D;  VCAP[STA]="stats"
VBIN[TRA]=$WET;  VPORT[TRA]=$WP; VDD[TRA]=$WET_D;  VCAP[TRA]="trace"
VARIANTS=(VAN STB OFF STA TRA)

stop_all(){
  for D in $BASE_D $STUB_D $WET_D; do su - pgbench -c "$WET/pg_ctl -D $D stop -m fast 2>/dev/null; exit 0" >/dev/null 2>&1||true; done
  pkill -9 -u pgbench postgres 2>/dev/null||true; sleep 3
}
set_conf(){ python3 - "$1" "$2" "$3" <<'PY'
import re,sys
p=sys.argv[1]+"/postgresql.conf"; k=sys.argv[2]; v=sys.argv[3]; c=open(p).read()
if re.search(r'^#?\s*'+k+r'\s*=', c, flags=re.M): c=re.sub(r'^#?\s*'+k+r'\s*=.*', f"{k} = '{v}'", c, flags=re.M)
else: c+=f"\n{k} = '{v}'\n"
open(p,"w").write(c)
PY
}
start_variant(){ local v=$1 sb=$2; stop_all
  set_conf "${VDD[$v]}" shared_buffers "$sb"
  [ "${VCAP[$v]}" != "-" ] && set_conf "${VDD[$v]}" wait_event_capture "${VCAP[$v]}"
  su - pgbench -c "${VBIN[$v]}/pg_ctl -D ${VDD[$v]} -l /tmp/v3/$v.log start" >/dev/null 2>&1; sleep 4
}
parse_idle(){ awk 'NR==2{for(i=1;i<=NF;i++)if($i=="id")c=i} NR>3&&c{s+=$c;n++} END{if(n)printf "%.0f",s/n}' "$1"; }
run_one(){ local v=$1; shift; local args="$*"
  ( vmstat 15 8 >/tmp/v3/vm.txt 2>&1 ) & local vp=$!
  if [ "${VCAP[$v]}" = "stats" ] || [ "${VCAP[$v]}" = "trace" ]; then
    ( sleep $((DUR/2)); local P=${VPORT[$v]} B=${VBIN[$v]} F=/tmp/v3/w4_sample_${v}.txt
      echo "=== W4 mid-run ($v) $(date '+%H:%M:%S') ===" >> $F
      su - pgbench -c "$B/psql -p $P -tAc \"SELECT 'LIVE_CLIENT_WAITS='||coalesce(sum(calls),0)||' over '||count(distinct pid)||' backends' FROM pg_stat_wait_event_timing WHERE backend_type='client backend';\" postgres" >> $F 2>&1
      su - pgbench -c "$B/psql -p $P -c \"SELECT wait_event_type,sum(calls) calls,round((100.0*sum(calls)/sum(sum(calls)) OVER ())::numeric,1) pct,round((sum(total_time_ms)/nullif(sum(calls),0)*1000)::numeric,2) avg_us FROM pg_stat_wait_event_timing WHERE backend_type='client backend' GROUP BY 1 ORDER BY 2 DESC;\" postgres" >> $F 2>&1
      [ "${VCAP[$v]}" = "stats" ] && su - pgbench -c "$B/psql -p $P -c \"SELECT wait_event,calls,total_time_ms,histogram FROM pg_stat_wait_event_timing WHERE backend_type='client backend' AND calls>0 ORDER BY calls DESC LIMIT 3;\" postgres" >> $F 2>&1
    ) &
  fi
  su - pgbench -c "${VBIN[$v]}/pgbench -p ${VPORT[$v]} $args -T $DUR -n --no-vacuum postgres 2>&1" >/tmp/v3/pg.txt
  kill $vp 2>/dev/null
  local tps lat idle
  tps=$(grep -oP 'tps = \K[0-9.]+' /tmp/v3/pg.txt|head -1)
  lat=$(grep -oP 'latency average = \K[0-9.]+' /tmp/v3/pg.txt|head -1)
  idle=$(parse_idle /tmp/v3/vm.txt)
  echo "$tps $lat $idle"
}
mstd(){ python3 -c "
import sys,statistics as s
v=[float(x) for x in sys.argv[1:] if x]
if len(v)<2: print('%.1f 0 0'%(v[0] if v else 0)); sys.exit()
m=s.mean(v); sd=s.pstdev(v); print('%.1f %.1f %.3f'%(m,sd,100*sd/m if m else 0))" "$@"; }
workload(){ local name=$1 sb=$2 args=$3
  log "========== $name  (SB=$sb ; $args) =========="
  declare -A SER LAT IDL; for v in "${VARIANTS[@]}"; do SER[$v]=""; LAT[$v]=""; IDL[$v]=""; done
  for r in $(seq 1 $ROUNDS); do
    local order=$(printf '%s\n' "${VARIANTS[@]}" | shuf | tr '\n' ' ')
    log "$name Round $r/$ROUNDS  order: $order"
    for v in $order; do
      start_variant "$v" "$sb"
      read t l i < <(run_one "$v" "$args")
      SER[$v]+="$t "; LAT[$v]+="$l "; IDL[$v]+="$i "
      log "  $v tps=$t lat=${l}ms cpu_idle=${i}%"
    done
  done
  log "--- $name SUMMARY (mean+-stddev over $ROUNDS rounds) ---"
  local van_mean=$(mstd ${SER[VAN]} | awk '{print $1}')
  for v in "${VARIANTS[@]}"; do
    read m sd cv < <(mstd ${SER[$v]}); read lm lsd lcv < <(mstd ${LAT[$v]})
    local d=$(python3 -c "print('%+.2f'%((($m)-($van_mean))/($van_mean)*100)) if $van_mean else print('NA')")
    log "  $v  TPS mean=$m sd=$sd (cv=${cv}%)  vs VAN: ${d}%   LAT mean=${lm}ms sd=${lsd}  idle≈$(echo ${IDL[$v]}|awk '{print $1}')%"
  done
  # raw series for offline significance testing
  for v in "${VARIANTS[@]}"; do log "  RAW $v TPS: ${SER[$v]}"; done
  for v in "${VARIANTS[@]}"; do log "  RAW $v LAT: ${LAT[$v]}"; done
}
init_scale(){ local sc=$1
  for trip in "$BASE|$BP|$BASE_D" "$STUB|$SP|$STUB_D" "$WET|$WP|$WET_D"; do
    IFS='|' read -r bin port dd <<< "$trip"
    stop_all; set_conf "$dd" shared_buffers 2GB
    su - pgbench -c "$bin/pg_ctl -D $dd -l /tmp/v3/init.log start" >/dev/null 2>&1; sleep 3
    su - pgbench -c "$bin/pgbench -p $port -i -s $sc --no-vacuum postgres 2>&1 | tail -1"
  done; stop_all
}
log "################ W4 latency under headroom (rate-limited 50%) ################"
log "=== init scale 100 (cached) on all 3 clusters ==="; init_scale 100 2>&1 | tail -3
workload "W4_latency_headroom" 8GB "-S -c 16 -j 16 -R 108000 -P 30"
log "################ W4 COMPLETE ################"

run_w5.sh — W5 wait-heavy latency (-R92000)

#!/bin/bash
# W3 add-on (corrected harness): buffer-miss SHORT-WAIT regime.
# 256MB shared_buffers vs ~6GB dataset (scale 400) -> high rate of short DataFileRead waits
# (served from OS page cache: sub-us..few-us). Stresses the per-transition fixed instrumentation cost.
# Same 5 variants incl STUB, randomized order, 5 rounds, mean+-stddev, mid-run histogram. idle by header.
set -uo pipefail
BASE=/opt/pg-baseline/bin; STUB=/opt/pg-stub/bin; WET=/opt/pg-wet/bin
BASE_D=/data/pg-baseline; STUB_D=/data/pg-stub; WET_D=/data/pg-wet
BP=5440; SP=5442; WP=5441
LOG=/root/bench_w5.log; DUR=120; ROUNDS=5
mkdir -p /tmp/v3; chmod 777 /tmp/v3; : > $LOG
exec > >(tee -a $LOG) 2>&1
log(){ echo "[$(date '+%H:%M:%S')] $*"; }

declare -A VBIN VPORT VDD VCAP
VBIN[VAN]=$BASE; VPORT[VAN]=$BP; VDD[VAN]=$BASE_D; VCAP[VAN]="-"
VBIN[STB]=$STUB; VPORT[STB]=$SP; VDD[STB]=$STUB_D; VCAP[STB]="-"
VBIN[OFF]=$WET;  VPORT[OFF]=$WP; VDD[OFF]=$WET_D;  VCAP[OFF]="off"
VBIN[STA]=$WET;  VPORT[STA]=$WP; VDD[STA]=$WET_D;  VCAP[STA]="stats"
VBIN[TRA]=$WET;  VPORT[TRA]=$WP; VDD[TRA]=$WET_D;  VCAP[TRA]="trace"
VARIANTS=(VAN STB OFF STA TRA)

stop_all(){
  for D in $BASE_D $STUB_D $WET_D; do su - pgbench -c "$WET/pg_ctl -D $D stop -m fast 2>/dev/null; exit 0" >/dev/null 2>&1||true; done
  pkill -9 -u pgbench postgres 2>/dev/null||true; sleep 3
}
set_conf(){ python3 - "$1" "$2" "$3" <<'PY'
import re,sys
p=sys.argv[1]+"/postgresql.conf"; k=sys.argv[2]; v=sys.argv[3]; c=open(p).read()
if re.search(r'^#?\s*'+k+r'\s*=', c, flags=re.M): c=re.sub(r'^#?\s*'+k+r'\s*=.*', f"{k} = '{v}'", c, flags=re.M)
else: c+=f"\n{k} = '{v}'\n"
open(p,"w").write(c)
PY
}
start_variant(){ local v=$1 sb=$2; stop_all
  set_conf "${VDD[$v]}" shared_buffers "$sb"
  [ "${VCAP[$v]}" != "-" ] && set_conf "${VDD[$v]}" wait_event_capture "${VCAP[$v]}"
  su - pgbench -c "${VBIN[$v]}/pg_ctl -D ${VDD[$v]} -l /tmp/v3/$v.log start" >/dev/null 2>&1; sleep 4
}
parse_idle(){ awk 'NR==2{for(i=1;i<=NF;i++)if($i=="id")c=i} NR>3&&c{s+=$c;n++} END{if(n)printf "%.0f",s/n}' "$1"; }
run_one(){ local v=$1; shift; local args="$*"
  ( vmstat 15 8 >/tmp/v3/vm.txt 2>&1 ) & local vp=$!
  if [ "${VCAP[$v]}" = "stats" ] || [ "${VCAP[$v]}" = "trace" ]; then
    ( sleep $((DUR/2)); local P=${VPORT[$v]} B=${VBIN[$v]} F=/tmp/v3/w5_sample_${v}.txt
      echo "=== W5 mid-run ($v) $(date '+%H:%M:%S') ===" >> $F
      su - pgbench -c "$B/psql -p $P -tAc \"SELECT 'LIVE_CLIENT_WAITS='||coalesce(sum(calls),0)||' over '||count(distinct pid)||' backends' FROM pg_stat_wait_event_timing WHERE backend_type='client backend';\" postgres" >> $F 2>&1
      su - pgbench -c "$B/psql -p $P -c \"SELECT wait_event_type,sum(calls) calls,round((100.0*sum(calls)/sum(sum(calls)) OVER ())::numeric,1) pct,round((sum(total_time_ms)/nullif(sum(calls),0)*1000)::numeric,2) avg_us FROM pg_stat_wait_event_timing WHERE backend_type='client backend' GROUP BY 1 ORDER BY 2 DESC;\" postgres" >> $F 2>&1
      [ "${VCAP[$v]}" = "stats" ] && su - pgbench -c "$B/psql -p $P -c \"SELECT wait_event,calls,total_time_ms,histogram FROM pg_stat_wait_event_timing WHERE backend_type='client backend' AND calls>0 ORDER BY calls DESC LIMIT 3;\" postgres" >> $F 2>&1
    ) &
  fi
  su - pgbench -c "${VBIN[$v]}/pgbench -p ${VPORT[$v]} $args -T $DUR -n --no-vacuum postgres 2>&1" >/tmp/v3/pg.txt
  kill $vp 2>/dev/null
  local tps lat idle
  tps=$(grep -oP 'tps = \K[0-9.]+' /tmp/v3/pg.txt|head -1)
  lat=$(grep -oP 'latency average = \K[0-9.]+' /tmp/v3/pg.txt|head -1)
  idle=$(parse_idle /tmp/v3/vm.txt)
  echo "$tps $lat $idle"
}
mstd(){ python3 -c "
import sys,statistics as s
v=[float(x) for x in sys.argv[1:] if x]
if len(v)<2: print('%.1f 0 0'%(v[0] if v else 0)); sys.exit()
m=s.mean(v); sd=s.pstdev(v); print('%.1f %.1f %.3f'%(m,sd,100*sd/m if m else 0))" "$@"; }
workload(){ local name=$1 sb=$2 args=$3
  log "========== $name  (SB=$sb ; $args) =========="
  declare -A SER LAT IDL; for v in "${VARIANTS[@]}"; do SER[$v]=""; LAT[$v]=""; IDL[$v]=""; done
  for r in $(seq 1 $ROUNDS); do
    local order=$(printf '%s\n' "${VARIANTS[@]}" | shuf | tr '\n' ' ')
    log "$name Round $r/$ROUNDS  order: $order"
    for v in $order; do
      start_variant "$v" "$sb"
      read t l i < <(run_one "$v" "$args")
      SER[$v]+="$t "; LAT[$v]+="$l "; IDL[$v]+="$i "
      log "  $v tps=$t lat=${l}ms cpu_idle=${i}%"
    done
  done
  log "--- $name SUMMARY (mean+-stddev over $ROUNDS rounds) ---"
  local van_mean=$(mstd ${SER[VAN]} | awk '{print $1}')
  for v in "${VARIANTS[@]}"; do
    read m sd cv < <(mstd ${SER[$v]}); read lm lsd lcv < <(mstd ${LAT[$v]})
    local d=$(python3 -c "print('%+.2f'%((($m)-($van_mean))/($van_mean)*100)) if $van_mean else print('NA')")
    log "  $v  TPS mean=$m sd=$sd (cv=${cv}%)  vs VAN: ${d}%   LAT mean=${lm}ms sd=${lsd}  idle≈$(echo ${IDL[$v]}|awk '{print $1}')%"
  done
  # raw series for offline significance testing
  for v in "${VARIANTS[@]}"; do log "  RAW $v TPS: ${SER[$v]}"; done
  for v in "${VARIANTS[@]}"; do log "  RAW $v LAT: ${LAT[$v]}"; done
}
init_scale(){ local sc=$1
  for trip in "$BASE|$BP|$BASE_D" "$STUB|$SP|$STUB_D" "$WET|$WP|$WET_D"; do
    IFS='|' read -r bin port dd <<< "$trip"
    stop_all; set_conf "$dd" shared_buffers 2GB
    su - pgbench -c "$bin/pg_ctl -D $dd -l /tmp/v3/init.log start" >/dev/null 2>&1; sleep 3
    su - pgbench -c "$bin/pgbench -p $port -i -s $sc --no-vacuum postgres 2>&1 | tail -1"
  done; stop_all
}
log "################ W5 latency under headroom, WAIT-HEAVY (buffer-miss, rate-limited 50%) ################"
log "=== init scale 400 (~6GB) on all 3 clusters ==="; init_scale 400 2>&1 | tail -3
workload "W5_latency_waitheavy" 256MB "-S -c 16 -j 16 -R 92000 -P 30"
log "################ W5 COMPLETE ################"

run_w6.sh — W6 cached latency n+5 replicate + pgbench -l percentiles

#!/bin/bash
# W6: cached-latency PERCENTILES + 5 extra rounds (addresses review: paired test power + tail/jitter mechanism).
# Same config as W4 (SB=8GB scale100 -c16 -R108000 -T120) so rounds POOL with W4 -> n=10 paired.
# Only OFF/STA/TRA (the clean same-binary comparison). pgbench -l --sampling-rate to get p95/p99/p99.9 cheaply.
set -uo pipefail
WET=/opt/pg-wet/bin; WD=/data/pg-wet; WP=5441
LOG=/root/bench_w6.log; DUR=120; ROUNDS=5
mkdir -p /tmp/v3; chmod 777 /tmp/v3; : > $LOG
exec > >(tee -a $LOG) 2>&1
log(){ echo "[$(date '+%H:%M:%S')] $*"; }
declare -A VCAP; VCAP[OFF]=off; VCAP[STA]=stats; VCAP[TRA]=trace
VARIANTS=(OFF STA TRA)
set_conf(){ python3 - "$1" "$2" "$3" <<'PY'
import re,sys
p=sys.argv[1]+"/postgresql.conf";k=sys.argv[2];v=sys.argv[3];c=open(p).read()
if re.search(r'^#?\s*'+k+r'\s*=',c,flags=re.M): c=re.sub(r'^#?\s*'+k+r'\s*=.*',f"{k} = '{v}'",c,flags=re.M)
else: c+=f"\n{k} = '{v}'\n"
open(p,"w").write(c)
PY
}
stopw(){ su - pgbench -c "$WET/pg_ctl -D $WD stop -m fast 2>/dev/null; exit 0" >/dev/null 2>&1||true; pkill -9 -u pgbench postgres 2>/dev/null||true; sleep 3; }
start(){ stopw; set_conf $WD shared_buffers 8GB; set_conf $WD wait_event_capture ${VCAP[$1]}; su - pgbench -c "$WET/pg_ctl -D $WD -l /tmp/v3/w6start.log start" >/dev/null 2>&1; sleep 4; }
pctl(){ python3 -c "
import sys,glob,statistics as s
xs=[]
for f in glob.glob(sys.argv[1]+'*'):
    for line in open(f):
        p=line.split()
        if len(p)>=3:
            try: xs.append(float(p[2]))
            except: pass
xs.sort()
if not xs: print('NODATA'); sys.exit()
def q(p): return xs[min(len(xs)-1,int(p*len(xs)))]
print('mean=%.0f p50=%.0f p95=%.0f p99=%.0f p999=%.0f n=%d'%(s.mean(xs),q(.5),q(.95),q(.99),q(.999),len(xs)))
" "$1"; }
log "### W6 cached-latency percentiles + extra rounds (OFF/STA/TRA, -R108000 -T${DUR}, -l 2% sample) ###"
declare -A LAT
for v in "${VARIANTS[@]}"; do LAT[$v]=""; done
for r in $(seq 1 $ROUNDS); do
  order=$(printf '%s\n' "${VARIANTS[@]}" | shuf | tr '\n' ' ')
  log "Round $r/$ROUNDS order: $order"
  for v in $order; do
    start "$v"
    rm -f /tmp/v3/plog_${v}* 2>/dev/null || true
    su - pgbench -c "$WET/pgbench -p $WP -S -c 16 -j 16 -R 108000 -T $DUR -n --no-vacuum -l --sampling-rate=0.02 --log-prefix=/tmp/v3/plog_${v} postgres 2>&1" > /tmp/v3/pg6.txt
    lat=$(grep -oP 'latency average = \K[0-9.]+' /tmp/v3/pg6.txt|head -1)
    pc=$(pctl /tmp/v3/plog_${v})
    LAT[$v]+="$lat "
    log "  $v lat_avg=${lat}ms  pctl(us): $pc"
  done
done
log "--- W6 latency means per round (pool with W4 for n=10 paired) ---"
for v in "${VARIANTS[@]}"; do log "  RAW $v LAT: ${LAT[$v]}"; done
stopw
log "### W6 COMPLETE ###"

build_stub.sh — stub build: patched source, --enable-wait-event-timing OMITTED (Mytkowicz control)

#!/bin/bash
# Build the STUB rung: wet-series source compiled WITHOUT --enable-wait-event-timing (feature #ifdef'd out)
cd /root/pg-src
git checkout -f wet-series 2>&1 | tail -1
git clean -fdxq
./configure --prefix=/opt/pg-stub CC="ccache gcc" CFLAGS="-O2" > /root/stub-configure.log 2>&1 || { echo "CONFIGURE FAIL"; tail -5 /root/stub-configure.log; exit 1; }
# verify the flag is ABSENT (this IS the stub)
if grep -q -- '--enable-wait-event-timing' config.log; then echo "ERROR: flag present, not a stub"; exit 1; fi
make -j16 > /root/stub-make.log 2>&1 || { echo "MAKE FAIL"; tail -8 /root/stub-make.log; exit 1; }
rm -rf /opt/pg-stub; make install > /root/stub-install.log 2>&1 || { echo "INSTALL FAIL"; exit 1; }
# build pg_stat_statements for it too (for parity with the other binaries)
make -C contrib/pg_stat_statements install >> /root/stub-install.log 2>&1
echo "STUB BUILT: $(/opt/pg-stub/bin/pg_config --configure | tr ' ' '\n' | grep -c wait_event) wait flags (expect 0)"
echo "stub pg_config: $(/opt/pg-stub/bin/pg_config --configure)"