Subject: Re: snapbuild woes
To: Erik Rijkers <er@xs4all.nl>
References: <20170413002959.apytyi5lkknauauj@alap3.anarazel.de>
 <0d06dfc1-0bc5-c3ab-3555-24e2f275d7fa@2ndquadrant.com>
 <30242bc6-eca4-b7bb-670e-8d0458753a8c@2ndquadrant.com>
 <20170501005921.qcqd7w2njpv3av6s@alap3.anarazel.de>
 <20170501013529.sejtgo2acxbvq26q@alap3.anarazel.de>
 <209861fc-718f-0a7b-3a1d-36512865c209@2ndquadrant.com>
 <20170501080348.vb6mj5whdex3f7l7@alap3.anarazel.de>
 <e6c1fdfe-50bc-62e4-3ad7-854f6ac5c35e@2ndquadrant.com>
 <20170501191419.coqbtx2jodu22ufz@alap3.anarazel.de>
 <ba7a3052-6e71-d162-d4a0-b5bdd7145c19@2ndquadrant.com>
 <20170505000004.gihrtl7bhxeolf3q@alap3.anarazel.de>
 <076a3e4c3d4fef091522d3cd7e50c7eb@xs4all.nl>
 <46835ad4-ce7d-ae45-bfdd-9e5f79d33a89@2ndquadrant.com>
 <169b7d221f3236b7cb790c8dd323dbe0@xs4all.nl>
Cc: Andres Freund <andres@anarazel.de>,
 PostgreSQL-development <pgsql-hackers@postgresql.org>,
 Robert Haas <robertmhaas@gmail.com>, Craig Ringer <craig@2ndquadrant.com>
From: Petr Jelinek <petr.jelinek@2ndquadrant.com>
Message-ID: <4ff19c9f-96ed-40ee-14f4-6286a56b5ac8@2ndquadrant.com>
Date: Tue, 9 May 2017 11:50:35 +0200
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101
 Thunderbird/45.8.0
MIME-Version: 1.0
In-Reply-To: <169b7d221f3236b7cb790c8dd323dbe0@xs4all.nl>
Content-Type: multipart/mixed;
 boundary="------------C6C73C061B6E3B21825A80B9"
Precedence: bulk
Sender: pgsql-hackers-owner@postgresql.org

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

On 09/05/17 10:59, Erik Rijkers wrote:
> On 2017-05-09 10:50, Petr Jelinek wrote:
>> On 09/05/17 00:03, Erik Rijkers wrote:
>>> On 2017-05-05 02:00, Andres Freund wrote:
>>>>
>>>> Could you have a look?
>>>
>>> Running tests with these three patches:
>>>
>>>> 0001-WIP-Fix-off-by-one-around-GetLastImportantRecPtr.patch+
>>>> 0002-WIP-Possibly-more-robust-snapbuild-approach.patch     +
>>>> fix-statistics-reporting-in-logical-replication-work.patch
>>>     (on top of 44c528810)
>>>
>>> I test by 15-minute pgbench runs while there is a logical replication
>>> connection. Primary and replica are on the same machine.
>>>
>>> I have seen errors on 3 different machines (where error means: at least
>>> 1 of the 4 pgbench tables is not md5-equal). It seems better, faster
>>> machines yield less errors.
>>>
>>> Normally I see in pg_stat_replication (on master) one process in state
>>> 'streaming'.
>>>
>>>  pid  |     wal     | replay_loc  |   diff   |   state   |   app   |
>>> sync_state
>>> 16495 | 11/EDBC0000 | 11/EA3FEEE8 | 58462488 | streaming | derail2 |
>>> async
>>>
>>> Often there are another two processes in pg_stat_replication that remain
>>> in state 'startup'.
>>>
>>> In the failing sessions the 'streaming'-state process is missing; in
>>> failing sessions there are only the two processes that are and remain in
>>> 'startup'.
>>
>> Hmm, startup is the state where slot creation is happening. I wonder if
>> it's just taking long time to create snapshot because of the 5th issue
>> which is not yet fixed (and the original patch will not apply on top of
>> this change). Alternatively there is a bug in this patch.
>>
>> Did you see high CPU usage during the test when there were those
>> "startup" state walsenders?
>>
> 
> I haven't noticed but I didn't pay attention to that particularly.
> 
> I'll try to get some CPU-info logged...
> 

