Обсуждение: Endless recovery

Hans-Juergen Schoenig wrote:
> Last week we have seen a problem with some horribly configured machine.
> The disk filled up (bad FSM ;) ) and once this happened the sysadmi killed the
> system (-9).
> After two days PostgreSQL has still not started up and they tried to restart it
> again and again making sure that the consistency check was started over an over
> again (thus causing more and more downtime).
>  From the admi point of view there was no way to find out whether the machine
> was actually dead or still recovering.
>
> Here is a small patch which issues a log message indicating that the recovery
> process can take ages.
> Maybe this can prevent some admis from interrupting the recovery process.

Wait, are you saying that the time was spent in the rm_cleanup phase?
That sounds unbelievable. Surely the time was spent in the redo phase, no?

> In our case, the recovery process took 3.5 days !!

That's a ridiculously long time. Was this a normal recovery, not a PITR
archive recovery? Any idea why the recovery took so long? Given the max.
checkpoint timeout of 1h, I would expect that the recovery would take a
maximum of few hours even with an extremely write-heavy workload.

--
   Heikki Linnakangas
   EnterpriseDB   http://www.enterprisedb.com

On Mon, 2008-02-11 at 09:29 +0100, Hans-Juergen Schoenig wrote:
> Last week we have seen a problem with some horribly configured
> machine.
> The disk filled up (bad FSM ;) ) and once this happened the sysadmi
> killed the system (-9).
> After two days PostgreSQL has still not started up and they tried to
> restart it again and again making sure that the consistency check was
> started over an over again (thus causing more and more downtime).
> From the admi point of view there was no way to find out whether the
> machine was actually dead or still recovering.

I'm sorry to hear about this problem.

Not sure we need a LOG message to warn people about the possible length
of recovery time. The chances of a recovery taking that much time seem
very low for normal Postgres, even with checkpoint parameters set at
their maximum values.

I note that the configuration section does not mention the likely
increase in recovery time that will result from setting those parameters
higher. That needs a patch. ISTM a serious omission that should be
treated as a bug and backpatched.

--
  Simon Riggs
  2ndQuadrant  http://www.2ndQuadrant.com

Hans-Juergen Schoenig wrote:
> this is he last info which was issued ...
>
> nothing in between ...
>
> during the rm_cleanup() nothing was logged into the logs. this is the
> last log from today dawn:
>
> [2008-02-11 03:45:16 CET ]LOG: lost parent for block 8558565
> [2008-02-11 03:45:16 CET ]LOG: index 1663/16384/16578435 needs VACUUM or
> REINDEX to finish crash recovery
> [2008-02-11 03:45:16 CET ]DETAIL: Incomplete insertion detected during
> crash replay.
> [2008-02-11 03:47:54 CET ]LOG: database system is ready
> [2008-02-11 03:47:54 CET ]LOG: transaction ID wrap limit is 1073742476,
> limited by database "blids"
>
> that's where it finished, nothing else was logged between the "redo
> done" and the last log messages

I bet you've bumped into a bug in gist redo code, the cleanup phase
shouldn't take long. It's just for completing any incomplete splits by
inserting pointers to upper-level pages, and there shouldn't be more
than a few of those active at any point in time.

It looks like there's been quite a few changes to gistlog.c that haven't
been back-patched. This one in particular might be relevant here:

> revision 1.15
> date: 2006-04-03 17:45:50 +0100;  author: tgl;  state: Exp;  lines: +15 -13;
> Fix thinko in gistRedoPageUpdateRecord: if XLR_BKP_BLOCK_1 is set, we
> don't have anything to do to the page, but we still have to adjust the
> incomplete_inserts list that we're maintaining in memory.

Teodor, what do you think?

--
   Heikki Linnakangas
   EnterpriseDB   http://www.enterprisedb.com

On Mon, 2008-02-11 at 10:44 +0100, Hans-Juergen Schoenig wrote:
> On Feb 11, 2008, at 10:26 AM, Heikki Linnakangas wrote:


> > Wait, are you saying that the time was spent in the rm_cleanup
> > phase? That sounds unbelievable. Surely the time was spent in the
> > redo phase, no?

> redo was done fast ...

...

> the DB version is 8.1.11. The entire DB is 116gb. It is more or less a
> table along with a 65 GB Gist index.

rmgrs might need to issue their own warnings, but the main recovery
system doesn't.


Slightly OT, but reading this I definitely want to split resource
managers into "essential" and "non-essential" groups, so we can come up
when essential operations are complete. I want the non-essential rmgrs
to be cancellable, plus give them the opportunity to rebuild corrupt
data structures without interfering with other aspects of the DB.

--
  Simon Riggs
  2ndQuadrant  http://www.2ndQuadrant.com

On Mon, 2008-02-11 at 11:50 +0100, Hans-Juergen Schoenig wrote:

> I have that feeling too - it could very well be some Gist issue in
> here but given what we have seen in the debugger this was not too
> obvious.
> At first glance it rather felt like a full check of the entire index.

Yeh, I'm happy for resource managers to do heavy lifting when they think
its the right thing to do (only they know), I just want to make sure
that doesn't affect anybody else. (Thinking to the future, not as a bug
fix).

--
  Simon Riggs
  2ndQuadrant  http://www.2ndQuadrant.com

"Heikki Linnakangas" <heikki@enterprisedb.com> writes:
> Hans-Juergen Schoenig wrote:
>> that's where it finished, nothing else was logged between the "redo
>> done" and the last log messages

> I bet you've bumped into a bug in gist redo code, the cleanup phase
> shouldn't take long.

That's what it smells like to me too.  Any chance that you still have
the WAL log for examination?

            regards, tom lane

Simon Riggs wrote:
> On Mon, 2008-02-11 at 09:29 +0100, Hans-Juergen Schoenig wrote:
> > Last week we have seen a problem with some horribly configured
> > machine.
> > The disk filled up (bad FSM ;) ) and once this happened the sysadmi
> > killed the system (-9).
> > After two days PostgreSQL has still not started up and they tried to
> > restart it again and again making sure that the consistency check was
> > started over an over again (thus causing more and more downtime).
> > From the admi point of view there was no way to find out whether the
> > machine was actually dead or still recovering.
>
> I'm sorry to hear about this problem.
>
> Not sure we need a LOG message to warn people about the possible length
> of recovery time. The chances of a recovery taking that much time seem
> very low for normal Postgres, even with checkpoint parameters set at
> their maximum values.
>
> I note that the configuration section does not mention the likely
> increase in recovery time that will result from setting those parameters
> higher. That needs a patch. ISTM a serious omission that should be
> treated as a bug and backpatched.

Patch attached and applied, and backpatched to 8.3.X.

--
  Bruce Momjian  <bruce@momjian.us>        http://momjian.us
  EnterpriseDB                             http://postgres.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.166
diff -c -c -r1.166 config.sgml
*** doc/src/sgml/config.sgml    16 Feb 2008 21:14:08 -0000    1.166
--- doc/src/sgml/config.sgml    5 Mar 2008 16:57:47 -0000
***************
*** 1584,1592 ****
        </indexterm>
        <listitem>
         <para>
!         Maximum distance between automatic WAL checkpoints, in log
!         file segments (each segment is normally 16 megabytes). The
!         default is three segments.
          This parameter can only be set in the <filename>postgresql.conf</>
          file or on the server command line.
         </para>
--- 1584,1593 ----
        </indexterm>
        <listitem>
         <para>
!         Maximum number of log file segments between automatic WAL
!         checkpoints (each segment is normally 16 megabytes). The default
!         is three segments.  Increasing this parameter can increase the
!         amount of time needed for crash recovery.
          This parameter can only be set in the <filename>postgresql.conf</>
          file or on the server command line.
         </para>
***************
*** 1602,1607 ****
--- 1603,1610 ----
         <para>
          Maximum time between automatic WAL checkpoints, in
          seconds. The default is five minutes (<literal>5min</>).
+         Increasing this parameter can increase the amount of time needed
+         for crash recovery.
          This parameter can only be set in the <filename>postgresql.conf</>
          file or on the server command line.
         </para>