Subject: Is WAL_DEBUG related code still relevant today?

From: Bharath Rupireddy <[email-masked]>
Date: Sat, 2 Dec 2023 19:36:29 +0530

Hi,

I was recently looking at the code around the WAL_DEBUG macro and GUC.
When enabled, the code does the following:

1. Creates a memory context that allows pallocs within critical sections.
2. Decodes (not logical decoding but DecodeXLogRecord()) every WAL
record using the above memory context that's generated in the server
and emits a LOG message.
3. Emits messages at DEBUG level in AdvanceXLInsertBuffer(),  at LOG
level in XLogFlush(), at LOG level in XLogBackgroundFlush().
4. Emits messages at LOG level for every record that the server
replays/applies in the main redo loop.

I enabled this code by compiling with the WAL_DEBUG macro and setting
wal_debug GUC to on. Firstly, the compilation on Windows failed
because XL_ROUTINE was passed inappropriately for XLogReaderAllocate()
used. After fixing the compilation issue [1], the TAP tests started to
fail [2] which I'm sure we can fix.

I started to think if this code is needed at all in production. How
about we do either of the following?

a) Remove the WAL_DEBUG macro and move all the code under the
wal_debug GUC? Since the GUC is already marked as DEVELOPER_OPTION,
the users will know the consequences of enabling it in production.
b) Remove both the WAL_DEBUG macro and the wal_debug GUC. I don't
think (2) is needed to be in core especially when tools like
pg_walinspect and pg_waldump can do the same job. And, the messages in
(3) and (4) can be turned to some DEBUGX level without being under the
WAL_DEBUG macro.

I have no idea if anyone uses WAL_DEBUG macro and wal_debug GUCs in
production, if we have somebody using it, I think we need to fix the
compilation and test failure issues, and start testing this code
(perhaps I can think of setting up a buildfarm member to help here).

I'm in favour of option (b), but I'd like to hear more thoughts on this.

[1]
diff --git a/src/backend/access/transam/xlog.c
b/src/backend/access/transam/xlog.c
index ca7100d4db..52633793d4 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -1023,8 +1023,12 @@ XLogInsertRecord(XLogRecData *rdata,

palloc(DecodeXLogRecordRequiredSpace(record->xl_tot_len));

                if (!debug_reader)
-                       debug_reader =
XLogReaderAllocate(wal_segment_size, NULL,
-
                   XL_ROUTINE(), NULL);
+                       debug_reader = XLogReaderAllocate(wal_segment_size,
+
                   NULL,
+
                   XL_ROUTINE(.page_read = NULL,
+
                                          .segment_open = NULL,
+
                                          .segment_close = NULL),
+
                                          NULL);

[2]
src/test/subscription/t/029_on_error.pl because the test gets LSN from
an error context message emitted to server logs which the new
WAL_DEBUG LOG messages flood the server logs with.
src/bin/initdb/t/001_initdb.pl because the WAL_DEBUG LOG messages are
emitted to the console while initdb.

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

---

From: Peter Eisentraut <[email-masked]>
Date: Wed, 6 Dec 2023 12:27:17 +0100

On 02.12.23 15:06, Bharath Rupireddy wrote:
> used.

This kind of thing could be mostly avoided if we didn't hide all the 
WAL_DEBUG behind #ifdefs.  For example, in the attached patch, I instead 
changed it so that

     if (XLOG_DEBUG)

resolves to

     if (false)

in the normal case.  That way, we don't need to wrap that in #ifdef 
WAL_DEBUG, and the compiler can see the disabled code and make sure it 
continues to build.
From 93c74462c3e253f3ce9fd1beba1f09290988de8c Mon Sep 17 00:00:00 2001
From: Peter Eisentraut <[email-masked]>
Date: Wed, 6 Dec 2023 12:22:38 +0100
Subject: [PATCH] Make WAL_DEBUG code harder to break accidentally

---
 src/backend/access/transam/generic_xlog.c |  2 --
 src/backend/access/transam/xlog.c         | 10 ----------
 src/backend/access/transam/xlogrecovery.c |  7 -------
 src/include/access/xlog.h                 |  2 ++
 4 files changed, 2 insertions(+), 19 deletions(-)

diff --git a/src/backend/access/transam/generic_xlog.c b/src/backend/access/transam/generic_xlog.c
index abd9e1c749..5b910f1024 100644
--- a/src/backend/access/transam/generic_xlog.c
+++ b/src/backend/access/transam/generic_xlog.c
@@ -248,7 +248,6 @@ computeDelta(PageData *pageData, Page curpage, Page targetpage)
 	 * If xlog debug is enabled, then check produced delta.  Result of delta
 	 * application to curpage should be equivalent to targetpage.
 	 */
-#ifdef WAL_DEBUG
 	if (XLOG_DEBUG)
 	{
 		PGAlignedBlock tmp;
@@ -260,7 +259,6 @@ computeDelta(PageData *pageData, Page curpage, Page targetpage)
 				   BLCKSZ - targetUpper) != 0)
 			elog(ERROR, "result of generic xlog apply does not match");
 	}