I rebased the above mentioned patch to apply to the patches Andres sent,
if you could try to add it on top of what you have and check if it still
fails, that would be helpful.

Thanks!

-- 
  Petr Jelinek                  http://www.2ndQuadrant.com/
  PostgreSQL Development, 24x7 Support, Training & Services

--------------C6C73C061B6E3B21825A80B9
Content-Type: binary/octet-stream;
 name="Skip-unnecessary-snapshot-builds.patch"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="Skip-unnecessary-snapshot-builds.patch"

From 1d1071aaacdb64228d195a1b5234be0f4716ce5c Mon Sep 17 00:00:00 2001
From: Petr Jelinek <pjmodos@pjmodos.net>
Date: Tue, 9 May 2017 11:49:00 +0200
Subject: [PATCH] Skip unnecessary snapshot builds

When doing initial snapshot build during logical decoding
initialization, don't build snapshots for transactions where we know the
transaction didn't do any catalog changes. Otherwise we might end up
with thousands of useless snapshots on busy server which can be quite
expensive.
---
 src/backend/replication/logical/snapbuild.c | 100 ++++++++++++++++------------
 1 file changed, 58 insertions(+), 42 deletions(-)

diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 1176d20..a6c0b66 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -912,9 +912,8 @@ SnapBuildCommitTxn(SnapBuild *builder, XLogRecPtr lsn, TransactionId xid,
 {
 	int			nxact;
 
-	bool		forced_timetravel = false;
-	bool		sub_needs_timetravel = false;
-	bool		top_needs_timetravel = false;
+	bool		need_timetravel = false;
+	bool		need_snapshot = false;
 
 	TransactionId xmax = xid;
 
@@ -934,12 +933,22 @@ SnapBuildCommitTxn(SnapBuild *builder, XLogRecPtr lsn, TransactionId xid,
 			builder->start_decoding_at = lsn + 1;
 
 		/*
-		 * We could avoid treating !SnapBuildTxnIsRunning transactions as
-		 * timetravel ones, but we want to be able to export a snapshot when
-		 * we reached consistency.
+		 * When building full snapshot we need to keep track of all
+		 * transactions.
 		 */
-		forced_timetravel = true;
-		elog(DEBUG1, "forced to assume catalog changes for xid %u because it was running too early", xid);
+		if (builder->building_full_snapshot)
+		{
+			need_timetravel = true;
+			elog(DEBUG1, "forced to assume catalog changes for xid %u because it was running too early", xid);
+		}
+
+		/*
+		 * If we could not observe the just finished transaction since it
+		 * started (because it started before we started tracking), we'll
+		 * always need a snapshot.
+		 */
+		if (TransactionIdPrecedes(xid, builder->started_collection_at))
+			need_snapshot = true;
 	}
 
 	for (nxact = 0; nxact < nsubxacts; nxact++)
@@ -947,23 +956,13 @@ SnapBuildCommitTxn(SnapBuild *builder, XLogRecPtr lsn, TransactionId xid,
 		TransactionId subxid = subxacts[nxact];
 
 		/*
-		 * If we're forcing timetravel we also need visibility information
-		 * about subtransaction, so keep track of subtransaction's state.
-		 */
-		if (forced_timetravel)
-		{
-			SnapBuildAddCommittedTxn(builder, subxid);
-			if (NormalTransactionIdFollows(subxid, xmax))
-				xmax = subxid;
-		}
-
-		/*
 		 * Add subtransaction to base snapshot if it DDL, we don't distinguish
 		 * to toplevel transactions there.
 		 */
-		else if (ReorderBufferXidHasCatalogChanges(builder->reorder, subxid))
+		if (ReorderBufferXidHasCatalogChanges(builder->reorder, subxid))
 		{
-			sub_needs_timetravel = true;
+			need_timetravel = true;
+			need_snapshot = true;
 
 			elog(DEBUG1, "found subtransaction %u:%u with catalog changes.",
 				 xid, subxid);
@@ -973,31 +972,40 @@ SnapBuildCommitTxn(SnapBuild *builder, XLogRecPtr lsn, TransactionId xid,
 			if (NormalTransactionIdFollows(subxid, xmax))
 				xmax = subxid;
 		}
+		/*
+		 * If we have already decided that timetravel is needed for this
+		 * transaction, we also need visibility information about
+		 * subtransaction, so keep track of subtransaction's state.
+		 */
+		else if (need_timetravel)
+		{
+			SnapBuildAddCommittedTxn(builder, subxid);
+			if (NormalTransactionIdFollows(subxid, xmax))
+				xmax = subxid;
+		}
 	}
 
-	if (forced_timetravel)
-	{
-		elog(DEBUG2, "forced transaction %u to do timetravel.", xid);
-
-		SnapBuildAddCommittedTxn(builder, xid);
-	}
-	/* add toplevel transaction to base snapshot */
-	else if (ReorderBufferXidHasCatalogChanges(builder->reorder, xid))
+	/*
+	 * Add toplevel transaction to base snapshot if it made any cataog
+	 * changes...
+	 */
+	if (ReorderBufferXidHasCatalogChanges(builder->reorder, xid))
 	{
 		elog(DEBUG2, "found top level transaction %u, with catalog changes!",
 			 xid);
 
-		top_needs_timetravel = true;
+		need_timetravel = true;
+		need_snapshot = true;
 		SnapBuildAddCommittedTxn(builder, xid);
 	}
-	else if (sub_needs_timetravel)
+	/* ... or if previous checks decided we need timetravel anyway. */
+	else if (need_timetravel)
 	{
-		/* mark toplevel txn as timetravel as well */
 		SnapBuildAddCommittedTxn(builder, xid);
 	}
 
 	/* if there's any reason to build a historic snapshot, do so now */
-	if (forced_timetravel || top_needs_timetravel || sub_needs_timetravel)
+	if (need_timetravel)
 	{
 		/*
 		 * Adjust xmax of the snapshot builder, we only do that for committed,
@@ -1018,15 +1026,25 @@ SnapBuildCommitTxn(SnapBuild *builder, XLogRecPtr lsn, TransactionId xid,
 		if (builder->state < SNAPBUILD_FULL_SNAPSHOT)
 			return;
 
+		/* We always need to build snapshot if there isn't one yet. */
+		need_snapshot = need_snapshot || !builder->snapshot;
+
 		/*
-		 * Decrease the snapshot builder's refcount of the old snapshot, note
-		 * that it still will be used if it has been handed out to the
-		 * reorderbuffer earlier.
+		 * Decrease the snapshot builder's refcount of the old snapshot if we
+		 * plan to build new one, note that it still will be used if it has
+		 * been handed out to the reorderbuffer earlier.
 		 */
-		if (builder->snapshot)
+		if (builder->snapshot && need_snapshot)
 			SnapBuildSnapDecRefcount(builder->snapshot);
 
-		builder->snapshot = SnapBuildBuildSnapshot(builder, xid);
+		/* Build new snapshot unless asked not to. */
+		if (need_snapshot)
+		{
+			builder->snapshot = SnapBuildBuildSnapshot(builder, xid);
+
+			/* refcount of the snapshot builder for the new snapshot */
+			SnapBuildSnapIncRefcount(builder->snapshot);
+		}
 
 		/* we might need to execute invalidations, add snapshot */
 		if (!ReorderBufferXidHasBaseSnapshot(builder->reorder, xid))
@@ -1036,11 +1054,9 @@ SnapBuildCommitTxn(SnapBuild *builder, XLogRecPtr lsn, TransactionId xid,
 										 builder->snapshot);
 		}
 
-		/* refcount of the snapshot builder for the new snapshot */
-		SnapBuildSnapIncRefcount(builder->snapshot);
-
 		/* add a new Snapshot to all currently running transactions */
-		SnapBuildDistributeNewCatalogSnapshot(builder, lsn);
+		if (need_snapshot)
+			SnapBuildDistributeNewCatalogSnapshot(builder, lsn);
 	}
 	else
 	{
-- 
2.7.4


--------------C6C73C061B6E3B21825A80B9
Content-Type: text/plain
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
MIME-Version: 1.0


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

--------------C6C73C061B6E3B21825A80B9--