Hot Standby startup with overflowed snapshots

Chris Redekop's recent report of slow startup for Hot Standby has made
me revisit the code there.

Although there isn't a bug, there is a missed opportunity for starting
up faster which could be the source of Chris' annoyance.

The following patch allows a faster startup in some circumstances.

The patch also alters the log levels for messages and gives a single
simple message for this situation. The log will now say

LOG: recovery snapshot waiting for non-overflowed snapshot or until
oldest active xid on standby is at least %u (now %u)
...multiple times until snapshot non-overflowed or xid reached...

whereas before the first LOG message shown was

LOG: consistent state delayed because recovery snapshot incomplete
and only later, at DEBUG2 do you see
LOG: recovery snapshot waiting for %u oldest active xid on standby is %u
...multiple times until xid reached...

Comments please.

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

Thanks for the patch Simon, but unfortunately it does not resolve the issue
I am seeing. The standby still refuses to finish starting up until long
after all clients have disconnected from the primary (>10 minutes). I do
see your new log statement on startup, but only once - it does not repeat.
Is there any way for me to see what the oldest xid on the standby is via
controldata or something like that? The standby does stream to keep up with
the primary while the primary has load, and then it becomes idle when the
primary becomes idle (when I kill all the connections)....so it appears to
be current...but it just doesn't finish starting up

I'm not sure if it's relevant, but after it has sat idle for a couple
minutes I start seeing these statements in the log (with the same offset
every time):
DEBUG: skipping restartpoint, already performed at 9/95000020

On Thu, Oct 27, 2011 at 7:26 AM, Simon Riggs <simon(at)2ndquadrant(dot)com> wrote:

