Thread

1. clog_redo causing very long recovery time

   Joe Conway <mail@joeconway.com> — 2011-05-02T06:26:05Z

   I'm working with a client that uses Postgres on what amounts to an
   appliance.
   
   The database is therefore subject to occasional torture such as, in this
   particular case, running out of disk space while performing a million
   plus queries (of mixed varieties, many using plpgsql with exception
   handling -- more on that later), and eventually being power-cycled. Upon
   restart, clog_redo was called approx 885000 times (CLOG_ZEROPAGE) during
   recovery, which took almost 2 hours on their hardware. I should note
   that this is on Postgres 8.3.x.
   
   After studying the source, I can only see one possible way that this
   could have occurred:
   
   In varsup.c:GetNewTracsactionId(), ExtendCLOG() needs to succeed on a
   freshly zeroed clog page, and ExtendSUBTRANS() has to fail. Both of
   these calls can lead to a page being pushed out of shared buffers and to
   disk, so given a lack of disk space, sufficient clog buffers, but lack
   of subtrans buffers, this could happen. At that point the transaction id
   does not get advanced, so clog zeros the same page, extendSUBTRANS()
   fails again, rinse and repeat.
   
   I believe in the case above, subtrans buffers were exhausted due to the
   extensive use of plpgsql with exception handling.
   
   I can simulate this failure with the attached debug-clog patch which
   makes use of two pre-existing debug GUCs to selectively interject an
   ERROR in between calls to ExtendCLOG() and ExtendSUBTRANS(). If you want
   to test this yourself, apply this patch and use the function in
   test_clog.sql to generate a million or so transactions. After the first
   32K or before (based on when clog gets its first opportunity to zero a
   new page) you should start seeing messages about injected ERRORs. Let a
   few hundred thousand ERRORs go by, then kill postgres. Recovery will
   take ages, because clog_redo is calling fsync hundreds of thousands of
   times in order to zero the same page over and over.
   
   The attached fix-clogredo diff is my proposal for a fix for this.
   
   Thoughts/alternatives, etc appreciated.
   
   Thanks,
   
   Joe
   
   
   -- 
   Joe Conway
   credativ LLC: http://www.credativ.us
   Linux, PostgreSQL, and general Open Source
   Training, Service, Consulting, & 24x7 Support
   
   

