Subject: Possible fails in pg_stat_statements test

From: "Anton A. Melnikov" <[email-masked]>
Date: Fri, 14 Jan 2022 11:11:07 +0300

Hello,

There are some places in the pg_state_statement's regress test where the 
bool result of comparison between the number of rows obtained and 
wal_records generated by query should be displayed.
Now counting the number of wal_records for some query in 
pg_state_statement is done by the global pgWalUsage.wal_records counter 
difference calculation.
During query execution the extra wal_records may appear that are not 
relate to the query.
There are two reasons why this might happen:
1) Owing to the hit into pruning of some page in optional pruning 
function (heap_page_prune_opt()).
2) When a new page is required for a new xid in clog and 
WriteZeroPageXlogRec() was called.
In both cases an extra wal record with zero xl_xid is generated, so 
wal_records counter gives an incremented value for this query and 
pg_stat_statement test will fail.

This patch introduces an additional counter of wal records not related 
to the query being executed.
Due to this counter pg_stat_statement finds out the number of wal 
records that are not relevant to the query and does not include them in 
the per query statistic.
This removes the possibility of the error described above.

There is a way to reproduce this error when patch is not applied:
1) start server with "shared_preload_libraries = 'pg_stat_statements'" 
string in the postgresql.conf;
2) replace makefile in contrib/pg_stat_statements with attached one;
3) replace test file 
contrib/pg_stat_statements/sql/pg_stat_statements.sql and expected 
results contrib/pg_stat_statements/expected/pg_stat_statements.out
with shorter versions from attached files;
4) copy test.sh to contrib/pg_stat_statements and make sure that PGHOME 
point to your server;
5) cd to contrib/pg_stat_statements and execute:
export ITER=1 && while ./start.sh || break; export ITER=$(($ITER+1)); do 
:; done

Usually 100-200 iterations will be enough.
To catch the error more faster one can add wal_records column to SELECT
in line 26 of contrib/pg_stat_statements/sql/pg_stat_statements.sql as 
followes:
SELECT query, calls, rows, wal_records,
and replace the contrib/pg_stat_statements/expected/pg_stat_statements.out
with attached pg_stat_statements-fast.out

With best regards,
-- 
Anton A. Melnikov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
commit 3f4659a8d8a390bb24fbc6f82a6add7949fbebe2
Author: Anton A. Melnikov <[email-masked]>
Date:   Fri Jan 14 10:54:35 2022 +0300

    Fix possible fails in pg_stat_statements test via taking into account non-query wal records.

diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c
index 082bfa8f77..bd437aefc3 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -1370,7 +1370,7 @@ pgss_store(const char *query, uint64 queryId,
 		e->counters.blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_read_time);
 		e->counters.blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_write_time);
 		e->counters.usage += USAGE_EXEC(total_time);
-		e->counters.wal_records += walusage->wal_records;
+		e->counters.wal_records += (walusage->wal_records - walusage->non_query_wal_recs);
 		e->counters.wal_fpi += walusage->wal_fpi;
 		e->counters.wal_bytes += walusage->wal_bytes;
 
diff --git a/src/backend/access/heap/pruneheap.c b/src/backend/access/heap/pruneheap.c
index 3201fcc52b..41f17ab97c 100644
--- a/src/backend/access/heap/pruneheap.c
+++ b/src/backend/access/heap/pruneheap.c
@@ -20,6 +20,7 @@
 #include "access/transam.h"
 #include "access/xlog.h"
 #include "catalog/catalog.h"
+#include "executor/instrument.h"
 #include "miscadmin.h"
 #include "pgstat.h"
 #include "storage/bufmgr.h"
@@ -208,6 +209,11 @@ heap_page_prune_opt(Relation relation, Buffer buffer)
 			ndeleted = heap_page_prune(relation, buffer, vistest, limited_xmin,
 									   limited_ts, &nnewlpdead, NULL);
 
+			/* Take into account that heap_page_prune() just generated a new
+			 * wal record with zero xl_xid that is not related to current query.
+			 */
+			pgWalUsage.non_query_wal_recs++;
+
 			/*
 			 * Report the number of tuples reclaimed to pgstats.  This is
 			 * ndeleted minus the number of newly-LP_DEAD-set items.
diff --git a/src/backend/access/transam/clog.c b/src/backend/access/transam/clog.c
index de787c3d37..e944fc3b1a 100644
--- a/src/backend/access/transam/clog.c
+++ b/src/backend/access/transam/clog.c
@@ -38,6 +38,7 @@
 #include "access/xlog.h"
 #include "access/xloginsert.h"
 #include "access/xlogutils.h"
+#include "executor/instrument.h"
 #include "miscadmin.h"
 #include "pg_trace.h"
 #include "pgstat.h"
@@ -955,6 +956,12 @@ WriteZeroPageXlogRec(int pageno)
 	XLogBeginInsert();
 	XLogRegisterData((char *) (&pageno), sizeof(int));
 	(void) XLogInsert(RM_CLOG_ID, CLOG_ZEROPAGE);
+
+	/*
+	 * Consider that a new unrelated to current query wal record
+	 * with zero xl_xid has just been created.
+	 */
+	pgWalUsage.non_query_wal_recs++;
 }
 
 /*
diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index c5ff02a842..214fb3cc45 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -268,6 +268,7 @@ WalUsageAdd(WalUsage *dst, WalUsage *add)
 	dst->wal_bytes += add->wal_bytes;
 	dst->wal_records += add->wal_records;
 	dst->wal_fpi += add->wal_fpi;
+	dst->non_query_wal_recs += add->non_query_wal_recs;
 }
 
 void
@@ -276,4 +277,5 @@ WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, const WalUsage *sub)
 	dst->wal_bytes += add->wal_bytes - sub->wal_bytes;
 	dst->wal_records += add->wal_records - sub->wal_records;
 	dst->wal_fpi += add->wal_fpi - sub->wal_fpi;
+	dst->non_query_wal_recs += add->non_query_wal_recs - sub->non_query_wal_recs;
 }
diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index 1b7157bdd1..0d83f37a3c 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -49,6 +49,11 @@ typedef struct WalUsage
 	int64		wal_records;	/* # of WAL records produced */
 	int64		wal_fpi;		/* # of WAL full page images produced */
 	uint64		wal_bytes;		/* size of WAL records produced */
+	/*
+	 * Number of WAL records unrelated to current query. In particular due to
+	 * heap_page_prune_opt() or WriteZeroPageXlogRec().
+	 */
+	int64		non_query_wal_recs;
 } WalUsage;
 
 /* Flag bits included in InstrAlloc's instrument_options bitmask */