pgstat: stats added in ReadPageInternal() aren't getting reported via pg_stat_wal

Started by Bharath Rupireddyover 3 years ago2 messages
#1Bharath Rupireddy
bharath.rupireddyforpostgres@gmail.com
1 attachment(s)

Hi,

I added xlogreader cache stats (hits/misses) to pg_stat_wal in
ReadPageInternal() for some of my work and ran some tests with logical
replication subscribers. I had expected that the new stats generated
by walsenders serving the subscribers would be accumulated and shown
via pg_stat_wal view in another session, but that didn't happen. Upon
looking around, I thought adding
pgstat_flush_wal()/pgstat_report_wal() around proc_exit() in
walsener.c might work, but that didn't help either. Can anyone please
let me know why the stats that I added aren't shown via pg_stat_wal
view despite the walsender doing pgstat_initialize() ->
pgstat_init_wal()? Am I missing something?

I'm attaching here with the patch that I was using.

--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

Attachments:

v1-0001-Add-xlogreader-cache-stats.patchapplication/x-patch; name=v1-0001-Add-xlogreader-cache-stats.patchDownload
From 6bee81b6284d1619d6828e521d1d210ae5505034 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Mon, 19 Sep 2022 13:11:31 +0000
Subject: [PATCH v1] Add xlogreader cache stats

---
 src/backend/access/transam/xlogreader.c | 9 +++++++++
 src/backend/catalog/system_views.sql    | 4 +++-
 src/backend/utils/activity/pgstat_wal.c | 2 ++
 src/backend/utils/adt/pgstatfuncs.c     | 9 +++++++--
 src/include/catalog/pg_proc.dat         | 6 +++---
 src/include/pgstat.h                    | 2 ++
 src/test/regress/expected/rules.out     | 6 ++++--
 7 files changed, 30 insertions(+), 8 deletions(-)

diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.c
index 050d2f424e..9a5b3d7893 100644
--- a/src/backend/access/transam/xlogreader.c
+++ b/src/backend/access/transam/xlogreader.c
@@ -1000,7 +1000,16 @@ ReadPageInternal(XLogReaderState *state, XLogRecPtr pageptr, int reqLen)
 	/* check whether we have all the requested data already */
 	if (targetSegNo == state->seg.ws_segno &&
 		targetPageOff == state->segoff && reqLen <= state->readLen)
+	{
+#ifndef FRONTEND
+		PendingWalStats.xlogreader_cache_hits++;
+#endif
 		return state->readLen;
+	}
+
+#ifndef FRONTEND
+	PendingWalStats.xlogreader_cache_misses++;
+#endif
 
 	/*
 	 * Invalidate contents of internal buffer before read attempt.  Just set
diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index 55f7ec79e0..0baab55e6b 100644
--- a/src/backend/catalog/system_views.sql
+++ b/src/backend/catalog/system_views.sql
@@ -1124,7 +1124,9 @@ CREATE VIEW pg_stat_wal AS
         w.wal_sync,
         w.wal_write_time,
         w.wal_sync_time,
-        w.stats_reset
+        w.stats_reset,
+        w.xlogreader_cache_hits,
+        w.xlogreader_cache_misses
     FROM pg_stat_get_wal() w;
 
 CREATE VIEW pg_stat_progress_analyze AS
diff --git a/src/backend/utils/activity/pgstat_wal.c b/src/backend/utils/activity/pgstat_wal.c
index 5a878bd115..ba97d71471 100644
--- a/src/backend/utils/activity/pgstat_wal.c
+++ b/src/backend/utils/activity/pgstat_wal.c
@@ -105,6 +105,8 @@ pgstat_flush_wal(bool nowait)
 	WALSTAT_ACC(wal_sync);
 	WALSTAT_ACC(wal_write_time);
 	WALSTAT_ACC(wal_sync_time);
+	WALSTAT_ACC(xlogreader_cache_hits);
+	WALSTAT_ACC(xlogreader_cache_misses);
 #undef WALSTAT_ACC
 
 	LWLockRelease(&stats_shmem->lock);
diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c
index be15b4b2e5..c65c7c08a8 100644
--- a/src/backend/utils/adt/pgstatfuncs.c
+++ b/src/backend/utils/adt/pgstatfuncs.c
@@ -1732,7 +1732,7 @@ pg_stat_get_buf_alloc(PG_FUNCTION_ARGS)
 Datum
 pg_stat_get_wal(PG_FUNCTION_ARGS)
 {
-#define PG_STAT_GET_WAL_COLS	9
+#define PG_STAT_GET_WAL_COLS	11
 	TupleDesc	tupdesc;
 	Datum		values[PG_STAT_GET_WAL_COLS] = {0};
 	bool		nulls[PG_STAT_GET_WAL_COLS] = {0};
@@ -1759,7 +1759,10 @@ pg_stat_get_wal(PG_FUNCTION_ARGS)
 					   FLOAT8OID, -1, 0);
 	TupleDescInitEntry(tupdesc, (AttrNumber) 9, "stats_reset",
 					   TIMESTAMPTZOID, -1, 0);
-
+	TupleDescInitEntry(tupdesc, (AttrNumber) 10, "xlogreader_cache_hits",
+					   INT8OID, -1, 0);
+	TupleDescInitEntry(tupdesc, (AttrNumber) 11, "xlogreader_cache_misses",
+					   INT8OID, -1, 0);
 	BlessTupleDesc(tupdesc);
 
 	/* Get statistics about WAL activity */
