Message-ID: <47524383-6fd1-4b13-8c4e-fb918b1d35ba@enterprisedb.com>
Date: Tue, 26 Mar 2024 20:12:59 +0100
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Subject: Re: speed up a logical replica setup
Content-Language: en-US
To: Euler Taveira <euler@eulerto.com>,
 "kuroda.hayato@fujitsu.com" <kuroda.hayato@fujitsu.com>,
 Peter Eisentraut <peter@eisentraut.org>,
 Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Cc: Amit Kapila <amit.kapila16@gmail.com>,
 Shlok Kyal <shlok.kyal.oss@gmail.com>,
 "pgsql-hackers@lists.postgresql.org" <pgsql-hackers@lists.postgresql.org>,
 Michael Paquier <michael@paquier.xyz>, Andres Freund <andres@anarazel.de>,
 Ashutosh Bapat <ashutosh.bapat.oss@gmail.com>,
 =?UTF-8?Q?Fabr=C3=ADzio_de_Royes_Mello?= <fabriziomello@gmail.com>,
 vignesh C <vignesh21@gmail.com>
References: <9a9c7e65-c47b-4400-a63e-ac6169c0860e@app.fastmail.com>
 <e8564096-3c4f-4990-ac7d-ba089739b878@app.fastmail.com>
 <CANhcyEW6-dH28gLbFc5XpDTJ6JPizU+t5g-aKUWJBf5W_Zriqw@mail.gmail.com>
 <2f0b73f3-e7c0-4e95-9712-1993442a6b64@app.fastmail.com>
 <CAA4eK1JtnzqYNQ_S+mj_XsPfgk7szxegKiVQq4-8fY1wUcUnpg@mail.gmail.com>
 <34637e7f-0330-420d-8f45-1d022962d2fe@app.fastmail.com>
 <7a970912-0b77-4942-84f7-2c9ca0bc05a5@eisentraut.org>
 <d546c4bb-92d1-4e2d-898f-48234b12ed25@app.fastmail.com>
 <CANhcyEWdTTO71v+GFYUTsOOUvHus1qccg88bRmsU9KykJqjSrQ@mail.gmail.com>
 <44de4e04-db22-40ed-8ba9-46387dc8bf83@app.fastmail.com>
 <3fa9ef0f-b277-4c13-850a-8ccc04de1406@eisentraut.org>
 <CALj2ACV85cn-cTNCTP=bPehYo9d2ddvZtfGhGq==0K+65SvufQ@mail.gmail.com>
 <65b841a8-0c2f-4953-b9cd-240fce84b90b@eisentraut.org>
 <TYCPR01MB12077907C052EC329C45AE198F5362@TYCPR01MB12077.jpnprd01.prod.outlook.com>
 <c8e92bcb-69c3-477e-93d4-6f39e030cab0@app.fastmail.com>
From: Tomas Vondra <tomas.vondra@enterprisedb.com>
In-Reply-To: <c8e92bcb-69c3-477e-93d4-6f39e030cab0@app.fastmail.com>
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit
Archived-At: <https://www.postgresql.org/message-id/47524383-6fd1-4b13-8c4e-fb918b1d35ba%40enterprisedb.com>
Precedence: bulk

