Horton

Thread

Commits

  1. Reimplement nullification of walsender timestamp

  2. pg_stat_activity: show NULL stmt start time for walsenders

  1. xact_start for walsender & logical decoding not updated

    Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2019-12-09T23:44:09Z

    Hi,

I think there's a minor bug in pg_stat_activity tracking of walsender
processes. The issue is that xact_start is only updated at the very
beginning when the walsender starts (so it's almost exactly equal to
backend_start) and then just flips between NULL and that value.

Reproducing this is trivial - just create a publication/subscription
with the built-in logical replication, and run arbitrary workload.
You'll see that the xact_start value never changes.

I think the right fix is calling SetCurrentStatementStartTimestamp()
right before StartTransactionCommand() in ReorderBufferCommit, per the
attached patch.


regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  2. Re: xact_start for walsender & logical decoding not updated

    Andres Freund <andres@anarazel.de> — 2019-12-10T00:04:40Z

    Hi,

On 2019-12-10 00:44:09 +0100, Tomas Vondra wrote:
> I think there's a minor bug in pg_stat_activity tracking of walsender
> processes. The issue is that xact_start is only updated at the very
> beginning when the walsender starts (so it's almost exactly equal to
> backend_start) and then just flips between NULL and that value.
> 
> Reproducing this is trivial - just create a publication/subscription
> with the built-in logical replication, and run arbitrary workload.
> You'll see that the xact_start value never changes.
> 
> I think the right fix is calling SetCurrentStatementStartTimestamp()
> right before StartTransactionCommand() in ReorderBufferCommit, per the
> attached patch.

> -- 
> Tomas Vondra                  http://www.2ndQuadrant.com
> PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