-#endif
 }
 
 /*
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 2d603d8dee..3a7a38a100 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -644,9 +644,7 @@ static bool updateMinRecoveryPoint = true;
 static int	MyLockNo = 0;
 static bool holdingAllLocks = false;
 
-#ifdef WAL_DEBUG
 static MemoryContext walDebugCxt = NULL;
-#endif
 
 static void CleanupAfterArchiveRecovery(TimeLineID EndOfLogTLI,
 										XLogRecPtr EndOfLog,
@@ -997,7 +995,6 @@ XLogInsertRecord(XLogRecData *rdata,
 		}
 	}
 
-#ifdef WAL_DEBUG
 	if (XLOG_DEBUG)
 	{
 		static XLogReaderState *debug_reader = NULL;
@@ -1061,7 +1058,6 @@ XLogInsertRecord(XLogRecData *rdata,
 		pfree(recordBuf.data);
 		MemoryContextSwitchTo(oldCxt);
 	}
-#endif
 
 	/*
 	 * Update our global variables
@@ -1997,13 +1993,11 @@ AdvanceXLInsertBuffer(XLogRecPtr upto, TimeLineID tli, bool opportunistic)
 	}
 	LWLockRelease(WALBufMappingLock);
 
-#ifdef WAL_DEBUG
 	if (XLOG_DEBUG && npages > 0)
 	{
 		elog(DEBUG1, "initialized %d pages, up to %X/%X",
 			 npages, LSN_FORMAT_ARGS(NewPageEndPtr));
 	}
-#endif
 }
 
 /*
@@ -2641,13 +2635,11 @@ XLogFlush(XLogRecPtr record)
 	if (record <= LogwrtResult.Flush)
 		return;
 
-#ifdef WAL_DEBUG
 	if (XLOG_DEBUG)
 		elog(LOG, "xlog flush request %X/%X; write %X/%X; flush %X/%X",
 			 LSN_FORMAT_ARGS(record),
 			 LSN_FORMAT_ARGS(LogwrtResult.Write),
 			 LSN_FORMAT_ARGS(LogwrtResult.Flush));
-#endif
 
 	START_CRIT_SECTION();
 
@@ -2903,14 +2895,12 @@ XLogBackgroundFlush(void)
 		WriteRqst.Flush = 0;
 	}
 
-#ifdef WAL_DEBUG
 	if (XLOG_DEBUG)
 		elog(LOG, "xlog bg flush request write %X/%X; flush: %X/%X, current is write %X/%X; flush %X/%X",
 			 LSN_FORMAT_ARGS(WriteRqst.Write),
 			 LSN_FORMAT_ARGS(WriteRqst.Flush),
 			 LSN_FORMAT_ARGS(LogwrtResult.Write),
 			 LSN_FORMAT_ARGS(LogwrtResult.Flush));
-#endif
 
 	START_CRIT_SECTION();
 
diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c
index c61566666a..26ba990b71 100644
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -396,9 +396,7 @@ static bool read_tablespace_map(List **tablespaces);
 static void xlogrecovery_redo(XLogReaderState *record, TimeLineID replayTLI);
 static void CheckRecoveryConsistency(void);
 static void rm_redo_error_callback(void *arg);
-#ifdef WAL_DEBUG
 static void xlog_outrec(StringInfo buf, XLogReaderState *record);
-#endif
 static void xlog_block_info(StringInfo buf, XLogReaderState *record);
 static void checkTimeLineSwitch(XLogRecPtr lsn, TimeLineID newTLI,
 								TimeLineID prevTLI, TimeLineID replayTLI);
@@ -1703,7 +1701,6 @@ PerformWalRecovery(void)
 				ereport_startup_progress("redo in progress, elapsed time: %ld.%02d s, current LSN: %X/%X",
 										 LSN_FORMAT_ARGS(xlogreader->ReadRecPtr));
 
-#ifdef WAL_DEBUG
 			if (XLOG_DEBUG ||
 				(record->xl_rmid == RM_XACT_ID && trace_recovery_messages <= DEBUG2) ||
 				(record->xl_rmid != RM_XACT_ID && trace_recovery_messages <= DEBUG3))
@@ -1720,7 +1717,6 @@ PerformWalRecovery(void)
 				elog(LOG, "%s", buf.data);
 				pfree(buf.data);
 			}
-#endif
 
 			/* Handle interrupt signals of startup process */
 			HandleStartupProcInterrupts();
