From: Julien Rouhaud Date: Thu, 19 Mar 2020 16:08:47 +0100 Subject: [PATCH v13 4/4] Expose WAL usage counters in verbose (auto)vacuum output. Author: Julien Rouhaud Reviewed-by: Fuji Masao Discussion: https://postgr.es/m/CAB-hujrP8ZfUkvL5OYETipQwA=e3n7oqHFU=4ZLxWS_Cza3kQQ@mail.gmail.com --- 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--