Subject: Re: BUG #17072: Assert for clogGroupNext failed due to a race
 condition in TransactionGroupUpdateXidStatus()
To: pgsql-bugs@lists.postgresql.org
References: <17072-2f8764857ef2c92a@postgresql.org>
From: Alexander Lakhin <exclusion@gmail.com>
Message-ID: <1ede0650-1fe1-9ab4-af34-64eda8fec665@gmail.com>
Date: Thu, 24 Jun 2021 19:15:00 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101
 Thunderbird/78.7.1
MIME-Version: 1.0
In-Reply-To: <17072-2f8764857ef2c92a@postgresql.org>
Content-Type: multipart/mixed;
 boundary="------------13A570D77E355D2F04759BE9"
Content-Language: en-US
Archived-At: 
 <https://www.postgresql.org/message-id/1ede0650-1fe1-9ab4-af34-64eda8fec665%40gmail.com>
Precedence: bulk

This is a multi-part message in MIME format.
--------------13A570D77E355D2F04759BE9
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit

24.06.2021 19:00, PG Bug reporting form wrote:
> With some diagnostic output added I've got in the server log:
The diagnostic patch is attached.

I could not find an easy reproduction for the issue, so I can propose
only dirty one, with the special debug patch and the following script:

for i in `seq 100`; do
createdb db$i
done

echo "
CREATE TABLE tst (i INT);
INSERT INTO tst SELECT i FROM generate_series(1,100) i;
DROP TABLE tst;
" >/tmp/action.sql

for n in `seq 100`; do
  echo "iteration $n"
  for i in `seq 100`; do
    ( { for f in `seq 10`; do cat /tmp/action.sql; done } | psql -d db$i
) >psql-$i.log 2>&1 &
  done
  wait
  coredumpctl --no-pager && break
done

(You need to set max_connections = 100 in postgresql.conf.)
This script with the patched server fails for me on iterations 66, 12, 12.

Best regards,
Alexander

--------------13A570D77E355D2F04759BE9
Content-Type: text/x-patch; charset=UTF-8;
 name="clog-diagnostics.patch"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="clog-diagnostics.patch"

diff --git a/src/backend/access/transam/clog.c b/src/backend/access/transam/clog.c
index 880f18c1473..126502363f5 100644
--- a/src/backend/access/transam/clog.c
+++ b/src/backend/access/transam/clog.c
@@ -432,7 +432,7 @@ TransactionGroupUpdateXidStatus(TransactionId xid, XidStatus status,
 	proc->clogGroupMemberLsn = lsn;
 
 	nextidx = pg_atomic_read_u32(&procglobal->clogGroupFirst);
-
+elog(WARNING, "TransactionGroupUpdateXidStatus: %d, %d", proc->pgprocno, nextidx);
 	while (true)
 	{
 		/*
@@ -451,9 +451,10 @@ TransactionGroupUpdateXidStatus(TransactionId xid, XidStatus status,
 			ProcGlobal->allProcs[nextidx].clogGroupMemberPage != proc->clogGroupMemberPage)
 		{
 			proc->clogGroupMember = false;
+elog(WARNING, "TransactionGroupUpdateXidStatus: return false (%d)", nextidx);
 			return false;
 		}
-
+elog(WARNING, "TransactionGroupUpdateXidStatus: pg_atomic_write_u32 nextidx: %p, %d", &proc->clogGroupNext, nextidx);
 		pg_atomic_write_u32(&proc->clogGroupNext, nextidx);
 
 		if (pg_atomic_compare_exchange_u32(&procglobal->clogGroupFirst,
@@ -461,7 +462,7 @@ TransactionGroupUpdateXidStatus(TransactionId xid, XidStatus status,
 										   (uint32) proc->pgprocno))
 			break;
 	}
-
+elog(WARNING, "TransactionGroupUpdateXidStatus: after while: %d", nextidx);
 	/*
 	 * If the list was not empty, the leader will update the status of our
 	 * XID. It is impossible to have followers without a leader because the
@@ -489,6 +490,7 @@ TransactionGroupUpdateXidStatus(TransactionId xid, XidStatus status,
 		/* Fix semaphore count for any absorbed wakeups */
 		while (extraWaits-- > 0)
 			PGSemaphoreUnlock(proc->sem);
+elog(WARNING, "TransactionGroupUpdateXidStatus: return true (%d)", nextidx);
 		return true;
 	}
 
@@ -540,8 +542,8 @@ TransactionGroupUpdateXidStatus(TransactionId xid, XidStatus status,
 	while (wakeidx != INVALID_PGPROCNO)
 	{
 		PGPROC	   *proc = &ProcGlobal->allProcs[wakeidx];
-
 		wakeidx = pg_atomic_read_u32(&proc->clogGroupNext);
+elog(WARNING, "TransactionGroupUpdateXidStatus: pg_atomic_write_u32 INVALID_PGPROCNO: %p, %d", &proc->clogGroupNext, INVALID_PGPROCNO);
 		pg_atomic_write_u32(&proc->clogGroupNext, INVALID_PGPROCNO);
 
 		/* ensure all previous writes are visible before follower continues. */
@@ -553,6 +555,7 @@ TransactionGroupUpdateXidStatus(TransactionId xid, XidStatus status,
 			PGSemaphoreUnlock(proc->sem);
 	}
 
+elog(WARNING, "TransactionGroupUpdateXidStatus: end");
 	return true;
 }
 

--------------13A570D77E355D2F04759BE9
Content-Type: text/x-patch; charset=UTF-8;
 name="clog-debug.patch"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="clog-debug.patch"

diff --git a/src/backend/access/transam/clog.c b/src/backend/access/transam/clog.c
index 880f18c1473..499989cb3a1 100644
--- a/src/backend/access/transam/clog.c
+++ b/src/backend/access/transam/clog.c
@@ -305,7 +305,7 @@ TransactionIdSetPageStatus(TransactionId xid, int nsubxids,
 		 * update.  If that doesn't work out, fall back to waiting for the
 		 * lock to perform an update for this transaction only.
 		 */
-		if (LWLockConditionalAcquire(XactSLRULock, LW_EXCLUSIVE))
+		if (0)
 		{
 			/* Got the lock without waiting!  Do the update. */
 			TransactionIdSetPageStatusInternal(xid, nsubxids, subxids, status,
@@ -432,7 +432,6 @@ TransactionGroupUpdateXidStatus(TransactionId xid, XidStatus status,
 	proc->clogGroupMemberLsn = lsn;
 
 	nextidx = pg_atomic_read_u32(&procglobal->clogGroupFirst);
-
 	while (true)
 	{
 		/*
@@ -451,10 +450,15 @@ TransactionGroupUpdateXidStatus(TransactionId xid, XidStatus status,
 			ProcGlobal->allProcs[nextidx].clogGroupMemberPage != proc->clogGroupMemberPage)
 		{
 			proc->clogGroupMember = false;
+elog(WARNING, "TransactionGroupUpdateXidStatus: return false");
 			return false;
 		}
-
 		pg_atomic_write_u32(&proc->clogGroupNext, nextidx);
+do {
+instr_time t;
+INSTR_TIME_SET_CURRENT(t);
+if ((t.tv_nsec % 1000000L) < 10L) break;
+} while (1);
 
 		if (pg_atomic_compare_exchange_u32(&procglobal->clogGroupFirst,
 										   &nextidx,

--------------13A570D77E355D2F04759BE9--