035_debugging.patch

application/x-patch

Filename: 035_debugging.patch
Type: application/x-patch
Part: 0
Message: Re: Refactor recovery conflict signaling a little

Patch

Format: unified
File+
src/backend/storage/ipc/procarray.c 87 2
src/backend/tcop/postgres.c 59 0
diff --git a/src/backend/storage/ipc/procarray.c b/src/backend/storage/ipc/procarray.c
index 40312df2cac..20207ca3af4 100644
--- a/src/backend/storage/ipc/procarray.c
+++ b/src/backend/storage/ipc/procarray.c
@@ -709,6 +709,28 @@ ProcArrayEndTransaction(PGPROC *proc, TransactionId latestXid)
 		/* be sure this is cleared in abort */
 		proc->delayChkptFlags = 0;
 
+		{
+			uint32		old_mask;
+			bool		self_is_target;
+
+			/* Avoid strong read cost on the common zero case. */
+			old_mask = pg_atomic_read_u32(&proc->pendingRecoveryConflicts);
+			if (old_mask != 0)
+			{
+				old_mask = pg_atomic_read_membarrier_u32(&proc->pendingRecoveryConflicts);
+				self_is_target = (proc == MyProc);
+				if (old_mask != 0)
+					ereport(LOG,
+							(errmsg("DBG ProcArrayEndTransaction self_pid=%d "
+									"target_pid=%d target_procno=%d self_is_target=%c "
+									"clearing pendingRecoveryConflicts=0x%x",
+									getpid(), (int) proc->pid,
+									(int) GetNumberFromPGProc(proc),
+									self_is_target ? 't' : 'f',
+									old_mask)));
+			}
+		}
+
 		pg_atomic_write_u32(&proc->pendingRecoveryConflicts, 0);
 
 		/* must be cleared with xid/xmin: */
@@ -751,6 +773,29 @@ ProcArrayEndTransactionInternal(PGPROC *proc, TransactionId latestXid)
 	/* be sure this is cleared in abort */
 	proc->delayChkptFlags = 0;
 
+	{
+		uint32		old_mask;
+		bool		self_is_target;
+
+		/* Avoid strong read cost on the common zero case. */
+		old_mask = pg_atomic_read_u32(&proc->pendingRecoveryConflicts);
+		if (old_mask != 0)
+		{
+			old_mask = pg_atomic_read_membarrier_u32(&proc->pendingRecoveryConflicts);
+			self_is_target = (proc == MyProc);
+			if (old_mask != 0)
+				ereport(LOG,
+						(errmsg("DBG ProcArrayEndTransactionInternal self_pid=%d "
+								"target_pid=%d target_procno=%d self_is_target=%c "
+								"clearing "
+								"pendingRecoveryConflicts=0x%x",
+								getpid(), (int) proc->pid,
+								(int) GetNumberFromPGProc(proc),
+								self_is_target ? 't' : 'f',
+								old_mask)));
+		}
+	}
+
 	pg_atomic_write_u32(&proc->pendingRecoveryConflicts, 0);
 
 	/* must be cleared with xid/xmin: */
@@ -910,6 +955,11 @@ void
 ProcArrayClearTransaction(PGPROC *proc)
 {
 	int			pgxactoff;
+	bool		log_clear = false;
+	int			target_procno = INVALID_PROC_NUMBER;
+	pid_t		target_pid = 0;
+	uint32		old_mask = 0;
+	bool		self_is_target = false;
 
 	/*
 	 * Currently we need to lock ProcArrayLock exclusively here, as we
@@ -934,6 +984,21 @@ ProcArrayClearTransaction(PGPROC *proc)
 
 	proc->vxid.lxid = InvalidLocalTransactionId;
 	proc->xmin = InvalidTransactionId;
+
+	/* Avoid strong read cost on the common zero case. */
+	old_mask = pg_atomic_read_u32(&proc->pendingRecoveryConflicts);
+	if (old_mask != 0)
+	{
+		old_mask = pg_atomic_read_membarrier_u32(&proc->pendingRecoveryConflicts);
+		if (old_mask != 0)
+		{
+			log_clear = true;
+			target_pid = proc->pid;
+			target_procno = GetNumberFromPGProc(proc);
+			self_is_target = (proc == MyProc);
+		}
+	}
+
 	pg_atomic_write_u32(&proc->pendingRecoveryConflicts, 0);
 
 	Assert(!(proc->statusFlags & PROC_VACUUM_STATE_MASK));
@@ -960,6 +1025,14 @@ ProcArrayClearTransaction(PGPROC *proc)
 	}
 
 	LWLockRelease(ProcArrayLock);
