Horton

Thread

Commits

  1. Workaround for RecoverPreparedTransactions()

  2. Fix LagTrackerRead() for timeline increments

  3. Make PostgresNode.pm check server status more carefully.

  4. Replication lag tracking for walsenders

  1. pgsql: Replication lag tracking for walsenders

    Simon Riggs <simon@2ndquadrant.com> — 2017-03-23T14:07:44Z

    Replication lag tracking for walsenders

Adds write_lag, flush_lag and replay_lag cols to pg_stat_replication.

Implements a lag tracker module that reports the lag times based upon
measurements of the time taken for recent WAL to be written, flushed and
replayed and for the sender to hear about it. These times
represent the commit lag that was (or would have been) introduced by each
synchronous commit level, if the remote server was configured as a
synchronous standby.  For an asynchronous standby, the replay_lag column
approximates the delay before recent transactions became visible to queries.
If the standby server has entirely caught up with the sending server and
there is no more WAL activity, the most recently measured lag times will
continue to be displayed for a short time and then show NULL.

Physical replication lag tracking is automatic. Logical replication tracking
is possible but is the responsibility of the logical decoding plugin.
Tracking is a private module operating within each walsender individually,
with values reported to shared memory. Module not used outside of walsender.

Design and code is good enough now to commit - kudos to the author.
In many ways a difficult topic, with important and subtle behaviour so this
shoudl be expected to generate discussion and multiple open items: Test now!

Author: Thomas Munro, following designs by Fujii Masao and Simon Riggs
Review: Simon Riggs, Ian Barwick and Craig Ringer

Branch
------
master

Details
-------
http://git.postgresql.org/pg/commitdiff/6912acc04f0bbcfdb799a120618507601e862490

Modified Files
--------------
doc/src/sgml/monitoring.sgml                |  69 +++++++
src/backend/access/transam/xlog.c           |  14 ++
src/backend/catalog/system_views.sql        |   3 +
src/backend/replication/walsender.c         | 277 +++++++++++++++++++++++++++-
src/include/catalog/pg_proc.h               |   2 +-
src/include/replication/logical.h           |   2 +
src/include/replication/walsender_private.h |   5 +
src/test/regress/expected/rules.out         |   5 +-
8 files changed, 370 insertions(+), 7 deletions(-)

  2. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Alvaro Herrera <alvherre@2ndquadrant.com> — 2017-04-21T19:06:29Z

    Simon Riggs wrote:
> Replication lag tracking for walsenders
> 
> Adds write_lag, flush_lag and replay_lag cols to pg_stat_replication.

Did anyone notice that this seems to be causing buildfarm member 'tern'
to fail the recovery check?  See here:

https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=tern&dt=2017-04-21%2012%3A48%3A09&stg=recovery-check
which has
TRAP: FailedAssertion("!(lsn >= prev.lsn)", File: "walsender.c", Line: 3331)

Line 3331 was added by this commit.

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

  3. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-04-21T21:04:08Z

    Alvaro Herrera <alvherre@2ndquadrant.com> writes:
> Simon Riggs wrote:
>> Replication lag tracking for walsenders
>> 
>> Adds write_lag, flush_lag and replay_lag cols to pg_stat_replication.

> Did anyone notice that this seems to be causing buildfarm member 'tern'
> to fail the recovery check?  See here:

> https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=tern&dt=2017-04-21%2012%3A48%3A09&stg=recovery-check
> which has
> TRAP: FailedAssertion("!(lsn >= prev.lsn)", File: "walsender.c", Line: 3331)

> Line 3331 was added by this commit.

Note that while that commit was some time back, tern has only just started
running recovery-check, following its update to the latest buildfarm
script.  It looks like it's run that test four times and failed twice,
so far.  So, not 100% reproducible, but there's something rotten there.
Timing-dependent, maybe?

Some excavation in the buildfarm database says that the coverage for
the recovery-check test has been mighty darn thin up until just recently.
These are all the reports we have:

pgbfprod=> select sysname, min(snapshot) as oldest, count(*) from build_status_log where log_stage = 'recovery-check.log' group by 1 order by 2;
 sysname  |       oldest        | count 
----------+---------------------+-------
 hamster  | 2016-03-01 02:34:26 |   182
 crake    | 2017-04-09 01:58:15 |    80
 nightjar | 2017-04-11 15:54:34 |    52
 longfin  | 2017-04-19 16:29:39 |     9
 hornet   | 2017-04-20 14:12:08 |     4
 mandrill | 2017-04-20 14:14:08 |     4
 sungazer | 2017-04-20 14:16:08 |     4
 tern     | 2017-04-20 14:18:08 |     4
 prion    | 2017-04-20 14:23:05 |     8
 jacana   | 2017-04-20 15:00:17 |     3
(10 rows)

