MIME-Version: 1.0
References: <CAM-w4HORsLbxwv8KVUHWu1PxKQLuCN1JjAnXknP8pFNSQfbh3A@mail.gmail.com>
 <20230324093547.amsbfoql2kmbqco2@alvherre.pgsql> <CALj2ACVdPMRBKCLd+XXGg+O9y5g1=0CtWs4bp39dX-J=oe=TTg@mail.gmail.com>
 <CAA4eK1K=4dcBn2rcPLai76RZAVgMKmk6xAEgu0CT0p=uHa4TXw@mail.gmail.com>
 <CAHut+PtP7nZT0DW6GLPi6hebJJpDx-nOr+TmcsY=gsCk1Te6kw@mail.gmail.com>
 <CALj2ACWjNSA=1hz0yOcrZbZNLVffZ7A5sPqV7_mMLjtMMs_kxQ@mail.gmail.com>
 <CAA4eK1LPe=7Rb0kR8BGuLye2urNfWs=3idmbU3OfV8VTJU9KCg@mail.gmail.com> <CALj2ACXCCfi_UhFfvDtQbGqyjpf8X+3sBbz0_BsUp0rANuh8Eg@mail.gmail.com>
In-Reply-To: <CALj2ACXCCfi_UhFfvDtQbGqyjpf8X+3sBbz0_BsUp0rANuh8Eg@mail.gmail.com>
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Mon, 13 Nov 2023 19:47:40 +0530
Message-ID: <CALj2ACWryGZ23dRZk3SMxMLgntOwM3fq+QD3Rbqr+-VOgfbTrw@mail.gmail.com>
Subject: Re: add log messages when replication slots become active and
 inactive (was Re: Is it worth adding ReplicationSlot active_pid to ReplicationSlotPersistentData?)
To: Amit Kapila <amit.kapila16@gmail.com>
Cc: Peter Smith <smithpb2250@gmail.com>, Alvaro Herrera <alvherre@alvh.no-ip.org>, 
	Greg Stark <stark@mit.edu>, Euler Taveira <euler@eulerto.com>, 
	Kyotaro Horiguchi <horikyota.ntt@gmail.com>, 
	PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Content-Type: multipart/mixed; boundary="000000000000f031cd060a095533"
Archived-At: <https://www.postgresql.org/message-id/CALj2ACWryGZ23dRZk3SMxMLgntOwM3fq%2BQD3Rbqr%2B-VOgfbTrw%40mail.gmail.com>
Precedence: bulk

--000000000000f031cd060a095533
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