+
+	if (log_clear)
+		ereport(LOG,
+				(errmsg("DBG ProcArrayClearTransaction self_pid=%d target_pid=%d "
+						"target_procno=%d self_is_target=%c "
+						"clearing pendingRecoveryConflicts=0x%x",
+						getpid(), (int) target_pid, target_procno,
+						self_is_target ? 't' : 'f', old_mask)));
 }
 
 /*
@@ -3458,6 +3531,9 @@ bool
 SignalRecoveryConflict(PGPROC *proc, pid_t pid, RecoveryConflictReason reason)
 {
 	bool		found = false;
+	int			procno = INVALID_PROC_NUMBER;
+	uint32		old_mask = 0;
+	uint32		new_mask = 0;
 
 	LWLockAcquire(ProcArrayLock, LW_SHARED);
 
@@ -3467,15 +3543,24 @@ SignalRecoveryConflict(PGPROC *proc, pid_t pid, RecoveryConflictReason reason)
 	 */
 	if (proc->pid == pid)
 	{
-		(void) pg_atomic_fetch_or_u32(&proc->pendingRecoveryConflicts, (1 << reason));
+		procno = GetNumberFromPGProc(proc);
+		old_mask = pg_atomic_fetch_or_u32(&proc->pendingRecoveryConflicts,
+										  (1 << reason));
+		new_mask = old_mask | (1 << reason);
 
 		/* wake up the process */
-		(void) SendProcSignal(pid, PROCSIG_RECOVERY_CONFLICT, GetNumberFromPGProc(proc));
+		(void) SendProcSignal(pid, PROCSIG_RECOVERY_CONFLICT, procno);
 		found = true;
 	}
 
 	LWLockRelease(ProcArrayLock);
 
+	if (found)
+		ereport(LOG,
+				(errmsg("DBG SignalRecoveryConflict self_pid=%d target_pid=%d "
+						"target_procno=%d reason=%d old_mask=0x%x new_mask=0x%x",
+						getpid(), pid, procno, (int) reason, old_mask, new_mask)));
+
 	return found;
 }
 
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index d01a09dd0c4..862f9e960c9 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -3070,11 +3070,15 @@ FloatExceptionHandler(SIGNAL_ARGS)
  * Tell the next CHECK_FOR_INTERRUPTS() to process recovery conflicts.  Runs
  * in a SIGUSR1 handler.
  */
+static volatile sig_atomic_t dbg_sigusr1_conflict_count = 0;
+
 void
 HandleRecoveryConflictInterrupt(void)
 {
 	if (pg_atomic_read_u32(&MyProc->pendingRecoveryConflicts) != 0)
 		InterruptPending = true;
+	if (dbg_sigusr1_conflict_count < INT_MAX)
+		dbg_sigusr1_conflict_count++;
 	/* latch will be set by procsignal_sigusr1_handler */
 }
 
@@ -3296,6 +3300,10 @@ ProcessRecoveryConflictInterrupts(void)
 	Assert(!proc_exit_inprogress);
 	Assert(InterruptHoldoffCount == 0);
 
+	ereport(LOG,
+			(errmsg("DBG ProcessRecoveryConflictInterrupts[%d] enter",
+					getpid())));
+
 	/* Are any recovery conflict pending? */
 	pending = pg_atomic_read_membarrier_u32(&MyProc->pendingRecoveryConflicts);
 	if (pending == 0)
@@ -3313,6 +3321,11 @@ ProcessRecoveryConflictInterrupts(void)
 	{
 		if ((pending & (1 << reason)) != 0)
 		{
+			ereport(LOG,
+					(errmsg("DBG ProcessRecoveryConflictInterrupts[%d] "
+							"dispatching reason=%d pending=0x%x",
+							getpid(), (int) reason, pending)));
+
 			/* clear the flag */
 			(void) pg_atomic_fetch_and_u32(&MyProc->pendingRecoveryConflicts, ~(1 << reason));
 
@@ -3506,6 +3519,52 @@ ProcessInterrupts(void)
 		}
 	}
 
+	{
+		int			handler_count;
+		uint32		weak;
+		uint32		strong;
+
+		handler_count = (int) dbg_sigusr1_conflict_count;
+		weak = pg_atomic_read_u32(&MyProc->pendingRecoveryConflicts);
+
+		/*
+		 * Don't pay for a strong read in the common case with no signal and no
+		 * pending conflicts.
+		 */
+		if (handler_count > 0 || weak != 0)
+		{
+			/*
+			 * This handoff is intentionally approximate for diagnostics: a signal
+			 * can arrive between reading and clearing this counter.
+			 */
+			dbg_sigusr1_conflict_count = 0;
+			strong = pg_atomic_read_membarrier_u32(&MyProc->pendingRecoveryConflicts);
+
+			if (weak != strong)
+				ereport(LOG,
+						(errmsg("DBG ProcessInterrupts[%d] weak/strong mismatch "
+								"weak=0x%x strong=0x%x handler_count=%d",
+								getpid(), weak, strong, handler_count)));
+			else if (handler_count > 0 && weak == 0)
+				ereport(LOG,
+						(errmsg("DBG ProcessInterrupts[%d] handler fired but "
+								"pending=0x0 (spurious wakeup, cleared, or "
+								"counter-race), handler_count=%d",
+								getpid(), handler_count)));
+			else if (handler_count > 0)
+				ereport(LOG,
+						(errmsg("DBG ProcessInterrupts[%d] handler fired "
+								"pending=0x%x handler_count=%d",
+								getpid(), weak, handler_count)));
+			else
+				ereport(LOG,
+						(errmsg("DBG ProcessInterrupts[%d] no handler but "
+								"pending=0x%x (preexisting)",
+								getpid(), weak)));
+		}
+	}
+
+	/* Preserve original dispatch behavior: weak read at point of check. */
 	if (pg_atomic_read_u32(&MyProc->pendingRecoveryConflicts) != 0)
 		ProcessRecoveryConflictInterrupts();