@@ -1785,6 +1788,8 @@ pg_stat_get_wal(PG_FUNCTION_ARGS)
 	values[7] = Float8GetDatum(((double) wal_stats->wal_sync_time) / 1000.0);
 
 	values[8] = TimestampTzGetDatum(wal_stats->stat_reset_timestamp);
+	values[9] = Int64GetDatum(wal_stats->xlogreader_cache_hits);
+	values[10] = Int64GetDatum(wal_stats->xlogreader_cache_misses);
 
 	/* Returns the record as Datum */
 	PG_RETURN_DATUM(HeapTupleGetDatum(heap_form_tuple(tupdesc, values, nulls)));
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index a07e737a33..f728406061 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5649,9 +5649,9 @@
 { oid => '1136', descr => 'statistics: information about WAL activity',
   proname => 'pg_stat_get_wal', proisstrict => 'f', provolatile => 's',
   proparallel => 'r', prorettype => 'record', proargtypes => '',
-  proallargtypes => '{int8,int8,numeric,int8,int8,int8,float8,float8,timestamptz}',
-  proargmodes => '{o,o,o,o,o,o,o,o,o}',
-  proargnames => '{wal_records,wal_fpi,wal_bytes,wal_buffers_full,wal_write,wal_sync,wal_write_time,wal_sync_time,stats_reset}',
+  proallargtypes => '{int8,int8,numeric,int8,int8,int8,float8,float8,timestamptz,int8,int8}',
+  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o}',
+  proargnames => '{wal_records,wal_fpi,wal_bytes,wal_buffers_full,wal_write,wal_sync,wal_write_time,wal_sync_time,stats_reset,xlogreader_cache_hits,xlogreader_cache_misses}',
   prosrc => 'pg_stat_get_wal' },
 { oid => '6248', descr => 'statistics: information about WAL prefetching',
   proname => 'pg_stat_get_recovery_prefetch', prorows => '1', proretset => 't',
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index ac28f813b4..f8a60f8a9e 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -393,6 +393,8 @@ typedef struct PgStat_WalStats
 	PgStat_Counter wal_write_time;
 	PgStat_Counter wal_sync_time;
 	TimestampTz stat_reset_timestamp;
+	PgStat_Counter	xlogreader_cache_hits;
+	PgStat_Counter	xlogreader_cache_misses;
 } PgStat_WalStats;
 
 
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 9dd137415e..b8c8c98a4c 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -2188,8 +2188,10 @@ pg_stat_wal| SELECT w.wal_records,
     w.wal_sync,
     w.wal_write_time,
     w.wal_sync_time,
-    w.stats_reset
-   FROM pg_stat_get_wal() w(wal_records, wal_fpi, wal_bytes, wal_buffers_full, wal_write, wal_sync, wal_write_time, wal_sync_time, stats_reset);
+    w.stats_reset,
+    w.xlogreader_cache_hits,
+    w.xlogreader_cache_misses
+   FROM pg_stat_get_wal() w(wal_records, wal_fpi, wal_bytes, wal_buffers_full, wal_write, wal_sync, wal_write_time, wal_sync_time, stats_reset, xlogreader_cache_hits, xlogreader_cache_misses);
 pg_stat_wal_receiver| SELECT s.pid,
     s.status,
     s.receive_start_lsn,
-- 
2.34.1

#2Kyotaro Horiguchi
horikyota.ntt@gmail.com
In reply to: Bharath Rupireddy (#1)
Re: pgstat: stats added in ReadPageInternal() aren't getting reported via pg_stat_wal

At Mon, 19 Sep 2022 18:46:17 +0530, Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote in

walsener.c might work, but that didn't help either. Can anyone please
let me know why the stats that I added aren't shown via pg_stat_wal
view despite the walsender doing pgstat_initialize() ->
pgstat_init_wal()? Am I missing something?

I'm attaching here with the patch that I was using.

pgstat_report_wal() is supposed to be called on user-facing (or query
executing) backends. The function is called while in idle state on
such backends. Other processes need to call one or more friend
functions as needed. Checkpointer calls pgstat_report_checkpoint/wal()
at the end of an iteration of the main waiting loop. Walwriter does
the same with pgstat_report_wal(). Thus we need to do the same on
startup process somewhere within the redo loop but where that call
doesn't cause contention on shared stats area.

About what the patch does, it increments the xlogreader_cache_hits
counter when the WAL page to read have been already loaded, but it's
not a cache but a buffer. The counter would approximately shows the
number about mean-(raw)-records-per-wal-page *
wal-page-ever-read. (mean-records-per-wal-page = page-size /
mean-record-length). So I don't think that the value offers something
valuable. I guess that the same value (for the moment) can be
calculated from the result of pg_get_wal_records_info().

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center