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

Search Discussions

  • Chris Redekop at Oct 27, 2011 at 4:26 pm
    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 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@postgresql.org)
    To make changes to your subscription:
    http://www.postgresql.org/mailpref/pgsql-hackers
  • Simon Riggs at Oct 27, 2011 at 5:28 pm

    On Thu, Oct 27, 2011 at 5:26 PM, Chris Redekop 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
  • Chris Redekop at Oct 27, 2011 at 9:37 pm
    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 wrote:
    On Thu, Oct 27, 2011 at 5:26 PM, Chris Redekop 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
  • Simon Riggs at Oct 27, 2011 at 11:00 pm

    On Thu, Oct 27, 2011 at 10:09 PM, Chris Redekop 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
  • Chris Redekop at Oct 28, 2011 at 2:50 am
    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 wrote:
    On Thu, Oct 27, 2011 at 10:09 PM, Chris Redekop 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
  • Simon Riggs at Nov 2, 2011 at 8:59 am

    On Fri, Oct 28, 2011 at 3:42 AM, Chris Redekop 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
  • Chris Redekop at Nov 2, 2011 at 2:44 pm
    oops....reply-to-all

    ---------- Forwarded message ----------
    From: Chris Redekop <chris@replicon.com>
    Date: Wed, Nov 2, 2011 at 8:41 AM
    Subject: Re: [HACKERS] Hot Standby startup with overflowed snapshots
    To: Simon Riggs <simon@2ndquadrant.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 wrote:
    On Fri, Oct 28, 2011 at 3:42 AM, Chris Redekop 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
  • Robert Haas at Oct 28, 2011 at 3:42 am

    On Thu, Oct 27, 2011 at 6:55 PM, Simon Riggs 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

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouppgsql-hackers @
categoriespostgresql
postedOct 27, '11 at 1:26p
activeNov 2, '11 at 2:44p
posts9
users3
websitepostgresql.org...
irc#postgresql

People

Translate

site design / logo © 2021 Grokbase