Subject: Re: Add a perl function in Cluster.pm to generate WAL

From: Bharath Rupireddy <[email-masked]>
Date: Sun, 11 Jun 2023 07:14:54 +0530

On Wed, Aug 24, 2022 at 6:42 AM Kyotaro Horiguchi
<[email-masked]> wrote:
>
> At Tue, 16 Aug 2022 18:40:49 +0200, Alvaro Herrera <[email-masked]> wrote in
> > On 2022-Aug-16, Andrew Dunstan wrote:
> >
> > > I don't think there's a hard and fast rule about it. Certainly the case
> > > would be more compelling if the functions were used across different TAP
> > > suites. The SSL suite has suite-specific modules. That's a pattern also
> > > worth considering. e.g something like.
> > >
> > >     use FindBin qw($Bin);
> > >     use lib $Bin;
> > >     use MySuite;
> > >
> > > and then you put your common routines in MySuite.pm in the same
> > > directory as the TAP test files.
> >
> > Yeah, I agree with that for advance_wal.  Regarding find_in_log, that
> > one seems general enough to warrant being in Cluster.pm -- consider
> > issues_sql_like, which also slurps_file($log).  That could be unified a
> > little bit, I think.
>
> +1

With the generalized function for find_in_log() has been added as part
of https://git.postgresql.org/gitweb/?p=postgresql.git;a=commitdiff;h=e25e5f7fc6b74c9d4ce82627e9145ef5537412e2,
I'm proposing a generalized function for advance_wal(). Please find
the attached patch.

I tried to replace the existing tests with the new cluster function
advance_wal(). Please let me know if I'm missing any other tests.
Also, this new function can be used by an in-progress feature -
https://commitfest.postgresql.org/43/3663/.

Thoughts?

FWIW, it's discussed here -
https://www.postgresql.org/message-id/ZIKVd%2Ba43UfsIWJE%40paquier.xyz.

--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Thu, 15 Jun 2023 13:40:15 +0900 (JST)

Mmm. It seems like the email I thought I'd sent failed to go out.

At Sun, 11 Jun 2023 07:14:54 +0530, Bharath Rupireddy <[email-masked]> wrote in 
> https://commitfest.postgresql.org/43/3663/.

Thanks!

+			"CREATE TABLE tt (); DROP TABLE tt; SELECT pg_switch_wal();");

At least since 11, we can utilize pg_logical_emit_message() for this
purpose. It's more lightweight and seems appropriate, not only because
it doesn't cause any side effects but also bacause we don't have to
worry about name conflicts.

-		 SELECT 'finished';",
-		timeout => $PostgreSQL::Test::Utils::timeout_default));
-is($result[1], 'finished', 'check if checkpoint command is not blocked');
-
+$node_primary2->advance_wal(1);
+$node_primary2->safe_psql('postgres', 'CHECKPOINT;');

This test anticipates that the checkpoint could get blocked. Shouldn't
we keep the timeout?