So, other than hamster which is certainly going to have its own spin
on the timing question, we have next to no track record for this test.
I wouldn't bet that this issue is unique to tern; more likely, that's
just the first critter to show an intermittent issue.

			regards, tom lane

  4. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Andres Freund <andres@anarazel.de> — 2017-04-21T21:45:14Z

    On 2017-04-21 17:04:08 -0400, Tom Lane wrote:
> Some excavation in the buildfarm database says that the coverage for
> the recovery-check test has been mighty darn thin up until just
> recently.

Hm, not good. Just enabled it for most of my animals (there seems to be
no point in having it on the C89 animal).  Very curious what it'll do to
skink's runtime :/.  I'll add a few more cores to the machine, otherwise
it'll probably wreak havock.

Greetings,

Andres Freund

  5. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Thomas Munro <thomas.munro@enterprisedb.com> — 2017-04-22T05:45:15Z

    On Sat, Apr 22, 2017 at 9:04 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Alvaro Herrera <alvherre@2ndquadrant.com> writes:
>> Simon Riggs wrote:
>>> Replication lag tracking for walsenders
>>>
>>> Adds write_lag, flush_lag and replay_lag cols to pg_stat_replication.
>
>> Did anyone notice that this seems to be causing buildfarm member 'tern'
>> to fail the recovery check?  See here:
>
>> https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=tern&dt=2017-04-21%2012%3A48%3A09&stg=recovery-check
>> which has
>> TRAP: FailedAssertion("!(lsn >= prev.lsn)", File: "walsender.c", Line: 3331)
>
>> Line 3331 was added by this commit.
>
> Note that while that commit was some time back, tern has only just started
> running recovery-check, following its update to the latest buildfarm
> script.  It looks like it's run that test four times and failed twice,
> so far.  So, not 100% reproducible, but there's something rotten there.
> Timing-dependent, maybe?

Thanks.  I'm away from my computer right now but will investigate this
and send a fix later today.

-- 
Thomas Munro
http://www.enterprisedb.com

  6. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Simon Riggs <simon@2ndquadrant.com> — 2017-04-22T09:13:44Z

    On 22 April 2017 at 06:45, Thomas Munro <thomas.munro@enterprisedb.com> wrote:

> Thanks.  I'm away from my computer right now but will investigate this
> and send a fix later today.

Thanks. I'll review later today.

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

  7. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Thomas Munro <thomas.munro@enterprisedb.com> — 2017-04-22T13:54:11Z

    On Sat, Apr 22, 2017 at 9:13 PM, Simon Riggs <simon@2ndquadrant.com> wrote:
> On 22 April 2017 at 06:45, Thomas Munro <thomas.munro@enterprisedb.com> wrote:
>
>> Thanks.  I'm away from my computer right now but will investigate this
>> and send a fix later today.
>
> Thanks. I'll review later today.

The assertion fails reliably for me, because standby2's reported write
LSN jumps backwards after the timeline changes: for example I see
3020000 then 3028470 then 3020000 followed by a normal progression.
Surprisingly, 004_timeline_switch.pl reports success anyway.  I'm not
sure why the test fails sometimes on tern, but you can see that even
when it passed on tern the assertion had failed.

Here is a fix for the assertion failure.

-- 
Thomas Munro
http://www.enterprisedb.com

  8. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-04-22T15:41:01Z

    Thomas Munro <thomas.munro@enterprisedb.com> writes:
> The assertion fails reliably for me, because standby2's reported write
> LSN jumps backwards after the timeline changes: for example I see
> 3020000 then 3028470 then 3020000 followed by a normal progression.
> Surprisingly, 004_timeline_switch.pl reports success anyway.  I'm not
> sure why the test fails sometimes on tern, but you can see that even
> when it passed on tern the assertion had failed.

Whoa.  This just turned into a much larger can of worms than I expected.
How can it be that processes are getting assertion crashes and yet the
test framework reports success anyway?  That's impossibly
broken/unacceptable.

Looking closer at the tern report we started the thread with, there
are actually TWO assertion trap reports, the one Alvaro noted and
another one in 009_twophase_master.log:

TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "subtrans.c", Line: 92)

When I run the recovery test on my own machine, it reports success
(quite reliably, I tried a bunch of times yesterday), but now that
I know to look:

