Message-ID: <1d7b08f2-64a2-77fb-c666-c9a74c68eeda@gmail.com>
Date: Fri, 13 Sep 2024 15:00:00 +0300
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.4.2
Subject: Re: [HACKERS] make async slave to wait for lsn to be replayed
To: Alexander Korotkov <aekorotkov@gmail.com>,
 Kevin Hale Boyes <kcboyes@gmail.com>
Cc: Kartyshov Ivan <i.kartyshov@postgrespro.ru>,
 Kyotaro Horiguchi <horikyota.ntt@gmail.com>, hlinnaka@iki.fi,
 alvherre@alvh.no-ip.org, pashkin.elfe@gmail.com,
 bharath.rupireddyforpostgres@gmail.com, euler@eulerto.com,
 thomas.munro@gmail.com, peter@eisentraut.org, amit.kapila16@gmail.com,
 dilipbalaut@gmail.com, smithpb2250@gmail.com,
 pgsql-hackers@lists.postgresql.org
References: <ca85a3c56e3c26cc29d1df14021845f6@postgrespro.ru>
 <CAPpHfdvGRssjqwX1+idm5Tu-eWsTcx6DthB2LhGqA1tZ29jJaw@mail.gmail.com>
 <CAPpHfdvDjrM6=XxDiuZBa+bg2qL34jwafa3uXf0Zsxm2PKOChg@mail.gmail.com>
 <20240620.173045.1163445432733259320.horikyota.ntt@gmail.com>
 <8d0286f9f0c2f9fc29794dda6b5f4600@postgrespro.ru>
 <CAPpHfdvwMn21n-zWecvr5gEzFy7rmszwbOTekjTE4taCe9frBw@mail.gmail.com>
 <CAPpHfds1QW-zZ_Hs4dkvX2pji=Ms1VE2C=oGFRu2xFbDA_-MgA@mail.gmail.com>
 <CAPpHfdt8rs0=NC3aHgcj_ZXGKEexZtk=Y8ytK188Ta3NWD5+Pg@mail.gmail.com>
 <CADAecHWKpaPuPGXAMOH=wmhTpydHWGPOk9KWX97UYhp5GdqCWw@mail.gmail.com>
 <CAPpHfdu5QN+ZGACS+7foxmr8_nekgA2PA+-G3BuOUrdBLBFb6Q@mail.gmail.com>
 <CAPpHfdtRZ+3use8n3Vc9RFVitXj59koTKuYLM4+3M0_En7BY9g@mail.gmail.com>
 <CAPpHfdsyZFEu-M5YLeX68cBG_N4j7R4TM6ROpP6wnNB_oDNKZA@mail.gmail.com>
 <CAPpHfdsgKwR5ifuBTdB4sOA1=h28=0tUHjaWRWi0C_VZR5PMdg@mail.gmail.com>
From: Alexander Lakhin <exclusion@gmail.com>
Content-Language: en-US
In-Reply-To: 
 <CAPpHfdsgKwR5ifuBTdB4sOA1=h28=0tUHjaWRWi0C_VZR5PMdg@mail.gmail.com>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit
Archived-At: 
 <https://www.postgresql.org/message-id/1d7b08f2-64a2-77fb-c666-c9a74c68eeda%40gmail.com>
Precedence: bulk

Hi Alexander,

10.08.2024 20:18, Alexander Korotkov wrote:
> On Sat, Aug 10, 2024 at 7:33 PM Alexander Korotkov <aekorotkov@gmail.com> wrote:
>> On Tue, Aug 6, 2024 at 5:17 AM Alexander Korotkov <aekorotkov@gmail.com> wrote:
>> ...
>> Here is a revised version of the patchset.  I've fixed some typos,
>> identation, etc.  I'm going to push this once it passes cfbot.
> The next revison of the patchset fixes uninitialized variable usage
> spotted by cfbot.

When running check-world on a rather slow armv7 device, I came across the
043_wal_replay_wait.pl test failure:
t/043_wal_replay_wait.pl .............. 7/? # Tests were run but no plan was declared and done_testing() was not seen.
# Looks like your test exited with 29 just after 8.

regress_log_043_wal_replay_wait contains:
...
01234[21:58:56.370](1.594s) ok 7 - multiple LSN waiters reported consistent data
### Promoting node "standby"
# Running: pg_ctl -D .../src/test/recovery/tmp_check/t_043_wal_replay_wait_standby_data/pgdata -l 
.../src/test/recovery/tmp_check/log/043_wal_replay_wait_standby.log promote
waiting for server to promote.... done
server promoted
[21:58:56.637](0.268s) ok 8 - got error after standby promote
error running SQL: 'psql:<stdin>:1: ERROR:  recovery is not in progress
HINT:  Waiting for LSN can only be executed during recovery.'
while running 'psql -XAtq -d port=10228 host=/tmp/Ftj8qpTQht dbname='postgres' -f - -v ON_ERROR_STOP=1' with sql 'CALL 
pg_wal_replay_wait('0/300D0E8');' at .../src/test/recovery/../../../src/test/perl/PostgreSQL/Test/Cluster.pm line 2140.

