Improve logging of checkpoints. Patch by Greg Smith, worked over
authorTom Lane <tgl@sss.pgh.pa.us>
Sat, 30 Jun 2007 19:12:02 +0000 (19:12 +0000)
committerTom Lane <tgl@sss.pgh.pa.us>
Sat, 30 Jun 2007 19:12:02 +0000 (19:12 +0000)
by Heikki and a little bit by me.

doc/src/sgml/config.sgml
src/backend/access/transam/xlog.c
src/backend/postmaster/bgwriter.c
src/backend/storage/buffer/bufmgr.c
src/backend/utils/misc/guc.c
src/backend/utils/misc/postgresql.conf.sample
src/include/access/xlog.h

index c7d2d395c7a8a531985ad117d4c9bdaa948797f6..73dcd0be6bd28412ed08afa1ec8733d52747c776 100644 (file)
@@ -1,4 +1,4 @@
-<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.129 2007/06/28 00:02:37 tgl Exp $ -->
+<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.130 2007/06/30 19:12:01 tgl Exp $ -->
 
 <chapter Id="runtime-config">
   <title>Server Configuration</title>
@@ -2660,6 +2660,23 @@ SELECT * FROM parent WHERE key = 2400;
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-log-checkpoints" xreflabel="log_checkpoints">
+      <term><varname>log_checkpoints</varname> (<type>boolean</type>)</term>
+      <indexterm>
+       <primary><varname>log_checkpoints</> configuration parameter</primary>
+      </indexterm>
+      <listitem>
+       <para>
+        Causes checkpoints to be logged in the server log. Some
+        statistics about each checkpoint are included in the log messages,
+        including the number of buffers written and the time spent writing
+        them.
+        This parameter can only be set in the <filename>postgresql.conf</>
+        file or on the server command line. The default is off.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-log-connections" xreflabel="log_connections">
       <term><varname>log_connections</varname> (<type>boolean</type>)</term>
       <indexterm>
@@ -2667,15 +2684,20 @@ SELECT * FROM parent WHERE key = 2400;
       </indexterm>
       <listitem>
        <para>
-        This outputs a line to the server log detailing each successful
-        connection. This is off by default, although it is probably very
-        useful.  Some client programs, like <application>psql</>, attempt 
-        to connect twice while determining if a password is required, so 
-        duplicate <quote>connection received</> messages do not
-        necessarily indicate a problem.
+        Causes each attempted connection to the server to be logged,
+        as well as successful completion of client authentication.
         This parameter can only be set in the <filename>postgresql.conf</>
-        file or on the server command line.
+        file or on the server command line.  The default is off.
        </para>
+
+       <note>
+        <para>
+         Some client programs, like <application>psql</>, attempt 
+         to connect twice while determining if a password is required, so 
+         duplicate <quote>connection received</> messages do not
+         necessarily indicate a problem.
+        </para>
+       </note>
       </listitem>
      </varlistentry>
 
@@ -2729,6 +2751,23 @@ SELECT * FROM parent WHERE key = 2400;
        </note>
       </listitem>
      </varlistentry>
+
+     <varlistentry id="guc-log-hostname" xreflabel="log_hostname">
+      <term><varname>log_hostname</varname> (<type>boolean</type>)</term>
+      <indexterm>
+       <primary><varname>log_hostname</> configuration parameter</primary>
+      </indexterm>
+      <listitem>
+       <para>
+        By default, connection log messages only show the IP address of the
+        connecting host. Turning on this parameter causes logging of the
+        host name as well.  Note that depending on your host name resolution
+        setup this might impose a non-negligible performance penalty.
+        This parameter can only be set in the <filename>postgresql.conf</>
+        file or on the server command line.
+       </para>
+      </listitem>
+     </varlistentry>
      
      <varlistentry id="guc-log-line-prefix" xreflabel="log_line_prefix">
       <term><varname>log_line_prefix</varname> (<type>string</type>)</term>
@@ -2860,6 +2899,21 @@ SELECT * FROM parent WHERE key = 2400;
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-log-lock-waits" xreflabel="log_lock_waits">
+      <term><varname>log_lock_waits</varname> (<type>boolean</type>)</term>
+      <indexterm>
+       <primary><varname>log_lock_waits</> configuration parameter</primary>
+      </indexterm>
+      <listitem>
+       <para>
+        Controls whether a log message is produced when a session waits
+        longer than <xref linkend="guc-deadlock-timeout"> to acquire a
+        lock.  This is useful in determining if lock waits are causing
+        poor performance.  The default is <literal>off</>.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-log-statement" xreflabel="log_statement">
       <term><varname>log_statement</varname> (<type>string</type>)</term>
       <indexterm>
@@ -2904,38 +2958,6 @@ SELECT * FROM parent WHERE key = 2400;
       </listitem>
      </varlistentry>
 
-     <varlistentry id="guc-log-hostname" xreflabel="log_hostname">
-      <term><varname>log_hostname</varname> (<type>boolean</type>)</term>
-      <indexterm>
-       <primary><varname>log_hostname</> configuration parameter</primary>
-      </indexterm>
-      <listitem>
-       <para>
-        By default, connection log messages only show the IP address of the
-        connecting host. Turning on this parameter causes logging of the
-        host name as well.  Note that depending on your host name resolution
-        setup this might impose a non-negligible performance penalty.
-        This parameter can only be set in the <filename>postgresql.conf</>
-        file or on the server command line.
-       </para>
-      </listitem>
-     </varlistentry>
-
-     <varlistentry id="guc-log-lock-waits" xreflabel="log_lock_waits">
-      <term><varname>log_lock_waits</varname> (<type>boolean</type>)</term>
-      <indexterm>
-       <primary><varname>log_lock_waits</> configuration parameter</primary>
-      </indexterm>
-      <listitem>
-       <para>
-        Controls whether a log message is produced when a session waits
-        longer than <xref linkend="guc-deadlock-timeout"> to acquire a
-        lock.  This is useful in determining if lock waits are causing
-        poor performance.  The default is <literal>off</>.
-       </para>
-      </listitem>
-     </varlistentry>
-
      <varlistentry id="guc-log-temp-files" xreflabel="log_temp_files">
       <term><varname>log_temp_files</varname> (<type>integer</type>)</term>
       <indexterm>
@@ -2944,11 +2966,12 @@ SELECT * FROM parent WHERE key = 2400;
       <listitem>
        <para>
         Controls whether temporary files are logged when deleted.
+        Temporary files can be
+        created for sorts, hashes, and temporary query results.
         A value of zero logs all temporary files, and positive
         values log only files whose size is equal or greater than
-        the specified number of kilobytes.  Temporary files can be
-        created for sorts, hashes, and temporary results.  The
-        default is <literal>-1</> (off).
+        the specified number of kilobytes.  The
+        default is <literal>-1</>, which disables this logging.
        </para>
       </listitem>
      </varlistentry>
index 7e45beb41ee37c8ce2accdd15084d105b5e73d63..15c9f310a63a57611f983d1b25319b9b9c5eaf2f 100644 (file)
@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1996-2007, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/backend/access/transam/xlog.c,v 1.273 2007/06/28 00:02:37 tgl Exp $
+ * $PostgreSQL: pgsql/src/backend/access/transam/xlog.c,v 1.274 2007/06/30 19:12:01 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -66,6 +66,7 @@ char     *XLogArchiveCommand = NULL;
 char      *XLOG_sync_method = NULL;
 const char XLOG_sync_method_default[] = DEFAULT_SYNC_METHOD_STR;
 bool       fullPageWrites = true;
+bool       log_checkpoints = false;
 
 #ifdef WAL_DEBUG
 bool       XLOG_DEBUG = false;
@@ -92,6 +93,13 @@ static int   open_sync_bit = DEFAULT_SYNC_FLAGBIT;
 #define XLOG_SYNC_BIT  (enableFsync ? open_sync_bit : 0)
 
 
+/*
+ * Statistics for current checkpoint are collected in this global struct.
+ * Because only the background writer or a stand-alone backend can perform
+ * checkpoints, this will be unused in normal backends.
+ */
+CheckpointStatsData CheckpointStats;
+
 /*
  * ThisTimeLineID will be same in all backends --- it identifies current
  * WAL timeline for the database system.
@@ -414,9 +422,8 @@ static int  XLogFileRead(uint32 log, uint32 seg, int emode);
 static void XLogFileClose(void);
 static bool RestoreArchivedFile(char *path, const char *xlogfname,
                    const char *recovername, off_t expectedSize);
-static int PreallocXlogFiles(XLogRecPtr endptr);
-static void RemoveOldXlogFiles(uint32 log, uint32 seg, XLogRecPtr endptr,
-               int *nsegsremoved, int *nsegsrecycled);
+static void PreallocXlogFiles(XLogRecPtr endptr);
+static void RemoveOldXlogFiles(uint32 log, uint32 seg, XLogRecPtr endptr);
 static void CleanupBackupHistory(void);
 static XLogRecord *ReadRecord(XLogRecPtr *RecPtr, int emode);
 static bool ValidXLOGHeader(XLogPageHeader hdr, int emode);
@@ -1578,10 +1585,10 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible, bool xlog_switch)
                Write->lastSegSwitchTime = time(NULL);
 
                /*
-                * Signal bgwriter to start a checkpoint if it's been too long
-                * since the last one.  (We look at local copy of RedoRecPtr
-                * which might be a little out of date, but should be close
-                * enough for this purpose.)
+                * Signal bgwriter to start a checkpoint if we've consumed too
+                * much xlog since the last one.  (We look at local copy of
+                * RedoRecPtr which might be a little out of date, but should
+                * be close enough for this purpose.)
                 *
                 * A straight computation of segment number could overflow 32
                 * bits.  Rather than assuming we have working 64-bit
@@ -1603,13 +1610,7 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible, bool xlog_switch)
                    new_highbits = openLogId / XLogSegSize;
                    if (new_highbits != old_highbits ||
                        new_segno >= old_segno + (uint32) (CheckPointSegments-1))
-                   {
-#ifdef WAL_DEBUG
-                       if (XLOG_DEBUG)
-                           elog(LOG, "time for a checkpoint, signaling bgwriter");
-#endif
-                       RequestCheckpoint(CHECKPOINT_WARNONTIME);
-                   }
+                       RequestCheckpoint(CHECKPOINT_CAUSE_XLOG);
                }
            }
        }
@@ -1855,7 +1856,7 @@ XLogFileInit(uint32 log, uint32 seg,
 {
    char        path[MAXPGPATH];
    char        tmppath[MAXPGPATH];
-   char        zbuffer[XLOG_BLCKSZ];
+   char       *zbuffer;
    uint32      installed_log;
    uint32      installed_seg;
    int         max_advance;
@@ -1889,6 +1890,8 @@ XLogFileInit(uint32 log, uint32 seg,
     * pre-creating an extra log segment.  That seems OK, and better than
     * holding the lock throughout this lengthy process.
     */
+   elog(DEBUG2, "creating and filling new WAL file");
+
    snprintf(tmppath, MAXPGPATH, XLOGDIR "/xlogtemp.%d", (int) getpid());
 
    unlink(tmppath);
@@ -1909,12 +1912,16 @@ XLogFileInit(uint32 log, uint32 seg,
     * fsync below) that all the indirect blocks are down on disk.  Therefore,
     * fdatasync(2) or O_DSYNC will be sufficient to sync future writes to the
     * log file.
+    *
+    * Note: palloc zbuffer, instead of just using a local char array, to
+    * ensure it is reasonably well-aligned; this may save a few cycles
+    * transferring data to the kernel.
     */
-   MemSet(zbuffer, 0, sizeof(zbuffer));
-   for (nbytes = 0; nbytes < XLogSegSize; nbytes += sizeof(zbuffer))
+   zbuffer = (char *) palloc0(XLOG_BLCKSZ);
+   for (nbytes = 0; nbytes < XLogSegSize; nbytes += XLOG_BLCKSZ)
    {
        errno = 0;
-       if ((int) write(fd, zbuffer, sizeof(zbuffer)) != (int) sizeof(zbuffer))
+       if ((int) write(fd, zbuffer, XLOG_BLCKSZ) != (int) XLOG_BLCKSZ)
        {
            int         save_errno = errno;
 
@@ -1930,6 +1937,7 @@ XLogFileInit(uint32 log, uint32 seg,
                     errmsg("could not write to file \"%s\": %m", tmppath)));
        }
    }
+   pfree(zbuffer);
 
    if (pg_fsync(fd) != 0)
        ereport(ERROR,
@@ -1960,6 +1968,8 @@ XLogFileInit(uint32 log, uint32 seg,
        unlink(tmppath);
    }
 
+   elog(DEBUG2, "done creating and filling new WAL file");
+
    /* Set flag to tell caller there was no existent file */
    *use_existent = false;
 
@@ -2525,10 +2535,9 @@ RestoreArchivedFile(char *path, const char *xlogfname,
  * recycled log segments, but the startup transient is likely to include
  * a lot of segment creations by foreground processes, which is not so good.
  */
-static int
+static void
 PreallocXlogFiles(XLogRecPtr endptr)
 {
-   int         nsegsadded = 0;
    uint32      _logId;
    uint32      _logSeg;
    int         lf;
@@ -2543,9 +2552,8 @@ PreallocXlogFiles(XLogRecPtr endptr)
        lf = XLogFileInit(_logId, _logSeg, &use_existent, true);
        close(lf);
        if (!use_existent)
-           nsegsadded++;
+           CheckpointStats.ckpt_segs_added++;
    }
-   return nsegsadded;
 }
 
 /*
@@ -2555,8 +2563,7 @@ PreallocXlogFiles(XLogRecPtr endptr)
  * whether we want to recycle rather than delete no-longer-wanted log files.
  */
 static void
-RemoveOldXlogFiles(uint32 log, uint32 seg, XLogRecPtr endptr,
-                  int *nsegsremoved, int *nsegsrecycled)
+RemoveOldXlogFiles(uint32 log, uint32 seg, XLogRecPtr endptr)
 {
    uint32      endlogId;
    uint32      endlogSeg;
@@ -2566,9 +2573,6 @@ RemoveOldXlogFiles(uint32 log, uint32 seg, XLogRecPtr endptr,
    char        lastoff[MAXFNAMELEN];
    char        path[MAXPGPATH];
 
-   *nsegsremoved = 0;
-   *nsegsrecycled = 0;
-
    /*
     * Initialize info about where to try to recycle to.  We allow recycling
     * segments up to XLOGfileslop segments beyond the current XLOG location.
@@ -2617,7 +2621,7 @@ RemoveOldXlogFiles(uint32 log, uint32 seg, XLogRecPtr endptr,
                    ereport(DEBUG2,
                            (errmsg("recycled transaction log file \"%s\"",
                                    xlde->d_name)));
-                   (*nsegsrecycled)++;
+                   CheckpointStats.ckpt_segs_recycled++;
                    /* Needn't recheck that slot on future iterations */
                    if (max_advance > 0)
                    {
@@ -2632,7 +2636,7 @@ RemoveOldXlogFiles(uint32 log, uint32 seg, XLogRecPtr endptr,
                            (errmsg("removing transaction log file \"%s\"",
                                    xlde->d_name)));
                    unlink(path);
-                   (*nsegsremoved)++;
+                   CheckpointStats.ckpt_segs_removed++;
                }
 
                XLogArchiveCleanup(xlde->d_name);
@@ -5127,7 +5131,7 @@ StartupXLOG(void)
    /*
     * Preallocate additional log files, if wanted.
     */
-   (void) PreallocXlogFiles(EndOfLog);
+   PreallocXlogFiles(EndOfLog);
 
    /*
     * Okay, we're officially UP.
@@ -5421,6 +5425,57 @@ ShutdownXLOG(int code, Datum arg)
            (errmsg("database system is shut down")));
 }
 
+/* 
+ * Log start of a checkpoint.
+ */
+static void
+LogCheckpointStart(int flags)
+{
+   elog(LOG, "checkpoint starting:%s%s%s%s%s%s",
+        (flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "",
+        (flags & CHECKPOINT_IMMEDIATE) ? " immediate" : "",
+        (flags & CHECKPOINT_FORCE) ? " force" : "",
+        (flags & CHECKPOINT_WAIT) ? " wait" : "",
+        (flags & CHECKPOINT_CAUSE_XLOG) ? " xlog" : "",
+        (flags & CHECKPOINT_CAUSE_TIME) ? " time" : "");
+}
+
+/* 
+ * Log end of a checkpoint.
+ */
+static void
+LogCheckpointEnd(void)
+{
+   long    write_secs, sync_secs, total_secs;
+   int     write_usecs, sync_usecs, total_usecs;
+
+   CheckpointStats.ckpt_end_t = GetCurrentTimestamp();
+
+   TimestampDifference(CheckpointStats.ckpt_start_t,
+                       CheckpointStats.ckpt_end_t,
+                       &total_secs, &total_usecs);
+
+   TimestampDifference(CheckpointStats.ckpt_write_t,
+                       CheckpointStats.ckpt_sync_t,
+                       &write_secs, &write_usecs);
+
+   TimestampDifference(CheckpointStats.ckpt_sync_t,
+                       CheckpointStats.ckpt_sync_end_t,
+                       &sync_secs, &sync_usecs);
+
+   elog(LOG, "checkpoint complete: wrote %d buffers (%.1f%%); "
+        "%d transaction log file(s) added, %d removed, %d recycled; "
+        "write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s",
+        CheckpointStats.ckpt_bufs_written,
+        (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+        CheckpointStats.ckpt_segs_added,
+        CheckpointStats.ckpt_segs_removed,
+        CheckpointStats.ckpt_segs_recycled,
+        write_secs, write_usecs/1000,
+        sync_secs, sync_usecs/1000,
+        total_secs, total_usecs/1000);
+}
+
 /*
  * Perform a checkpoint --- either during shutdown, or on-the-fly
  *
@@ -5431,7 +5486,7 @@ ShutdownXLOG(int code, Datum arg)
  * CHECKPOINT_FORCE: force a checkpoint even if no XLOG activity has occured
  *     since the last one (implied by CHECKPOINT_IS_SHUTDOWN).
  *
- * Note: flags might contain other bits of interest to RequestCheckpoint.
+ * Note: flags contains other bits, of interest here only for logging purposes.
  * In particular note that this routine is synchronous and does not pay
  * attention to CHECKPOINT_WAIT.
  */
@@ -5446,9 +5501,6 @@ CreateCheckPoint(int flags)
    uint32      freespace;
    uint32      _logId;
    uint32      _logSeg;
-   int         nsegsadded = 0;
-   int         nsegsremoved = 0;
-   int         nsegsrecycled = 0;
    TransactionId *inCommitXids;
    int         nInCommit;
 
@@ -5460,6 +5512,16 @@ CreateCheckPoint(int flags)
     */
    LWLockAcquire(CheckpointLock, LW_EXCLUSIVE);
 
+   /*
+    * Prepare to accumulate statistics.
+    *
+    * Note: because it is possible for log_checkpoints to change while a
+    * checkpoint proceeds, we always accumulate stats, even if
+    * log_checkpoints is currently off.
+    */
+   MemSet(&CheckpointStats, 0, sizeof(CheckpointStats));
+   CheckpointStats.ckpt_start_t = GetCurrentTimestamp();
+
    /*
     * Use a critical section to force system panic if we have trouble.
     */
@@ -5560,9 +5622,12 @@ CreateCheckPoint(int flags)
     */
    LWLockRelease(WALInsertLock);
 
-   if (!shutdown)
-       ereport(DEBUG2,
-               (errmsg("checkpoint starting")));
+   /*
+    * If enabled, log checkpoint start.  We postpone this until now
+    * so as not to log anything if we decided to skip the checkpoint.
+    */
+   if (log_checkpoints)
+       LogCheckpointStart(flags);
 
    /*
     * Before flushing data, we must wait for any transactions that are
@@ -5699,8 +5764,7 @@ CreateCheckPoint(int flags)
    if (_logId || _logSeg)
    {
        PrevLogSeg(_logId, _logSeg);
-       RemoveOldXlogFiles(_logId, _logSeg, recptr,
-                          &nsegsremoved, &nsegsrecycled);
+       RemoveOldXlogFiles(_logId, _logSeg, recptr);
    }
 
    /*
@@ -5708,7 +5772,7 @@ CreateCheckPoint(int flags)
     * segments, since that may supply some of the needed files.)
     */
    if (!shutdown)
-       nsegsadded = PreallocXlogFiles(recptr);
+       PreallocXlogFiles(recptr);
 
    /*
     * Truncate pg_subtrans if possible.  We can throw away all data before
@@ -5720,10 +5784,9 @@ CreateCheckPoint(int flags)
    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)));
+   /* All real work is done, but log before releasing lock. */
+   if (log_checkpoints)
+       LogCheckpointEnd();
 
    LWLockRelease(CheckpointLock);
 }
index bbadd06fe02e70aa1268537ed255e307edf309be..a4d758d536a7936823b049addb6b292115a73803 100644 (file)
@@ -37,7 +37,7 @@
  *
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/postmaster/bgwriter.c,v 1.39 2007/06/28 00:02:38 tgl Exp $
+ *   $PostgreSQL: pgsql/src/backend/postmaster/bgwriter.c,v 1.40 2007/06/30 19:12:01 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -352,6 +352,7 @@ BackgroundWriterMain(void)
    for (;;)
    {
        bool        do_checkpoint = false;
+       int         flags = 0;
        time_t      now;
        int         elapsed_secs;
 
@@ -393,15 +394,19 @@ BackgroundWriterMain(void)
        }
 
        /*
-        * Do an unforced checkpoint if too much time has elapsed since the
-        * last one.
+        * Force a checkpoint if too much time has elapsed since the
+        * last one.  Note that we count a timed checkpoint in stats only
+        * when this occurs without an external request, but we set the
+        * CAUSE_TIME flag bit even if there is also an external request.
         */
        now = time(NULL);
        elapsed_secs = now - last_checkpoint_time;
-       if (!do_checkpoint && elapsed_secs >= CheckPointTimeout)
+       if (elapsed_secs >= CheckPointTimeout)
        {
+           if (!do_checkpoint)
+               BgWriterStats.m_timed_checkpoints++;
            do_checkpoint = true;
-           BgWriterStats.m_timed_checkpoints++;
+           flags |= CHECKPOINT_CAUSE_TIME;
        }
 
        /*
@@ -412,7 +417,6 @@ BackgroundWriterMain(void)
        {
            /* use volatile pointer to prevent code rearrangement */
            volatile BgWriterShmemStruct *bgs = BgWriterShmem;
-           int     flags;
 
            /*
             * Atomically fetch the request flags to figure out what
@@ -421,19 +425,19 @@ BackgroundWriterMain(void)
             * a new checkpoint.
             */
            SpinLockAcquire(&bgs->ckpt_lck);
-           flags = bgs->ckpt_flags;
+           flags |= bgs->ckpt_flags;
            bgs->ckpt_flags = 0;
            bgs->ckpt_started++;
            SpinLockRelease(&bgs->ckpt_lck);
 
            /*
             * We will warn if (a) too soon since last checkpoint (whatever
-            * caused it) and (b) somebody set the CHECKPOINT_WARNONTIME flag
+            * caused it) and (b) somebody set the CHECKPOINT_CAUSE_XLOG flag
             * since the last checkpoint start.  Note in particular that this
             * implementation will not generate warnings caused by
             * CheckPointTimeout < CheckPointWarning.
             */
-           if ((flags & CHECKPOINT_WARNONTIME) &&
+           if ((flags & CHECKPOINT_CAUSE_XLOG) &&
                elapsed_secs < CheckPointWarning)
                ereport(LOG,
                        (errmsg("checkpoints are occurring too frequently (%d seconds apart)",
@@ -843,12 +847,10 @@ BgWriterShmemInit(void)
  *     ignoring checkpoint_completion_target parameter. 
  * CHECKPOINT_FORCE: force a checkpoint even if no XLOG activity has occured
  *     since the last one (implied by CHECKPOINT_IS_SHUTDOWN).
- * CHECKPOINT_WARNONTIME: if it's "too soon" since the last checkpoint,
- *     the bgwriter will log a warning.  This should be true only for
- *     checkpoints requested due to xlog filling, else the warning will
- *     be misleading.
  * CHECKPOINT_WAIT: wait for completion before returning (otherwise,
  *     just signal bgwriter to do it, and return).
+ * CHECKPOINT_CAUSE_XLOG: checkpoint is requested due to xlog filling.
+ *     (This affects logging, and in particular enables CheckPointWarning.)
  */
 void
 RequestCheckpoint(int flags)
@@ -891,7 +893,7 @@ RequestCheckpoint(int flags)
 
    old_failed = bgs->ckpt_failed;
    old_started = bgs->ckpt_started;
-   bgs->ckpt_flags |= (flags & ~CHECKPOINT_WAIT);
+   bgs->ckpt_flags |= flags;
 
    SpinLockRelease(&bgs->ckpt_lck);
 
index 82fa49abc48470b6fbb720195bbb849ba840ed94..12564a69ee4f070c5cccb72aba45f4647fd62e9c 100644 (file)
@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/storage/buffer/bufmgr.c,v 1.222 2007/06/28 00:02:38 tgl Exp $
+ *   $PostgreSQL: pgsql/src/backend/storage/buffer/bufmgr.c,v 1.223 2007/06/30 19:12:01 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -1096,6 +1096,12 @@ BufferSync(int flags)
        if (++buf_id >= NBuffers)
            buf_id = 0;
    }
+
+   /*
+    * Update checkpoint statistics. As noted above, this doesn't
+    * include buffers written by other backends or bgwriter scan.
+    */
+   CheckpointStats.ckpt_bufs_written += num_written;
 }
 
 /*
@@ -1362,8 +1368,11 @@ PrintBufferLeakWarning(Buffer buffer)
 void
 CheckPointBuffers(int flags)
 {
+   CheckpointStats.ckpt_write_t = GetCurrentTimestamp();
    BufferSync(flags);
+   CheckpointStats.ckpt_sync_t = GetCurrentTimestamp();
    smgrsync();
+   CheckpointStats.ckpt_sync_end_t = GetCurrentTimestamp();
 }
 
 
index 4fa883133d86c5339da9964c2508bf498001dcfa..a542a22565ec646af2f35dea0d67b45cbf8a2303 100644 (file)
@@ -10,7 +10,7 @@
  * Written by Peter Eisentraut <peter_e@gmx.net>.
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/utils/misc/guc.c,v 1.403 2007/06/28 00:02:39 tgl Exp $
+ *   $PostgreSQL: pgsql/src/backend/utils/misc/guc.c,v 1.404 2007/06/30 19:12:02 tgl Exp $
  *
  *--------------------------------------------------------------------
  */
@@ -586,6 +586,14 @@ static struct config_bool ConfigureNamesBool[] =
        &SilentMode,
        false, NULL, NULL
    },
+   {
+       {"log_checkpoints", PGC_SIGHUP, LOGGING_WHAT,
+           gettext_noop("Logs each checkpoint."),
+           NULL
+       },
+       &log_checkpoints,
+       false, NULL, NULL
+   },
    {
        {"log_connections", PGC_BACKEND, LOGGING_WHAT,
            gettext_noop("Logs each successful connection."),
index 4c56c797134724f9e7780a79b1d3ba0da4180a52..9729eb2ce7629ef05a53fd5a22e8ab47c59acbdb 100644 (file)
 #debug_print_rewritten = off
 #debug_print_plan = off
 #debug_pretty_print = off
+#log_checkpoints = off
 #log_connections = off
 #log_disconnections = off
 #log_duration = off
+#log_hostname = off
 #log_line_prefix = ''          # Special values:
                    #   %u = user name
                    #   %d = database name
                    #        processes
                    #   %% = '%'
                    # e.g. '<%u%%%d> '
+#log_lock_waits = off          # Log lock waits >= deadlock_timeout
 #log_statement = 'none'            # none, ddl, mod, all
-#log_hostname = off
-#log_lock_waits = off          # Log lock waits longer than deadlock_timeout
 #log_temp_files = -1           # Log temporary files equal or larger
-                   # than the specified number of kilobytes.
+                   # than specified number of kilobytes.
                    # -1 disables;  0 logs all temp files
 
 #---------------------------------------------------------------------------
index e4f9747de7d18f2798fcee87a65ecc65e1116f3a..1b4fecdb966f11f485360e28345c109cedcce15c 100644 (file)
@@ -6,7 +6,7 @@
  * Portions Copyright (c) 1996-2007, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/access/xlog.h,v 1.79 2007/06/28 00:02:39 tgl Exp $
+ * $PostgreSQL: pgsql/src/include/access/xlog.h,v 1.80 2007/06/30 19:12:02 tgl Exp $
  */
 #ifndef XLOG_H
 #define XLOG_H
@@ -16,6 +16,7 @@
 #include "lib/stringinfo.h"
 #include "storage/buf.h"
 #include "utils/pg_crc.h"
+#include "utils/timestamp.h"
 
 
 /*
@@ -150,6 +151,7 @@ extern char *XLogArchiveCommand;
 extern int XLogArchiveTimeout;
 extern char *XLOG_sync_method;
 extern const char XLOG_sync_method_default[];
+extern bool log_checkpoints;
 
 #define XLogArchivingActive()  (XLogArchiveCommand[0] != '\0')
 
@@ -157,12 +159,39 @@ extern const char XLOG_sync_method_default[];
 extern bool XLOG_DEBUG;
 #endif
 
-/* OR-able flags for RequestCheckpoint, CreateCheckPoint and subsidiaries */
+/*
+ * OR-able request flag bits for checkpoints.  The "cause" bits are used only
+ * for logging purposes.  Note: the flags must be defined so that it's
+ * sensible to OR together request flags arising from different requestors.
+ */
+
+/* These directly affect the behavior of CreateCheckPoint and subsidiaries */
 #define CHECKPOINT_IS_SHUTDOWN 0x0001      /* Checkpoint is for shutdown */
 #define CHECKPOINT_IMMEDIATE   0x0002      /* Do it without delays */
 #define CHECKPOINT_FORCE       0x0004      /* Force even if no activity */
-#define CHECKPOINT_WARNONTIME  0x0008      /* Enable CheckPointWarning */
-#define CHECKPOINT_WAIT            0x0010      /* Wait for completion */
+/* These are important to RequestCheckpoint */
+#define CHECKPOINT_WAIT            0x0008      /* Wait for completion */
+/* These indicate the cause of a checkpoint request */
+#define CHECKPOINT_CAUSE_XLOG  0x0010      /* XLOG consumption */
+#define CHECKPOINT_CAUSE_TIME  0x0020      /* Elapsed time */
+
+/* Checkpoint statistics */
+typedef struct CheckpointStatsData
+{
+   TimestampTz ckpt_start_t;       /* start of checkpoint */
+   TimestampTz ckpt_write_t;       /* start of flushing buffers */
+   TimestampTz ckpt_sync_t;        /* start of fsyncs */
+   TimestampTz ckpt_sync_end_t;    /* end of fsyncs */
+   TimestampTz ckpt_end_t;         /* end of checkpoint */
+
+   int         ckpt_bufs_written;  /* # of buffers written */
+
+   int         ckpt_segs_added;    /* # of new xlog segments created */
+   int         ckpt_segs_removed;  /* # of xlog segments deleted */
+   int         ckpt_segs_recycled; /* # of xlog segments recycled */
+} CheckpointStatsData;
+
+extern CheckpointStatsData CheckpointStats;
 
 
 extern XLogRecPtr XLogInsert(RmgrId rmid, uint8 info, XLogRecData *rdata);