Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sha14-004N6B-BY for pgsql-general@arkaria.postgresql.org; Fri, 23 Aug 2024 19:32:10 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1sha12-00GffJ-Ec for pgsql-general@arkaria.postgresql.org; Fri, 23 Aug 2024 19:32:08 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sha11-00Gfex-V4 for pgsql-general@lists.postgresql.org; Fri, 23 Aug 2024 19:32:08 +0000 Received: from mail-ej1-x634.google.com ([2a00:1450:4864:20::634]) by makus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (Exim 4.94.2) (envelope-from ) id 1sha0z-0016hm-6p for pgsql-general@lists.postgresql.org; Fri, 23 Aug 2024 19:32:07 +0000 Received: by mail-ej1-x634.google.com with SMTP id a640c23a62f3a-a86a37208b2so153009866b.0 for ; Fri, 23 Aug 2024 12:32:05 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20230601; t=1724441523; x=1725046323; darn=lists.postgresql.org; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:from:to:cc:subject:date:message-id:reply-to; bh=d9Y69nnbewDaTx39L8IMGgKWqq9Inqy6TykvyNy0kqE=; b=TCUUizl/69yjD79qs9LE/5TA22bAl7aEm34EhrpPe1vTMNHZBEBG8yKHpm7W9AOJ+1 WZadfYG2Fqtc4F9boTWvk/J2Si9sr6995k9SY/l4HGlSoa4AgGn77jRVJepsijPg33xj xhVIbbGARM5bmcZUAp0fAerSDFSBqYCUJCfZ31GejKqgxqEP4vKSKqCD68l/YrdLaleW 6mZBJIydKZiX940OyOzLs+e6sdNnPw24oPK2lcvCmTWeYDUxgB5mj8OlhVh+yj7p3mC+ CXEMHBc+u43TrqzYZB1wHfJkfSP+htLRPt0wJKVlXNpOdyHkDVBJCMVuqhGDQCy3wtz0 OgSQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1724441523; x=1725046323; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:x-gm-message-state:from:to:cc:subject:date:message-id :reply-to; bh=d9Y69nnbewDaTx39L8IMGgKWqq9Inqy6TykvyNy0kqE=; b=J9+rrsZcBmaBIVrJqYsfr15ZPaO9B9sOfcGi4nFK1t3B+uZpvGmGko5kdp1EJ1q6aH a7iiSRlX8kPYxq8BN4b6otO4DS3uPVP8xS+ekimVsPM4gaVSciUNROZ5GCKPQWyEvRW7 HlfFzexAgX0YxdJBQZhEZpycRtWO64gzBuazKHuNgljFSwti6P2D7msu4XB/TxkvhZml f1lexv1+ojlhzn8TyyqeuA3ErqtaXfLDDWUM57u9wqJeZnRhq91HYZKYtdYfSA0a94tW +imIJeiPteH4RMr+lDKZH6kpgJyUWL0XLoY80rzGlwr1brTguh1wZaCQ5fWQWeoJkPvb N53Q== X-Gm-Message-State: AOJu0YwAFx+Mbc+RMV6NsjmNeZM2OE6KZpNPlgnLjQQp/PWY3K2zeR/B Y+sMEHzSHiQQQ5Cn1e1FpFFyCcb53rZiX6Ja0oR2Kwruf8daN5F67r7bV1YC2+2vO6ejlQ1kbCq KVTOmSVHqnfDg6TTNe9yxxbm1QG3qRf2F X-Google-Smtp-Source: AGHT+IFBx92v3uK4SjifGtoeWsv7lWMTrPnZvTYXnS1U0t5TBaWPt6DD/tT0DR/pyiFyoQdpaOHwhLY1RvPcieBWZDI= X-Received: by 2002:a17:907:f708:b0:a86:7fc3:8620 with SMTP id a640c23a62f3a-a86a52cce7cmr235272466b.31.1724441522614; Fri, 23 Aug 2024 12:32:02 -0700 (PDT) MIME-Version: 1.0 References: <65d55d32-c9c3-4446-a367-d3cca3282dea@aklaver.com> In-Reply-To: <65d55d32-c9c3-4446-a367-d3cca3282dea@aklaver.com> From: Koen De Groote Date: Fri, 23 Aug 2024 21:31:51 +0200 Message-ID: Subject: Re: On a subscriber, why is last_msg_send_time in pg_stat_subscription sometimes null? To: Adrian Klaver Cc: PostgreSQL General Content-Type: multipart/alternative; boundary="0000000000006437f306205ed4c3" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --0000000000006437f306205ed4c3 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable 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=3Dpostgresql.git;a=3Dblob;f=3Dsrc/back= end/replication/logical/launcher.c;h=3Dc566d50a072b92bd07f4179100275d0d0b1f= 4c7c;hb=3DHEAD#l1288 And in particular, this: 1332 if (worker.last_send_time =3D=3D 0) 1333 nulls[5] =3D true; 1334 else 1335 values[5] =3D TimestampTzGetDatum(worker.last_send_time); 1336 if (worker.last_recv_time =3D=3D 0) 1337 nulls[6] =3D true; 1338 else 1339 values[6] =3D 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 On Fri, Aug 23, 2024 at 5:02=E2=80=AFPM Adrian Klaver wrote: > On 8/23/24 07:33, Koen De Groote wrote: > > 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? > > The source has that information: > > > https://git.postgresql.org/gitweb/?p=3Dpostgresql.git;a=3Dblob;f=3Dsrc/ba= ckend/replication/logical/applyparallelworker.c;h=3De7f7d4c5e4bd3ff63687cb2= 1b84534a05a3962cc;hb=3DHEAD > > 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 the= se > * statistics in the leader apply worker, we can ignore these fields in > the > * parallel apply worker (see function LogicalRepApplyLoop). > */ > > > > > Regards, > > Koen De Groote > > -- > Adrian Klaver > adrian.klaver@aklaver.com > > --0000000000006437f306205ed4c3 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Adrian,

Thanks for pointing = me at the source code.


And in particular, this:

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

I don't ha= ve any knowledge of C, or postgres internals, so I may well be wrong in wha= t 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=20 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...

A= nd these parallel workers get created on the fly, I assume? So they might w= ell have a=20 last_send_time of 0 if they haven't done anything yet?

What I would expect to see is a table that tel= ls me how a particular publishers/subscriber is doing, and the metrics arou= nd 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 li= fespan 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





On Fri, Aug 23, 2024 at = 5:02=E2=80=AFPM Adrian Klaver <adrian.klaver@aklaver.com> wrote:
On 8/23/24 07:33, Koen De Groote wrote:
> I'm running this query:
>
> SELECT subname, received_lsn,=C2=A0latest_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 f= ind in the
> documentation is that this value represents: "Send time of last m= essage
> 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?

The source has that information:

= https://git.postgresql.org/gitweb/?p=3Dpostgresql.git;a=3Dblob;f=3Dsrc/back= end/replication/logical/applyparallelworker.c;h=3De7f7d4c5e4bd3ff63687cb21b= 84534a05a3962cc;hb=3DHEAD

The top part explains the process.

As to the time:

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

>
> Regards,
> Koen De Groote

--
Adrian Klaver
adrian.klave= r@aklaver.com

--0000000000006437f306205ed4c3--