> diff --git a/src/backend/replication/logical/reorderbuffer.c b/src/backend/replication/logical/reorderbuffer.c
> index 53affeb877..5235fb31b8 100644
> --- a/src/backend/replication/logical/reorderbuffer.c
> +++ b/src/backend/replication/logical/reorderbuffer.c
> @@ -1554,7 +1554,10 @@ ReorderBufferCommit(ReorderBuffer *rb, TransactionId xid,
>  		if (using_subtxn)
>  			BeginInternalSubTransaction("replay");
>  		else
> +		{
> +			SetCurrentStatementStartTimestamp();
>  			StartTransactionCommand();
> +		}

I'm quite doubtful this is useful. To me this seems to do nothing but
add the overhead of timestamp computation - which isn't always that
cheap. I don't think you really can draw meaning from this?

Greetings,

Andres Freund

  3. Re: xact_start for walsender & logical decoding not updated

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2019-12-10T00:42:17Z

    At Tue, 10 Dec 2019 00:44:09 +0100, Tomas Vondra <tomas.vondra@2ndquadrant.com> wrote in 
> Hi,
> 
> I think there's a minor bug in pg_stat_activity tracking of walsender
> processes. The issue is that xact_start is only updated at the very
> beginning when the walsender starts (so it's almost exactly equal to
> backend_start) and then just flips between NULL and that value.
> 
> Reproducing this is trivial - just create a publication/subscription
> with the built-in logical replication, and run arbitrary workload.
> You'll see that the xact_start value never changes.
> 
> I think the right fix is calling SetCurrentStatementStartTimestamp()
> right before StartTransactionCommand() in ReorderBufferCommit, per the
> attached patch.

I'm not sure how much xact_start for walsender is useful and we really
is not running a statement there.  Also autovac launcher starts
transaction without a valid statement timestamp perhaps for the same
reason.

However, if we want to show something meaningful there, I think
commit_time might be more informative there.  If we use
GetCurrentTimestamp(), StartTransaction() already has the same feature
for autonomous transactions. I suppose we should do them a unified
way.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  4. Re: xact_start for walsender & logical decoding not updated

    Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2019-12-10T11:56:56Z

    On Mon, Dec 09, 2019 at 04:04:40PM -0800, Andres Freund wrote:
>Hi,
>
>On 2019-12-10 00:44:09 +0100, Tomas Vondra wrote:
>> I think there's a minor bug in pg_stat_activity tracking of walsender
>> processes. The issue is that xact_start is only updated at the very
>> beginning when the walsender starts (so it's almost exactly equal to
>> backend_start) and then just flips between NULL and that value.
>>
>> Reproducing this is trivial - just create a publication/subscription
>> with the built-in logical replication, and run arbitrary workload.
>> You'll see that the xact_start value never changes.
>>
>> I think the right fix is calling SetCurrentStatementStartTimestamp()
>> right before StartTransactionCommand() in ReorderBufferCommit, per the
>> attached patch.
>
>> --
>> Tomas Vondra                  http://www.2ndQuadrant.com
>> PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
>
>> diff --git a/src/backend/replication/logical/reorderbuffer.c b/src/backend/replication/logical/reorderbuffer.c
>> index 53affeb877..5235fb31b8 100644
>> --- a/src/backend/replication/logical/reorderbuffer.c
>> +++ b/src/backend/replication/logical/reorderbuffer.c
>> @@ -1554,7 +1554,10 @@ ReorderBufferCommit(ReorderBuffer *rb, TransactionId xid,
>>  		if (using_subtxn)
>>  			BeginInternalSubTransaction("replay");
>>  		else
>> +		{
>> +			SetCurrentStatementStartTimestamp();
>>  			StartTransactionCommand();
>> +		}
>
>I'm quite doubtful this is useful. To me this seems to do nothing but
>add the overhead of timestamp computation - which isn't always that
>cheap. I don't think you really can draw meaning from this?
>

I don't want to use this timestamp directly, but it does interfere with
monitoring of long-running transactiosn looking at pg_stat_activity.
With the current behavior, the walsender entries have ancient timestamps
and produce random blips in monitoring. Of course, it's possible to edit
the queries to skip entries with backend_type = walsender, but that's a
bit inconvenient.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  5. Re: xact_start for walsender & logical decoding not updated

    Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2019-12-10T11:59:03Z

    On Tue, Dec 10, 2019 at 09:42:17AM +0900, Kyotaro Horiguchi wrote:
>At Tue, 10 Dec 2019 00:44:09 +0100, Tomas Vondra <tomas.vondra@2ndquadrant.com> wrote in
>> Hi,
>>
>> I think there's a minor bug in pg_stat_activity tracking of walsender
>> processes. The issue is that xact_start is only updated at the very
>> beginning when the walsender starts (so it's almost exactly equal to
>> backend_start) and then just flips between NULL and that value.
>>
>> Reproducing this is trivial - just create a publication/subscription
>> with the built-in logical replication, and run arbitrary workload.
>> You'll see that the xact_start value never changes.
>>
>> I think the right fix is calling SetCurrentStatementStartTimestamp()
>> right before StartTransactionCommand() in ReorderBufferCommit, per the
>> attached patch.
>
>I'm not sure how much xact_start for walsender is useful and we really
>is not running a statement there.  Also autovac launcher starts
>transaction without a valid statement timestamp perhaps for the same
>reason.
>

Maybe, but then maybe we should change it so that we don't report any
timestamps for such processes.

>However, if we want to show something meaningful there, I think
>commit_time might be more informative there.  If we use
>GetCurrentTimestamp(), StartTransaction() already has the same feature
>for autonomous transactions. I suppose we should do them a unified
>way.
>

I don't think so. We have this information from the apply side, and this
is really about the *new* transaction started in reorderbuffer.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  6. Re: xact_start for walsender & logical decoding not updated

    Alvaro Herrera <alvherre@2ndquadrant.com> — 2019-12-10T18:08:21Z

    On 2019-Dec-10, Tomas Vondra wrote:

> On Tue, Dec 10, 2019 at 09:42:17AM +0900, Kyotaro Horiguchi wrote:
> > At Tue, 10 Dec 2019 00:44:09 +0100, Tomas Vondra <tomas.vondra@2ndquadrant.com> wrote in

> > I'm not sure how much xact_start for walsender is useful and we really
> > is not running a statement there.  Also autovac launcher starts
> > transaction without a valid statement timestamp perhaps for the same
> > reason.
> 
> Maybe, but then maybe we should change it so that we don't report any
> timestamps for such processes.

Yeah, I think we should to that.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  7. Re: xact_start for walsender & logical decoding not updated

    Andres Freund <andres@anarazel.de> — 2019-12-10T22:37:16Z

    Hi,

On 2019-12-10 12:56:56 +0100, Tomas Vondra wrote:
> On Mon, Dec 09, 2019 at 04:04:40PM -0800, Andres Freund wrote:
> > On 2019-12-10 00:44:09 +0100, Tomas Vondra wrote:
> > > I think there's a minor bug in pg_stat_activity tracking of walsender
> > > processes. The issue is that xact_start is only updated at the very
> > > beginning when the walsender starts (so it's almost exactly equal to
> > > backend_start) and then just flips between NULL and that value.
> > > 
> > > Reproducing this is trivial - just create a publication/subscription
> > > with the built-in logical replication, and run arbitrary workload.
> > > You'll see that the xact_start value never changes.
> > > 
> > > I think the right fix is calling SetCurrentStatementStartTimestamp()
> > > right before StartTransactionCommand() in ReorderBufferCommit, per the
> > > attached patch.

> > 
> > > diff --git a/src/backend/replication/logical/reorderbuffer.c b/src/backend/replication/logical/reorderbuffer.c
> > > index 53affeb877..5235fb31b8 100644
> > > --- a/src/backend/replication/logical/reorderbuffer.c
> > > +++ b/src/backend/replication/logical/reorderbuffer.c
> > > @@ -1554,7 +1554,10 @@ ReorderBufferCommit(ReorderBuffer *rb, TransactionId xid,
> > >  		if (using_subtxn)
> > >  			BeginInternalSubTransaction("replay");
> > >  		else
> > > +		{
> > > +			SetCurrentStatementStartTimestamp();
> > >  			StartTransactionCommand();
> > > +		}
> > 
> > I'm quite doubtful this is useful. To me this seems to do nothing but
> > add the overhead of timestamp computation - which isn't always that
> > cheap. I don't think you really can draw meaning from this?
> > 
> 
> I don't want to use this timestamp directly, but it does interfere with
> monitoring of long-running transactiosn looking at pg_stat_activity.
> With the current behavior, the walsender entries have ancient timestamps
> and produce random blips in monitoring. Of course, it's possible to edit
> the queries to skip entries with backend_type = walsender, but that's a
> bit inconvenient.

Oh, I'm not suggesting that we shouldn't fix this somehow, just that I'm
doubtful that that adding a lot of additional
SetCurrentStatementStartTimestamp() calls is the right thing. Besides
the overhead, it'd also just not be a meaningful value here - neither is
it an actual transaction, nor is it the right thing to be monitoring
when concerned about bloat or such.

It seems like it might be better to instead cause NULL to be returned
for the respective column in pg_stat_activity etc?

Greetings,

Andres Freund

  8. Re: xact_start for walsender & logical decoding not updated

    Craig Ringer <craig@2ndquadrant.com> — 2019-12-13T05:05:41Z

    On Wed, 11 Dec 2019 at 02:08, Alvaro Herrera <alvherre@2ndquadrant.com>
wrote:

> On 2019-Dec-10, Tomas Vondra wrote:
>
> > On Tue, Dec 10, 2019 at 09:42:17AM +0900, Kyotaro Horiguchi wrote:
> > > At Tue, 10 Dec 2019 00:44:09 +0100, Tomas Vondra <
> tomas.vondra@2ndquadrant.com> wrote in
>
> > > I'm not sure how much xact_start for walsender is useful and we really
> > > is not running a statement there.  Also autovac launcher starts
> > > transaction without a valid statement timestamp perhaps for the same
> > > reason.
> >
> > Maybe, but then maybe we should change it so that we don't report any
> > timestamps for such processes.
>
> Yeah, I think we should to that.


Agreed. Don't report a transaction start timestamp at all if we're not in a
read/write txn in the walsender, which we should never be when using a
historic snapshot.

It's not interesting or relevant.

Reporting the commit timestamp of the current or last-processed xact would
likely just be fonfusing. I'd rather see that in pg_stat_replication if
we're going to show it, that way we can label it usefully.

-- 
 Craig Ringer                   http://www.2ndQuadrant.com/
 2ndQuadrant - PostgreSQL Solutions for the Enterprise

  9. Re: xact_start for walsender & logical decoding not updated

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2019-12-13T06:01:24Z

    At Fri, 13 Dec 2019 13:05:41 +0800, Craig Ringer <craig@2ndquadrant.com> wrote in 
> On Wed, 11 Dec 2019 at 02:08, Alvaro Herrera <alvherre@2ndquadrant.com>
> wrote:
> 
> > On 2019-Dec-10, Tomas Vondra wrote:
> >
> > > On Tue, Dec 10, 2019 at 09:42:17AM +0900, Kyotaro Horiguchi wrote:
> > > > At Tue, 10 Dec 2019 00:44:09 +0100, Tomas Vondra <
> > tomas.vondra@2ndquadrant.com> wrote in
> >
> > > > I'm not sure how much xact_start for walsender is useful and we really
> > > > is not running a statement there.  Also autovac launcher starts
> > > > transaction without a valid statement timestamp perhaps for the same
> > > > reason.
> > >
> > > Maybe, but then maybe we should change it so that we don't report any
> > > timestamps for such processes.
> >
> > Yeah, I think we should to that.
> 
> 
> Agreed. Don't report a transaction start timestamp at all if we're not in a
> read/write txn in the walsender, which we should never be when using a
> historic snapshot.
> 
> It's not interesting or relevant.
> 
> Reporting the commit timestamp of the current or last-processed xact would
> likely just be fonfusing. I'd rather see that in pg_stat_replication if
> we're going to show it, that way we can label it usefully.

Sounds reasonable.  By the way, the starting of this thread is a valid
value in xact_timestample for a moment at the starting of logical
replication. (I couln't see it unless I inserted a sleep() in
IndentifySystem()). I'm not sure but AFAIS it is the only instance in
walsendeer. Should we take the trouble to stop that?  (I put -1 for it)

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  10. Re: xact_start for walsender & logical decoding not updated

    Alvaro Herrera <alvherre@2ndquadrant.com> — 2019-12-27T19:46:18Z

    On 2019-Dec-13, Kyotaro Horiguchi wrote:

> At Fri, 13 Dec 2019 13:05:41 +0800, Craig Ringer <craig@2ndquadrant.com> wrote in 
> > On Wed, 11 Dec 2019 at 02:08, Alvaro Herrera <alvherre@2ndquadrant.com>
> > wrote:
> > 
> > > On 2019-Dec-10, Tomas Vondra wrote:
> > >
> > > > On Tue, Dec 10, 2019 at 09:42:17AM +0900, Kyotaro Horiguchi wrote:
> > > > > At Tue, 10 Dec 2019 00:44:09 +0100, Tomas Vondra <
> > > tomas.vondra@2ndquadrant.com> wrote in
> > >
> > > > > I'm not sure how much xact_start for walsender is useful and we really
> > > > > is not running a statement there.  Also autovac launcher starts
> > > > > transaction without a valid statement timestamp perhaps for the same
> > > > > reason.
> > > >
> > > > Maybe, but then maybe we should change it so that we don't report any
> > > > timestamps for such processes.
> > >
> > > Yeah, I think we should to that.
> > Agreed. Don't report a transaction start timestamp at all if we're not in a
> > read/write txn in the walsender, which we should never be when using a
> > historic snapshot.
> > 
> > It's not interesting or relevant.

This patch changes xact.c to avoid updating transaction start timestamps
for walsenders (maybe more commentary is desirable).  I think logical
decoding is just a special form of walsender and thus it would also be
updated by this patch, unless I misunderstood what Tomas explained.

> > Reporting the commit timestamp of the current or last-processed xact would
> > likely just be confusing. I'd rather see that in pg_stat_replication if
> > we're going to show it, that way we can label it usefully.
> 
> Sounds reasonable.

Developers interested in this feature can submit a patch, as usual :-)

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  11. Re: xact_start for walsender & logical decoding not updated

    Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2019-12-28T23:34:33Z

    On Fri, Dec 27, 2019 at 04:46:18PM -0300, Alvaro Herrera wrote:
>On 2019-Dec-13, Kyotaro Horiguchi wrote:
>
>> At Fri, 13 Dec 2019 13:05:41 +0800, Craig Ringer <craig@2ndquadrant.com> wrote in
>> > On Wed, 11 Dec 2019 at 02:08, Alvaro Herrera <alvherre@2ndquadrant.com>
>> > wrote:
>> >
>> > > On 2019-Dec-10, Tomas Vondra wrote:
>> > >
>> > > > On Tue, Dec 10, 2019 at 09:42:17AM +0900, Kyotaro Horiguchi wrote:
>> > > > > At Tue, 10 Dec 2019 00:44:09 +0100, Tomas Vondra <
>> > > tomas.vondra@2ndquadrant.com> wrote in
>> > >
>> > > > > I'm not sure how much xact_start for walsender is useful and we really
>> > > > > is not running a statement there.  Also autovac launcher starts
>> > > > > transaction without a valid statement timestamp perhaps for the same
>> > > > > reason.
>> > > >
>> > > > Maybe, but then maybe we should change it so that we don't report any
>> > > > timestamps for such processes.
>> > >
>> > > Yeah, I think we should to that.
>> > Agreed. Don't report a transaction start timestamp at all if we're not in a
>> > read/write txn in the walsender, which we should never be when using a
>> > historic snapshot.
>> >
>> > It's not interesting or relevant.
>
>This patch changes xact.c to avoid updating transaction start timestamps
>for walsenders (maybe more commentary is desirable).  I think logical
>decoding is just a special form of walsender and thus it would also be
>updated by this patch, unless I misunderstood what Tomas explained.
>

It's true walsender should not be doing any read-write transactions or
executing statements (well, maybe a decoding plugin could, but using
historic snapshot).

So I agree not leaving xact_start for walsender processes seems OK.

>> > Reporting the commit timestamp of the current or last-processed xact would
>> > likely just be confusing. I'd rather see that in pg_stat_replication if
>> > we're going to show it, that way we can label it usefully.
>>
>> Sounds reasonable.
>
>Developers interested in this feature can submit a patch, as usual :-)
>

;-)


regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  12. Re: xact_start for walsender & logical decoding not updated

    Alvaro Herrera <alvherre@2ndquadrant.com> — 2020-01-07T21:17:17Z

    On 2019-Dec-29, Tomas Vondra wrote:

> On Fri, Dec 27, 2019 at 04:46:18PM -0300, Alvaro Herrera wrote:
> > 
> > This patch changes xact.c to avoid updating transaction start timestamps
> > for walsenders (maybe more commentary is desirable).  I think logical
> > decoding is just a special form of walsender and thus it would also be
> > updated by this patch, unless I misunderstood what Tomas explained.
> > 
> 
> It's true walsender should not be doing any read-write transactions or
> executing statements (well, maybe a decoding plugin could, but using
> historic snapshot).
> 
> So I agree not leaving xact_start for walsender processes seems OK.

OK, I pushed my patch to branches 10 - master.
(See https://postgr.es/m/20200107211624.GA18974@alvherre.pgsql )

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  13. Re: xact_start for walsender & logical decoding not updated

    Tom Lane <tgl@sss.pgh.pa.us> — 2020-01-07T23:07:32Z

    Alvaro Herrera <alvherre@2ndquadrant.com> writes:
> OK, I pushed my patch to branches 10 - master.
> (See https://postgr.es/m/20200107211624.GA18974@alvherre.pgsql )

The buildfarm seems less than happy with this.

			regards, tom lane

  14. Re: xact_start for walsender & logical decoding not updated

    Tom Lane <tgl@sss.pgh.pa.us> — 2020-01-07T23:12:43Z

    I wrote:
> The buildfarm seems less than happy with this.

... and, having now looked at the patch, I'm not surprised.
Breaking stmtStartTimestamp, which is what you did, seems like
an awfully side-effect-filled route to the goal.  If you want
to prevent monitoring from showing this, why didn't you just
prevent monitoring from showing it?  That is, I'd have expected
some am_walsender logic in or near pgstat.c, not here.

			regards, tom lane

  15. Re: xact_start for walsender & logical decoding not updated

    Alvaro Herrera <alvherre@2ndquadrant.com> — 2020-01-07T23:52:34Z

    On 2020-Jan-07, Tom Lane wrote:

> I wrote:
> > The buildfarm seems less than happy with this.
> 
> ... and, having now looked at the patch, I'm not surprised.
> Breaking stmtStartTimestamp, which is what you did, seems like
> an awfully side-effect-filled route to the goal.  If you want
> to prevent monitoring from showing this, why didn't you just
> prevent monitoring from showing it?  That is, I'd have expected
> some am_walsender logic in or near pgstat.c, not here.

That seems a pretty simple patch; attached (untested).  However, my
patch seemed a pretty decent way to achieve the goal, and I don't
understand why it causes the failure, or indeed why we care about
stmtStartTimestamp at all.  I'll look into this again tomorrow.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  16. Re: xact_start for walsender & logical decoding not updated

    Tom Lane <tgl@sss.pgh.pa.us> — 2020-01-08T00:42:48Z

    Alvaro Herrera <alvherre@2ndquadrant.com> writes:
> On 2020-Jan-07, Tom Lane wrote:
>> ... and, having now looked at the patch, I'm not surprised.
>> Breaking stmtStartTimestamp, which is what you did, seems like
>> an awfully side-effect-filled route to the goal.  If you want
>> to prevent monitoring from showing this, why didn't you just
>> prevent monitoring from showing it?  That is, I'd have expected
>> some am_walsender logic in or near pgstat.c, not here.

> That seems a pretty simple patch; attached (untested).

I think you want && not ||, but otherwise that looks about right.

> However, my
> patch seemed a pretty decent way to achieve the goal, and I don't
> understand why it causes the failure, or indeed why we care about
> stmtStartTimestamp at all.  I'll look into this again tomorrow.

I'm not 100% sure why the failure either.  The assertion is in
code that should only be reached in a parallel worker, and surely
walsenders don't launch parallel queries?  But it looks to me
that all the critters using force_parallel_mode are unhappy.

In any case, my larger point is that stmtStartTimestamp is globally
accessible state (via GetCurrentStatementStartTimestamp()) and you
can have little idea which corners of our code are using it, let
alone what extensions might expect about it.  Plus it feeds into
xactStartTimestamp (cf StartTransaction()), increasing the footprint
for unwanted side-effects even more.  Redefining its meaning
to fix this problem is a really bad idea IMO.

			regards, tom lane

  17. Re: xact_start for walsender & logical decoding not updated

    Alvaro Herrera <alvherre@2ndquadrant.com> — 2020-01-08T18:12:05Z

    On 2020-Jan-07, Tom Lane wrote:

> Alvaro Herrera <alvherre@2ndquadrant.com> writes:
> > On 2020-Jan-07, Tom Lane wrote:

> > That seems a pretty simple patch; attached (untested).
> 
> I think you want && not ||, but otherwise that looks about right.

Thanks, you were right; pushed.

> > However, my
> > patch seemed a pretty decent way to achieve the goal, and I don't
> > understand why it causes the failure, or indeed why we care about
> > stmtStartTimestamp at all.  I'll look into this again tomorrow.
> 
> I'm not 100% sure why the failure either.  The assertion is in
> code that should only be reached in a parallel worker, and surely
> walsenders don't launch parallel queries?  But it looks to me
> that all the critters using force_parallel_mode are unhappy.

I reproduced here with force_parallel_mode=regress, and indeed what is
happening is that log.rep. subscription walsenders (???) are running
queries per commands/subscriptioncmds.c::fetch_table_list(), and under
that GUC they beget parallel workers; and because the parent has
am_walsender=true then they pass a timestamp of 0 to the children; but
the children retain am_walsender=false, so the assertion fires.

I didn't spend more time on that, but it seems strange and possibly
dangerous, since am_walsender is used to implement some restrictions.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  18. Re: xact_start for walsender & logical decoding not updated

    Tom Lane <tgl@sss.pgh.pa.us> — 2020-01-08T18:38:12Z

    Alvaro Herrera <alvherre@2ndquadrant.com> writes:
>> I'm not 100% sure why the failure either.  The assertion is in
>> code that should only be reached in a parallel worker, and surely
>> walsenders don't launch parallel queries?  But it looks to me
>> that all the critters using force_parallel_mode are unhappy.

> I reproduced here with force_parallel_mode=regress, and indeed what is
> happening is that log.rep. subscription walsenders (???) are running
> queries per commands/subscriptioncmds.c::fetch_table_list(), and under
> that GUC they beget parallel workers; and because the parent has
> am_walsender=true then they pass a timestamp of 0 to the children; but
> the children retain am_walsender=false, so the assertion fires.

> I didn't spend more time on that, but it seems strange and possibly
> dangerous, since am_walsender is used to implement some restrictions.

Indeed.  I think it's a truly horrible idea that we are issuing SPI
queries inside replication mechanisms.  Quite aside from this problem,
do we really think that's free of security issues?  Or even if you
think it is today, can it be kept so?

(I've ranted before about keeping a proper layering design in this
stuff.  Just because it's easier to do stuff by calling a SQL query
doesn't mean that we should consider that acceptable.)

			regards, tom lane