Subject: [PATCH v13 4/4] Expose WAL usage counters in verbose (auto)vacuum output.

From: Julien Rouhaud <[email-masked]>
Date: Thu, 19 Mar 2020 16:08:47 +0100

Author: Julien Rouhaud
Reviewed-by: Fuji Masao
Discussion: https://postgr.es/m/CAB-hujrP8ZfUkvL5OYETipQwA=e3n7oqHFU=[email-masked]
---
 src/backend/access/heap/vacuumlazy.c | 24 +++++++++++++++++++++++-
 1 file changed, 23 insertions(+), 1 deletion(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index cc7e8521a5..735087dd74 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -410,6 +410,8 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
 	int			nindexes;
 	PGRUsage	ru0;
 	TimestampTz starttime = 0;
+	WalUsage walusage_start = pgWalUsage;
+	WalUsage walusage = {0, 0, 0};
 	long		secs;
 	int			usecs;
 	double		read_rate,
@@ -614,6 +616,9 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
 
 			TimestampDifference(starttime, endtime, &secs, &usecs);
 
+			memset(&walusage, 0, sizeof(WalUsage));
+			WalUsageAccumDiff(&walusage, &pgWalUsage, &walusage_start);
+
 			read_rate = 0;
 			write_rate = 0;
 			if ((secs > 0) || (usecs > 0))
@@ -666,7 +671,13 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
 							 (long long) VacuumPageDirty);
 			appendStringInfo(&buf, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"),
 							 read_rate, write_rate);
-			appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0));
+			appendStringInfo(&buf, _("system usage: %s\n"), pg_rusage_show(&ru0));
+			appendStringInfo(&buf,
+							 _("WAL usage: %ld records, %ld full page writes, "
+							 UINT64_FORMAT " bytes"),
+							 walusage.wal_records,
+							 walusage.wal_num_fpw,
+							 walusage.wal_bytes);
 
 			ereport(LOG,
 					(errmsg_internal("%s", buf.data)));
@@ -758,6 +769,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	IndexBulkDeleteResult **indstats;
 	int			i;
 	PGRUsage	ru0;
+	WalUsage walusage_start = pgWalUsage;
+	WalUsage walusage = {0, 0, 0};
 	Buffer		vmbuffer = InvalidBuffer;
 	BlockNumber next_unskippable_block;
 	bool		skipping_blocks;
@@ -1727,6 +1740,15 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 									"%u pages are entirely empty.\n",
 									empty_pages),
 					 empty_pages);
+
+	memset(&walusage, 0, sizeof(WalUsage));
+	WalUsageAccumDiff(&walusage, &pgWalUsage, &walusage_start);
+	appendStringInfo(&buf, _("%ld WAL records, %ld WAL full page writes, "
+							UINT64_FORMAT " WAL bytes\n"),
+							walusage.wal_records,
+							walusage.wal_num_fpw,
+							walusage.wal_bytes);
+
 	appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
 
 	ereport(elevel,
-- 
2.20.1

--dFWYt1i2NyOo1oI9
Content-Type: application/x-sh
Content-Disposition: attachment; filename="wal_test.sh"
Content-Transfer-Encoding: quoted-printable

#!/bin/bash=0A=0Aset -e=0A=0APSQL=3D"psql -Xc"=0ABASE_LINES=3D1000=0ASCALES=
=3D(1 10 100 1000)=0AMIN_WORKERS=3D0=0AMAX_WORKERS=3D8=0A=0Acleanup() {=0A =
   ${PSQL} "VACUUM;"=0A    ${PSQL} "CHECKPOINT;"=0A    ${PSQL} "SELECT pg_s=
witch_wal();"=0A}=0A=0A${PSQL} "ALTER SYSTEM SET max_parallel_maintenance_w=
orkers =3D ${MAX_WORKERS};"=0A${PSQL} "SELECT pg_reload_conf();"=0Aret=3D$(=
psql -AXtc "SELECT current_setting('max_parallel_maintenance_workers')::int=
 <=3D current_setting('max_worker_processes')::int;")=0A=0Aif [[ ${ret} !=
=3D "t" ]]; then=0A    echo "Unexpected: ${ret}"=0A    exit 1=0Afi=0A=0A${P=
SQL} "CREATE EXTENSION IF NOT EXISTS pg_stat_statements;"=0A${PSQL} "SELECT=
 pg_stat_statements_reset();"=0A=0Afor SCALE in ${SCALES[@]}; do=0A    NB=
=3D$((${BASE_LINES} * ${SCALE}))=0A    echo "Setup with scale ${SCALE} (${N=
B} lines)"=0A    ${PSQL} "DROP TABLE IF EXISTS t1;"=0A    ${PSQL} "CREATE T=
ABLE t1 (id integer);"=0A    ${PSQL} "INSERT INTO t1 SELECT generate_series=
(1, ${NB});"=0A=0A    for PASS in "a" "b"; do=0A        for WORKER in $(seq=
 ${MIN_WORKERS} ${MAX_WORKERS}); do=0A            echo "Test with ${WORKER}=
 workers, pass ${PASS}"=0A            IDXNAME=3D$(printf "t1_idx_s%03d_p${P=
ASS}_w${WORKER}" ${SCALE})=0A            ${PSQL} "ALTER TABLE t1 SET (paral=
lel_workers =3D ${WORKER});"=0A            cleanup=0A            ${PSQL} "C=
REATE INDEX ${IDXNAME} ON t1 (id);"=0A        done=0A    done=0Adone=0A=0Ae=
cho "Summarry of indexes size:"=0A${PSQL} "SELECT pg_relation_size(oid), st=
ring_agg(relname, ', ') FROM pg_class WHERE relname LIKE 't1_idx%' GROUP BY=
 1"=0A=0Aecho "CREATE INDEX WAL stats:"=0A${PSQL} "SELECT query, wal_bytes,=
 wal_records, wal_num_fpw FROM pg_stat_statements WHERE query ILIKE '%creat=
e index%' ORDER BY query;"=0A=0Aecho "INSERT WAL testing"=0A${PSQL} "SELECT=
 pg_stat_statements_reset();"=0A=0Afor SCALE in ${SCALES[@]}; do=0A    NB=
=3D$((${BASE_LINES} * ${SCALE}))=0A    echo "INSERT test with scale ${SCALE=
} (${NB} lines)"=0A    for PASS in "a" "b"; do=0A        TBLNAME=3D$(printf=
 "t_%03d_${PASS}" ${SCALE})=0A        ${PSQL} "DROP TABLE IF EXISTS ${TBLNA=
ME};"=0A        ${PSQL} "CREATE TABLE ${TBLNAME} (id integer);"=0A        c=
leanup=0A        ${PSQL} "INSERT INTO ${TBLNAME} SELECT generate_series(1, =
${NB});"=0A    done=0Adone=0A=0Aecho "INSERT WAL stats:"=0A${PSQL} "SELECT =
query, wal_bytes, wal_records, wal_num_fpw FROM pg_stat_statements WHERE qu=
ery ILIKE '%INSERT INTO%' ORDER BY query;"=0A
--dFWYt1i2NyOo1oI9--