2. Re: clog_redo causing very long recovery time

   Tom Lane <tgl@sss.pgh.pa.us> — 2011-05-06T03:22:43Z

   Joseph Conway <mail@joeconway.com> writes:
   > I'm working with a client that uses Postgres on what amounts to an
   > appliance.
   
   > The database is therefore subject to occasional torture such as, in this
   > particular case, running out of disk space while performing a million
   > plus queries (of mixed varieties, many using plpgsql with exception
   > handling -- more on that later), and eventually being power-cycled. Upon
   > restart, clog_redo was called approx 885000 times (CLOG_ZEROPAGE) during
   > recovery, which took almost 2 hours on their hardware. I should note
   > that this is on Postgres 8.3.x.
   
   > After studying the source, I can only see one possible way that this
   > could have occurred:
   
   > In varsup.c:GetNewTracsactionId(), ExtendCLOG() needs to succeed on a
   > freshly zeroed clog page, and ExtendSUBTRANS() has to fail. Both of
   > these calls can lead to a page being pushed out of shared buffers and to
   > disk, so given a lack of disk space, sufficient clog buffers, but lack
   > of subtrans buffers, this could happen. At that point the transaction id
   > does not get advanced, so clog zeros the same page, extendSUBTRANS()
   > fails again, rinse and repeat.
   
   > I believe in the case above, subtrans buffers were exhausted due to the
   > extensive use of plpgsql with exception handling.
   
   Hmm, interesting.  I believe that it's not really a question of buffer
   space or lack of it, but whether the OS will give us disk space when we
   try to add a page to the current pg_subtrans file.  In any case, the
   point is that a failure between ExtendCLOG and incrementing nextXid
   is bad news.
   
   > The attached fix-clogredo diff is my proposal for a fix for this.
   
   That seems pretty grotty :-(
   
   I think a more elegant fix might be to just swap the order of the 
   ExtendCLOG and ExtendSUBTRANS calls in GetNewTransactionId.  The
   reason that would help is that pg_subtrans isn't WAL-logged, so if
   we succeed doing ExtendSUBTRANS and then fail in ExtendCLOG, we
   won't have written any XLOG entry, and thus repeated failures will not
   result in repeated XLOG entries.  I seem to recall having considered
   exactly that point when the clog WAL support was first done, but the
   scenario evidently wasn't considered when subtransactions were stuck
   in :-(.
   
   It would probably also help to put in a comment admonishing people
   to not add stuff right there.  I see the SSI guys have fallen into
   the same trap.
   
   			regards, tom lane
   
   

3. Re: clog_redo causing very long recovery time

   Alvaro Herrera <alvherre@commandprompt.com> — 2011-05-06T03:29:13Z

   Excerpts from Tom Lane's message of vie may 06 00:22:43 -0300 2011:
   
   > I think a more elegant fix might be to just swap the order of the 
   > ExtendCLOG and ExtendSUBTRANS calls in GetNewTransactionId.  The
   > reason that would help is that pg_subtrans isn't WAL-logged, so if
   > we succeed doing ExtendSUBTRANS and then fail in ExtendCLOG, we
   > won't have written any XLOG entry, and thus repeated failures will not
   > result in repeated XLOG entries.  I seem to recall having considered
   > exactly that point when the clog WAL support was first done, but the
   > scenario evidently wasn't considered when subtransactions were stuck
   > in :-(.
   
   I'm pretty sure it would have never occured to me to consider such a
   scenario.
   
   -- 
   Álvaro Herrera <alvherre@commandprompt.com>
   The PostgreSQL Company - Command Prompt, Inc.
   PostgreSQL Replication, Consulting, Custom Development, 24x7 support
   
   

4. Re: clog_redo causing very long recovery time

   Joe Conway <mail@joeconway.com> — 2011-05-06T03:41:10Z

   On 05/05/2011 08:22 PM, Tom Lane wrote:
   > Joseph Conway <mail@joeconway.com> writes:
   >> The attached fix-clogredo diff is my proposal for a fix for this.
   > 
   > That seems pretty grotty :-(
   > 
   > I think a more elegant fix might be to just swap the order of the 
   > ExtendCLOG and ExtendSUBTRANS calls in GetNewTransactionId.  The
   > reason that would help is that pg_subtrans isn't WAL-logged, so if
   > we succeed doing ExtendSUBTRANS and then fail in ExtendCLOG, we
   > won't have written any XLOG entry, and thus repeated failures will not
   > result in repeated XLOG entries.  I seem to recall having considered
   > exactly that point when the clog WAL support was first done, but the
   > scenario evidently wasn't considered when subtransactions were stuck
   > in :-(.
   
   Yes, that does seem much nicer :-)
   
   > It would probably also help to put in a comment admonishing people
   > to not add stuff right there.  I see the SSI guys have fallen into
   > the same trap.
   
   Right -- I think another similar problem exists in GetNewMultiXactId
   where ExtendMultiXactOffset could succeed and write an XLOG entry and
   then  ExtendMultiXactMember could fail before advancing nextMXact. The
   problem in this case is that they both write XLOG entries, so a simple
   reversal doesn't help.
   
   Joe
   
   -- 
   Joe Conway
   credativ LLC: http://www.credativ.us
   Linux, PostgreSQL, and general Open Source
   Training, Service, Consulting, & 24x7 Support
   
   

5. Re: clog_redo causing very long recovery time

   Tom Lane <tgl@sss.pgh.pa.us> — 2011-05-06T04:00:53Z

   Joe Conway <mail@joeconway.com> writes:
   > Right -- I think another similar problem exists in GetNewMultiXactId
   > where ExtendMultiXactOffset could succeed and write an XLOG entry and
   > then  ExtendMultiXactMember could fail before advancing nextMXact. The
   > problem in this case is that they both write XLOG entries, so a simple
   > reversal doesn't help.
   
   Hmm.  Maybe we need a real fix then.  I was just sitting here
   speculating about whether we'd ever decide we need to WAL-log
   pg_subtrans --- because if we did, my solution would fail.
   
   I still think that the right fix is to avoid emitting redundant
   XLOG records in the first place, rather than hacking recovery
   to not process them.  Possibly we could modify slru.c so that
   it could be determined whether zeroing of the current page had
   already happened.  In a quick look, it looks like noting whether
   latest_page_number had already been advanced to that page might
   do the trick.
   
   			regards, tom lane
   
   

6. Re: clog_redo causing very long recovery time

   Joe Conway <joe.conway@credativ.com> — 2011-05-06T06:18:18Z

   On 05/05/2011 09:00 PM, Tom Lane wrote:
   > Joe Conway <mail@joeconway.com> writes:
   >> Right -- I think another similar problem exists in GetNewMultiXactId
   >> where ExtendMultiXactOffset could succeed and write an XLOG entry and
   >> then  ExtendMultiXactMember could fail before advancing nextMXact. The
   >> problem in this case is that they both write XLOG entries, so a simple
   >> reversal doesn't help.
   > 
   > Hmm.  Maybe we need a real fix then.  I was just sitting here
   > speculating about whether we'd ever decide we need to WAL-log
   > pg_subtrans --- because if we did, my solution would fail.
   > 
   > I still think that the right fix is to avoid emitting redundant
   > XLOG records in the first place, rather than hacking recovery
   > to not process them.  Possibly we could modify slru.c so that
   > it could be determined whether zeroing of the current page had
   > already happened.  In a quick look, it looks like noting whether
   > latest_page_number had already been advanced to that page might
   > do the trick.
   
   Thanks -- I'll test that out.
   
   Joe
   
   
   -- 
   Joseph E Conway
   President/CEO
   credativ LLC
   www.credativ.us
   
   616 Burnham Street
   El Cajon, CA 92019
   
   Office: +1 619 270 8787
   Mobile: +1 619 843 8340
   
   

7. Re: clog_redo causing very long recovery time

   Simon Riggs <simon@2ndquadrant.com> — 2011-05-09T07:22:40Z

   On Fri, May 6, 2011 at 4:22 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
   
   >> The attached fix-clogredo diff is my proposal for a fix for this.
   >
   > That seems pretty grotty :-(
   >
   > I think a more elegant fix might be to just swap the order of the
   > ExtendCLOG and ExtendSUBTRANS calls in GetNewTransactionId.  The
   > reason that would help is that pg_subtrans isn't WAL-logged, so if
   > we succeed doing ExtendSUBTRANS and then fail in ExtendCLOG, we
   > won't have written any XLOG entry, and thus repeated failures will not
   > result in repeated XLOG entries.  I seem to recall having considered
   > exactly that point when the clog WAL support was first done, but the
   > scenario evidently wasn't considered when subtransactions were stuck
   > in :-(.
   
   I agree with Tom about the need for a fix that prevents generation of
   repeated WAL records.
   
   OTOH, I also like Joe's fix in the recovery code to avoid responding
   to repeated records.
   
   Can we have both please?
   
   -- 
    Simon Riggs                   http://www.2ndQuadrant.com/
    PostgreSQL Development, 24x7 Support, Training & Services
   
   

8. Re: clog_redo causing very long recovery time

   Tom Lane <tgl@sss.pgh.pa.us> — 2011-05-09T13:39:46Z

   Simon Riggs <simon@2ndQuadrant.com> writes:
   > I agree with Tom about the need for a fix that prevents generation of
   > repeated WAL records.
   
   > OTOH, I also like Joe's fix in the recovery code to avoid responding
   > to repeated records.
   
   > Can we have both please?
   
   Why?  The patch in the recovery code is seriously ugly, and it won't
   do anything useful once we've fixed the other end.  Please notice also
   that we'd need several instances of that kluge if we want to cover all
   the SLRU-based cases.
   
   			regards, tom lane