Content-Type: multipart/mixed; boundary="------------hvZVoQq2QkdAfGYgE0zuRmYG"
Message-ID: <e217cdaf-53a1-6d41-59e2-4f4a8bbe9f23@gmail.com>
Date: Tue, 11 Apr 2023 10:55:43 +0200
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:102.0)
 Gecko/20100101 Thunderbird/102.9.1
Subject: Re: Minimal logical decoding on standbys
Content-Language: en-US
From: "Drouvot, Bertrand" <bertranddrouvot.pg@gmail.com>
To: Noah Misch <noah@leadboat.com>, Andres Freund <andres@anarazel.de>
Cc: Amit Kapila <amit.kapila16@gmail.com>,
 Alvaro Herrera <alvherre@alvh.no-ip.org>, Jeff Davis <pgsql@j-davis.com>,
 Robert Haas <robertmhaas@gmail.com>, Thomas Munro <thomas.munro@gmail.com>,
 Ibrar Ahmed <ibrar.ahmad@gmail.com>, Amit Khandekar
 <amitdkhan.pg@gmail.com>, fabriziomello@gmail.com,
 tushar <tushar.ahuja@enterprisedb.com>,
 Rahila Syed <rahila.syed@2ndquadrant.com>,
 pgsql-hackers <pgsql-hackers@postgresql.org>
References: <1903ca9b-1dc9-20a6-404a-d4c460c7bdcc@gmail.com>
 <CAA4eK1KFrxgQJt7kc-_o5ruLvafw_FR=NUizA8A7Bp1TDOEj8g@mail.gmail.com>
 <2b002763-f39f-0814-e98e-c48989ddc3c3@gmail.com>
 <3c9d4998-a338-081f-a5f6-d038ead75384@gmail.com>
 <20230407055618.33gjg5vd5hq3kje4@awork3.anarazel.de>
 <71c3d91a-6b3b-5c0a-ffb9-630f17fe693e@gmail.com>
 <20230407075009.igg7be27ha2htkbt@awork3.anarazel.de>
 <1e923731-ed09-3621-c8b9-61f938b4c355@gmail.com>
 <20230407154757.ywqnldz4nsycap3g@awork3.anarazel.de>
 <20230407181226.6oyt4jcazy6eh7rx@awork3.anarazel.de>
 <20230411053657.GA1177147@rfd.leadboat.com>
 <7eb26a22-a6b2-f938-6d3c-6adcf4785004@gmail.com>
In-Reply-To: <7eb26a22-a6b2-f938-6d3c-6adcf4785004@gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/e217cdaf-53a1-6d41-59e2-4f4a8bbe9f23%40gmail.com>
Precedence: bulk

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

Hi,