043_wal_replay_wait_standby.log contains:
2024-09-12 21:58:56.518 UTC [15220:1] [unknown] LOG:  connection received: host=[local]
2024-09-12 21:58:56.520 UTC [15220:2] [unknown] LOG:  connection authenticated: user="android" method=trust 
(.../src/test/recovery/tmp_check/t_043_wal_replay_wait_standby_data/pgdata/pg_hba.conf:117)
2024-09-12 21:58:56.520 UTC [15220:3] [unknown] LOG:  connection authorized: user=android database=postgres 
application_name=043_wal_replay_wait.pl
2024-09-12 21:58:56.527 UTC [15220:4] 043_wal_replay_wait.pl LOG: statement: CALL pg_wal_replay_wait('2/570CB4E8');
2024-09-12 21:58:56.535 UTC [15123:7] LOG:  received promote request
2024-09-12 21:58:56.535 UTC [15124:2] FATAL:  terminating walreceiver process due to administrator command
2024-09-12 21:58:56.537 UTC [15123:8] LOG:  invalid record length at 0/300D0B0: expected at least 24, got 0
2024-09-12 21:58:56.537 UTC [15123:9] LOG:  redo done at 0/300D088 system usage: CPU: user: 0.01 s, system: 0.00 s, 
elapsed: 14.23 s
2024-09-12 21:58:56.537 UTC [15123:10] LOG:  last completed transaction was at log time 2024-09-12 21:58:55.322831+00
2024-09-12 21:58:56.540 UTC [15123:11] LOG:  selected new timeline ID: 2
2024-09-12 21:58:56.589 UTC [15123:12] LOG:  archive recovery complete
2024-09-12 21:58:56.590 UTC [15220:5] 043_wal_replay_wait.pl ERROR: recovery is not in progress
2024-09-12 21:58:56.590 UTC [15220:6] 043_wal_replay_wait.pl DETAIL:  Recovery ended before replaying target LSN 
2/570CB4E8; last replay LSN 0/300D0B0.
2024-09-12 21:58:56.591 UTC [15121:1] LOG:  checkpoint starting: force
2024-09-12 21:58:56.592 UTC [15220:7] 043_wal_replay_wait.pl LOG: disconnection: session time: 0:00:00.075 user=android 
database=postgres host=[local]
2024-09-12 21:58:56.595 UTC [15120:4] LOG:  database system is ready to accept connections
2024-09-12 21:58:56.665 UTC [15227:1] [unknown] LOG:  connection received: host=[local]
2024-09-12 21:58:56.668 UTC [15227:2] [unknown] LOG:  connection authenticated: user="android" method=trust 
(.../src/test/recovery/tmp_check/t_043_wal_replay_wait_standby_data/pgdata/pg_hba.conf:117)
2024-09-12 21:58:56.668 UTC [15227:3] [unknown] LOG:  connection authorized: user=android database=postgres 
application_name=043_wal_replay_wait.pl
2024-09-12 21:58:56.675 UTC [15227:4] 043_wal_replay_wait.pl LOG: statement: CALL pg_wal_replay_wait('0/300D0E8');
2024-09-12 21:58:56.677 UTC [15227:5] 043_wal_replay_wait.pl ERROR: recovery is not in progress
2024-09-12 21:58:56.677 UTC [15227:6] 043_wal_replay_wait.pl HINT: Waiting for LSN can only be executed during recovery.
2024-09-12 21:58:56.679 UTC [15227:7] 043_wal_replay_wait.pl LOG: disconnection: session time: 0:00:00.015 user=android 
database=postgres host=[local]

Note that last replay LSN is 300D0B0, but the latter pg_wal_replay_wait
call wants to wait for 300D0E8.

pg_waldump -p src/test/recovery/tmp_check/t_043_wal_replay_wait_primary_data/pgdata/pg_wal/ 000000010000000000000003
shows:
rmgr: Heap        len (rec/tot):     59/    59, tx:        748, lsn: 0/0300D048, prev 0/0300D020, desc: INSERT off: 35, 
flags: 0x00, blkref #0: rel 1663/5/16384 blk 0
rmgr: Transaction len (rec/tot):     34/    34, tx:        748, lsn: 0/0300D088, prev 0/0300D048, desc: COMMIT 
2024-09-12 21:58:55.322831 UTC
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/0300D0B0, prev 0/0300D088, desc: RUNNING_XACTS 
nextXid 749 latestCompletedXid 748 oldestRunningXid 749

I could reproduce this failure on my workstation with bgworker modified
as below:
--- a/src/backend/postmaster/bgwriter.c
+++ b/src/backend/postmaster/bgwriter.c
@@ -69 +69 @@ int            BgWriterDelay = 200;
-#define LOG_SNAPSHOT_INTERVAL_MS 15000
+#define LOG_SNAPSHOT_INTERVAL_MS 15
@@ -307 +307 @@ BackgroundWriterMain(char *startup_data, size_t startup_data_len)
-                       BgWriterDelay /* ms */ , WAIT_EVENT_BGWRITER_MAIN);
+                       1 /* ms */ , WAIT_EVENT_BGWRITER_MAIN);


When looking at the test, I noticed probably a typo in the test message:
wait for already replayed LSN exists immediately ...
shouldn't it be "exits" there (though maybe the whole phrase could be
improved)?

I also suspect that "achieve" is not suitable word in the context of LSNs
and timeouts. Maybe you would find it appropriate to replace it with
"reach"?

Best regards,
Alexander