Date: Tue, 10 Dec 2019 12:56:56 +0100
From: Tomas Vondra <tomas.vondra@2ndquadrant.com>
To: Andres Freund <andres@anarazel.de>
Cc: pgsql-hackers@postgresql.org
Subject: Re: xact_start for walsender & logical decoding not updated
Message-ID: <20191210115656.6nmx6cndqfa4dami@development>
References: <20191209234409.exe7osmyalwkt5j4@development>
 <20191210000440.daqpb6nvk3dpcblr@alap3.anarazel.de>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii; format=flowed
Content-Disposition: inline
In-Reply-To: <20191210000440.daqpb6nvk3dpcblr@alap3.anarazel.de>
Precedence: bulk

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