Date: Sun, 31 Dec 2017 21:52:27 -0800
From: Noah Misch <noah@leadboat.com>
To: Alvaro Herrera <alvherre@2ndquadrant.com>
Cc: Michael Paquier <michael.paquier@gmail.com>,
	PostgreSQL mailing lists <pgsql-hackers@postgresql.org>
Subject: Re: Increasing timeout of poll_query_until for TAP tests
Message-ID: <20180101055227.GA2952815@rfd.leadboat.com>
References: 
 <CAB7nPqSeW9nbBaUYMARF6COWCsfU6tJZC9mac8K8zRN5DrUCbA@mail.gmail.com>
 <20160802222103.GA602448@alvherre.pgsql>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20160802222103.GA602448@alvherre.pgsql>
User-Agent: Mutt/1.5.24 (2015-08-30)
Precedence: bulk

On Tue, Aug 02, 2016 at 06:21:03PM -0400, Alvaro Herrera wrote:
> Michael Paquier wrote:
> > $node_master->safe_psql('postgres',
> >         "INSERT INTO tab_int VALUES (generate_series(1001,2000))");
> > my $recovery_txid =
> >   $node_master->safe_psql('postgres', "SELECT txid_current()");
> > my $lsn2 =
> >   $node_master->safe_psql('postgres', "SELECT pg_current_xlog_location();");
> > What I think we had better do is reverse the calls
> > pg_current_xlog_location() and txid_current() so as we are sure that
> > the LSN we track for replay is lower than the real target LSN. The
> > same problem exists when defining the timestamp target.
> > 
> > The patch attached does that,
> 
> Why not capture both items in a single select, such as in the attached
> patch?

> -my $recovery_time = $node_master->safe_psql('postgres', "SELECT now()");
> -my $lsn3 =
> -  $node_master->safe_psql('postgres', "SELECT pg_current_xlog_location();");
> +$ret =
> +  $node_master->safe_psql('postgres', "SELECT pg_current_xlog_location(), now();");
> +my ($lsn3, $recovery_time) = split /\|/, $ret;

Since now() is transaction_timestamp(), $recovery_time precedes or equals
$lsn3, and this didn't close the race.  Using clock_timestamp() here would
work, as does using separate transactions like recovery-test-fixes.patch did.
I'll shortly push a fix for this and a similar ordering problem in the
standby_5 test, which first appeared subsequent to this thread.