On Mon, Nov 13, 2023 at 5:43=E2=80=AFPM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
>
> On Mon, Nov 6, 2023 at 9:09=E2=80=AFAM Amit Kapila <amit.kapila16@gmail.c=
om> wrote:
> >
> > On Sun, Nov 5, 2023 at 4:01=E2=80=AFAM Bharath Rupireddy
> > <bharath.rupireddyforpostgres@gmail.com> wrote:
> > >
> > > On Thu, Nov 2, 2023 at 7:19=E2=80=AFAM Peter Smith <smithpb2250@gmail=
.com> wrote:
> > > >
> > > > But that's not quite compatible with what Alvaro [2] had written lo=
ng
> > > > back ("... the only acquisitions that would log messages are those =
in
> > > > StartReplication and StartLogicalReplication.").
> > > >
> > > > In other words, ReplicationSlotAcquire/ReplicationSlotRelease is
> > > > called by more places than you care to log from.
> > >
> > > I refreshed my thoughts for this patch and I think it's enough if
> > > walsenders alone log messages when slots become active and inactive.
> > > How about something like the attached v11 patch?
> > >
> >
> > + * This function is currently used only in walsender.
> > + */
> > +void
> > +ReplicationSlotAcquireAndLog(const char *name, bool nowait)
> >
> > BTW, is the reason for using it only in walsender is that it is a
> > background process and it is not very apparent whether the slot is
> > created, and for foreground processes, it is a bit clear when the
> > command is executed.
> >
> > Can you please tell me the use case of this additional message?
>
> Replication slot acquisitions and releases by backends say when
> running pg_replication_slot_advance or pg_logical_slot_get_changes or
> pg_drop_replication_slot or pg_create_{physical,
> logical}_replication_slot are transient unlike walsenders which
> comparatively hold slots for longer durations. Therefore, I've added
> them only for walsenders. These messages help to know the lifetime of
> a replication slot - one can know how long a streaming standby or
> logical subscriber is down, IOW, how long a replication slot is
> inactive in production. For instance, the time between released and
> acquired slots in the below messages is the inactive replication slot
> duration.
>
> 2023-11-13 11:06:34.338 UTC [470262] LOG:  acquired physical
> replication slot "sb_repl_slot"
> 2023-11-13 11:06:34.338 UTC [470262] STATEMENT:  START_REPLICATION
> SLOT "sb_repl_slot" 0/3000000 TIMELINE 1
> 2023-11-13 11:09:24.918 UTC [470262] LOG:  released physical
> replication slot "sb_repl_slot"
> 2023-11-13 12:01:40.530 UTC [470967] LOG:  acquired physical
> replication slot "sb_repl_slot"
> 2023-11-13 12:01:40.530 UTC [470967] STATEMENT:  START_REPLICATION
> SLOT "sb_repl_slot" 0/3000000 TIMELINE 1
>
> > If so, the other alternative is to either use a
> > parameter to the existing function or directly use am_walsender flag
> > to distinguish when to print the message in acquire/release calls.
>
> Done that way. PSA v12.
>
> > A few other minor comments:
> > 1.
> > +        Causes each replication command and related activity to be log=
ged in
> > +        the server log.
> >
> > Can we be bit more specific by changing to something like: "Causes
> > each replication command and slot acquisition/release to be logged in
> > the server log."
>
> Done.
>
> > 2.
> > + ereport(log_replication_commands ? LOG : DEBUG1,
> > + (errmsg("walsender process with PID %d acquired %s replication slot \=
"%s\"",
> >
> > It seems PID and process name is quite unlike what we print in other
> > similar messages. For example, see below messages when we start
> > replication via pub/sub :
> >
> > We can get the PID from the log line as for other logs and I don't see
> > the process name printed anywhere else.
>
> There was a comment upthread to have PID printed, but I agree to be
> consistent and changed the messages to be: acquired physical/logical
> replication slot "foo" and released physical/logical replication slot
> "foo".
>
> PSA v12 patch.

Compiler isn't happy with v12
https://cirrus-ci.com/task/5543061376204800?logs=3Dgcc_warning#L405. PSA
v13 patch.

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

--000000000000f031cd060a095533
Content-Type: application/octet-stream; 
	name="v13-0001-Log-messages-for-replication-slot-acquisition-an.patch"
Content-Disposition: attachment; 
	filename="v13-0001-Log-messages-for-replication-slot-acquisition-an.patch"
Content-Transfer-Encoding: base64
Content-ID: <f_lowzfgt30>
X-Attachment-Id: f_lowzfgt30

RnJvbSAzOTBjZDVjODE1MThmMjA5ZTMwZTdkZGUzMjIwMTg1YWUwMDZiMDRkIE1vbiBTZXAgMTcg
MDA6MDA6MDAgMjAwMQpGcm9tOiBCaGFyYXRoIFJ1cGlyZWRkeSA8YmhhcmF0aC5ydXBpcmVkZHlm
b3Jwb3N0Z3Jlc0BnbWFpbC5jb20+CkRhdGU6IE1vbiwgMTMgTm92IDIwMjMgMTQ6MDg6MjMgKzAw
MDAKU3ViamVjdDogW1BBVENIIHYxM10gTG9nIG1lc3NhZ2VzIGZvciByZXBsaWNhdGlvbiBzbG90
IGFjcXVpc2l0aW9uIGFuZCByZWxlYXNlCgpUaGlzIGNvbW1pdCBhZGRzIGxvZyBtZXNzYWdlcyAo
YXQgTE9HIGxldmVsIHdoZW4KbG9nX3JlcGxpY2F0aW9uX2NvbW1hbmRzIGlzIHNldCwgb3RoZXJ3
aXNlIGF0IERFQlVHMSBsZXZlbCkgd2hlbgp3YWxzZW5kZXJzIGFjcXVpcmUgYW5kIHJlbGVhc2Ug
cmVwbGljYXRpb24gc2xvdHMuIFRoZXNlIG1lc3NhZ2VzCmhlbHAgdG8ga25vdyB0aGUgbGlmZXRp
bWUgb2YgYSByZXBsaWNhdGlvbiBzbG90IC0gb25lIGNhbiBrbm93IGhvdwpsb25nIGEgc3RyZWFt
aW5nIHN0YW5kYnkgb3IgbG9naWNhbCBzdWJzY3JpYmVyIG9yIHJlcGxpY2F0aW9uIHNsb3QKY29u
c3VtZXIgaXMgZG93bi4gSW4gb3RoZXIgd29yZHMsIG9uZSBjYW4ga25vdyBob3cgbG9uZyBhCnJl
cGxpY2F0aW9uIHNsb3QgaXMgaW5hY3RpdmUgLSB0aGUgdGltZSBiZXR3ZWVuIHJlbGVhc2VkIGFu
ZAphY3F1aXJlZCBzbG90IG1lc3NhZ2VzIGlzIHRoZSBpbmFjdGl2ZSByZXBsaWNhdGlvbiBzbG90
IGR1cmF0aW9uLgpUaGVzZSBtZXNzYWdlcyB3aWxsIGJlIGV4dHJlbWVseSB1c2VmdWwgb24gcHJv
ZHVjdGlvbiBzZXJ2ZXJzIHRvCmRlYnVnIGFuZCBhbmFseXplIGluYWN0aXZlIHJlcGxpY2F0aW9u
IHNsb3QgaXNzdWVzLgoKTm90ZSB0aGF0IHRoZXNlIG1lc3NhZ2VzIGFyZSBlbWl0dGVkIG9ubHkg
Zm9yIHdhbHNlbmRlcnMgd2hlbgpyZXBsaWNhdGlvbiBzbG90IGlzIGFjcXVpcmVkIGFuZCByZWxl
YXNlZCwgYnV0IG5vdCBmb3IgYmFja2VuZHMuClRoaXMgaXMgYmVjYXVzZSB3YWxzZW5kZXJzIGFy
ZSB0aGUgb25lcyB0aGF0IHR5cGljYWxseSBob2xkCnJlcGxpY2F0aW9uIHNsb3RzIGZvciBsb25n
ZXIgZHVyYXRpb25zIHVubGlrZSBiYWNrZW5kcyB3aGljaCBob2xkCnJlcGxpY2F0aW9uIHNsb3Rz
IGZvciBleGVjdXRpbmcgc29tZSByZXBsaWNhdGlvbiByZWxhdGVkCmZ1bmN0aW9ucy4KLS0tCiBk
b2Mvc3JjL3NnbWwvY29uZmlnLnNnbWwgICAgICAgfCAxMCArKysrKy0tLS0tCiBzcmMvYmFja2Vu
ZC9yZXBsaWNhdGlvbi9zbG90LmMgfCAyNCArKysrKysrKysrKysrKysrKysrKysrKysKIDIgZmls
ZXMgY2hhbmdlZCwgMjkgaW5zZXJ0aW9ucygrKSwgNSBkZWxldGlvbnMoLSkKCmRpZmYgLS1naXQg
YS9kb2Mvc3JjL3NnbWwvY29uZmlnLnNnbWwgYi9kb2Mvc3JjL3NnbWwvY29uZmlnLnNnbWwKaW5k
ZXggZmMzNWE0NmU1ZS4uMWRjMDE0Y2U4NCAxMDA2NDQKLS0tIGEvZG9jL3NyYy9zZ21sL2NvbmZp
Zy5zZ21sCisrKyBiL2RvYy9zcmMvc2dtbC9jb25maWcuc2dtbApAQCAtNzUxMCwxMSArNzUxMCwx
MSBAQCBsb2dfbGluZV9wcmVmaXggPSAnJW0gWyVwXSAlcSV1QCVkLyVhICcKICAgICAgIDwvdGVy
bT4KICAgICAgIDxsaXN0aXRlbT4KICAgICAgICA8cGFyYT4KLSAgICAgICAgQ2F1c2VzIGVhY2gg
cmVwbGljYXRpb24gY29tbWFuZCB0byBiZSBsb2dnZWQgaW4gdGhlIHNlcnZlciBsb2cuCi0gICAg
ICAgIFNlZSA8eHJlZiBsaW5rZW5kPSJwcm90b2NvbC1yZXBsaWNhdGlvbiIvPiBmb3IgbW9yZSBp
bmZvcm1hdGlvbiBhYm91dAotICAgICAgICByZXBsaWNhdGlvbiBjb21tYW5kLiBUaGUgZGVmYXVs
dCB2YWx1ZSBpcyA8bGl0ZXJhbD5vZmY8L2xpdGVyYWw+LgotICAgICAgICBPbmx5IHN1cGVydXNl
cnMgYW5kIHVzZXJzIHdpdGggdGhlIGFwcHJvcHJpYXRlIDxsaXRlcmFsPlNFVDwvbGl0ZXJhbD4K
LSAgICAgICAgcHJpdmlsZWdlIGNhbiBjaGFuZ2UgdGhpcyBzZXR0aW5nLgorICAgICAgICBDYXVz
ZXMgZWFjaCByZXBsaWNhdGlvbiBjb21tYW5kIGFuZCBzbG90IGFjcXVpc2l0aW9uL3JlbGVhc2Ug
dG8gYmUKKyAgICAgICAgbG9nZ2VkIGluIHRoZSBzZXJ2ZXIgbG9nLiBTZWUgPHhyZWYgbGlua2Vu
ZD0icHJvdG9jb2wtcmVwbGljYXRpb24iLz4KKyAgICAgICAgZm9yIG1vcmUgaW5mb3JtYXRpb24g
YWJvdXQgcmVwbGljYXRpb24gY29tbWFuZC4gVGhlIGRlZmF1bHQgdmFsdWUgaXMKKyAgICAgICAg
PGxpdGVyYWw+b2ZmPC9saXRlcmFsPi4gT25seSBzdXBlcnVzZXJzIGFuZCB1c2VycyB3aXRoIHRo
ZSBhcHByb3ByaWF0ZQorICAgICAgICA8bGl0ZXJhbD5TRVQ8L2xpdGVyYWw+IHByaXZpbGVnZSBj
YW4gY2hhbmdlIHRoaXMgc2V0dGluZy4KICAgICAgICA8L3BhcmE+CiAgICAgICA8L2xpc3RpdGVt
PgogICAgICA8L3Zhcmxpc3RlbnRyeT4KZGlmZiAtLWdpdCBhL3NyYy9iYWNrZW5kL3JlcGxpY2F0
aW9uL3Nsb3QuYyBiL3NyYy9iYWNrZW5kL3JlcGxpY2F0aW9uL3Nsb3QuYwppbmRleCA3ODFhYTQz
Y2M0Li4zNzlhZWNlMDMxIDEwMDY0NAotLS0gYS9zcmMvYmFja2VuZC9yZXBsaWNhdGlvbi9zbG90
LmMKKysrIGIvc3JjL2JhY2tlbmQvcmVwbGljYXRpb24vc2xvdC5jCkBAIC01MzcsNiArNTM3LDEy
IEBAIHJldHJ5OgogCSAqLwogCWlmIChTbG90SXNMb2dpY2FsKHMpKQogCQlwZ3N0YXRfYWNxdWly
ZV9yZXBsc2xvdChzKTsKKworCWlmIChhbV93YWxzZW5kZXIpCisJCWVyZXBvcnQobG9nX3JlcGxp
Y2F0aW9uX2NvbW1hbmRzID8gTE9HIDogREVCVUcxLAorCQkJCWVycm1zZ19pbnRlcm5hbCgiYWNx
dWlyZWQgJXMgcmVwbGljYXRpb24gc2xvdCBcIiVzXCIiLAorCQkJCQkJCQlTbG90SXNQaHlzaWNh
bChNeVJlcGxpY2F0aW9uU2xvdCkgPyAicGh5c2ljYWwiIDogImxvZ2ljYWwiLAorCQkJCQkJCQlO
YW1lU3RyKE15UmVwbGljYXRpb25TbG90LT5kYXRhLm5hbWUpKSk7CiB9CiAKIC8qCkBAIC01NDks
OSArNTU1LDE3IEBAIHZvaWQKIFJlcGxpY2F0aW9uU2xvdFJlbGVhc2Uodm9pZCkKIHsKIAlSZXBs
aWNhdGlvblNsb3QgKnNsb3QgPSBNeVJlcGxpY2F0aW9uU2xvdDsKKwljaGFyCSAgICpzbG90bmFt
ZSA9IE5VTEw7CS8qIGtlZXAgY29tcGlsZXIgcXVpZXQgKi8KKwlib29sCQlpc19waHlzaWNhbCA9
IGZhbHNlOwkvKiBrZWVwIGNvbXBpbGVyIHF1aWV0ICovCiAKIAlBc3NlcnQoc2xvdCAhPSBOVUxM
ICYmIHNsb3QtPmFjdGl2ZV9waWQgIT0gMCk7CiAKKwlpZiAoYW1fd2Fsc2VuZGVyKQorCXsKKwkJ
c2xvdG5hbWUgPSBwc3RyZHVwKE5hbWVTdHIoTXlSZXBsaWNhdGlvblNsb3QtPmRhdGEubmFtZSkp
OworCQlpc19waHlzaWNhbCA9IFNsb3RJc1BoeXNpY2FsKE15UmVwbGljYXRpb25TbG90KTsKKwl9
CisKIAlpZiAoc2xvdC0+ZGF0YS5wZXJzaXN0ZW5jeSA9PSBSU19FUEhFTUVSQUwpCiAJewogCQkv
KgpAQCAtNTk2LDYgKzYxMCwxNiBAQCBSZXBsaWNhdGlvblNsb3RSZWxlYXNlKHZvaWQpCiAJTXlQ
cm9jLT5zdGF0dXNGbGFncyAmPSB+UFJPQ19JTl9MT0dJQ0FMX0RFQ09ESU5HOwogCVByb2NHbG9i
YWwtPnN0YXR1c0ZsYWdzW015UHJvYy0+cGd4YWN0b2ZmXSA9IE15UHJvYy0+c3RhdHVzRmxhZ3M7
CiAJTFdMb2NrUmVsZWFzZShQcm9jQXJyYXlMb2NrKTsKKworCWlmIChhbV93YWxzZW5kZXIpCisJ
eworCQllcmVwb3J0KGxvZ19yZXBsaWNhdGlvbl9jb21tYW5kcyA/IExPRyA6IERFQlVHMSwKKwkJ
CQllcnJtc2dfaW50ZXJuYWwoInJlbGVhc2VkICVzIHJlcGxpY2F0aW9uIHNsb3QgXCIlc1wiIiwK
KwkJCQkJCQkJaXNfcGh5c2ljYWwgPyAicGh5c2ljYWwiIDogImxvZ2ljYWwiLAorCQkJCQkJCQlz
bG90bmFtZSkpOworCisJCXBmcmVlKHNsb3RuYW1lKTsKKwl9CiB9CiAKIC8qCi0tIAoyLjM0LjEK
Cg==
--000000000000f031cd060a095533--