Subject: On a subscriber, why is last_msg_send_time in pg_stat_subscription sometimes null?

From: Koen De Groote <[email-masked]>
Date: Fri, 23 Aug 2024 16:33:08 +0200

I'm running this query:

SELECT subname, received_lsn, latest_end_lsn,
last_msg_send_time, last_msg_receipt_time
FROM pg_catalog.pg_stat_subscription;

And "last_msg_send_time" will sometimes be null. All I can find in the
documentation is that this value represents: "Send time of last message
received from origin WAL sender; NULL for parallel apply workers"

But I have no context for what parallel apply workers are or why they are
NULL sometimes and other times not.

Can anyone explain?

Regards,
Koen De Groote

---

From: Adrian Klaver <[email-masked]>
Date: Fri, 23 Aug 2024 08:02:56 -0700

On 8/23/24 07:33, Koen De Groote wrote:
> But I have no context for what parallel apply workers are or why they 
> are NULL sometimes and other times not. >
> Can anyone explain?

The source has that information:

https://git.postgresql.org/gitweb/?p=postgresql.git;a=blob;f=src/backend/replication/logical/applyparallelworker.c;h=e7f7d4c5e4bd3ff63687cb21b84534a05a3962cc;hb=HEAD

The top part explains the process.

As to the time:

/*
  * There are three fields in each message received by the parallel apply
  * worker: start_lsn, end_lsn and send_time. Because we have updated these
  * statistics in the leader apply worker, we can ignore these fields in the
  * parallel apply worker (see function LogicalRepApplyLoop).
  */

-- 
Adrian Klaver
[email-masked]

---

From: Koen De Groote <[email-masked]>
Date: Fri, 23 Aug 2024 21:31:51 +0200

Adrian,

Thanks for pointing me at the source code.

Digging a bit, the view seems to eventually get its data on last msg send
time from here:
https://git.postgresql.org/gitweb/?p=postgresql.git;a=blob;f=src/backend/replication/logical/launcher.c;h=c566d50a072b92bd07f4179100275d0d0b1f4c7c;hb=HEAD#l1288

And in particular, this:

1332         if (worker.last_send_time == 0)
1333             nulls[5] = true;
1334         else
1335             values[5] = TimestampTzGetDatum(worker.last_send_time);
1336         if (worker.last_recv_time == 0)
1337             nulls[6] = true;
1338         else
1339             values[6] = TimestampTzGetDatum(worker.last_recv_time);

I don't have any knowledge of C, or postgres internals, so I may well be
wrong in what follows:

>From the bit of comment you posted my impression is that this means there
are separate workers that each send their update, that is then reflected in
the output of the pg_stat_subscription table... many workers, but only 1
table to show metrics, to show both the update by the leader and the
parallel workers...

And these parallel workers get created on the fly, I assume? So they might
well have a last_send_time of 0 if they haven't done anything yet?

What I would expect to see is a table that tells me how a particular
publishers/subscriber is doing, and the metrics around that process, and
the concept of "when data was last sent" to be persistent on the level of
the publisher/subscriber, not based on the lifespan of ephemeral workers
that each time they get created start at 0 and so now the table claims
"last_send_msg" is NULL because of it.

Am I getting that wrong? Is my understanding mistaken?

Regards,
Koen De Groote

---

From: Adrian Klaver <[email-masked]>
Date: Fri, 23 Aug 2024 13:14:31 -0700

On 8/23/24 12:31, Koen De Groote wrote:
> Digging a bit, the view seems to eventually get its data on last msg 
> send time from here: 
> https://git.postgresql.org/gitweb/?p=postgresql.git;a=blob;f=src/backend/replication/logical/launcher.c;h=c566d50a072b92bd07f4179100275d0d0b1f4c7c;hb=HEAD#l1288 <https://git.postgresql.org/gitweb/?p=postgresql.git;a=blob;f=src/backend/replication/logical/launcher.c;h=c566d50a072b92bd07f4179100275d0d0b1f4c7c;hb=HEAD#l1288>
> 
> And in particular, this:
> 
>  From the bit of comment you posted my impression is that this means 
> there are separate workers that each send their update, that is then 
> reflected in the output of the pg_stat_subscription table... many 
> workers, but only 1 table to show metrics, to show both the update by 
> the leader and the parallel workers...

This is getting out of my depth, but that has not stopped me before so 
onward.

I think it is important to realize parallel workers are optional:

https://www.postgresql.org/docs/current/sql-createsubscription.html

streaming (enum)

     Specifies whether to enable streaming of in-progress transactions 
for this subscription. The default value is off, meaning all 
transactions are fully decoded on the publisher and only then sent to 
the subscriber as a whole.

     If set to on, the incoming changes are written to temporary files 
and then applied only after the transaction is committed on the 
publisher and received by the subscriber.

     If set to parallel, incoming changes are directly applied via one 
of the parallel apply workers, if available. If no parallel apply worker 
is free to handle streaming transactions then the changes are written to 
temporary files and applied after the transaction is committed. Note 
that if an error happens in a parallel apply worker, the finish LSN of 
the remote transaction might not be reported in the server log.

> 
> And these parallel workers get created on the fly, I assume? So they 
> might well have a last_send_time of 0 if they haven't done anything yet?
> 
> the concept of "when data was last sent" to be persistent on the level 
> of the publisher/subscriber, not based on the lifespan of ephemeral 
> workers that each time they get created start at 0 and so now the table 
> claims "last_send_msg" is NULL because of it.

Some combination of?:

https://www.postgresql.org/docs/current/view-pg-replication-slots.html

https://www.postgresql.org/docs/current/catalog-pg-subscription-rel.html