On 3/26/24 03:53, Euler Taveira wrote:
> On Mon, Mar 25, 2024, at 1:06 PM, Hayato Kuroda (Fujitsu) wrote:
>> ## Analysis for failure 1
>>
>> The failure caused by a time lag between walreceiver finishes and pg_is_in_recovery()
>> returns true.
>>
>> According to the output [1], it seems that the tool failed at wait_for_end_recovery()
>> with the message "standby server disconnected from the primary". Also, lines
>> "redo done at..." and "terminating walreceiver process due to administrator command"
>> meant that walreceiver was requested to shut down by XLogShutdownWalRcv().
>>
>> According to the source, we confirm that walreceiver is shut down in
>> StartupXLOG()->FinishWalRecovery()->XLogShutdownWalRcv(). Also, SharedRecoveryState
>> is changed to RECOVERY_STATE_DONE (this meant the pg_is_in_recovery() return true)
>> at the latter part of StartupXLOG().
>>
>> So, if there is a delay between FinishWalRecovery() and change the state, the check
>> in wait_for_end_recovery() would be failed during the time. Since we allow to miss
>> the walreceiver 10 times and it is checked once per second, the failure occurs if
>> the time lag is longer than 10 seconds.
>>
>> I do not have a good way to fix it. One approach is make NUM_CONN_ATTEMPTS larger,
>> but it's not a fundamental solution.
> 
> I was expecting that slow hosts might have issues in wait_for_end_recovery().
> As you said it took a lot of steps between FinishWalRecovery() (where
> walreceiver is shutdown -- XLogShutdownWalRcv) and SharedRecoveryState is set to
> RECOVERY_STATE_DONE. If this window takes longer than NUM_CONN_ATTEMPTS *
> WAIT_INTERVAL (10 seconds), it aborts the execution. That's a bad decision
> because it already finished the promotion and it is just doing the final
> preparation for the host to become a primary.
> 
>         /*   
>          * If it is still in recovery, make sure the target server is
>          * connected to the primary so it can receive the required WAL to
>          * finish the recovery process. If it is disconnected try
>          * NUM_CONN_ATTEMPTS in a row and bail out if not succeed.
>          */
>         res = PQexec(conn,
>                      "SELECT 1 FROM pg_catalog.pg_stat_wal_receiver");
>         if (PQntuples(res) == 0)
>         {
>             if (++count > NUM_CONN_ATTEMPTS)
>             {
>                 stop_standby_server(subscriber_dir);
>                 pg_log_error("standby server disconnected from the primary");
>                 break;
>             }    
>         }
>         else
>             count = 0;          /* reset counter if it connects again */
> 
> This code was add to defend against the death/crash of the target server. There
> are at least 3 options:
> 
> (1) increase NUM_CONN_ATTEMPTS * WAIT_INTERVAL seconds. We discussed this constant
> and I decided to use 10 seconds because even in some slow hosts, this time
> wasn't reached during my tests. It seems I forgot to test the combination of slow
> host, asserts enabled, and ubsan. I didn't notice that pg_promote() uses 60
> seconds as default wait. Maybe that's a reasonable value. I checked the
> 004_timeline_switch test and the last run took: 39.2s (serinus), 33.1s
> (culicidae), 18.31s (calliphoridae) and 27.52s (olingo).
> > (2) check if the primary is not running when walreceiver is not
available on the
> target server. Increase the connection attempts iif the primary is not running.
> Hence, the described case doesn't cause an increment on the count variable.
> 
> (3) set recovery_timeout default to != 0 and remove pg_stat_wal_receiver check
> protection against the death/crash target server. I explained in a previous
> message that timeout may occur in cases that WAL replay to reach consistent
> state takes more than recovery-timeout seconds.
> 
> Option (1) is the easiest fix, however, we can have the same issue again if a
> slow host decides to be even slower, hence, we have to adjust this value again.
> Option (2) interprets the walreceiver absence as a recovery end and if the
> primary server is running it can indicate that the target server is in the
> imminence of the recovery end. Option (3) is not as resilient as the other
> options.
> 
> The first patch implements a combination of (1) and (2).
> 
>> ## Analysis for failure 2
>>
>> According to [2], the physical replication slot which is specified as primary_slot_name
>> was not used by the walsender process. At that time walsender has not existed.
>>
>> ```
>> ...
>> pg_createsubscriber: publisher: current wal senders: 0
>> pg_createsubscriber: command is: SELECT 1 FROM pg_catalog.pg_replication_slots WHERE active AND slot_name = 'physical_slot'
>> pg_createsubscriber: error: could not obtain replication slot information: got 0 rows, expected 1 row
>> ...
>> ```
>>
>> Currently standby must be stopped before the command and current code does not
>> block the flow to ensure the replication is started. So there is a possibility
>> that the checking is run before walsender is launched.
>>
>> One possible approach is to wait until the replication starts. Alternative one is
>> to ease the condition.
> 
> That's my suggestion too. I reused NUM_CONN_ATTEMPTS (that was renamed to
> NUM_ATTEMPTS in the first patch). See second patch.
> 

Perhaps I'm missing something, but why is NUM_CONN_ATTEMPTS even needed?
Why isn't recovery_timeout enough to decide if wait_for_end_recovery()
waited long enough?

IMHO the test should simply pass PG_TEST_DEFAULT_TIMEOUT when calling
pg_createsubscriber, and that should do the trick.

Increasing PG_TEST_DEFAULT_TIMEOUT is what buildfarm animals doing
things like ubsan/valgrind already use to deal with exactly this kind of
timeout problem.

Or is there a deeper problem with deciding if the system is in recovery?


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company