On 4/11/23 10:20 AM, Drouvot, Bertrand wrote:
> Hi,
> 
> On 4/11/23 7:36 AM, Noah Misch wrote:
>> On Fri, Apr 07, 2023 at 11:12:26AM -0700, Andres Freund wrote:
>>> --- /dev/null
>>> +++ b/src/test/recovery/t/035_standby_logical_decoding.pl
>>> @@ -0,0 +1,720 @@
>>> +# logical decoding on standby : test logical decoding,
>>> +# recovery conflict and standby promotion.
>> ...
>>> +$node_primary->append_conf('postgresql.conf', q{
>>> +wal_level = 'logical'
>>> +max_replication_slots = 4
>>> +max_wal_senders = 4
>>> +log_min_messages = 'debug2'
>>> +log_error_verbosity = verbose
>>> +});
>>
>> Buildfarm member hoverfly stopped reporting in when this test joined the tree.
>> It's currently been stuck here for 140 minutes:
>>
> 
> Thanks for the report!
> 
> It's looping on:
> 
> 2023-04-11 02:57:52.516 UTC [62718288:5] 035_standby_logical_decoding.pl LOG:  00000: statement: SELECT restart_lsn IS NOT NULL
>                          FROM pg_catalog.pg_replication_slots WHERE slot_name = 'promotion_inactiveslot'
> 
> And the reason is that the slot is not being created:
> 
> $ grep "CREATE_REPLICATION_SLOT" 035_standby_logical_decoding_standby.log | tail -2
> 2023-04-11 02:57:47.287 UTC [9241178:15] 035_standby_logical_decoding.pl STATEMENT:  CREATE_REPLICATION_SLOT "otherslot" LOGICAL "test_decoding" ( SNAPSHOT 'nothing')
> 2023-04-11 02:57:47.622 UTC [9241178:23] 035_standby_logical_decoding.pl STATEMENT:  CREATE_REPLICATION_SLOT "otherslot" LOGICAL "test_decoding" ( SNAPSHOT 'nothing')
> 
> Not sure why the slot is not being created.
> 
> There is also "replication apply delay" increasing:
> 
> 2023-04-11 02:57:49.183 UTC [13304488:253] DEBUG:  00000: sendtime 2023-04-11 02:57:49.111363+00 receipttime 2023-04-11 02:57:49.183512+00 replication apply delay 644 ms transfer latency 73 ms
> 2023-04-11 02:57:49.184 UTC [13304488:259] DEBUG:  00000: sendtime 2023-04-11 02:57:49.183461+00 receipttime 2023-04-11 02:57:49.1842+00 replication apply delay 645 ms transfer latency 1 ms
> 2023-04-11 02:57:49.221 UTC [13304488:265] DEBUG:  00000: sendtime 2023-04-11 02:57:49.184166+00 receipttime 2023-04-11 02:57:49.221059+00 replication apply delay 682 ms transfer latency 37 ms
> 2023-04-11 02:57:49.222 UTC [13304488:271] DEBUG:  00000: sendtime 2023-04-11 02:57:49.221003+00 receipttime 2023-04-11 02:57:49.222144+00 replication apply delay 683 ms transfer latency 2 ms
> 2023-04-11 02:57:49.222 UTC [13304488:277] DEBUG:  00000: sendtime 2023-04-11 02:57:49.222095+00 receipttime 2023-04-11 02:57:49.2228+00 replication apply delay 684 ms transfer latency 1 ms
> 
> Noah, I think hoverfly is yours, would it be possible to have access (I'm not an AIX expert though) or check if you see a slot creation hanging and if so why?
> 

Well, we can see in 035_standby_logical_decoding_standby.log:

2023-04-11 02:57:49.180 UTC [62718258:5] [unknown] FATAL:  3D000: database "testdb" does not exist

While, on the primary:

2023-04-11 02:57:48.505 UTC [62718254:5] 035_standby_logical_decoding.pl LOG:  00000: statement: CREATE DATABASE testdb

The TAP test is doing:

"
##################################################
# Test standby promotion and logical decoding behavior
# after the standby gets promoted.
##################################################

$node_standby->reload;

$node_primary->psql('postgres', q[CREATE DATABASE testdb]);
$node_primary->safe_psql('testdb', qq[CREATE TABLE decoding_test(x integer, y text);]);

# create the logical slots
create_logical_slots($node_standby, 'promotion_');
"

I think we might want to add:

$node_primary->wait_for_replay_catchup($node_standby);

before calling the slot creation.

It's done in the attached, would it be possible to give it a try please?

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
--------------hvZVoQq2QkdAfGYgE0zuRmYG
Content-Type: text/plain; charset=UTF-8; name="hoverfly.patch"
Content-Disposition: attachment; filename="hoverfly.patch"
Content-Transfer-Encoding: base64

ZGlmZiAtLWdpdCBhL3NyYy90ZXN0L3JlY292ZXJ5L3QvMDM1X3N0YW5kYnlfbG9naWNhbF9k
ZWNvZGluZy5wbCBiL3NyYy90ZXN0L3JlY292ZXJ5L3QvMDM1X3N0YW5kYnlfbG9naWNhbF9k
ZWNvZGluZy5wbAppbmRleCBiYTk4YTE4YmQyLi5hZDg0NWFlZTI4IDEwMDY0NAotLS0gYS9z
cmMvdGVzdC9yZWNvdmVyeS90LzAzNV9zdGFuZGJ5X2xvZ2ljYWxfZGVjb2RpbmcucGwKKysr
IGIvc3JjL3Rlc3QvcmVjb3ZlcnkvdC8wMzVfc3RhbmRieV9sb2dpY2FsX2RlY29kaW5nLnBs
CkBAIC02NTMsNiArNjUzLDkgQEAgJG5vZGVfc3RhbmRieS0+cmVsb2FkOwogJG5vZGVfcHJp
bWFyeS0+cHNxbCgncG9zdGdyZXMnLCBxW0NSRUFURSBEQVRBQkFTRSB0ZXN0ZGJdKTsKICRu
b2RlX3ByaW1hcnktPnNhZmVfcHNxbCgndGVzdGRiJywgcXFbQ1JFQVRFIFRBQkxFIGRlY29k
aW5nX3Rlc3QoeCBpbnRlZ2VyLCB5IHRleHQpO10pOwogCisjIFdhaXQgZm9yIHRoZSBzdGFu
ZGJ5IHRvIGNhdGNodXAgYmVmb3JlIGNyZWF0aW5nIHRoZSBzbG90cworJG5vZGVfcHJpbWFy
eS0+d2FpdF9mb3JfcmVwbGF5X2NhdGNodXAoJG5vZGVfc3RhbmRieSk7CisKICMgY3JlYXRl
IHRoZSBsb2dpY2FsIHNsb3RzCiBjcmVhdGVfbG9naWNhbF9zbG90cygkbm9kZV9zdGFuZGJ5
LCAncHJvbW90aW9uXycpOwogCg==

--------------hvZVoQq2QkdAfGYgE0zuRmYG--