$ grep TRAP tmp_check/log/*
tmp_check/log/009_twophase_master.log:TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "subtrans.c", Line: 92)

So we now have three problems not just one:

* How is it that the TAP tests aren't noticing the failure?  This one,
to my mind, is a code-red situation, as it basically invalidates every
TAP test we've ever run.

* If Thomas's explanation for the timeline-switch assertion is correct,
why isn't it reproducible everywhere?

* What's with that second TRAP?

> Here is a fix for the assertion failure.

As for this patch itself, is it reasonable to try to assert that the
timeline has in fact changed?

			regards, tom lane

  9. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-04-22T15:59:37Z

    I wrote:
> Whoa.  This just turned into a much larger can of worms than I expected.
> How can it be that processes are getting assertion crashes and yet the
> test framework reports success anyway?  That's impossibly
> broken/unacceptable.

Taking a quick census of other buildfarm machines that are known to be
running the recovery test, it appears that most (not all) are seeing
one or both traps.  But the test is reporting success anyway, everywhere
except on Noah's 32-bit AIX critters.

			regards, tom lane

  10. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-04-22T16:27:35Z

    I wrote:
> Taking a quick census of other buildfarm machines that are known to be
> running the recovery test, it appears that most (not all) are seeing
> one or both traps.  But the test is reporting success anyway, everywhere
> except on Noah's 32-bit AIX critters.

Or, to be a bit more scientific, let's dig into the buildfarm database.
A couple more critters have started running the recovery test since
yesterday; these are the latest reports we have:

pgbfprod=> select sysname, max(snapshot) as newest, count(*) from build_status_log where log_stage = 'recovery-check.log' group by 1 order by 2;
    sysname    |       newest        | count 
---------------+---------------------+-------
 hamster       | 2016-09-24 16:00:07 |   182
 jacana        | 2017-04-20 21:00:20 |     3
 skink         | 2017-04-22 05:00:01 |     2
 sungazer      | 2017-04-22 06:07:17 |     7
 tern          | 2017-04-22 06:38:09 |     8
 hornet        | 2017-04-22 06:41:12 |     7
 mandrill      | 2017-04-22 08:44:09 |     8
 nightjar      | 2017-04-22 13:54:24 |    55
 longfin       | 2017-04-22 14:29:17 |    13
 calliphoridae | 2017-04-22 14:30:01 |     4
 piculet       | 2017-04-22 14:30:01 |     3
 culicidae     | 2017-04-22 14:30:01 |     5
 francolin     | 2017-04-22 14:30:01 |     3
 prion         | 2017-04-22 14:33:05 |    12
 crake         | 2017-04-22 14:37:21 |    86
(15 rows)

Grepping those specific reports for "TRAP" yields

    sysname    |                                                                                                            l                                                                                                             
---------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 jacana        | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "c:/mingw/msys/1.0/home/pgrunner/bf/root/HEAD/pgsql.build/../pgsql/src/backend/access/transam/subtrans.c", Line: 92)
 sungazer      | TRAP: FailedAssertion("!(lsn >= prev.lsn)", File: "walsender.c", Line: 3331)
 sungazer      | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "subtrans.c", Line: 92)
 tern          | TRAP: FailedAssertion("!(lsn >= prev.lsn)", File: "walsender.c", Line: 3331)
 tern          | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "subtrans.c", Line: 92)
 hornet        | TRAP: FailedAssertion("!(lsn >= prev.lsn)", File: "walsender.c", Line: 3331)
 hornet        | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "subtrans.c", Line: 92)
 mandrill      | TRAP: FailedAssertion("!(lsn >= prev.lsn)", File: "walsender.c", Line: 3331)
 mandrill      | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "subtrans.c", Line: 92)
 nightjar      | TRAP: FailedAssertion("!(lsn >= prev.lsn)", File: "/pgbuild/root/HEAD/pgsql.build/../pgsql/src/backend/replication/walsender.c", Line: 3331)
 nightjar      | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "/pgbuild/root/HEAD/pgsql.build/../pgsql/src/backend/access/transam/subtrans.c", Line: 92)
 longfin       | TRAP: FailedAssertion("!(lsn >= prev.lsn)", File: "walsender.c", Line: 3331)
 longfin       | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "subtrans.c", Line: 92)
 calliphoridae | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "/home/andres/build/buildfarm-calliphoridae/HEAD/pgsql.build/../pgsql/src/backend/access/transam/subtrans.c", Line: 92)
 piculet       | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "/home/andres/build/buildfarm-piculet/HEAD/pgsql.build/../pgsql/src/backend/access/transam/subtrans.c", Line: 92)
 culicidae     | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "/home/andres/build/buildfarm-culicidae/HEAD/pgsql.build/../pgsql/src/backend/access/transam/subtrans.c", Line: 92)
 francolin     | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "/home/andres/build/buildfarm-francolin/HEAD/pgsql.build/../pgsql/src/backend/access/transam/subtrans.c", Line: 92)
 prion         | TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "/home/ec2-user/bf/root/HEAD/pgsql.build/../pgsql/src/backend/access/transam/subtrans.c", Line: 92)
(18 rows)

So 6 of 15 critters are getting the walsender.c assertion,
and those six plus six more are seeing the subtrans.c one,
and three are seeing neither one.  There's probably a pattern
to that, don't know what it is.

(Actually, it looks like hamster stopped running this test
a long time ago, so whatever is in its last report is probably
not very relevant.  So more like 12 of 14 critters are seeing
one or both traps.)

			regards, tom lane

  11. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-04-22T16:37:50Z

    I wrote:
> So 6 of 15 critters are getting the walsender.c assertion,
> and those six plus six more are seeing the subtrans.c one,
> and three are seeing neither one.  There's probably a pattern
> to that, don't know what it is.

Ah, got it: skink *is* seeing the subtrans.c assertion, but not
the other.  (I'd forgotten to limit the query to the HEAD branch,
and it was looking at 9.6 for skink.)  hamster, as stated, isn't
giving us a recent report; and crake is running the test but it
doesn't use --enable-cassert, hence no TRAP.

So actually, every single buildfarm member that could be reporting
the subtrans.c crash is doing so.  But only about half of them are
reporting the walsender.c crash.

			regards, tom lane

  12. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-04-22T18:40:28Z

    I wrote:
> Whoa.  This just turned into a much larger can of worms than I expected.
> How can it be that processes are getting assertion crashes and yet the
> test framework reports success anyway?  That's impossibly
> broken/unacceptable.

I poked into this on my laptop, where I'm able to reproduce both assertion
failures.  The reason the one in subtrans.c is not being detected by the
test framework is that it happens late in the run and the test doesn't
do anything more with that server than shut it down.  "pg_ctl stop"
actually notices there's a problem; for instance, the log on tern for
this step shows

### Stopping node "master" using mode immediate
# Running: pg_ctl -D /home/nm/farm/gcc32/HEAD/pgsql.build/src/test/recovery/tmp_check/data_master_xHGA/pgdata -m immediate stop
pg_ctl: PID file "/home/nm/farm/gcc32/HEAD/pgsql.build/src/test/recovery/tmp_check/data_master_xHGA/pgdata/postmaster.pid" does not exist
Is server running?
# No postmaster PID

However, PostgresNode::stop blithely ignores the failure exit from
pg_ctl.  I think it should use system_or_bail() not just system_log(),
so that we'll notice if the server is not running when we expect it
to be.  It's conceivable that there should also be a "stop_if_running"
method that allows the case where the server is not running, but so
far as I can find, no existing TAP test needs such a behavior --- and
it certainly shouldn't be the default.

The walsender.c crash is harder to detect because the postmaster very
nicely recovers and restarts its children.  That's great for robustness,
but it sucks for testing.  I think that we ought to disable that in
TAP tests, which we can do by having PostgresNode::init include
"restart_after_crash = off" in the postgresql.conf modifications it
applies.  Again, it's conceivable that some tests would not want that,
but there is no existing test that seems to need crash recovery on,
and I don't see a good argument for it being default for test purposes.

As best I've been able to tell, the reason why the walsender.c crash
is detected when it's detected is that the TAP script chances to try
to connect while the recovery is happening:

connection error: 'psql: FATAL:  the database system is in recovery mode'
while running 'psql -XAtq -d port=57718 host=/tmp/_uP8FKEynq dbname='postgres' -f - -v ON_ERROR_STOP=1' at /home/nm/farm/gcc32/HEAD/pgsql.build/src/test/recovery/../../../src/test/perl/PostgresNode.pm line 1173.

The window for that is not terribly wide, explaining why the detection
is unreliable even when the crash does occur.

In short then, I propose the attached patch to make these cases fail
more reliably.  We might extend this later to allow the old behaviors
to be explicitly opted-into, but we don't seem to need that today.

			regards, tom lane

  13. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Thomas Munro <thomas.munro@enterprisedb.com> — 2017-04-23T02:11:40Z

    On Sun, Apr 23, 2017 at 3:41 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Thomas Munro <thomas.munro@enterprisedb.com> writes:
>> The assertion fails reliably for me, because standby2's reported write
>> LSN jumps backwards after the timeline changes: for example I see
>> 3020000 then 3028470 then 3020000 followed by a normal progression.
>> Surprisingly, 004_timeline_switch.pl reports success anyway.  I'm not
>> sure why the test fails sometimes on tern, but you can see that even
>> when it passed on tern the assertion had failed.
>
> Whoa.  This just turned into a much larger can of worms than I expected.
> How can it be that processes are getting assertion crashes and yet the
> test framework reports success anyway?  That's impossibly
> broken/unacceptable.

Agreed, thanks for fixing that.

> Looking closer at the tern report we started the thread with, there
> are actually TWO assertion trap reports, the one Alvaro noted and
> another one in 009_twophase_master.log:
>
> TRAP: FailedAssertion("!(*ptr == ((TransactionId) 0) || (*ptr == parent && overwriteOK))", File: "subtrans.c", Line: 92)

I see you started another thread for that one.  I admit I spent a
couple of hours trying to figure this out before I saw your email, but
I was looking at the wrong bit of git history and didn't spot that
it's likely a 7 year old problem.  So this is a good result for these
TAP tests, despite teething difficulties with, erm, "pass" vs "fail"
and the fact that 009_twophase.pl was bombing from the moment it was
committed.  Hoping to use this framework in future work.

>> Here is a fix for the assertion failure.
>
> As for this patch itself, is it reasonable to try to assert that the
> timeline has in fact changed?

The protocol doesn't include the timeline in reply messages, so it's
not clear how the upstream server would know what timeline the standby
thinks it's dealing with in any given reply message.  The sending
server has its own idea of the current timeline but it's not in sync
with the stream of incoming replies.

-- 
Thomas Munro
http://www.enterprisedb.com

  14. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Mark Dilger <hornschnorter@gmail.com> — 2017-04-23T02:44:28Z

    > On Apr 22, 2017, at 11:40 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> 
> I wrote:
>> Whoa.  This just turned into a much larger can of worms than I expected.
>> How can it be that processes are getting assertion crashes and yet the
>> test framework reports success anyway?  That's impossibly
>> broken/unacceptable.
> 
> I poked into this on my laptop, where I'm able to reproduce both assertion
> failures.  The reason the one in subtrans.c is not being detected by the
> test framework is that it happens late in the run and the test doesn't
> do anything more with that server than shut it down.  "pg_ctl stop"
> actually notices there's a problem; for instance, the log on tern for
> this step shows
> 
> ### Stopping node "master" using mode immediate
> # Running: pg_ctl -D /home/nm/farm/gcc32/HEAD/pgsql.build/src/test/recovery/tmp_check/data_master_xHGA/pgdata -m immediate stop
> pg_ctl: PID file "/home/nm/farm/gcc32/HEAD/pgsql.build/src/test/recovery/tmp_check/data_master_xHGA/pgdata/postmaster.pid" does not exist
> Is server running?
> # No postmaster PID
> 
> However, PostgresNode::stop blithely ignores the failure exit from
> pg_ctl.  I think it should use system_or_bail() not just system_log(),
> so that we'll notice if the server is not running when we expect it
> to be.  It's conceivable that there should also be a "stop_if_running"
> method that allows the case where the server is not running, but so
> far as I can find, no existing TAP test needs such a behavior --- and
> it certainly shouldn't be the default.
> 
> The walsender.c crash is harder to detect because the postmaster very
> nicely recovers and restarts its children.  That's great for robustness,
> but it sucks for testing.  I think that we ought to disable that in
> TAP tests, which we can do by having PostgresNode::init include
> "restart_after_crash = off" in the postgresql.conf modifications it
> applies.  Again, it's conceivable that some tests would not want that,
> but there is no existing test that seems to need crash recovery on,
> and I don't see a good argument for it being default for test purposes.
> 
> As best I've been able to tell, the reason why the walsender.c crash
> is detected when it's detected is that the TAP script chances to try
> to connect while the recovery is happening:
> 
> connection error: 'psql: FATAL:  the database system is in recovery mode'
> while running 'psql -XAtq -d port=57718 host=/tmp/_uP8FKEynq dbname='postgres' -f - -v ON_ERROR_STOP=1' at /home/nm/farm/gcc32/HEAD/pgsql.build/src/test/recovery/../../../src/test/perl/PostgresNode.pm line 1173.
> 
> The window for that is not terribly wide, explaining why the detection
> is unreliable even when the crash does occur.
> 
> In short then, I propose the attached patch to make these cases fail
> more reliably.  We might extend this later to allow the old behaviors
> to be explicitly opted-into, but we don't seem to need that today.
> 
> 			regards, tom lane

I pulled fresh sources with your latest commit, 7d68f2281a4b56834c8e5648fc7da0b73b674c45,
and the tests consistently fail (5 out of 5 attempts) for me on my laptop with:

/Applications/Xcode.app/Contents/Developer/usr/bin/make -C recovery check
for extra in contrib/test_decoding; do /Applications/Xcode.app/Contents/Developer/usr/bin/make -C '../../..'/$extra DESTDIR='/Users/mark/vanilla/bitoctetlength'/tmp_install install >>'/Users/mark/vanilla/bitoctetlength'/tmp_install/log/install.log || exit; done
rm -rf /Users/mark/vanilla/bitoctetlength/src/test/recovery/tmp_check/log
cd . && TESTDIR='/Users/mark/vanilla/bitoctetlength/src/test/recovery' PATH="/Users/mark/vanilla/bitoctetlength/tmp_install/usr/local/pgsql/bin:$PATH" DYLD_LIBRARY_PATH="/Users/mark/vanilla/bitoctetlength/tmp_install/usr/local/pgsql/lib" PGPORT='65432' PG_REGRESS='/Users/mark/vanilla/bitoctetlength/src/test/recovery/../../../src/test/regress/pg_regress' prove -I ../../../src/test/perl/ -I .  t/*.pl
t/001_stream_rep.pl .................. ok     
t/002_archiving.pl ................... ok   
t/003_recovery_targets.pl ............ ok   
t/004_timeline_switch.pl ............. Bailout called.  Further testing stopped:  system pg_ctl failed
FAILED--Further testing stopped: system pg_ctl failed
make[2]: *** [check] Error 255
make[1]: *** [check-recovery-recurse] Error 2
make: *** [check-world-src/test-recurse] Error 2

The first time, I had some local changes, but I've stashed them and am still getting the error each of
these next four times.  I'm compiling as follows:

make distclean; make clean; ./configure --enable-cassert --enable-tap-tests --enable-depend && make -j4 && make check-world

Are the errors expected now?

mark

  15. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-04-23T05:26:46Z

    Mark Dilger <hornschnorter@gmail.com> writes:
>> On Apr 22, 2017, at 11:40 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> In short then, I propose the attached patch to make these cases fail
>> more reliably.  We might extend this later to allow the old behaviors
>> to be explicitly opted-into, but we don't seem to need that today.

> I pulled fresh sources with your latest commit, 7d68f2281a4b56834c8e5648fc7da0b73b674c45,
> and the tests consistently fail (5 out of 5 attempts) for me on my laptop with:

> Are the errors expected now?

Yes, as of right now, if HEAD *doesn't* fail the src/test/recovery tests
for you in an assert-enabled build, that would be surprising.  The next
step is to actually fix the bugs ... but the point of commit 7d68f2281
was to make these failures reproducible, which they were not before.

			regards, tom lane

  16. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-04-23T06:01:34Z

    Thomas Munro <thomas.munro@enterprisedb.com> writes:
> On Sun, Apr 23, 2017 at 3:41 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> As for this patch itself, is it reasonable to try to assert that the
>> timeline has in fact changed?

> The protocol doesn't include the timeline in reply messages, so it's
> not clear how the upstream server would know what timeline the standby
> thinks it's dealing with in any given reply message.  The sending
> server has its own idea of the current timeline but it's not in sync
> with the stream of incoming replies.

Fair enough.  But I'd still like an explanation of why only about
half of the population is showing a failure here.  Seems like every
machine should be seeing the LSN as moving backwards in this test.
So (a) why aren't they all failing, and (b) should we change the
test to make sure every platform sees that happening?

			regards, tom lane

  17. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Simon Riggs <simon@2ndquadrant.com> — 2017-04-23T10:10:33Z

    On 22 April 2017 at 16:41, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Thomas Munro <thomas.munro@enterprisedb.com> writes:
>> The assertion fails reliably for me, because standby2's reported write
>> LSN jumps backwards after the timeline changes: for example I see
>> 3020000 then 3028470 then 3020000 followed by a normal progression.
>> Surprisingly, 004_timeline_switch.pl reports success anyway.  I'm not
>> sure why the test fails sometimes on tern, but you can see that even
>> when it passed on tern the assertion had failed.
>
> Whoa.  This just turned into a much larger can of worms than I expected.
> How can it be that processes are getting assertion crashes and yet the
> test framework reports success anyway?  That's impossibly
> broken/unacceptable.

Agreed, thanks for fixing.

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

  18. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Thomas Munro <thomas.munro@enterprisedb.com> — 2017-04-23T22:34:44Z

    On Sun, Apr 23, 2017 at 6:01 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Thomas Munro <thomas.munro@enterprisedb.com> writes:
>> On Sun, Apr 23, 2017 at 3:41 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>>> As for this patch itself, is it reasonable to try to assert that the
>>> timeline has in fact changed?
>
>> The protocol doesn't include the timeline in reply messages, so it's
>> not clear how the upstream server would know what timeline the standby
>> thinks it's dealing with in any given reply message.  The sending
>> server has its own idea of the current timeline but it's not in sync
>> with the stream of incoming replies.
>
> Fair enough.  But I'd still like an explanation of why only about
> half of the population is showing a failure here.  Seems like every
> machine should be seeing the LSN as moving backwards in this test.
> So (a) why aren't they all failing, and (b) should we change the
> test to make sure every platform sees that happening?

Every machine sees the LSN moving backwards, but the code path that
had the assertion only reached if it decides to interpolate, which is
timing dependent: there needs to be a future sample in the lag
tracking buffer, which I guess is not the case in those runs.  For
example, "jacana" is one of the animals that reported the assertion
failure for 009_twophase.pl but not the one for
004_timeline_switch.pl, in this run:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=jacana&dt=2017-04-20%2021%3A00%3A20

This standby2 log fragment corresponds to the LSN zigzag manoeuvre:

2017-04-20 22:04:51.744 GMT [1984] LOG:  fetching timeline history
file for timeline 2 from primary server
2017-04-20 22:04:51.744 GMT [1984] LOG:  started streaming WAL from
primary at 0/3000000 on timeline 1
2017-04-20 22:04:51.744 GMT [1984] LOG:  replication terminated by
primary server
2017-04-20 22:04:51.744 GMT [1984] DETAIL:  End of WAL reached on
timeline 1 at 0/3028D50.
2017-04-20 22:04:51.744 GMT [1708] LOG:  new target timeline is 2
2017-04-20 22:04:51.744 GMT [1984] LOG:  restarted WAL streaming at
0/3000000 on timeline 2

It looks approximately the same on my development machine where I got
the assertion failure until commit 84638808:

2017-04-24 09:04:46.563 NZST [95164] LOG:  fetching timeline history
file for timeline 2 from primary server
2017-04-24 09:04:46.563 NZST [95164] LOG:  started streaming WAL from
primary at 0/3000000 on timeline 1
2017-04-24 09:04:46.564 NZST [95164] LOG:  replication terminated by
primary server
2017-04-24 09:04:46.564 NZST [95164] DETAIL:  End of WAL reached on
timeline 1 at 0/3028470.
2017-04-24 09:04:46.565 NZST [95160] LOG:  new target timeline is 2
2017-04-24 09:04:46.565 NZST [95164] LOG:  restarted WAL streaming at
0/3000000 on timeline 2

-- 
Thomas Munro
http://www.enterprisedb.com

  19. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-04-24T02:53:15Z

    Thomas Munro <thomas.munro@enterprisedb.com> writes:
> On Sun, Apr 23, 2017 at 6:01 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Fair enough.  But I'd still like an explanation of why only about
>> half of the population is showing a failure here.  Seems like every
>> machine should be seeing the LSN as moving backwards in this test.
>> So (a) why aren't they all failing, and (b) should we change the
>> test to make sure every platform sees that happening?

> Every machine sees the LSN moving backwards, but the code path that
> had the assertion only reached if it decides to interpolate, which is
> timing dependent: there needs to be a future sample in the lag
> tracking buffer, which I guess is not the case in those runs.

I'm dissatisfied with this explanation because if it's just timing,
it doesn't seem very likely that some machines would reproduce the
failure every single time while others never would.  Maybe that can be
blamed on kernel scheduler vagaries + different numbers of cores, but
I can't escape the feeling that there's something here we've not
fully understood.

While chasing after this earlier today, I turned on some debug logging
and noted that the standby's reports look like

2017-04-23 15:46:46.206 EDT [34829] LOG:  database system is ready to accept read only connections
2017-04-23 15:46:46.212 EDT [34834] LOG:  fetching timeline history file for timeline 2 from primary server
2017-04-23 15:46:46.212 EDT [34834] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2017-04-23 15:46:46.213 EDT [34834] LOG:  sending write 0/3020000 flush 0/3028470 apply 0/3028470
2017-04-23 15:46:46.214 EDT [34834] LOG:  replication terminated by primary server
2017-04-23 15:46:46.214 EDT [34834] DETAIL:  End of WAL reached on timeline 1 at 0/3028470.
2017-04-23 15:46:46.214 EDT [34834] LOG:  sending write 0/3028470 flush 0/3028470 apply 0/3028470
2017-04-23 15:46:46.214 EDT [34830] LOG:  new target timeline is 2
2017-04-23 15:46:46.214 EDT [34834] LOG:  restarted WAL streaming at 0/3000000 on timeline 2
2017-04-23 15:46:46.228 EDT [34834] LOG:  sending write 0/3020000 flush 0/3028470 apply 0/3028470

So you're right that the standby's reported "write" position can go
backward, but it seems pretty darn odd that the flush and apply
positions didn't go backward too.  Is there a bug there?

I remain of the opinion that if we can't tell from the transmitted
data whether a timeline switch has caused the position to go backward,
then that's a protocol shortcoming that ought to be fixed.

			regards, tom lane

  20. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Mark Dilger <hornschnorter@gmail.com> — 2017-04-24T22:41:25Z

    > On Apr 23, 2017, at 7:53 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> 
> Thomas Munro <thomas.munro@enterprisedb.com> writes:
>> On Sun, Apr 23, 2017 at 6:01 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>>> Fair enough.  But I'd still like an explanation of why only about
>>> half of the population is showing a failure here.  Seems like every
>>> machine should be seeing the LSN as moving backwards in this test.
>>> So (a) why aren't they all failing, and (b) should we change the
>>> test to make sure every platform sees that happening?
> 
>> Every machine sees the LSN moving backwards, but the code path that
>> had the assertion only reached if it decides to interpolate, which is
>> timing dependent: there needs to be a future sample in the lag
>> tracking buffer, which I guess is not the case in those runs.
> 
> I'm dissatisfied with this explanation because if it's just timing,
> it doesn't seem very likely that some machines would reproduce the
> failure every single time while others never would.  Maybe that can be
> blamed on kernel scheduler vagaries + different numbers of cores, but
> I can't escape the feeling that there's something here we've not
> fully understood.
> 
> While chasing after this earlier today, I turned on some debug logging
> and noted that the standby's reports look like
> 
> 2017-04-23 15:46:46.206 EDT [34829] LOG:  database system is ready to accept read only connections
> 2017-04-23 15:46:46.212 EDT [34834] LOG:  fetching timeline history file for timeline 2 from primary server
> 2017-04-23 15:46:46.212 EDT [34834] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
> 2017-04-23 15:46:46.213 EDT [34834] LOG:  sending write 0/3020000 flush 0/3028470 apply 0/3028470
> 2017-04-23 15:46:46.214 EDT [34834] LOG:  replication terminated by primary server
> 2017-04-23 15:46:46.214 EDT [34834] DETAIL:  End of WAL reached on timeline 1 at 0/3028470.
> 2017-04-23 15:46:46.214 EDT [34834] LOG:  sending write 0/3028470 flush 0/3028470 apply 0/3028470
> 2017-04-23 15:46:46.214 EDT [34830] LOG:  new target timeline is 2
> 2017-04-23 15:46:46.214 EDT [34834] LOG:  restarted WAL streaming at 0/3000000 on timeline 2
> 2017-04-23 15:46:46.228 EDT [34834] LOG:  sending write 0/3020000 flush 0/3028470 apply 0/3028470
> 
> So you're right that the standby's reported "write" position can go
> backward, but it seems pretty darn odd that the flush and apply
> positions didn't go backward too.  Is there a bug there?
> 
> I remain of the opinion that if we can't tell from the transmitted
> data whether a timeline switch has caused the position to go backward,
> then that's a protocol shortcoming that ought to be fixed.

The recent fix in 546c13e11b29a5408b9d6a6e3cca301380b47f7f has local variable overwriteOK
assigned but not used in twophase.c RecoverPreparedTransactions(void).  I'm not sure if that's
future-proofing or an oversight.  It seems to be used in other functions.  Just FYI.

Mark Dilger

  21. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Andres Freund <andres@anarazel.de> — 2017-04-24T22:46:36Z

    On 2017-04-24 15:41:25 -0700, Mark Dilger wrote:
> The recent fix in 546c13e11b29a5408b9d6a6e3cca301380b47f7f has local variable overwriteOK
> assigned but not used in twophase.c RecoverPreparedTransactions(void).  I'm not sure if that's
> future-proofing or an oversight.  It seems to be used in other functions.  Just FYI.

That's just a temporary workaround while the problem's being analyzed.

- Andres

  22. Re: [COMMITTERS] pgsql: Replication lag tracking for walsenders

    Thomas Munro <thomas.munro@enterprisedb.com> — 2017-04-28T05:10:42Z

    On Mon, Apr 24, 2017 at 2:53 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Thomas Munro <thomas.munro@enterprisedb.com> writes:
>> Every machine sees the LSN moving backwards, but the code path that
>> had the assertion only reached if it decides to interpolate, which is
>> timing dependent: there needs to be a future sample in the lag
>> tracking buffer, which I guess is not the case in those runs.
>
> I'm dissatisfied with this explanation because if it's just timing,
> it doesn't seem very likely that some machines would reproduce the
> failure every single time while others never would.  Maybe that can be
> blamed on kernel scheduler vagaries + different numbers of cores, but
> I can't escape the feeling that there's something here we've not
> fully understood.

Ahh.  It is timing-dependent, but what I said before wasn't right.
The write LSN always jumps back to the start of the current segment,
but some machines don't report that upstream because of timing
effects.

I found a machine that doesn't reproduce the earlier assertion failure
(or, rather, an elog I put into that code path where the assertion
was).  It's a VirtualBox VM running Debian 8 on amd64, and it doesn't
matter whether I tell it to use 1 or 4 CPU cores.

After the timeline change, standby2 restarts WAL streaming from
0/3000000, and standby1 sends it two messages: one 128KB message, and
then another smaller one.  On this virtual machine, the inner message
processing loop in walreceiver.c reliably manages to read both
messages from the socket one after the other, taking it all the way to
0/3028470 (end of WAL).  Then it calls XLogWalRcvSendReply, so the
position reported to the upstream server never goes backwards.

On my other machines it reliably reads the first message, runs out of
data on the socket so it falls out of the loop, and calls
XLogWalRcvSendReply to report the intermediate location 0/3020000.
Then the socket's soon ready again, we go around the outer loop again
and finally report 0/3028470.

> [...]
>
> So you're right that the standby's reported "write" position can go
> backward, but it seems pretty darn odd that the flush and apply
> positions didn't go backward too.  Is there a bug there?

Flush doesn't go backwards because XLogWalRcvFlush does nothing unless
Flush < Write.  I am not sure whether it constitutes a bug that we
rewrite the start of the current segment without flushing it.

A timeline change isn't actually necessary for the
rewind-to-start-of-segment behaviour, by the way: we always do that at
the start of streaming, as described in RequestXLogStreaming.  But
it's it's only a problem for timeline changes, because in other cases
it's talking to a fresh walsender that doesn't have any state that
would have triggered the (now removed) assertion.  I think the change
that was committed in 84638808 was therefore correct.

> I remain of the opinion that if we can't tell from the transmitted
> data whether a timeline switch has caused the position to go backward,
> then that's a protocol shortcoming that ought to be fixed.

Another approach might have been to teach the switch case for
T_StartReplicationCmd in exec_replication_command to clear all
LagTracker state, since that is the point at which the remote
walreceiver has requested a new stream and all subsequent messages
will refer to that stream.

-- 
Thomas Munro
http://www.enterprisedb.com