From: Drouvot, Bertrand <bertranddrouvot.pg@gmail.com>
To: Amit Kapila <amit.kapila16@gmail.com>
Cc: vignesh C <vignesh21@gmail.com>
Cc: Yu Shi (Fujitsu) <shiy.fnst@fujitsu.com>
Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Subject: Re: Add two missing tests in 035_standby_logical_decoding.pl
Date: Fri, 5 May 2023 12:32:33 +0200
Message-ID: <2c544b9f-419d-d18e-47be-f3d6f3d24e4e@gmail.com> (raw)
In-Reply-To: <CAA4eK1+-H9TBSG-qEd7aykdKHhRo3YCsQ_i6mquTdiL2zXVAPw@mail.gmail.com>
References: <2fefa454-5a70-2174-ddbf-4a0e41537139@gmail.com>
<CAA4eK1JeAZ9MUf3qPAOA5t9=e_vPJSEi6nZ3OygDYi-913eO+Q@mail.gmail.com>
<74f80bc1-6b39-b2a8-c716-98beefb75e0b@gmail.com>
<OSZPR01MB6310F24417BDD04731BD7978FD659@OSZPR01MB6310.jpnprd01.prod.outlook.com>
<17b6b056-4f53-c444-0c94-869547d1a5df@gmail.com>
<CAA4eK1JiYisk1aqn1uvjd+VCfsVtXLby7uMmkLQU_ggAx7xt6w@mail.gmail.com>
<054defef-de15-53e4-6c5a-d16ccc21d4ba@gmail.com>
<CAA4eK1LEQfC-ZxOkN4=cuAxB1N=2iLcEEb+Mb=XGCqGhwvMkaA@mail.gmail.com>
<8a13f0d8-71f3-773b-7135-5974fd53724b@gmail.com>
<CAA4eK1+FhvUm6w-TYqXAAMNDPZcin05pyCu7Lzn-AnafFYYhBg@mail.gmail.com>
<CALDaNm3GOW-7DfdqUiJADhEmQNQkFA+OonV4kvKkZcbK=0yr5w@mail.gmail.com>
<CAA4eK1La2uVZdSNdp_AwpxVP85SvWHMT3ecfJgVYqPMjGVViyw@mail.gmail.com>
<6711e200-0d5c-98c3-ba39-7d64a6936f7a@gmail.com>
<CAA4eK1LQmnSroXZcR+w1JuHsOyQLdj=-QWUw8ExYem3kUpBE3A@mail.gmail.com>
<a3f02689-fd8b-e290-2e62-9f7a5eb6f4d8@gmail.com>
<CAA4eK1+-H9TBSG-qEd7aykdKHhRo3YCsQ_i6mquTdiL2zXVAPw@mail.gmail.com>
On 5/5/23 11:29 AM, Amit Kapila wrote:
> On Fri, May 5, 2023 at 1:16 PM Drouvot, Bertrand
> <bertranddrouvot.pg@gmail.com> wrote:
>>
>>
>> After multiple attempts, I got one failing one.
>>
>> Issue is that we expect this file to be removed:
>>
>> [07:24:27.261](0.899s) #WAL file is /Users/admin/pgsql/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_standby_data/pgdata/pg_wal/000000010000000000000003
>>
>> But the standby emits:
>>
>> 2023-05-05 07:24:27.216 UTC [17909][client backend] [035_standby_logical_decoding.pl][3/6:0] LOG: statement: checkpoint;
>> 2023-05-05 07:24:27.216 UTC [17745][checkpointer] LOG: restartpoint starting: immediate wait
>> 2023-05-05 07:24:27.259 UTC [17745][checkpointer] LOG: attempting to remove WAL segments older than log file 000000000000000000000002
>>
>> So it seems the test is not right (missing activity??), not sure why yet.
>>
>
> Can you try to print the value returned by
> XLogGetReplicationSlotMinimumLSN() in KeepLogSeg() on standby? Also,
> please try to print "attempting to remove WAL segments ..." on the
> primary. We can see, if by any chance some slot is holding us to
> remove the required WAL file.
>
I turned DEBUG2 on. We can also see on the primary:
2023-05-05 08:23:30.843 UTC [16833][checkpointer] LOCATION: CheckPointReplicationSlots, slot.c:1576
2023-05-05 08:23:30.844 UTC [16833][checkpointer] DEBUG: 00000: snapshot of 0+0 running transaction ids (lsn 0/40000D0 oldest xid 746 latest complete 745 next xid 746)
2023-05-05 08:23:30.844 UTC [16833][checkpointer] LOCATION: LogCurrentRunningXacts, standby.c:1377
2023-05-05 08:23:30.845 UTC [16833][checkpointer] LOG: 00000: BDT1 about to call RemoveOldXlogFiles in CreateCheckPoint
2023-05-05 08:23:30.845 UTC [16833][checkpointer] LOCATION: CreateCheckPoint, xlog.c:6835
2023-05-05 08:23:30.845 UTC [16833][checkpointer] LOG: 00000: attempting to remove WAL segments older than log file 000000000000000000000002
2023-05-05 08:23:30.845 UTC [16833][checkpointer] LOCATION: RemoveOldXlogFiles, xlog.c:3560
2023-05-05 08:23:30.845 UTC [16833][checkpointer] DEBUG: 00000: recycled write-ahead log file "000000010000000000000001"
2023-05-05 08:23:30.845 UTC [16833][checkpointer] LOCATION: RemoveXlogFile, xlog.c:3708
2023-05-05 08:23:30.845 UTC [16833][checkpointer] DEBUG: 00000: recycled write-ahead log file "000000010000000000000002"
2023-05-05 08:23:30.845 UTC [16833][checkpointer] LOCATION: RemoveXlogFile, xlog.c:3708
2023-05-05 08:23:30.845 UTC [16833][checkpointer] DEBUG: 00000: SlruScanDirectory invoking callback on pg_subtrans/0000
So, 000000010000000000000003 is not removed on the primary.
It has been recycled on:
2023-05-05 08:23:38.605 UTC [16833][checkpointer] DEBUG: 00000: recycled write-ahead log file "000000010000000000000003"
Which is later than the test:
[08:23:31.931](0.000s) not ok 19 - invalidated logical slots do not lead to retaining WAL
FWIW, the failing test with DEBUG2 can be found there: https://cirrus-ci.com/task/5615316688961536
Regards,
--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: bertranddrouvot.pg@gmail.com, amit.kapila16@gmail.com, vignesh21@gmail.com, shiy.fnst@fujitsu.com, pgsql-hackers@lists.postgresql.org
Subject: Re: Add two missing tests in 035_standby_logical_decoding.pl
In-Reply-To: <2c544b9f-419d-d18e-47be-f3d6f3d24e4e@gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox