Re: Logging checkpoints and other slowdown causes - Mailing list pgsql-patches

Here's a work-in-progress updated version of this patch. It's not
completed, but I've settled on:

- a log_checkpoints GUC variable to control whether anything is printed
or not. This is in line with log_connections, log_autovacuum etc.

- when checkpoints are logged, LOG-level is used

- the following log output:

LOG:  checkpoint starting (CHECKPOINT command)
LOG:  checkpoint complete; buffers written=3.1 MB (9.6%) write=96.8 ms
sync=32.0 ms

where "checkpoint starting" is obviously printed when checkpoint starts,
and "checkpoint complete" when the checkpoint is fully complete.

- all information on the progress of checkpoint is collected to a global
struct. A global struct sounds a bit ugly, but it avoids the ugliness of
littering all functions with multiple return values to pass back
information to the caller that's only used to print it out. This makes
it easy to add more data points. MoveOfflineLogs should probably be
changed to use that as well for the sake of consistency, instead of
returning nsegsremoved and nsegsrecycled through pointers.

- RequestCheckpoint and CreateCheckpoint was changed to take a
CheckpointReason enum as argument, instead of boolean flags. This allows
printing a different message depending on the cause of checkpoint, and
is also cleaner IMHO.

I'm posting now to allow others, and Greg Smith in particular, to review
the changes this far, and take over from here.

--
   Heikki Linnakangas
   EnterpriseDB   http://www.enterprisedb.com
Index: src/backend/access/transam/xlog.c
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/access/transam/xlog.c,v
retrieving revision 1.268
diff -c -r1.268 xlog.c
*** src/backend/access/transam/xlog.c    30 Apr 2007 21:01:52 -0000    1.268
--- src/backend/access/transam/xlog.c    20 May 2007 15:21:49 -0000
***************
*** 71,76 ****
--- 71,78 ----
  bool        XLOG_DEBUG = false;
  #endif

+ bool log_checkpoints = false;
+
  /*
   * XLOGfileslop is used in the code as the allowed "fuzz" in the number of
   * preallocated XLOG segments --- we try to have at least XLOGfiles advance
***************
*** 120,125 ****
--- 122,130 ----
  static TimestampTz recoveryStopTime;
  static bool recoveryStopAfter;

+ CheckpointProgressData checkpointProgress;
+
+
  /*
   * During normal operation, the only timeline we care about is ThisTimeLineID.
   * During recovery, however, things are more complicated.  To simplify life
***************
*** 1595,1601 ****
                          if (XLOG_DEBUG)
                              elog(LOG, "time for a checkpoint, signaling bgwriter");
  #endif
!                         RequestCheckpoint(false, true);
                      }
                  }
              }
--- 1600,1606 ----
                          if (XLOG_DEBUG)
                              elog(LOG, "time for a checkpoint, signaling bgwriter");
  #endif
!                         RequestCheckpoint(false, CHKP_SEGMENTS);
                      }
                  }
              }
***************
*** 5067,5073 ****
           * the rule that TLI only changes in shutdown checkpoints, which
           * allows some extra error checking in xlog_redo.
           */
!         CreateCheckPoint(true, true);

          /*
           * Close down recovery environment
--- 5072,5078 ----
           * the rule that TLI only changes in shutdown checkpoints, which
           * allows some extra error checking in xlog_redo.
           */
!         CreateCheckPoint(CHKP_SHUTDOWN); /* XXX startup rather than shutdown... */

          /*
           * Close down recovery environment
***************
*** 5340,5346 ****
      ereport(LOG,
              (errmsg("shutting down")));

!     CreateCheckPoint(true, true);
      ShutdownCLOG();
      ShutdownSUBTRANS();
      ShutdownMultiXact();
--- 5345,5351 ----
      ereport(LOG,
              (errmsg("shutting down")));

!     CreateCheckPoint(CHKP_SHUTDOWN);
      ShutdownCLOG();
      ShutdownSUBTRANS();
      ShutdownMultiXact();
***************
*** 5356,5362 ****
   * activity has occurred since the last one.
   */
  void
! CreateCheckPoint(bool shutdown, bool force)
  {
      CheckPoint    checkPoint;
      XLogRecPtr    recptr;
--- 5361,5367 ----
   * activity has occurred since the last one.
   */
  void
! CreateCheckPoint(CheckpointReason reason)
  {
      CheckPoint    checkPoint;
      XLogRecPtr    recptr;
***************
*** 5370,5375 ****
--- 5375,5435 ----
      int            nsegsrecycled = 0;
      TransactionId *inCommitXids;
      int            nInCommit;
+     struct timeval start_t;
+     int            elapsed_secs;
+
+     /* Log beginning of checkpoint */
+
+     gettimeofday(&start_t, NULL);
+
+     if (log_checkpoints)
+     {
+         switch(reason)
+         {
+             case CHKP_SHUTDOWN:
+                 /* ereport(LOG, (errmsg("checkpoint starting (shutdown)"))); */
+                 break;
+             case CHKP_COMMAND:
+                 ereport(LOG, (errmsg("checkpoint starting (CHECKPOINT command)")));
+                 break;
+             case CHKP_BACKUP:
+                 ereport(LOG, (errmsg("checkpoint starting (starting backup)")));
+                 break;
+             case CHKP_TIMEOUT:
+                 ereport(LOG, (errmsg("checkpoint starting (checkpoint_timeout reached)")));
+                 break;
+             case CHKP_SEGMENTS:
+                 ereport(LOG, (errmsg("checkpoint starting (checkpoint_segments reached)")));
+                 break;
+             case CHKP_CREATEDB:
+                 ereport(LOG, (errmsg("checkpoint starting (creating database)")));
+                 break;
+             case CHKP_DROPDB:
+                 ereport(LOG, (errmsg("checkpoint starting (dropping database)")));
+                 break;
+             default:
+                 elog(WARNING, "unexpected checkpoint reason %d", reason);
+                 break;
+         }
+     }
+
+     /*
+      * We will warn if (a) too soon since last checkpoint (whatever
+      * caused it) and (b) somebody has set the ckpt_time_warn flag
+      * since the last checkpoint start.  Note in particular that this
+      * implementation will not generate warnings caused by
+      * CheckPointTimeout < CheckPointWarning.
+      */
+     elapsed_secs = start_t.tv_sec - checkpointProgress.cs_start_t.tv_sec;
+     if (reason == CHKP_SEGMENTS && elapsed_secs < CheckPointWarning)
+         ereport(LOG,
+                 (errmsg("checkpoints are occurring too frequently (%d seconds apart)",
+                         elapsed_secs),
+                  errhint("Consider increasing the configuration parameter \"checkpoint_segments\".")));
+
+
+     checkpointProgress.cs_reason = reason;
+     checkpointProgress.cs_start_t = start_t;

      /*
       * Acquire CheckpointLock to ensure only one checkpoint happens at a time.
***************
*** 5384,5390 ****
       */
      START_CRIT_SECTION();

!     if (shutdown)
      {
          ControlFile->state = DB_SHUTDOWNING;
          ControlFile->time = time(NULL);
--- 5444,5450 ----
       */
      START_CRIT_SECTION();

!     if (reason == CHKP_SHUTDOWN)
      {
          ControlFile->state = DB_SHUTDOWNING;
          ControlFile->time = time(NULL);
***************
*** 5416,5422 ****
       * the end of the last checkpoint record, and its redo pointer must point
       * to itself.
       */
!     if (!shutdown && !force)
      {
          XLogRecPtr    curInsert;

--- 5476,5482 ----
       * the end of the last checkpoint record, and its redo pointer must point
       * to itself.
       */
!     if (reason == CHKP_TIMEOUT) /* XXX is the condition same as on head? */
      {
          XLogRecPtr    curInsert;

***************
*** 5479,5488 ****
       */
      LWLockRelease(WALInsertLock);

-     if (!shutdown)
-         ereport(DEBUG2,
-                 (errmsg("checkpoint starting")));
-
      /*
       * Before flushing data, we must wait for any transactions that are
       * currently in their commit critical sections.  If an xact inserted its
--- 5539,5544 ----
***************
*** 5530,5540 ****

      LWLockAcquire(OidGenLock, LW_SHARED);
      checkPoint.nextOid = ShmemVariableCache->nextOid;
!     if (!shutdown)
          checkPoint.nextOid += ShmemVariableCache->oidCount;
      LWLockRelease(OidGenLock);

!     MultiXactGetCheckptMulti(shutdown,
                               &checkPoint.nextMulti,
                               &checkPoint.nextMultiOffset);

--- 5586,5596 ----

      LWLockAcquire(OidGenLock, LW_SHARED);
      checkPoint.nextOid = ShmemVariableCache->nextOid;
!     if (reason != CHKP_SHUTDOWN)
          checkPoint.nextOid += ShmemVariableCache->oidCount;
      LWLockRelease(OidGenLock);

!     MultiXactGetCheckptMulti(reason == CHKP_SHUTDOWN,
                               &checkPoint.nextMulti,
                               &checkPoint.nextMultiOffset);

***************
*** 5561,5567 ****
      rdata.next = NULL;

      recptr = XLogInsert(RM_XLOG_ID,
!                         shutdown ? XLOG_CHECKPOINT_SHUTDOWN :
                          XLOG_CHECKPOINT_ONLINE,
                          &rdata);

--- 5617,5623 ----
      rdata.next = NULL;

      recptr = XLogInsert(RM_XLOG_ID,
!                         (reason == CHKP_SHUTDOWN) ? XLOG_CHECKPOINT_SHUTDOWN :
                          XLOG_CHECKPOINT_ONLINE,
                          &rdata);

***************
*** 5571,5577 ****
       * We now have ProcLastRecPtr = start of actual checkpoint record, recptr
       * = end of actual checkpoint record.
       */
!     if (shutdown && !XLByteEQ(checkPoint.redo, ProcLastRecPtr))
          ereport(PANIC,
                  (errmsg("concurrent transaction log activity while database system is shutting down")));

--- 5627,5633 ----
       * We now have ProcLastRecPtr = start of actual checkpoint record, recptr
       * = end of actual checkpoint record.
       */
!     if (reason == CHKP_SHUTDOWN && !XLByteEQ(checkPoint.redo, ProcLastRecPtr))
          ereport(PANIC,
                  (errmsg("concurrent transaction log activity while database system is shutting down")));

***************
*** 5585,5591 ****
       * Update the control file.
       */
      LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
!     if (shutdown)
          ControlFile->state = DB_SHUTDOWNED;
      ControlFile->prevCheckPoint = ControlFile->checkPoint;
      ControlFile->checkPoint = ProcLastRecPtr;
--- 5641,5647 ----
       * Update the control file.
       */
      LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
!     if (reason == CHKP_SHUTDOWN)
          ControlFile->state = DB_SHUTDOWNED;
      ControlFile->prevCheckPoint = ControlFile->checkPoint;
      ControlFile->checkPoint = ProcLastRecPtr;
***************
*** 5626,5634 ****
       * Make more log segments if needed.  (Do this after deleting offline log
       * segments, to avoid having peak disk space usage higher than necessary.)
       */
!     if (!shutdown)
          nsegsadded = PreallocXlogFiles(recptr);

      /*
       * Truncate pg_subtrans if possible.  We can throw away all data before
       * the oldest XMIN of any running transaction.    No future transaction will
--- 5682,5694 ----
       * Make more log segments if needed.  (Do this after deleting offline log
       * segments, to avoid having peak disk space usage higher than necessary.)
       */
!     if (reason != CHKP_SHUTDOWN)
          nsegsadded = PreallocXlogFiles(recptr);

+         ereport(DEBUG2,
+                 (errmsg("checkpoint: %d transaction log file(s) added, %d removed, %d recycled",
+                         nsegsadded, nsegsremoved, nsegsrecycled)));
+
      /*
       * Truncate pg_subtrans if possible.  We can throw away all data before
       * the oldest XMIN of any running transaction.    No future transaction will
***************
*** 5639,5650 ****
      if (!InRecovery)
          TruncateSUBTRANS(GetOldestXmin(true, false));

-     if (!shutdown)
-         ereport(DEBUG2,
-                 (errmsg("checkpoint complete; %d transaction log file(s) added, %d removed, %d recycled",
-                         nsegsadded, nsegsremoved, nsegsrecycled)));
-
      LWLockRelease(CheckpointLock);
  }

  /*
--- 5699,5725 ----
      if (!InRecovery)
          TruncateSUBTRANS(GetOldestXmin(true, false));

      LWLockRelease(CheckpointLock);
+
+     /* Checkpoint complete. All we have left is updating and printing stats */
+
+     gettimeofday(&checkpointProgress.cs_end_t, NULL);
+     if (log_checkpoints)
+     {
+         long write_usecs;
+         long sync_usecs;
+
+         write_usecs = 1000000 * (long) (checkpointProgress.cs_sync_t.tv_sec - checkpointProgress.cs_start_t.tv_sec) +
+         (long) (checkpointProgress.cs_sync_t.tv_usec - checkpointProgress.cs_start_t.tv_usec);
+         sync_usecs = 1000000 * (long) (checkpointProgress.cs_end_t.tv_sec - checkpointProgress.cs_sync_t.tv_sec) +
+         (long) (checkpointProgress.cs_end_t.tv_usec - checkpointProgress.cs_sync_t.tv_usec);
+
+         ereport(LOG,(errmsg(
+             "checkpoint complete; buffers written=%.1f MB (%.1f%%) write=%.1f ms sync=%.1f ms",
+             (float) (BLCKSZ * checkpointProgress.cs_buffers_written) / (1024*1024),
+             (float) 100 * checkpointProgress.cs_buffers_written / NBuffers,
+         (float) write_usecs / 1000, (float) sync_usecs / 1000)));
+     }
  }

  /*
Index: src/backend/bootstrap/bootstrap.c
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/bootstrap/bootstrap.c,v
retrieving revision 1.233
diff -c -r1.233 bootstrap.c
*** src/backend/bootstrap/bootstrap.c    7 Mar 2007 13:35:02 -0000    1.233
--- src/backend/bootstrap/bootstrap.c    20 May 2007 10:03:27 -0000
***************
*** 489,495 ****

      /* Perform a checkpoint to ensure everything's down to disk */
      SetProcessingMode(NormalProcessing);
!     CreateCheckPoint(true, true);

      /* Clean up and exit */
      cleanup();
--- 489,495 ----

      /* Perform a checkpoint to ensure everything's down to disk */
      SetProcessingMode(NormalProcessing);
!     CreateCheckPoint(CHKP_SHUTDOWN);

      /* Clean up and exit */
      cleanup();
Index: src/backend/commands/dbcommands.c
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/commands/dbcommands.c,v
retrieving revision 1.194
diff -c -r1.194 dbcommands.c
*** src/backend/commands/dbcommands.c    12 Apr 2007 15:04:35 -0000    1.194
--- src/backend/commands/dbcommands.c    20 May 2007 10:04:27 -0000
***************
*** 503,509 ****
           * Perhaps if we ever implement CREATE DATABASE in a less cheesy way,
           * we can avoid this.
           */
!         RequestCheckpoint(true, false);

          /*
           * Close pg_database, but keep lock till commit (this is important to
--- 503,509 ----
           * Perhaps if we ever implement CREATE DATABASE in a less cheesy way,
           * we can avoid this.
           */
!         RequestCheckpoint(true, CHKP_CREATEDB);

          /*
           * Close pg_database, but keep lock till commit (this is important to
***************
*** 656,662 ****
       * open files, which would cause rmdir() to fail.
       */
  #ifdef WIN32
!     RequestCheckpoint(true, false);
  #endif

      /*
--- 656,662 ----
       * open files, which would cause rmdir() to fail.
       */
  #ifdef WIN32
!     RequestCheckpoint(true, CHKP_DROPDB);
  #endif

      /*
Index: src/backend/postmaster/bgwriter.c
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/postmaster/bgwriter.c,v
retrieving revision 1.37
diff -c -r1.37 bgwriter.c
*** src/backend/postmaster/bgwriter.c    30 Mar 2007 18:34:55 -0000    1.37
--- src/backend/postmaster/bgwriter.c    20 May 2007 15:31:30 -0000
***************
*** 116,122 ****
      sig_atomic_t ckpt_done;        /* advances when checkpoint done */
      sig_atomic_t ckpt_failed;    /* advances when checkpoint fails */

!     sig_atomic_t ckpt_time_warn;    /* warn if too soon since last ckpt? */

      int            num_requests;    /* current # of requests */
      int            max_requests;    /* allocated array size */
--- 116,122 ----
      sig_atomic_t ckpt_done;        /* advances when checkpoint done */
      sig_atomic_t ckpt_failed;    /* advances when checkpoint fails */

!     sig_atomic_t ckpt_reason;    /* XXX */

      int            num_requests;    /* current # of requests */
      int            max_requests;    /* allocated array size */
***************
*** 340,349 ****
      for (;;)
      {
          bool        do_checkpoint = false;
!         bool        force_checkpoint = false;
          time_t        now;
          int            elapsed_secs;
          long        udelay;

          /*
           * Emergency bailout if postmaster has died.  This is to avoid the
--- 340,350 ----
      for (;;)
      {
          bool        do_checkpoint = false;
!         CheckpointReason reason = 0; /* init to keep compiler happy */
          time_t        now;
          int            elapsed_secs;
          long        udelay;
+

          /*
           * Emergency bailout if postmaster has died.  This is to avoid the
***************
*** 366,372 ****
          {
              checkpoint_requested = false;
              do_checkpoint = true;
!             force_checkpoint = true;
              BgWriterStats.m_requested_checkpoints++;
          }
          if (shutdown_requested)
--- 367,373 ----
          {
              checkpoint_requested = false;
              do_checkpoint = true;
!             reason = BgWriterShmem->ckpt_reason;
              BgWriterStats.m_requested_checkpoints++;
          }
          if (shutdown_requested)
***************
*** 389,399 ****
           */
          now = time(NULL);
          elapsed_secs = now - last_checkpoint_time;
!         if (elapsed_secs >= CheckPointTimeout)
          {
!             do_checkpoint = true;
!             if (!force_checkpoint)
                  BgWriterStats.m_timed_checkpoints++;
          }

          /*
--- 390,404 ----
           */
          now = time(NULL);
          elapsed_secs = now - last_checkpoint_time;
!         if (!do_checkpoint)
          {
!             elapsed_secs = now - last_checkpoint_time;
!             if (elapsed_secs >= CheckPointTimeout)
!             {
!                 do_checkpoint = true;
!                 reason = CHKP_TIMEOUT;
                  BgWriterStats.m_timed_checkpoints++;
+             }
          }

          /*
***************
*** 404,421 ****
          {
              /*
               * We will warn if (a) too soon since last checkpoint (whatever
!              * caused it) and (b) somebody has set the ckpt_time_warn flag
!              * since the last checkpoint start.  Note in particular that this
               * implementation will not generate warnings caused by
               * CheckPointTimeout < CheckPointWarning.
               */
!             if (BgWriterShmem->ckpt_time_warn &&
!                 elapsed_secs < CheckPointWarning)
                  ereport(LOG,
                          (errmsg("checkpoints are occurring too frequently (%d seconds apart)",
                                  elapsed_secs),
                           errhint("Consider increasing the configuration parameter \"checkpoint_segments\".")));
-             BgWriterShmem->ckpt_time_warn = false;

              /*
               * Indicate checkpoint start to any waiting backends.
--- 409,424 ----
          {
              /*
               * We will warn if (a) too soon since last checkpoint (whatever
!              * caused it) and (b) checkpoint was initiated by filling WAL
!              * segments.  Note in particular that this
               * implementation will not generate warnings caused by
               * CheckPointTimeout < CheckPointWarning.
               */
!             if (reason == CHKP_SEGMENTS && elapsed_secs < CheckPointWarning)
                  ereport(LOG,
                          (errmsg("checkpoints are occurring too frequently (%d seconds apart)",
                                  elapsed_secs),
                           errhint("Consider increasing the configuration parameter \"checkpoint_segments\".")));

              /*
               * Indicate checkpoint start to any waiting backends.
***************
*** 423,429 ****
              ckpt_active = true;
              BgWriterShmem->ckpt_started++;

!             CreateCheckPoint(false, force_checkpoint);

              /*
               * After any checkpoint, close all smgr files.    This is so we
--- 426,432 ----
              ckpt_active = true;
              BgWriterShmem->ckpt_started++;

!             CreateCheckPoint(reason);

              /*
               * After any checkpoint, close all smgr files.    This is so we
***************
*** 637,648 ****
   * before returning; otherwise, just signal the request and return
   * immediately.
   *
!  * If warnontime is true, and it's "too soon" since the last checkpoint,
   * the bgwriter will log a warning.  This should be true only for checkpoints
   * caused due to xlog filling, else the warning will be misleading.
   */
  void
! RequestCheckpoint(bool waitforit, bool warnontime)
  {
      /* use volatile pointer to prevent code rearrangement */
      volatile BgWriterShmemStruct *bgs = BgWriterShmem;
--- 640,651 ----
   * before returning; otherwise, just signal the request and return
   * immediately.
   *
!  * XXX If warnontime is true, and it's "too soon" since the last checkpoint,
   * the bgwriter will log a warning.  This should be true only for checkpoints
   * caused due to xlog filling, else the warning will be misleading.
   */
  void
! RequestCheckpoint(bool waitforit, CheckpointReason reason)
  {
      /* use volatile pointer to prevent code rearrangement */
      volatile BgWriterShmemStruct *bgs = BgWriterShmem;
***************
*** 654,660 ****
       */
      if (!IsPostmasterEnvironment)
      {
!         CreateCheckPoint(false, true);

          /*
           * After any checkpoint, close all smgr files.    This is so we won't
--- 657,663 ----
       */
      if (!IsPostmasterEnvironment)
      {
!         CreateCheckPoint(reason);

          /*
           * After any checkpoint, close all smgr files.    This is so we won't
***************
*** 666,673 ****
      }

      /* Set warning request flag if appropriate */
!     if (warnontime)
!         bgs->ckpt_time_warn = true;

      /*
       * Send signal to request checkpoint.  When waitforit is false, we
--- 669,675 ----
      }

      /* Set warning request flag if appropriate */
!     bgs->ckpt_reason = reason;

      /*
       * Send signal to request checkpoint.  When waitforit is false, we
Index: src/backend/storage/buffer/bufmgr.c
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/storage/buffer/bufmgr.c,v
retrieving revision 1.218
diff -c -r1.218 bufmgr.c
*** src/backend/storage/buffer/bufmgr.c    2 May 2007 23:34:48 -0000    1.218
--- src/backend/storage/buffer/bufmgr.c    20 May 2007 16:09:02 -0000
***************
*** 43,48 ****
--- 43,49 ----
  #include "postgres.h"

  #include <sys/file.h>
+ #include <sys/time.h>
  #include <unistd.h>

  #include "miscadmin.h"
***************
*** 1006,1011 ****
--- 1007,1013 ----
          if (SyncOneBuffer(buf_id, false))
          {
              BgWriterStats.m_buf_written_checkpoints++;
+             checkpointProgress.cs_buffers_written++;

              /*
               * If in bgwriter, absorb pending fsync requests after each
***************
*** 1323,1330 ****
--- 1325,1339 ----
  void
  FlushBufferPool(void)
  {
+     checkpointProgress.cs_buffers_written = 0;
+
      BufferSync();
+
+     gettimeofday(&checkpointProgress.cs_write_t, NULL);
+
      smgrsync();
+
+     gettimeofday(&checkpointProgress.cs_sync_t, NULL);
  }


Index: src/backend/tcop/utility.c
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/tcop/utility.c,v
retrieving revision 1.279
diff -c -r1.279 utility.c
*** src/backend/tcop/utility.c    27 Apr 2007 22:05:49 -0000    1.279
--- src/backend/tcop/utility.c    20 May 2007 10:22:16 -0000
***************
*** 1089,1095 ****
                  ereport(ERROR,
                          (errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
                           errmsg("must be superuser to do CHECKPOINT")));
!             RequestCheckpoint(true, false);
              break;

          case T_ReindexStmt:
--- 1089,1095 ----
                  ereport(ERROR,
                          (errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
                           errmsg("must be superuser to do CHECKPOINT")));
!             RequestCheckpoint(true, CHKP_COMMAND);
              break;

          case T_ReindexStmt:
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.391
diff -c -r1.391 guc.c
*** src/backend/utils/misc/guc.c    8 May 2007 16:33:51 -0000    1.391
--- src/backend/utils/misc/guc.c    20 May 2007 10:11:45 -0000
***************
*** 104,109 ****
--- 104,110 ----
  extern int    CommitSiblings;
  extern char *default_tablespace;
  extern bool fullPageWrites;
+ extern bool log_checkpoints;

  #ifdef TRACE_SORT
  extern bool trace_sort;
***************
*** 596,601 ****
--- 597,610 ----
          false, NULL, NULL
      },
      {
+         {"log_checkpoints", PGC_BACKEND, LOGGING_WHAT,
+             gettext_noop("Logs beginning and end of checkpoints, and some stats XXX."),
+             NULL
+         },
+         &log_checkpoints,
+         false, NULL, NULL
+     },
+     {
          {"debug_assertions", PGC_USERSET, DEVELOPER_OPTIONS,
              gettext_noop("Turns on various assertion checks."),
              gettext_noop("This is a debugging aid."),
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.215
diff -c -r1.215 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample    18 Apr 2007 16:44:18 -0000    1.215
--- src/backend/utils/misc/postgresql.conf.sample    20 May 2007 10:14:36 -0000
***************
*** 318,323 ****
--- 318,324 ----
  #debug_print_rewritten = off
  #debug_print_plan = off
  #debug_pretty_print = off
+ #log_checkpoints = off # XXX: Should this be under the checkpoints section?
  #log_connections = off
  #log_disconnections = off
  #log_duration = off
Index: src/include/access/xlog.h
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/include/access/xlog.h,v
retrieving revision 1.76
diff -c -r1.76 xlog.h
*** src/include/access/xlog.h    5 Jan 2007 22:19:51 -0000    1.76
--- src/include/access/xlog.h    20 May 2007 15:10:43 -0000
***************
*** 128,133 ****
--- 128,164 ----
      struct XLogRecData *next;    /* next struct in chain, or NULL */
  } XLogRecData;

+ /* specifying CHKP_SHUTDOWN modifies behavior. The other reasons
+  * are distinct for informational purposes */
+ typedef enum CheckpointReason
+ {
+     CHKP_SHUTDOWN = 1,
+     CHKP_COMMAND,
+     CHKP_BACKUP,
+     CHKP_TIMEOUT,
+     CHKP_SEGMENTS,
+     CHKP_CREATEDB,
+     CHKP_DROPDB
+ } CheckpointReason;
+
+ /* CheckpointProgress is used to collect information about the progress
+  * of checkpoint. When there's no checkpoint in progress, the fields store
+  * the details of the last finished checkpoint.
+  *
+  * The fields are in the order they're filled in during a checkpoint.
+  */
+ typedef struct CheckpointProgressData
+ {
+     CheckpointReason cs_reason;
+     struct timeval    cs_start_t;
+     int                cs_buffers_written;
+     struct timeval    cs_write_t;
+     struct timeval    cs_sync_t;
+     struct timeval    cs_end_t;
+ } CheckpointProgressData;
+
+ extern CheckpointProgressData checkpointProgress;
+
  extern TimeLineID ThisTimeLineID;        /* current TLI */
  extern bool InRecovery;
  extern XLogRecPtr MyLastRecPtr;
***************
*** 162,168 ****
  extern void StartupXLOG(void);
  extern void ShutdownXLOG(int code, Datum arg);
  extern void InitXLOGAccess(void);
! extern void CreateCheckPoint(bool shutdown, bool force);
  extern void XLogPutNextOid(Oid nextOid);
  extern XLogRecPtr GetRedoRecPtr(void);
  extern void GetNextXidAndEpoch(TransactionId *xid, uint32 *epoch);
--- 193,199 ----
  extern void StartupXLOG(void);
  extern void ShutdownXLOG(int code, Datum arg);
  extern void InitXLOGAccess(void);
! extern void CreateCheckPoint(CheckpointReason reason);
  extern void XLogPutNextOid(Oid nextOid);
  extern XLogRecPtr GetRedoRecPtr(void);
  extern void GetNextXidAndEpoch(TransactionId *xid, uint32 *epoch);
Index: src/include/postmaster/bgwriter.h
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/include/postmaster/bgwriter.h,v
retrieving revision 1.9
diff -c -r1.9 bgwriter.h
*** src/include/postmaster/bgwriter.h    5 Jan 2007 22:19:57 -0000    1.9
--- src/include/postmaster/bgwriter.h    20 May 2007 10:05:03 -0000
***************
*** 12,17 ****
--- 12,18 ----
  #ifndef _BGWRITER_H
  #define _BGWRITER_H

+ #include "access/xlog.h"
  #include "storage/block.h"
  #include "storage/relfilenode.h"

***************
*** 23,29 ****

  extern void BackgroundWriterMain(void);

! extern void RequestCheckpoint(bool waitforit, bool warnontime);

  extern bool ForwardFsyncRequest(RelFileNode rnode, BlockNumber segno);
  extern void AbsorbFsyncRequests(void);
--- 24,30 ----

  extern void BackgroundWriterMain(void);

! extern void RequestCheckpoint(bool waitforit, CheckpointReason reason);

  extern bool ForwardFsyncRequest(RelFileNode rnode, BlockNumber segno);
  extern void AbsorbFsyncRequests(void);