]> granicus.if.org Git - postgresql/commitdiff
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);