Improve logging of checkpoints. Patch by Greg Smith, worked over

by Heikki and a little bit by me.

doc/src/sgml/config.sgml

-<!-- $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 
+        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.  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.
-        This parameter can only be set in the <filename>postgresql.conf</>
-        file or on the server command line.
         </para>
+       </note>
       </listitem>
      </varlistentry>
 
@@ -2730,6 +2752,23 @@ 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-line-prefix" xreflabel="log_line_prefix">
       <term><varname>log_line_prefix</varname> (<type>string</type>)</term>
       <indexterm>
@@ -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>

src/backend/access/transam/xlog.c

@@ -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);
 }

src/backend/postmaster/bgwriter.c

@@ -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)
 		{
-			do_checkpoint = true;
+			if (!do_checkpoint)
 				BgWriterStats.m_timed_checkpoints++;
+			do_checkpoint = true;
+			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);
 

src/backend/storage/buffer/bufmgr.c

@@ -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();
 }
 
 

src/backend/utils/misc/guc.c

@@ -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."),

src/backend/utils/misc/postgresql.conf.sample

@@ -317,9 +317,11 @@
 #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
@@ -337,11 +339,10 @@
 					#        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
 
 #---------------------------------------------------------------------------

src/include/access/xlog.h

@@ -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);