Thread

1. Hot Standby startup with overflowed snapshots

   Simon Riggs <simon@2ndquadrant.com> — 2011-10-27T13:26:00Z

   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
   

2. Re: Hot Standby startup with overflowed snapshots

   Chris Redekop <chris@replicon.com> — 2011-10-27T16:26:24Z

   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@2ndquadrant.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@postgresql.org)
   > To make changes to your subscription:
   > http://www.postgresql.org/mailpref/pgsql-hackers
   >
   >
   

3. Re: Hot Standby startup with overflowed snapshots

   Simon Riggs <simon@2ndquadrant.com> — 2011-10-27T17:27:51Z

   On Thu, Oct 27, 2011 at 5:26 PM, Chris Redekop <chris@replicon.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
   

4. Re: Hot Standby startup with overflowed snapshots

   Chris Redekop <chris@replicon.com> — 2011-10-27T21:09:40Z

   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@2ndquadrant.com> wrote:
   
   > On Thu, Oct 27, 2011 at 5:26 PM, Chris Redekop <chris@replicon.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
   >
   

5. Re: Hot Standby startup with overflowed snapshots

   Simon Riggs <simon@2ndquadrant.com> — 2011-10-27T22:55:38Z

   On Thu, Oct 27, 2011 at 10:09 PM, Chris Redekop <chris@replicon.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
   
   

6. Re: Hot Standby startup with overflowed snapshots

   Chris Redekop <chris@replicon.com> — 2011-10-28T02:42:47Z

   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@2ndquadrant.com> wrote:
   
   > On Thu, Oct 27, 2011 at 10:09 PM, Chris Redekop <chris@replicon.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
   >
   

7. Re: Hot Standby startup with overflowed snapshots

   Robert Haas <robertmhaas@gmail.com> — 2011-10-28T03:42:20Z

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

8. Re: Hot Standby startup with overflowed snapshots

   Simon Riggs <simon@2ndquadrant.com> — 2011-11-02T08:59:23Z

   On Fri, Oct 28, 2011 at 3:42 AM, Chris Redekop <chris@replicon.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
   
   

9. Re: Hot Standby startup with overflowed snapshots

   Chris Redekop <chris@replicon.com> — 2011-11-02T14:44:17Z

   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 <simon@2ndquadrant.com> wrote:
   
   > On Fri, Oct 28, 2011 at 3:42 AM, Chris Redekop <chris@replicon.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
   >