@@ -2256,8 +2252,6 @@ xlog_outdesc(StringInfo buf, XLogReaderState *record)
 	rmgr.rm_desc(buf, record);
 }
 
-#ifdef WAL_DEBUG
-
 static void
 xlog_outrec(StringInfo buf, XLogReaderState *record)
 {
@@ -2270,7 +2264,6 @@ xlog_outrec(StringInfo buf, XLogReaderState *record)
 
 	xlog_block_info(buf, record);
 }
-#endif							/* WAL_DEBUG */
 
 /*
  * Returns a string giving information about all the blocks in an
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index a14126d164..698dd79c2d 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -125,6 +125,8 @@ extern PGDLLIMPORT int wal_level;
 
 #ifdef WAL_DEBUG
 extern PGDLLIMPORT bool XLOG_DEBUG;
+#else
+#define XLOG_DEBUG false
 #endif
 
 /*
-- 
2.43.0

---

From: "Euler Taveira" <[email-masked]>
Date: Wed, 06 Dec 2023 09:46:09 -0300

On Wed, Dec 6, 2023, at 8:27 AM, Peter Eisentraut wrote:
> WAL_DEBUG behind #ifdefs.

AFAICS LOCK_DEBUG also hides its GUCs behind #ifdefs. The fact that XLOG_DEBUG
is a variable but seems like a constant surprises me. I would rename it to
XLogDebug or xlog_debug.

> WAL_DEBUG, and the compiler can see the disabled code and make sure it 

I didn't check the LOCK_DEBUG code path to make sure it fits in the same
category as WAL_DEBUG. If it does, maybe it is worth to apply the same logic
there.

--
Euler Taveira
EDB   https://www.enterprisedb.com/

---

From: Tom Lane <[email-masked]>
Date: Wed, 06 Dec 2023 10:06:17 -0500

> WAL_DEBUG, and the compiler can see the disabled code and make sure it 

Hmm, maybe, but I'm not sure this would be an unalloyed good.
The main concern I have is compilers and static analyzers starting
to bleat about unreachable code (warnings like "variable set but
never used", or the like, seem plausible).  The dead code would
also decrease our code coverage statistics, not that those are
wonderful now.

			regards, tom lane

---

From: Michael Paquier <[email-masked]>
Date: Thu, 7 Dec 2023 09:51:28 +0900

> is a variable but seems like a constant surprises me. I would rename it to

+1.  Or just wal_debug for greppability.

> category as WAL_DEBUG. If it does, maybe it is worth to apply the same logic

PerformWalRecovery() with its log for RM_XACT_ID is something that
stresses me a bit though because this is in the main redo loop which
is never free.  The same can be said about GenericXLogFinish() because
the extra computation happens while holding a buffer and marking it
dirty.  The ones in xlog.c are free of charge as they are called
outside any critical portions.

This makes me wonder how much we need to care about
trace_recovery_messages, actually, and I've never used it.
--
Michael