-$node_primary->safe_psql(
-	'postgres', "create table retain_test(a int);
-									 select pg_switch_wal();
-									 insert into retain_test values(1);
-									 checkpoint;");
+$node_primary->advance_wal(1);
+$node_primary->safe_psql('postgres', "checkpoint;");

The original test generated some WAL after the segment switch, which
appears to be a significant characteristics of the test.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

---

From: Michael Paquier <[email-masked]>
Date: Fri, 16 Jun 2023 11:30:15 +0900

> worry about name conflicts.

Making this as cheap as possible by design is a good concept for a
common routine.  +1.

> This test anticipates that the checkpoint could get blocked. Shouldn't

Indeed, this would partially invalidate what's getting tested in light
of 1816a1c6 where we run a secondary command after the checkpoint.  So
the last SELECT should remain around.

> appears to be a significant characteristics of the test.

Still it does not matter for this specific case?  The logical slot has
been already invalidated, so we don't care much about logical changes
in WAL, do we?
--
Michael

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Fri, 16 Jun 2023 13:30:21 +0900 (JST)

Thanks for the comments.

At Fri, 16 Jun 2023 11:30:15 +0900, Michael Paquier <[email-masked]> wrote in 
> been already invalidated, so we don't care much about logical changes

The change itself doesn't seem to matter, but it seems intended to let
checkpoint trigger the removal of the last segment. However, I'm
unsure how the insert would influence this that way. If my
understanding is correct, then I'd support its removal.

regards.

---

From: Bharath Rupireddy <[email-masked]>
Date: Wed, 19 Jul 2023 16:11:13 +0530

> Making this as cheap as possible by design is a good concept for a

While it seems reasonable to use pg_logical_emit_message, it won't
work for all the cases - what if someone wants to advance WAL by a few
WAL files? I think pg_switch_wal() is the way, no? For instance, the
replslot_limit.pl test increases the WAL in a very calculated way - it
increases by 5 WAL files. So, -1 to use pg_logical_emit_message.

I understand the naming conflicts for the table name used ('tt' in
this case). If the table name 'tt' looks so simple and easy for
someone to have tables with that name in their tests file, we can
generate a random table name in advance_wal, something like in the
attached v2 patch.

> the last SELECT should remain around.

Changed.

> been already invalidated, so we don't care much about logical changes

Correct, the slot has already been invalidated and the test is
verifying that WAL isn't retained by the invalidated slot, so
essentially what it needs is to generate "some" wal. So, using
advance_wal there seems fine to me. CFBot doesn't complain anything -
https://github.com/BRupireddy/postgres/tree/add_a_TAP_test_function_to_generate_WAL_v2.

Attached the v2 patch. Thoughts?

---

From: Bharath Rupireddy <[email-masked]>
Date: Mon, 18 Dec 2023 11:09:41 +0530

> Attached the v2 patch. Thoughts?

Rebase needed, attached v3 patch.

---

From: "Euler Taveira" <[email-masked]>
Date: Mon, 18 Dec 2023 08:48:09 -0300

> Rebase needed, attached v3 patch.

I think you don't understand the suggestion proposed by Michael and Kyotaro. If
you do a comparison with the following SQL commands:

euler=# select pg_walfile_name(pg_current_wal_lsn());
     pg_walfile_name      
--------------------------
000000010000000000000040
(1 row)

euler=# select pg_logical_emit_message(true, 'prefix', 'message4');
pg_logical_emit_message 
-------------------------
0/400000A8
(1 row)

euler=# select pg_switch_wal();
pg_switch_wal 
---------------
0/400000F0
(1 row)

euler=# create table cc (b int);
CREATE TABLE
euler=# drop table cc;
DROP TABLE
euler=# select pg_switch_wal();
pg_switch_wal 
---------------
0/41017C88
(1 row)

euler=# select pg_walfile_name(pg_current_wal_lsn());
     pg_walfile_name      
--------------------------
000000010000000000000041
(1 row)

You get

$ pg_waldump 000000010000000000000040
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/40000028, prev 0/3F0001C0, desc: RUNNING_XACTS nextXid 295180 latestCompletedXid 295179 oldestRunningXid 295180
rmgr: LogicalMessage len (rec/tot):     65/    65, tx:     295180, lsn: 0/40000060, prev 0/40000028, desc: MESSAGE transactional, prefix "prefix"; payload (8 bytes): 6D 65 73 73 61 67 65 34
rmgr: Transaction len (rec/tot):     46/    46, tx:     295180, lsn: 0/400000A8, prev 0/40000060, desc: COMMIT 2023-12-18 08:35:06.821322 -03
rmgr: XLOG        len (rec/tot):     24/    24, tx:          0, lsn: 0/400000D8, prev 0/400000A8, desc: SWITCH 

$ pg_waldump 000000010000000000000041
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/41000028, prev 0/400000D8, desc: RUNNING_XACTS nextXid 295181 latestCompletedXid 295180 oldestRunningXid 295181
rmgr: Storage     len (rec/tot):     42/    42, tx:          0, lsn: 0/41000060, prev 0/41000028, desc: CREATE base/33287/88102
rmgr: Heap2       len (rec/tot):     60/    60, tx:     295181, lsn: 0/41000090, prev 0/41000060, desc: NEW_CID rel: 1663/33287/1247, tid: 14/16, cmin: 0, cmax: 4294967295, combo: 4294967295
rmgr: Heap        len (rec/tot):     54/  3086, tx:     295181, lsn: 0/410000D0, prev 0/41000090, desc: INSERT off: 16, flags: 0x00, blkref #0: rel 1663/33287/1247 blk 14 FPW
rmgr: Btree       len (rec/tot):     53/  5133, tx:     295181, lsn: 0/41000CE0, prev 0/410000D0, desc: INSERT_LEAF off: 252, blkref #0: rel 1663/33287/2703 blk 2 FPW
.
.
.
rmgr: Btree       len (rec/tot):     72/    72, tx:     295181, lsn: 0/41016E48, prev 0/41014F00, desc: INSERT_LEAF off: 111, blkref #0: rel 1663/33287/2674 blk 7
rmgr: Heap2       len (rec/tot):     69/    69, tx:     295181, lsn: 0/41016E90, prev 0/41016E48, desc: PRUNE snapshotConflictHorizon: 295177, nredirected: 0, ndead: 7, nunused: 0, redirected: [], dead: [20, 21, 22, 23, 24, 26, 27], unused: [], blkref #0: rel 1663/33287/1249 blk 17
rmgr: Transaction len (rec/tot):    385/   385, tx:     295181, lsn: 0/41016ED8, prev 0/41016E90, desc: INVALIDATION ; inval msgs: catcache 80 catcache 79 catcache 80 catcache 79 catcache 55 catcache 54 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 snapshot 2608 relcache 88102
rmgr: Standby     len (rec/tot):     42/    42, tx:     295181, lsn: 0/41017060, prev 0/41016ED8, desc: LOCK xid 295181 db 33287 rel 88102 
rmgr: Transaction len (rec/tot):    405/   405, tx:     295181, lsn: 0/41017090, prev 0/41017060, desc: COMMIT 2023-12-18 08:35:22.342122 -03; inval msgs: catcache 80 catcache 79 catcache 80 catcache 79 catcache 55 catcache 54 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 snapshot 2608 relcache 88102
rmgr: Standby     len (rec/tot):     42/    42, tx:     295182, lsn: 0/41017228, prev 0/41017090, desc: LOCK xid 295182 db 33287 rel 88102 
rmgr: Heap2       len (rec/tot):     61/    61, tx:     295182, lsn: 0/41017258, prev 0/41017228, desc: PRUNE snapshotConflictHorizon: 295177, nredirected: 0, ndead: 3, nunused: 0, redirected: [], dead: [9, 12, 15], unused: [], blkref #0: rel 1663/33287/2608 blk 3
rmgr: Heap2       len (rec/tot):     60/    60, tx:     295182, lsn: 0/41017298, prev 0/41017258, desc: NEW_CID rel: 1663/33287/1247, tid: 14/17, cmin: 4294967295, cmax: 0, combo: 4294967295
rmgr: Heap        len (rec/tot):     54/    54, tx:     295182, lsn: 0/410172D8, prev 0/41017298, desc: DELETE xmax: 295182, off: 17, infobits: [KEYS_UPDATED], flags: 0x00, blkref #0: rel 1663/33287/1247 blk 14
.
.
.
rmgr: Heap2       len (rec/tot):     60/    60, tx:     295182, lsn: 0/410178D8, prev 0/410178A0, desc: NEW_CID rel: 1663/33287/2608, tid: 3/24, cmin: 4294967295, cmax: 2, combo: 4294967295
rmgr: Heap        len (rec/tot):     54/    54, tx:     295182, lsn: 0/41017918, prev 0/410178D8, desc: DELETE xmax: 295182, off: 24, infobits: [KEYS_UPDATED], flags: 0x00, blkref #0: rel 1663/33287/2608 blk 3
rmgr: Transaction len (rec/tot):    321/   321, tx:     295182, lsn: 0/41017950, prev 0/41017918, desc: INVALIDATION ; inval msgs: catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 relcache 88102 snapshot 2608
rmgr: Transaction len (rec/tot):    469/   469, tx:     295182, lsn: 0/41017A98, prev 0/41017950, desc: COMMIT 2023-12-18 08:35:25.053905 -03; rels: base/33287/88102; dropped stats: 2/33287/88102; inval msgs: catcache 80 catcache 79 catcache 80 catcache 79 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 55 catcache 54 snapshot 2608 snapshot 2608 relcache 88102 snapshot 2608
rmgr: XLOG        len (rec/tot):     24/    24, tx:          0, lsn: 0/41017C70, prev 0/41017A98, desc: SWITCH

The difference is

euler=# select '0/400000A8'::pg_lsn - '0/40000028'::pg_lsn;
?column? 
----------
      128
(1 row)

euler=# select '0/41017A98'::pg_lsn - '0/41000028'::pg_lsn;
?column? 
----------
    96880
(1 row)

It is cheaper.

--
Euler Taveira
EDB   https://www.enterprisedb.com/

---

From: Michael Paquier <[email-masked]>
Date: Tue, 19 Dec 2023 13:21:02 +0900

> It is cheaper.

Agreed that this could just use a set of pg_logical_emit_message()
when jumping across N segments.  Another thing that seems quite
important to me is to force a flush of WAL with the last segment
switch, and the new "flush" option of pg_logical_emit_message() can
be very handy for this purpose.
--
Michael

---

From: Bharath Rupireddy <[email-masked]>
Date: Tue, 19 Dec 2023 11:25:50 +0530

On Tue, Dec 19, 2023 at 9:51 AM Michael Paquier <[email-masked]> wrote:
> when jumping across N segments.

Thanks. I missed the point of using pg_logical_emit_message() over
CREATE .. DROP TABLE to generate WAL. And, I agree that it's better
and relatively cheaper in terms of amount of WAL generated.

> Another thing that seems quite

I used pg_logical_emit_message() in non-transactional mode without
needing an explicit WAL flush as the pg_switch_wal() does a WAL flush
at the end [1].

Attached v4 patch.

[1]
    /*
     * If this was an XLOG_SWITCH record, flush the record and the empty
     * padding space that fills the rest of the segment, and perform
     * end-of-segment actions (eg, notifying archiver).
     */
    if (class == WALINSERT_SPECIAL_SWITCH)
    {
        TRACE_POSTGRESQL_WAL_SWITCH();
        XLogFlush(EndPos);

---

From: Michael Paquier <[email-masked]>
Date: Wed, 20 Dec 2023 08:00:19 +0900

> needing an explicit WAL flush as the pg_switch_wal() does a WAL flush

Indeed, that should be enough to answer my comment.

> Attached v4 patch.

LGTM, thanks.  Euler, what do you think?
--
Michael

---

From: "Euler Taveira" <[email-masked]>
Date: Wed, 20 Dec 2023 00:24:04 -0300

> LGTM, thanks.  Euler, what do you think?

LGTM.

---

From: Michael Paquier <[email-masked]>
Date: Thu, 21 Dec 2023 10:21:45 +0900

> LGTM.

I was eyeing at 020_messages.pl and it has a pg_switch_wal() after a
transaction rollbacked.  020_archive_status.pl creates a table, does 
one segment switch, then a checkpoint (table is used afterwards).
Perhaps these could be changed with the new routine, but it does not
seem like this improves the readability of the tests, either, contrary
to the ones updated here where a fake table is created to force some
records.  What do you think?

We have a few more pg_switch_wal() calls, as well, but these rely on
WAL being already generated beforehand.

I have added a comment about pg_logical_emit_message() being in
non-transactional mode and the flush implied by pg_switch_wal() as
that's important, edited a bit the whole, then applied the patch.
--
Michael

---

From: Tom Lane <[email-masked]>
Date: Wed, 03 Jan 2024 18:39:29 -0500

> that's important, edited a bit the whole, then applied the patch.

Buildfarm member skink has failed 3 times in
035_standby_logical_decoding.pl in the last couple of days:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2024-01-03%2020%3A07%3A15

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2024-01-03%2017%3A09%3A27

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2024-01-01%2020%3A10%3A18

These all look like

# poll_query_until timed out executing this query:
# select (confl_active_logicalslot = 1) from pg_stat_database_conflicts where datname = 'testdb'
# expecting this output:
# t
# last actual query output:
# f

although it's notable that two different tests are involved
(vacuum vs. vacuum full).

I am not real sure what is happening there, but I see that c161ab74f
changed some details of how that test works, so I wonder if it's
responsible for these failures.  The timing isn't a perfect match,
since this commit went in two weeks ago, but I don't see any
more-recent commits that seem like plausible explanations.

			regards, tom lane

---

From: Alexander Lakhin <[email-masked]>
Date: Thu, 4 Jan 2024 16:00:01 +0300

Hello Tom,

> more-recent commits that seem like plausible explanations.

Reproduced here.
As I can see in the failure logs you referenced, the first problem is:
#   Failed test 'inactiveslot slot invalidation is logged with vacuum on pg_authid'
#   at t/035_standby_logical_decoding.pl line 224.

It reminded me of:
https://www.postgresql.org/message-id/b2a1f7d0-7629-72c0-2da7-e9c4e336b010%40gmail.com

It seems that it's not something new, and maybe that my analysis is still
valid. If so, VACUUM FREEZE/autovacuum = off should fix the issue.

Best regards,
Alexander

---

From: Michael Paquier <[email-masked]>
Date: Fri, 5 Jan 2024 08:48:33 +0900

> Reproduced here.

Did you just make the run slow enough to show the failure with
valgrind?

> valid. If so, VACUUM FREEZE/autovacuum = off should fix the issue.

Not sure about that yet.
--
Michael