Hi, On Thu, Oct 8, 2026 at 10:37 PM Michael Paquier <[email protected]> wrote: > > It would be more correct to me to count the > number of hits as of the *number of pages* we are able to read while > attempting to retrieve "count" bytes worth of WAL in a single call of > WALReadFromBuffers(). > > If we read for example 1GB worth of data in > one call of WALReadFromBuffers() it would be confusing to count that > as 1 hit, that should be (1024^3 / XLOG_BLCKSZ) hits. Let's use a > counter that is incremented while scanning the pages through the while > loop, then increment pg_stat_io once at the end of > WALReadFromBuffers() if (nread > 0).
Done that way.
> In terms of 0002, 0003 and 0005, anybody who does a serious review of
> this patch set will need to run benchmarks to confirm your points. If
> you could post a script, that would be useful IMO. The difficulty of
> this patch is not its implementation, it's the testing.
Sorry for not sharing them earlier. I attached the test scripts I used
for my benchmarking. I also did a new run and shared the results [1].
> I am not convinced that 0004 offers much value if integrated, still it
> seems nice to have to stress the CI.
Agreed. I dropped this patch, since we now know the fix and it works,
and v9 has it for the records.
I also did some correctness testing. I disabled the WAL writer's
opportunistic WAL buffer page initialization and forced the WAL
buffers to 2GB in the code (patch attached for this), so that most of
the WAL is available in the WAL buffers for readers, and ran make
check-world. I don't see any issues except the one TAP test failure
that happens on HEAD as well as with the patches, since it strictly
depends on the WAL buffers size.
Please find the attached v10 patches. I reworded the comments a bit
and rewrote the commit messages.
[1]
With WAL direct IO on, HEAD vs PATCHED, file reads reduced by 99.9%,
53.4% and 64.1%, and WAL disk read IO reduced by 99.9%, 98.9% and
27.8%, for the logical walsender, local WAL reads and WAL summarizer
resp. With WAL direct IO off, file reads reduced by 99.9%, 65.5% and
65.0%.
Test setup: Amazon EC2 r7i.4xlarge instance (16 vCPU, 128 GB RAM),
pg_wal on a dedicated gp3 volume. shared_buffers=8GB,
wal_buffers=16MB, max_wal_size=64GB, synchronous_commit=on. 350 byte
logical messages using pgbench with 16 clients for 180 seconds, while
the reader reads that WAL back. Each is an average of 5 runs.
0002 logical walsender:
# build WAL direct IO TPS WAL generated MB walsender read MB
file reads buffer hits WAL-disk reads WAL-disk writes replication
lag
1 HEAD on 6393 511 1056
204243 0 13.4 MB/s 9.5 MB/s 9.3 KB
2 PATCHED on 7394 591 1.5
198 240183 0.02 MB/s 10.9 MB/s 4.6 KB
3 HEAD off 7368 589 1231
239521 0 0 MB/s 10.8 MB/s 4.6 KB
4 PATCHED off 7321 585 1.8
229 237596 0 MB/s 10.8 MB/s 4.1 KB
0003 local WAL reads:
# build WAL direct IO TPS scans/s WAL generated MB reader read
MB file reads buffer hits WAL-disk reads WAL-disk writes reader
lag
1 HEAD on 6695 313 544 1476
214098 0 10.1 MB/s 9.9 MB/s 22.1 KB
2 PATCHED on 7494 493 612 779
99759 192916 0.11 MB/s 11.1 MB/s 14.9 KB
3 HEAD off 7412 491 606 1878
292188 0 0 MB/s 11.0 MB/s 14.9 KB
4 PATCHED off 7450 493 609 787
100790 193393 0 MB/s 11.0 MB/s 14.9 KB
0004 WAL summarizer:
# build WAL direct IO TPS WAL generated MB summarizer file read
MB file reads buffer hits WAL-disk reads WAL-disk writes
1 HEAD on 7366 578 582
74887 0 10.0 MB/s 12.4 MB/s
2 PATCHED on 7394 580 210
26913 48264 7.2 MB/s 10.8 MB/s
3 HEAD off 7313 574 578
74383 0 0 MB/s 10.6 MB/s
4 PATCHED off 7300 573 204
26057 48792 0 MB/s 10.6 MB/s
--
Bharath Rupireddy
Amazon Web Services: https://aws.amazon.com
v10-0001-Report-pages-read-from-WAL-buffers-in-pg_stat_io.patch
Description: Binary data
v10-0002-Use-WALReadFromBuffers-for-logical-walsenders.patch
Description: Binary data
v10-0003-Use-WALReadFromBuffers-for-local-WAL-reads.patch
Description: Binary data
v10-0004-Use-WALReadFromBuffers-for-WAL-summarizer.patch
Description: Binary data
nocfbot-Disable-opportunistic-WAL-buffer-page-initialization.patch
Description: Binary data
#!/bin/bash
#
# 0002: Use WALReadFromBuffers() for logical walsenders.
#
# Emits WAL with pg_logical_emit_message() and lets pg_recvlogical read it back,
# so the logical walsender is the only WAL reader.
#
# Run once per build, same knobs both times:
# BUILD=HEAD PGBIN=~/pg/head/bin RUNS=3 ./nocfbot-logical_walsender_perf.sh
# BUILD=PATCHED PGBIN=~/pg/patched/bin RUNS=3 ./nocfbot-logical_walsender_perf.sh
#
# Needs test_decoding (make -C contrib/test_decoding install) and sysstat.
set -eo pipefail
PGBIN=${PGBIN:?set PGBIN to the bin directory of the build under test}
BUILD=${BUILD:-HEAD}
RUNS=${RUNS:-3}
DURATION=${DURATION:-180}
CLIENTS=${CLIENTS:-16}
DIRECT_IO=${DIRECT_IO:-"on off"}
DATA_ROOT=${DATA_ROOT:-/pgdata}
PGDATA=${PGDATA:-$DATA_ROOT/$BUILD/walsender-data}
WALDIR=${WALDIR:-}
PORT=${PORT:-5432}
SHARED_BUFFERS=${SHARED_BUFFERS:-8GB}
WAL_BUFFERS=${WAL_BUFFERS:-16MB}
MAX_WAL_SIZE=${MAX_WAL_SIZE:-64GB}
OUTDIR=${OUTDIR:-$HOME/wal-read-perf/walsender-$BUILD-$(date -u +%Y%m%d-%H%M%S)}
export PGHOST=/tmp PGPORT=$PORT PGDATABASE=postgres
PATH=$PGBIN:$PATH
mkdir -p "$OUTDIR"
CSV=$OUTDIR/runs.csv
SUMMARY=$OUTDIR/SUMMARY.txt
FMT='%-8s %-14s %-9s %-18s %-18s %-12s %-13s %-15s %-16s %s\n'
psql_q() { psql -Atq -F' ' -c "$1"; }
pg_start() {
pg_ctl -D "$PGDATA" -l "$OUTDIR/server-$1.log" -w start >/dev/null ||
{ echo "server did not start, see $OUTDIR/server-$1.log"; exit 1; }
}
pg_stop() { pg_ctl -D "$PGDATA" -m fast -w stop >/dev/null 2>&1 || true; }
BG_PIDS=()
trap 'kill ${BG_PIDS[@]} 2>/dev/null || true; pg_stop' EXIT
# median of the per-run values: integers for counts and large values, more
# digits only where a small value would otherwise round away to nothing
median() { printf '%s\n' "$@" | sort -n |
awk '{a[NR]=$1} END {m = (NR%2) ? a[(NR+1)/2] : (a[NR/2]+a[NR/2+1])/2
fmt = (m == int(m)) ? "%d\n" : (m >= 100) ? "%.0f\n" : (m >= 1) ? "%.1f\n" : "%.2f\n"
printf fmt, m}'; }
# peak read and write MB/s, skipping iostat's first since-boot report
iostat_peak() {
[ -s "$1" ] || { echo "0 0"; return; }
awk '/^Device/ { hdr++; for (i = 1; i <= NF; i++) { if ($i == "rMB/s") r = i; if ($i == "wMB/s") w = i } next }
hdr >= 2 && r > 0 && NF > 3 { if ($r > pr) pr = $r; if ($w > pw) pw = $w }
END { printf "%.2f %.2f\n", pr, pw }' "$1"
}
# assert builds and a build that overrides wal_buffers make the numbers useless
check_server() {
[ "$(psql_q "SELECT current_setting('debug_assertions')")" = off ] || [ "${ALLOW_CASSERT:-0}" = 1 ] ||
{ echo "$PGBIN is an assert-enabled build, use a release build or set ALLOW_CASSERT=1"; exit 1; }
[ "$(psql_q "SELECT pg_size_bytes(current_setting('wal_buffers')) = pg_size_bytes('$WAL_BUFFERS')")" = t ] ||
{ echo "wal_buffers is $(psql_q "SELECT current_setting('wal_buffers')"), not the requested $WAL_BUFFERS: this build forces it"; exit 1; }
}
setup_cluster() {
if [ ! -s "$PGDATA/PG_VERSION" ]; then
mkdir -p "$(dirname "$PGDATA")" "${WALDIR:-$PGDATA}"
initdb -D "$PGDATA" --no-sync ${WALDIR:+-X "$WALDIR"} >"$OUTDIR/initdb.log" 2>&1
fi
grep -q "include 'bench.conf'" "$PGDATA/postgresql.conf" ||
echo "include 'bench.conf'" >>"$PGDATA/postgresql.conf"
[ -f "$(pg_config --pkglibdir)/test_decoding.so" ] ||
{ echo "test_decoding not installed: make -C contrib/test_decoding install"; exit 1; }
}
write_conf() { # $1 = debug_io_direct value ('wal' or '')
cat >"$PGDATA/bench.conf" <<EOF
port = $PORT
unix_socket_directories = '/tmp'
shared_buffers = $SHARED_BUFFERS
wal_buffers = $WAL_BUFFERS
max_wal_size = $MAX_WAL_SIZE
synchronous_commit = on
wal_level = logical
track_io_timing = on
debug_io_direct = '$1'
EOF
}
detect_wal_dev() {
local src
src=$(df --output=source "$PGDATA/pg_wal" | tail -1)
lsblk -no PKNAME "$src" 2>/dev/null | head -1 | grep . || basename "$src"
}
sample_lag() { # $1 = output file
while :; do
psql_q "SELECT round(coalesce(max(pg_wal_lsn_diff(pg_current_wal_lsn(), sent_lsn))/1024.0, 0), 1) FROM pg_stat_replication" 2>/dev/null
sleep 5
done >"$1"
}
run_one() { # $1 = direct io label (on|off), $2 = run number
local dio=$1 run=$2 tag="$BUILD-dio$1-run$2"
psql_q "SELECT pg_drop_replication_slot('bench') FROM pg_replication_slots WHERE slot_name = 'bench'" >/dev/null
psql_q "SELECT pg_create_logical_replication_slot('bench', 'test_decoding')" >/dev/null
psql_q "CHECKPOINT" >/dev/null
psql_q "SELECT pg_stat_reset_shared('io')" >/dev/null
local start_lsn ios= recv lag
start_lsn=$(psql_q "SELECT pg_current_wal_lsn()")
pg_recvlogical -d postgres --slot bench --start -f /dev/null \
>"$OUTDIR/recvlogical-$tag.log" 2>&1 &
recv=$!; disown $recv 2>/dev/null || true
if [ "$WAL_DEV" != none ]; then
iostat -dxm 1 "$WAL_DEV" >"$OUTDIR/iostat-$tag.log" 2>/dev/null &
ios=$!; disown $ios 2>/dev/null || true
fi
sample_lag "$OUTDIR/lag-$tag.log" &
lag=$!; disown $lag 2>/dev/null || true
BG_PIDS=($recv $ios $lag)
sleep 2
pgbench -n -f "$OUTDIR/emit.sql" -c "$CLIENTS" -j "$CLIENTS" -T "$DURATION" -P 10 \
>"$OUTDIR/pgbench-$tag.txt" 2>&1
local wal_mb
wal_mb=$(psql_q "SELECT round(pg_wal_lsn_diff(pg_current_wal_lsn(), '$start_lsn')/1048576.0, 1)")
kill $ios $lag $recv 2>/dev/null || true
BG_PIDS=()
# the walsender flushes its stats when it exits, so wait for it to go away
for i in $(seq 1 15); do
[ "$(psql_q "SELECT count(*) FROM pg_stat_replication")" = 0 ] && break
sleep 1
done
sleep 1
local tps read_mb hits reads pr pw lag_kb
tps=$(awk '/^tps =/ {print $3}' "$OUTDIR/pgbench-$tag.txt" | tail -1)
read -r read_mb hits reads <<<"$(psql_q "SELECT round(coalesce(sum(read_bytes), 0)/1048576.0, 1), coalesce(sum(hits), 0), coalesce(sum(reads), 0) FROM pg_stat_io WHERE backend_type = 'walsender' AND object = 'wal'")"
read -r pr pw <<<"$(iostat_peak "$OUTDIR/iostat-$tag.log")"
lag_kb=$(sort -n "$OUTDIR/lag-$tag.log" 2>/dev/null | tail -1)
: "${lag_kb:=0}"
echo "$BUILD,$dio,$run,$tps,$wal_mb,$read_mb,$reads,$hits,$pr,$pw,$lag_kb" | tee -a "$CSV"
R_TPS+=("$tps"); R_WAL+=("$wal_mb"); R_READ+=("$read_mb"); R_READS+=("$reads")
R_HITS+=("$hits"); R_DR+=("$pr"); R_DW+=("$pw"); R_LAG+=("$lag_kb")
}
echo "SELECT pg_logical_emit_message(true, 'bench', repeat('x', 350));" >"$OUTDIR/emit.sql"
setup_cluster
WAL_DEV=${WAL_DEV:-$(detect_wal_dev)}
[ -n "$WAL_DEV" ] || { echo "could not detect the pg_wal device, set WAL_DEV"; exit 1; }
[ "$WAL_DEV" = none ] || command -v iostat >/dev/null ||
{ echo "iostat not found: install sysstat, or set WAL_DEV=none to skip disk sampling"; exit 1; }
echo "build=$BUILD pgdata=$PGDATA wal_dev=$WAL_DEV runs=$RUNS duration=${DURATION}s clients=$CLIENTS out=$OUTDIR"
echo "build,direct_io,run,tps,wal_generated_mb,walsender_read_mb,reads,hits,disk_read_peak_mbs,disk_write_peak_mbs,lag_kb" >"$CSV"
{
echo "logical walsender, build=$BUILD"
echo "shared_buffers=$SHARED_BUFFERS wal_buffers=$WAL_BUFFERS max_wal_size=$MAX_WAL_SIZE synchronous_commit=on"
echo "workload: pgbench -n -f emit.sql -c $CLIENTS -j $CLIENTS -T $DURATION, reader: pg_recvlogical -f /dev/null"
echo "runs=$RUNS (median reported), wal device=$WAL_DEV"
echo "binary: $PGBIN, $(pg_config --version)"
echo
printf "$FMT" build "WAL direct IO" TPS "WAL generated MB" "walsender read MB" \
"file reads" "buffer hits" "WAL-disk reads" "WAL-disk writes" "replication lag"
} >"$SUMMARY"
for dio in $DIRECT_IO; do
if [ "$dio" = on ]; then write_conf wal; else write_conf ''; fi
pg_stop
pg_start "$BUILD-dio$dio"
check_server
# report what the server actually used, a build may override these
psql_q "SELECT name || ' = ' || current_setting(name) FROM pg_settings WHERE name IN ('shared_buffers', 'wal_buffers', 'max_wal_size', 'synchronous_commit', 'wal_level', 'debug_io_direct', 'summarize_wal', 'wal_writer_delay')" >"$OUTDIR/settings-$dio.txt"
echo "direct IO $dio: effective wal_buffers=$(psql_q "SELECT current_setting('wal_buffers')") debug_io_direct='$(psql_q "SELECT current_setting('debug_io_direct')")'"
R_TPS=(); R_WAL=(); R_READ=(); R_READS=(); R_HITS=(); R_DR=(); R_DW=(); R_LAG=()
for run in $(seq 1 "$RUNS"); do run_one "$dio" "$run"; done
printf "$FMT" "$BUILD" "$dio" "$(median "${R_TPS[@]}")" "$(median "${R_WAL[@]}")" \
"$(median "${R_READ[@]}")" "$(median "${R_READS[@]}")" "$(median "${R_HITS[@]}")" \
"$(median "${R_DR[@]}") MB/s" "$(median "${R_DW[@]}") MB/s" \
"$(median "${R_LAG[@]}") KB" >>"$SUMMARY"
pg_stop
done
cat "$SUMMARY"
echo "per-run rows and effective settings in $OUTDIR"
#!/bin/bash
#
# 0003: Use WALReadFromBuffers() for local WAL reads.
#
# Emits WAL with pg_logical_emit_message() while one backend scans it back with
# pg_walinspect, which reads through read_local_xlog_page().
#
# Run once per build, same knobs both times:
# BUILD=HEAD PGBIN=~/pg/head/bin RUNS=3 ./nocfbot-local_wal_read_perf.sh
# BUILD=PATCHED PGBIN=~/pg/patched/bin RUNS=3 ./nocfbot-local_wal_read_perf.sh
#
# Needs pg_walinspect (make -C contrib/pg_walinspect install) and sysstat.
set -eo pipefail
PGBIN=${PGBIN:?set PGBIN to the bin directory of the build under test}
BUILD=${BUILD:-HEAD}
RUNS=${RUNS:-3}
DURATION=${DURATION:-180}
CLIENTS=${CLIENTS:-16}
DRAIN=${DRAIN:-30}
SCAN_SLEEP=${SCAN_SLEEP:-0}
DIRECT_IO=${DIRECT_IO:-"on off"}
DATA_ROOT=${DATA_ROOT:-/pgdata}
PGDATA=${PGDATA:-$DATA_ROOT/$BUILD/localread-data}
WALDIR=${WALDIR:-}
PORT=${PORT:-5432}
SHARED_BUFFERS=${SHARED_BUFFERS:-8GB}
WAL_BUFFERS=${WAL_BUFFERS:-16MB}
MAX_WAL_SIZE=${MAX_WAL_SIZE:-64GB}
OUTDIR=${OUTDIR:-$HOME/wal-read-perf/localread-$BUILD-$(date -u +%Y%m%d-%H%M%S)}
export PGHOST=/tmp PGPORT=$PORT PGDATABASE=postgres
PATH=$PGBIN:$PATH
mkdir -p "$OUTDIR"
CSV=$OUTDIR/runs.csv
SUMMARY=$OUTDIR/SUMMARY.txt
FMT='%-8s %-14s %-9s %-11s %-18s %-20s %-12s %-13s %-15s %-16s %s\n'
psql_q() { psql -Atq -F' ' -c "$1"; }
pg_start() {
pg_ctl -D "$PGDATA" -l "$OUTDIR/server-$1.log" -w start >/dev/null ||
{ echo "server did not start, see $OUTDIR/server-$1.log"; exit 1; }
}
pg_stop() { pg_ctl -D "$PGDATA" -m fast -w stop >/dev/null 2>&1 || true; }
BG_PIDS=()
trap 'kill ${BG_PIDS[@]} 2>/dev/null || true; pg_stop' EXIT
# median of the per-run values: integers for counts and large values, more
# digits only where a small value would otherwise round away to nothing
median() { printf '%s\n' "$@" | sort -n |
awk '{a[NR]=$1} END {m = (NR%2) ? a[(NR+1)/2] : (a[NR/2]+a[NR/2+1])/2
fmt = (m == int(m)) ? "%d\n" : (m >= 100) ? "%.0f\n" : (m >= 1) ? "%.1f\n" : "%.2f\n"
printf fmt, m}'; }
# peak read and write MB/s, skipping iostat's first since-boot report
iostat_peak() {
[ -s "$1" ] || { echo "0 0"; return; }
awk '/^Device/ { hdr++; for (i = 1; i <= NF; i++) { if ($i == "rMB/s") r = i; if ($i == "wMB/s") w = i } next }
hdr >= 2 && r > 0 && NF > 3 { if ($r > pr) pr = $r; if ($w > pw) pw = $w }
END { printf "%.2f %.2f\n", pr, pw }' "$1"
}
# assert builds and a build that overrides wal_buffers make the numbers useless
check_server() {
[ "$(psql_q "SELECT current_setting('debug_assertions')")" = off ] || [ "${ALLOW_CASSERT:-0}" = 1 ] ||
{ echo "$PGBIN is an assert-enabled build, use a release build or set ALLOW_CASSERT=1"; exit 1; }
[ "$(psql_q "SELECT pg_size_bytes(current_setting('wal_buffers')) = pg_size_bytes('$WAL_BUFFERS')")" = t ] ||
{ echo "wal_buffers is $(psql_q "SELECT current_setting('wal_buffers')"), not the requested $WAL_BUFFERS: this build forces it"; exit 1; }
}
setup_cluster() {
if [ ! -s "$PGDATA/PG_VERSION" ]; then
mkdir -p "$(dirname "$PGDATA")" "${WALDIR:-$PGDATA}"
initdb -D "$PGDATA" --no-sync ${WALDIR:+-X "$WALDIR"} >"$OUTDIR/initdb.log" 2>&1
fi
grep -q "include 'bench.conf'" "$PGDATA/postgresql.conf" ||
echo "include 'bench.conf'" >>"$PGDATA/postgresql.conf"
[ -f "$(pg_config --pkglibdir)/pg_walinspect.so" ] ||
{ echo "pg_walinspect not installed: make -C contrib/pg_walinspect install"; exit 1; }
}
write_conf() { # $1 = debug_io_direct value ('wal' or '')
cat >"$PGDATA/bench.conf" <<EOF
port = $PORT
unix_socket_directories = '/tmp'
shared_buffers = $SHARED_BUFFERS
wal_buffers = $WAL_BUFFERS
max_wal_size = $MAX_WAL_SIZE
synchronous_commit = on
wal_level = logical
track_io_timing = on
debug_io_direct = '$1'
EOF
}
detect_wal_dev() {
local src
src=$(df --output=source "$PGDATA/pg_wal" | tail -1)
lsblk -no PKNAME "$src" 2>/dev/null | head -1 | grep . || basename "$src"
}
sample_lag() { # $1 = output file; how far the reader trails the insert point
while :; do
psql_q "SELECT round(pg_wal_lsn_diff(pg_current_wal_lsn(), lsn)/1024.0, 1) FROM wal_scan_pos" 2>/dev/null
sleep 5
done >"$1"
}
# the reader: one forward step from where the last step stopped to the flush point
setup_reader() {
psql_q "CREATE EXTENSION IF NOT EXISTS pg_walinspect" >/dev/null
psql_q "CREATE UNLOGGED TABLE IF NOT EXISTS wal_scan_pos (lsn pg_lsn)" >/dev/null
psql_q "CREATE OR REPLACE FUNCTION wal_scan_step() RETURNS bigint LANGUAGE plpgsql AS \$fn\$
DECLARE s pg_lsn; e pg_lsn; n bigint := 0;
BEGIN
SELECT lsn INTO s FROM wal_scan_pos FOR UPDATE;
e := pg_current_wal_flush_lsn();
IF e > s THEN
-- the flush point can land mid record, in which case there is no
-- complete record after s yet; leave the cursor and retry later
BEGIN
SELECT coalesce(sum(count), 0) INTO n FROM pg_get_wal_stats(s, e);
UPDATE wal_scan_pos SET lsn = e;
EXCEPTION WHEN others THEN
PERFORM pg_sleep(0.001);
END;
ELSE
PERFORM pg_sleep(0.001); -- nothing new yet, do not spin
END IF;
RETURN n;
END \$fn\$" >/dev/null
psql_q "TRUNCATE wal_scan_pos" >/dev/null
psql_q "INSERT INTO wal_scan_pos VALUES (pg_current_wal_flush_lsn())" >/dev/null
}
run_one() { # $1 = direct io label (on|off), $2 = run number
local dio=$1 run=$2 tag="$BUILD-dio$1-run$2" start_lsn ios= dec lag
setup_reader
psql_q "CHECKPOINT" >/dev/null
psql_q "SELECT pg_stat_reset_shared('io')" >/dev/null
start_lsn=$(psql_q "SELECT pg_current_wal_lsn()")
if [ "$WAL_DEV" != none ]; then
iostat -dxm 1 "$WAL_DEV" >"$OUTDIR/iostat-$tag.log" 2>/dev/null &
ios=$!; disown $ios 2>/dev/null || true
fi
sample_lag "$OUTDIR/lag-$tag.log" &
lag=$!; disown $lag 2>/dev/null || true
# the reader keeps scanning for DRAIN seconds after the emitters stop
pgbench -n -f "$OUTDIR/scan.sql" -c 1 -j 1 -T $((DURATION + DRAIN)) \
>"$OUTDIR/scan-$tag.txt" 2>&1 &
dec=$!
BG_PIDS=($ios $lag $dec)
sleep 2
pgbench -n -f "$OUTDIR/emit.sql" -c "$CLIENTS" -j "$CLIENTS" -T "$DURATION" -P 10 \
>"$OUTDIR/pgbench-$tag.txt" 2>&1
local wal_mb
wal_mb=$(psql_q "SELECT round(pg_wal_lsn_diff(pg_current_wal_lsn(), '$start_lsn')/1048576.0, 1)")
wait $dec 2>/dev/null || true
kill $ios $lag 2>/dev/null || true
BG_PIDS=()
sleep 3 # let the exited backends' stats land
local tps dtps read_mb hits reads pr pw lag_kb
tps=$(awk '/^tps =/ {print $3}' "$OUTDIR/pgbench-$tag.txt" | tail -1)
dtps=$(awk '/^tps =/ {print $3}' "$OUTDIR/scan-$tag.txt" | tail -1)
read -r read_mb hits reads <<<"$(psql_q "SELECT round(coalesce(sum(read_bytes), 0)/1048576.0, 1), coalesce(sum(hits), 0), coalesce(sum(reads), 0) FROM pg_stat_io WHERE backend_type = 'client backend' AND object = 'wal'")"
read -r pr pw <<<"$(iostat_peak "$OUTDIR/iostat-$tag.log")"
lag_kb=$(sort -n "$OUTDIR/lag-$tag.log" 2>/dev/null | tail -1)
: "${lag_kb:=0}"
echo "$BUILD,$dio,$run,$tps,$dtps,$wal_mb,$read_mb,$reads,$hits,$pr,$pw,$lag_kb" | tee -a "$CSV"
R_TPS+=("$tps"); R_DTPS+=("$dtps"); R_WAL+=("$wal_mb"); R_READ+=("$read_mb")
R_READS+=("$reads"); R_HITS+=("$hits"); R_DR+=("$pr"); R_DW+=("$pw"); R_LAG+=("$lag_kb")
}
echo "SELECT pg_logical_emit_message(true, 'bench', repeat('x', 350));" >"$OUTDIR/emit.sql"
echo "SELECT wal_scan_step();" >"$OUTDIR/scan.sql"
[ "$SCAN_SLEEP" = 0 ] || echo "SELECT pg_sleep($SCAN_SLEEP);" >>"$OUTDIR/scan.sql"
setup_cluster
WAL_DEV=${WAL_DEV:-$(detect_wal_dev)}
[ -n "$WAL_DEV" ] || { echo "could not detect the pg_wal device, set WAL_DEV"; exit 1; }
[ "$WAL_DEV" = none ] || command -v iostat >/dev/null ||
{ echo "iostat not found: install sysstat, or set WAL_DEV=none to skip disk sampling"; exit 1; }
echo "build=$BUILD pgdata=$PGDATA wal_dev=$WAL_DEV runs=$RUNS duration=${DURATION}s clients=$CLIENTS out=$OUTDIR"
echo "build,direct_io,run,emit_tps,scans_per_sec,wal_generated_mb,reader_read_mb,reads,hits,disk_read_peak_mbs,disk_write_peak_mbs,lag_kb" >"$CSV"
{
echo "local WAL reads via pg_walinspect forward scan, build=$BUILD"
echo "shared_buffers=$SHARED_BUFFERS wal_buffers=$WAL_BUFFERS max_wal_size=$MAX_WAL_SIZE synchronous_commit=on"
echo "workload: pgbench -n -f emit.sql -c $CLIENTS -j $CLIENTS -T $DURATION, reader: pg_get_wal_stats() forward scan (1 client, +${DRAIN}s drain)"
echo "runs=$RUNS (median reported), wal device=$WAL_DEV"
echo "binary: $PGBIN, $(pg_config --version)"
echo
printf "$FMT" build "WAL direct IO" TPS "scans/s" "WAL generated MB" "reader read MB" \
"file reads" "buffer hits" "WAL-disk reads" "WAL-disk writes" "reader lag"
} >"$SUMMARY"
for dio in $DIRECT_IO; do
if [ "$dio" = on ]; then write_conf wal; else write_conf ''; fi
pg_stop
pg_start "$BUILD-dio$dio"
check_server
# report what the server actually used, a build may override these
psql_q "SELECT name || ' = ' || current_setting(name) FROM pg_settings WHERE name IN ('shared_buffers', 'wal_buffers', 'max_wal_size', 'synchronous_commit', 'wal_level', 'debug_io_direct', 'summarize_wal', 'wal_writer_delay')" >"$OUTDIR/settings-$dio.txt"
echo "direct IO $dio: effective wal_buffers=$(psql_q "SELECT current_setting('wal_buffers')") debug_io_direct='$(psql_q "SELECT current_setting('debug_io_direct')")'"
R_TPS=(); R_DTPS=(); R_WAL=(); R_READ=(); R_READS=(); R_HITS=(); R_DR=(); R_DW=(); R_LAG=()
for run in $(seq 1 "$RUNS"); do run_one "$dio" "$run"; done
printf "$FMT" "$BUILD" "$dio" "$(median "${R_TPS[@]}")" "$(median "${R_DTPS[@]}")" \
"$(median "${R_WAL[@]}")" "$(median "${R_READ[@]}")" "$(median "${R_READS[@]}")" \
"$(median "${R_HITS[@]}")" "$(median "${R_DR[@]}") MB/s" "$(median "${R_DW[@]}") MB/s" \
"$(median "${R_LAG[@]}") KB" >>"$SUMMARY"
pg_stop
done
cat "$SUMMARY"
echo "per-run rows and effective settings in $OUTDIR"
#!/bin/bash
#
# 0004: Use WALReadFromBuffers() for WAL summarizer.
#
# Emits WAL with pg_logical_emit_message() and lets the WAL summarizer read it
# back (summarize_wal = on), so it is the only WAL reader.
#
# Run once per build, same knobs both times:
# BUILD=HEAD PGBIN=~/pg/head/bin RUNS=3 ./nocfbot-wal_summarizer_perf.sh
# BUILD=PATCHED PGBIN=~/pg/patched/bin RUNS=3 ./nocfbot-wal_summarizer_perf.sh
#
# Needs sysstat.
set -eo pipefail
PGBIN=${PGBIN:?set PGBIN to the bin directory of the build under test}
BUILD=${BUILD:-HEAD}
RUNS=${RUNS:-3}
DURATION=${DURATION:-180}
CLIENTS=${CLIENTS:-16}
DIRECT_IO=${DIRECT_IO:-"on off"}
DATA_ROOT=${DATA_ROOT:-/pgdata}
PGDATA=${PGDATA:-$DATA_ROOT/$BUILD/walsummary-data}
WALDIR=${WALDIR:-}
PORT=${PORT:-5432}
SHARED_BUFFERS=${SHARED_BUFFERS:-8GB}
WAL_BUFFERS=${WAL_BUFFERS:-16MB}
MAX_WAL_SIZE=${MAX_WAL_SIZE:-64GB}
WAL_LEVEL=${WAL_LEVEL:-replica}
CATCHUP_TIMEOUT=${CATCHUP_TIMEOUT:-300}
OUTDIR=${OUTDIR:-$HOME/wal-read-perf/walsummary-$BUILD-$(date -u +%Y%m%d-%H%M%S)}
export PGHOST=/tmp PGPORT=$PORT PGDATABASE=postgres
PATH=$PGBIN:$PATH
mkdir -p "$OUTDIR"
CSV=$OUTDIR/runs.csv
SUMMARY=$OUTDIR/SUMMARY.txt
FMT='%-8s %-14s %-9s %-18s %-24s %-12s %-13s %-15s %s\n'
psql_q() { psql -Atq -F' ' -c "$1"; }
pg_start() {
pg_ctl -D "$PGDATA" -l "$OUTDIR/server-$1.log" -w start >/dev/null ||
{ echo "server did not start, see $OUTDIR/server-$1.log"; exit 1; }
}
pg_stop() { pg_ctl -D "$PGDATA" -m fast -w stop >/dev/null 2>&1 || true; }
BG_PIDS=()
trap 'kill ${BG_PIDS[@]} 2>/dev/null || true; pg_stop' EXIT
# median of the per-run values: integers for counts and large values, more
# digits only where a small value would otherwise round away to nothing
median() { printf '%s\n' "$@" | sort -n |
awk '{a[NR]=$1} END {m = (NR%2) ? a[(NR+1)/2] : (a[NR/2]+a[NR/2+1])/2
fmt = (m == int(m)) ? "%d\n" : (m >= 100) ? "%.0f\n" : (m >= 1) ? "%.1f\n" : "%.2f\n"
printf fmt, m}'; }
# peak read and write MB/s, skipping iostat's first since-boot report
iostat_peak() {
[ -s "$1" ] || { echo "0 0"; return; }
awk '/^Device/ { hdr++; for (i = 1; i <= NF; i++) { if ($i == "rMB/s") r = i; if ($i == "wMB/s") w = i } next }
hdr >= 2 && r > 0 && NF > 3 { if ($r > pr) pr = $r; if ($w > pw) pw = $w }
END { printf "%.2f %.2f\n", pr, pw }' "$1"
}
# assert builds and a build that overrides wal_buffers make the numbers useless
check_server() {
[ "$(psql_q "SELECT current_setting('debug_assertions')")" = off ] || [ "${ALLOW_CASSERT:-0}" = 1 ] ||
{ echo "$PGBIN is an assert-enabled build, use a release build or set ALLOW_CASSERT=1"; exit 1; }
[ "$(psql_q "SELECT pg_size_bytes(current_setting('wal_buffers')) = pg_size_bytes('$WAL_BUFFERS')")" = t ] ||
{ echo "wal_buffers is $(psql_q "SELECT current_setting('wal_buffers')"), not the requested $WAL_BUFFERS: this build forces it"; exit 1; }
}
setup_cluster() {
if [ ! -s "$PGDATA/PG_VERSION" ]; then
mkdir -p "$(dirname "$PGDATA")" "${WALDIR:-$PGDATA}"
initdb -D "$PGDATA" --no-sync ${WALDIR:+-X "$WALDIR"} >"$OUTDIR/initdb.log" 2>&1
fi
grep -q "include 'bench.conf'" "$PGDATA/postgresql.conf" ||
echo "include 'bench.conf'" >>"$PGDATA/postgresql.conf"
}
write_conf() { # $1 = debug_io_direct value ('wal' or '')
cat >"$PGDATA/bench.conf" <<EOF
port = $PORT
unix_socket_directories = '/tmp'
shared_buffers = $SHARED_BUFFERS
wal_buffers = $WAL_BUFFERS
max_wal_size = $MAX_WAL_SIZE
synchronous_commit = on
wal_level = $WAL_LEVEL
summarize_wal = on
track_io_timing = on
debug_io_direct = '$1'
EOF
}
detect_wal_dev() {
local src
src=$(df --output=source "$PGDATA/pg_wal" | tail -1)
lsblk -no PKNAME "$src" 2>/dev/null | head -1 | grep . || basename "$src"
}
# summarized_lsn only advances when a summary file is written, which happens at a
# segment boundary or a redo point, so force both before waiting on it
flush_summaries() {
psql_q "SELECT pg_switch_wal()" >/dev/null
psql_q "CHECKPOINT" >/dev/null
}
wait_summarized() { # $1 = LSN to wait for
local i
for i in $(seq 1 "$CATCHUP_TIMEOUT"); do
[ "$(psql_q "SELECT summarized_lsn >= '$1'::pg_lsn FROM pg_get_wal_summarizer_state()")" = t ] && return 0
sleep 1
done
echo " warning: summarizer did not catch up to $1 within ${CATCHUP_TIMEOUT}s"
}
run_one() { # $1 = direct io label (on|off), $2 = run number
local dio=$1 run=$2 tag="$BUILD-dio$1-run$2" pre start_lsn end_lsn ios=
pre=$(psql_q "SELECT pg_current_wal_lsn()")
flush_summaries
wait_summarized "$pre"
psql_q "SELECT pg_stat_reset_shared('io')" >/dev/null
start_lsn=$(psql_q "SELECT pg_current_wal_lsn()")
if [ "$WAL_DEV" != none ]; then
iostat -dxm 1 "$WAL_DEV" >"$OUTDIR/iostat-$tag.log" 2>/dev/null &
ios=$!; disown $ios 2>/dev/null || true
BG_PIDS=($ios)
fi
pgbench -n -f "$OUTDIR/emit.sql" -c "$CLIENTS" -j "$CLIENTS" -T "$DURATION" -P 10 \
>"$OUTDIR/pgbench-$tag.txt" 2>&1
end_lsn=$(psql_q "SELECT pg_current_wal_lsn()")
local wal_mb
wal_mb=$(psql_q "SELECT round(pg_wal_lsn_diff('$end_lsn', '$start_lsn')/1048576.0, 1)")
flush_summaries
wait_summarized "$end_lsn"
kill $ios 2>/dev/null || true
BG_PIDS=()
sleep 3 # let the summarizer's stats land
local tps read_mb hits reads pr pw
tps=$(awk '/^tps =/ {print $3}' "$OUTDIR/pgbench-$tag.txt" | tail -1)
read -r read_mb hits reads <<<"$(psql_q "SELECT round(coalesce(sum(read_bytes), 0)/1048576.0, 1), coalesce(sum(hits), 0), coalesce(sum(reads), 0) FROM pg_stat_io WHERE backend_type = 'walsummarizer' AND object = 'wal'")"
read -r pr pw <<<"$(iostat_peak "$OUTDIR/iostat-$tag.log")"
echo "$BUILD,$dio,$run,$tps,$wal_mb,$read_mb,$reads,$hits,$pr,$pw" | tee -a "$CSV"
R_TPS+=("$tps"); R_WAL+=("$wal_mb"); R_READ+=("$read_mb"); R_READS+=("$reads")
R_HITS+=("$hits"); R_DR+=("$pr"); R_DW+=("$pw")
}
echo "SELECT pg_logical_emit_message(true, 'bench', repeat('x', 350));" >"$OUTDIR/emit.sql"
setup_cluster
WAL_DEV=${WAL_DEV:-$(detect_wal_dev)}
[ -n "$WAL_DEV" ] || { echo "could not detect the pg_wal device, set WAL_DEV"; exit 1; }
[ "$WAL_DEV" = none ] || command -v iostat >/dev/null ||
{ echo "iostat not found: install sysstat, or set WAL_DEV=none to skip disk sampling"; exit 1; }
echo "build=$BUILD pgdata=$PGDATA wal_dev=$WAL_DEV runs=$RUNS duration=${DURATION}s clients=$CLIENTS out=$OUTDIR"
echo "build,direct_io,run,tps,wal_generated_mb,summarizer_read_mb,reads,hits,disk_read_peak_mbs,disk_write_peak_mbs" >"$CSV"
{
echo "WAL summarizer, build=$BUILD"
echo "shared_buffers=$SHARED_BUFFERS wal_buffers=$WAL_BUFFERS max_wal_size=$MAX_WAL_SIZE synchronous_commit=on wal_level=$WAL_LEVEL summarize_wal=on"
echo "workload: pgbench -n -f emit.sql -c $CLIENTS -j $CLIENTS -T $DURATION, reader: WAL summarizer"
echo "runs=$RUNS (median reported), wal device=$WAL_DEV"
echo "binary: $PGBIN, $(pg_config --version)"
echo
printf "$FMT" build "WAL direct IO" TPS "WAL generated MB" "summarizer file read MB" \
"file reads" "buffer hits" "WAL-disk reads" "WAL-disk writes"
} >"$SUMMARY"
for dio in $DIRECT_IO; do
if [ "$dio" = on ]; then write_conf wal; else write_conf ''; fi
pg_stop
pg_start "$BUILD-dio$dio"
check_server
# report what the server actually used, a build may override these
psql_q "SELECT name || ' = ' || current_setting(name) FROM pg_settings WHERE name IN ('shared_buffers', 'wal_buffers', 'max_wal_size', 'synchronous_commit', 'wal_level', 'debug_io_direct', 'summarize_wal', 'wal_writer_delay')" >"$OUTDIR/settings-$dio.txt"
echo "direct IO $dio: effective wal_buffers=$(psql_q "SELECT current_setting('wal_buffers')") debug_io_direct='$(psql_q "SELECT current_setting('debug_io_direct')")'"
R_TPS=(); R_WAL=(); R_READ=(); R_READS=(); R_HITS=(); R_DR=(); R_DW=()
for run in $(seq 1 "$RUNS"); do run_one "$dio" "$run"; done
printf "$FMT" "$BUILD" "$dio" "$(median "${R_TPS[@]}")" "$(median "${R_WAL[@]}")" \
"$(median "${R_READ[@]}")" "$(median "${R_READS[@]}")" "$(median "${R_HITS[@]}")" \
"$(median "${R_DR[@]}") MB/s" "$(median "${R_DW[@]}") MB/s" >>"$SUMMARY"
pg_stop
done
cat "$SUMMARY"
echo "per-run rows and effective settings in $OUTDIR"