> Chris Redekop's recent report of slow startup for Hot Standby has made
> me revisit the code there.
>
> Although there isn't a bug, there is a missed opportunity for starting
> up faster which could be the source of Chris' annoyance.
>
> The following patch allows a faster startup in some circumstances.
>
> The patch also alters the log levels for messages and gives a single
> simple message for this situation. The log will now say
>
> LOG: recovery snapshot waiting for non-overflowed snapshot or until
> oldest active xid on standby is at least %u (now %u)
> ...multiple times until snapshot non-overflowed or xid reached...
>
> whereas before the first LOG message shown was
>
> LOG: consistent state delayed because recovery snapshot incomplete
> and only later, at DEBUG2 do you see
> LOG: recovery snapshot waiting for %u oldest active xid on standby is %u
> ...multiple times until xid reached...
>
> Comments please.
>
> --
> Simon Riggs http://www.2ndQuadrant.com/
> PostgreSQL Development, 24x7 Support, Training & Services
>
>
> --
> Sent via pgsql-hackers mailing list (pgsql-hackers(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-hackers
>
>

On Thu, Oct 27, 2011 at 5:26 PM, Chris Redekop <chris(at)replicon(dot)com> wrote:

> Thanks for the patch Simon, but unfortunately it does not resolve the issue
> I am seeing.  The standby still refuses to finish starting up until long
> after all clients have disconnected from the primary (>10 minutes).  I do
> see your new log statement on startup, but only once - it does not repeat.
>  Is there any way for me to see  what the oldest xid on the standby is via
> controldata or something like that?  The standby does stream to keep up with
> the primary while the primary has load, and then it becomes idle when the
> primary becomes idle (when I kill all the connections)....so it appears to
> be current...but it just doesn't finish starting up
> I'm not sure if it's relevant, but after it has sat idle for a couple
> minutes I start seeing these statements in the log (with the same offset
> every time):
> DEBUG:  skipping restartpoint, already performed at 9/95000020

OK, so it looks like there are 2 opportunities to improve, not just one.

Try this.

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

hrmz, still basically the same behaviour. I think it might be a *little*
better with this patch. Before when under load it would start up quickly
maybe 2 or 3 times out of 10 attempts....with this patch it might be up to 4
or 5 times out of 10...ish...or maybe it was just fluke *shrug*. I'm still
only seeing your log statement a single time (I'm running at debug2). I
have discovered something though - when the standby is in this state if I
force a checkpoint on the primary then the standby comes right up. Is there
anything I check or try for you to help figure this out?....or is it
actually as designed that it could take 10-ish minutes to start up even
after all clients have disconnected from the primary?

On Thu, Oct 27, 2011 at 11:27 AM, Simon Riggs <simon(at)2ndquadrant(dot)com> wrote:

> On Thu, Oct 27, 2011 at 5:26 PM, Chris Redekop <chris(at)replicon(dot)com> wrote:
>
> > Thanks for the patch Simon, but unfortunately it does not resolve the
> issue
> > I am seeing. The standby still refuses to finish starting up until long
> > after all clients have disconnected from the primary (>10 minutes). I do
> > see your new log statement on startup, but only once - it does not
> repeat.
> > Is there any way for me to see what the oldest xid on the standby is
> via
> > controldata or something like that? The standby does stream to keep up
> with
> > the primary while the primary has load, and then it becomes idle when the
> > primary becomes idle (when I kill all the connections)....so it appears
> to
> > be current...but it just doesn't finish starting up
> > I'm not sure if it's relevant, but after it has sat idle for a couple
> > minutes I start seeing these statements in the log (with the same offset
> > every time):
> > DEBUG: skipping restartpoint, already performed at 9/95000020
>
> OK, so it looks like there are 2 opportunities to improve, not just one.
>
> Try this.
>
> --
> Simon Riggs http://www.2ndQuadrant.com/
> PostgreSQL Development, 24x7 Support, Training & Services
>

On Thu, Oct 27, 2011 at 10:09 PM, Chris Redekop <chris(at)replicon(dot)com> wrote:

> hrmz, still basically the same behaviour.  I think it might be a *little*
> better with this patch.  Before when under load it would start up quickly
> maybe 2 or 3 times out of 10 attempts....with this patch it might be up to 4
> or 5 times out of 10...ish...or maybe it was just fluke *shrug*.  I'm still
> only seeing your log statement a single time (I'm running at debug2).  I
> have discovered something though - when the standby is in this state if I
> force a checkpoint on the primary then the standby comes right up.  Is there
> anything I check or try for you to help figure this out?....or is it
> actually as designed that it could take 10-ish minutes to start up even
> after all clients have disconnected from the primary?

Thanks for testing. The improvements cover specific cases, so its not
subject to chance; its not a performance patch.

It's not "designed" to act the way you describe, but it does.

The reason this occurs is that you have a transaction heavy workload
with occasional periods of complete quiet and a base backup time that
is much less than checkpoint_timeout. If your base backup was slower
the checkpoint would have hit naturally before recovery had reached a
consistent state. Which seems fairly atypical. I guess you're doing
this on a test system.

It seems cheap to add in a call to LogStandbySnapshot() after each
call to pg_stop_backup().

Does anyone think this case is worth adding code for? Seems like one
more thing to break.

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

Sorry..."designed" was poor choice of words, I meant "not unexpected".
Doing the checkpoint right after pg_stop_backup() looks like it will work
perfectly for me, so thanks for all your help!

On a side note I am sporadically seeing another error on hotstandby startup.
I'm not terribly concerned about it as it is pretty rare and it will work
on a retry so it's not a big deal. The error is "FATAL: out-of-order XID
insertion in KnownAssignedXids". If you think it might be a bug and are
interested in hunting it down let me know and I'll help any way I can...but
if you're not too worried about it then neither am I :)

On Thu, Oct 27, 2011 at 4:55 PM, Simon Riggs <simon(at)2ndquadrant(dot)com> wrote:

> On Thu, Oct 27, 2011 at 10:09 PM, Chris Redekop <chris(at)replicon(dot)com>
> wrote:
>
> > hrmz, still basically the same behaviour. I think it might be a *little*
> > better with this patch. Before when under load it would start up quickly
> > maybe 2 or 3 times out of 10 attempts....with this patch it might be up
> to 4
> > or 5 times out of 10...ish...or maybe it was just fluke *shrug*. I'm
> still
> > only seeing your log statement a single time (I'm running at debug2). I
> > have discovered something though - when the standby is in this state if I
> > force a checkpoint on the primary then the standby comes right up. Is
> there
> > anything I check or try for you to help figure this out?....or is it
> > actually as designed that it could take 10-ish minutes to start up even
> > after all clients have disconnected from the primary?
>
> Thanks for testing. The improvements cover specific cases, so its not
> subject to chance; its not a performance patch.
>
> It's not "designed" to act the way you describe, but it does.
>
> The reason this occurs is that you have a transaction heavy workload
> with occasional periods of complete quiet and a base backup time that
> is much less than checkpoint_timeout. If your base backup was slower
> the checkpoint would have hit naturally before recovery had reached a
> consistent state. Which seems fairly atypical. I guess you're doing
> this on a test system.
>
> It seems cheap to add in a call to LogStandbySnapshot() after each
> call to pg_stop_backup().
>
> Does anyone think this case is worth adding code for? Seems like one
> more thing to break.
>
> --
> Simon Riggs http://www.2ndQuadrant.com/
> PostgreSQL Development, 24x7 Support, Training & Services
>

On Thu, Oct 27, 2011 at 6:55 PM, Simon Riggs <simon(at)2ndquadrant(dot)com> wrote:
> It seems cheap to add in a call to LogStandbySnapshot() after each
> call to pg_stop_backup().
>
> Does anyone think this case is worth adding code for? Seems like one
> more thing to break.

Why at that particular time?

It would maybe nice if the master could notice when it has a plausible
(non-overflowed) snapshot and log it then. But that might be more
code than the problem is worth.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On Fri, Oct 28, 2011 at 3:42 AM, Chris Redekop <chris(at)replicon(dot)com> wrote:

> On a side note I am sporadically seeing another error on hotstandby startup.
>  I'm not terribly concerned about it as it is pretty rare and it will work
> on a retry so it's not a big deal.  The error is "FATAL:  out-of-order XID
> insertion in KnownAssignedXids".  If you think it might be a bug and are
> interested in hunting it down let me know and I'll help any way I can...but
> if you're not too worried about it then neither am I :)

I'd be interested to see further details of this if you see it again,
or have access to previous logs.

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

oops....reply-to-all

---------- Forwarded message ----------
From: Chris Redekop <chris(at)replicon(dot)com>
Date: Wed, Nov 2, 2011 at 8:41 AM
Subject: Re: [HACKERS] Hot Standby startup with overflowed snapshots
To: Simon Riggs <simon(at)2ndquadrant(dot)com>

Sure, I've got quite a few logs lying around - I've attached 3 of 'em...let
me know if there are any specific things you'd like me to do or look for
next time it happens....

On Wed, Nov 2, 2011 at 2:59 AM, Simon Riggs <simon(at)2ndquadrant(dot)com> wrote:

> On Fri, Oct 28, 2011 at 3:42 AM, Chris Redekop <chris(at)replicon(dot)com> wrote:
>
> > On a side note I am sporadically seeing another error on hotstandby
> startup.
> > I'm not terribly concerned about it as it is pretty rare and it will
> work
> > on a retry so it's not a big deal. The error is "FATAL: out-of-order
> XID
> > insertion in KnownAssignedXids". If you think it might be a bug and are
> > interested in hunting it down let me know and I'll help any way I
> can...but
> > if you're not too worried about it then neither am I :)
>
> I'd be interested to see further details of this if you see it again,
> or have access to previous logs.
>
> --
> Simon Riggs http://www.2ndQuadrant.com/
> PostgreSQL Development, 24x7 Support, Training & Services
>