Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.129
diff -c -r1.129 config.sgml
*** doc/src/sgml/config.sgml 28 Jun 2007 00:02:37 -0000 1.129
--- doc/src/sgml/config.sgml 28 Jun 2007 17:15:41 -0000
***************
*** 1547,1552 ****
--- 1547,1570 ----
+
+ log_checkpoints (boolean)
+
+ log_checkpoints configuration parameter
+
+
+
+ Logs the start and end of each checkpoint in the server log. Some
+ statistics of the checkpoint are included in the log message,
+ including the number of dirty buffers in the buffer cache when the
+ checkpoint started, and time spent writing them.
+
+ This parameter can only be set in the postgresql.conf
+ file or on the server command line. The default is off.
+
+
+
+
Index: src/backend/access/transam/xlog.c
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/access/transam/xlog.c,v
retrieving revision 1.273
diff -c -r1.273 xlog.c
*** src/backend/access/transam/xlog.c 28 Jun 2007 00:02:37 -0000 1.273
--- src/backend/access/transam/xlog.c 28 Jun 2007 17:16:37 -0000
***************
*** 66,71 ****
--- 66,72 ----
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;
***************
*** 93,98 ****
--- 94,106 ----
/*
+ * Statistics from current checkpoint are collected to 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,422 ****
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 CleanupBackupHistory(void);
static XLogRecord *ReadRecord(XLogRecPtr *RecPtr, int emode);
static bool ValidXLOGHeader(XLogPageHeader hdr, int emode);
--- 422,429 ----
static void XLogFileClose(void);
static bool RestoreArchivedFile(char *path, const char *xlogfname,
const char *recovername, off_t expectedSize);
! 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);
***************
*** 2525,2534 ****
* 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
PreallocXlogFiles(XLogRecPtr endptr)
{
- int nsegsadded = 0;
uint32 _logId;
uint32 _logSeg;
int lf;
--- 2532,2540 ----
* 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 void
PreallocXlogFiles(XLogRecPtr endptr)
{
uint32 _logId;
uint32 _logSeg;
int lf;
***************
*** 2543,2551 ****
lf = XLogFileInit(_logId, _logSeg, &use_existent, true);
close(lf);
if (!use_existent)
! nsegsadded++;
}
- return nsegsadded;
}
/*
--- 2549,2556 ----
lf = XLogFileInit(_logId, _logSeg, &use_existent, true);
close(lf);
if (!use_existent)
! CheckpointStats.ckpt_segs_added++;
}
}
/*
***************
*** 2555,2562 ****
* 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)
{
uint32 endlogId;
uint32 endlogSeg;
--- 2560,2566 ----
* whether we want to recycle rather than delete no-longer-wanted log files.
*/
static void
! RemoveOldXlogFiles(uint32 log, uint32 seg, XLogRecPtr endptr)
{
uint32 endlogId;
uint32 endlogSeg;
***************
*** 2566,2574 ****
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.
--- 2570,2575 ----
***************
*** 2617,2623 ****
ereport(DEBUG2,
(errmsg("recycled transaction log file \"%s\"",
xlde->d_name)));
! (*nsegsrecycled)++;
/* Needn't recheck that slot on future iterations */
if (max_advance > 0)
{
--- 2618,2624 ----
ereport(DEBUG2,
(errmsg("recycled transaction log file \"%s\"",
xlde->d_name)));
! CheckpointStats.ckpt_segs_recycled++;
/* Needn't recheck that slot on future iterations */
if (max_advance > 0)
{
***************
*** 2632,2638 ****
(errmsg("removing transaction log file \"%s\"",
xlde->d_name)));
unlink(path);
! (*nsegsremoved)++;
}
XLogArchiveCleanup(xlde->d_name);
--- 2633,2639 ----
(errmsg("removing transaction log file \"%s\"",
xlde->d_name)));
unlink(path);
! CheckpointStats.ckpt_segs_removed++;
}
XLogArchiveCleanup(xlde->d_name);
***************
*** 5421,5426 ****
--- 5422,5474 ----
(errmsg("database system is shut down")));
}
+ /*
+ * Reset checkpoint statistics data.
+ */
+ static void
+ ResetCheckpointStats()
+ {
+ memset(&CheckpointStats, 0, sizeof(CheckpointStats));
+ }
+
+ /*
+ * Prints a summary of a checkpoint that was just finished.
+ */
+ static void
+ PrintCheckpointStats()
+ {
+ if (log_checkpoints)
+ {
+ long write_secs, sync_secs, total_secs;
+ int write_usecs, sync_usecs, total_usecs;
+
+ 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; buffers written=%d (%.1f%%); write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s",
+ CheckpointStats.ckpt_bufs_written,
+ (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+ write_secs, write_usecs/1000,
+ sync_secs, sync_usecs/1000,
+ total_secs, total_usecs/1000);
+
+ /* Print some more details in DEBUG2 level */
+ elog(DEBUG2, "%d transaction log file(s) added, %d removed, %d recycled",
+ CheckpointStats.ckpt_segs_added,
+ CheckpointStats.ckpt_segs_removed,
+ CheckpointStats.ckpt_segs_recycled);
+ }
+ }
+
/*
* Perform a checkpoint --- either during shutdown, or on-the-fly
*
***************
*** 5446,5457 ****
uint32 freespace;
uint32 _logId;
uint32 _logSeg;
- int nsegsadded = 0;
- int nsegsremoved = 0;
- int nsegsrecycled = 0;
TransactionId *inCommitXids;
int nInCommit;
/*
* Acquire CheckpointLock to ensure only one checkpoint happens at a time.
* (This is just pro forma, since in the present system structure there is
--- 5494,5505 ----
uint32 freespace;
uint32 _logId;
uint32 _logSeg;
TransactionId *inCommitXids;
int nInCommit;
+ ResetCheckpointStats();
+ CheckpointStats.ckpt_start_t = GetCurrentTimestamp();
+
/*
* Acquire CheckpointLock to ensure only one checkpoint happens at a time.
* (This is just pro forma, since in the present system structure there is
***************
*** 5561,5568 ****
LWLockRelease(WALInsertLock);
if (!shutdown)
! ereport(DEBUG2,
! (errmsg("checkpoint starting")));
/*
* Before flushing data, we must wait for any transactions that are
--- 5609,5624 ----
LWLockRelease(WALInsertLock);
if (!shutdown)
! {
! /*
! * We don't print this until now, because we might have decided
! * above to skip this checkpoint altogether.
! */
! if (flags & CHECKPOINT_IMMEDIATE)
! elog(LOG, "checkpoint starting (immediate)");
! else
! elog(LOG, "checkpoint starting");
! }
/*
* Before flushing data, we must wait for any transactions that are
***************
*** 5699,5706 ****
if (_logId || _logSeg)
{
PrevLogSeg(_logId, _logSeg);
! RemoveOldXlogFiles(_logId, _logSeg, recptr,
! &nsegsremoved, &nsegsrecycled);
}
/*
--- 5755,5761 ----
if (_logId || _logSeg)
{
PrevLogSeg(_logId, _logSeg);
! RemoveOldXlogFiles(_logId, _logSeg, recptr);
}
/*
***************
*** 5708,5714 ****
* segments, since that may supply some of the needed files.)
*/
if (!shutdown)
! nsegsadded = PreallocXlogFiles(recptr);
/*
* Truncate pg_subtrans if possible. We can throw away all data before
--- 5763,5769 ----
* segments, since that may supply some of the needed files.)
*/
if (!shutdown)
! PreallocXlogFiles(recptr);
/*
* Truncate pg_subtrans if possible. We can throw away all data before
***************
*** 5720,5731 ****
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);
}
/*
--- 5775,5788 ----
if (!InRecovery)
TruncateSUBTRANS(GetOldestXmin(true, false));
+ LWLockRelease(CheckpointLock);
+
+ /* All real work is done. */
+ CheckpointStats.ckpt_end_t = GetCurrentTimestamp();
+
if (!shutdown)
! PrintCheckpointStats();
}
/*
Index: src/backend/storage/buffer/bufmgr.c
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/storage/buffer/bufmgr.c,v
retrieving revision 1.222
diff -c -r1.222 bufmgr.c
*** src/backend/storage/buffer/bufmgr.c 28 Jun 2007 00:02:38 -0000 1.222
--- src/backend/storage/buffer/bufmgr.c 28 Jun 2007 17:23:29 -0000
***************
*** 1096,1101 ****
--- 1096,1107 ----
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,1371 ****
void
CheckPointBuffers(int flags)
{
BufferSync(flags);
smgrsync();
- }
/*
* Do whatever is needed to prepare for commit at the bufmgr and smgr levels
--- 1368,1381 ----
void
CheckPointBuffers(int flags)
{
+ CheckpointStats.ckpt_write_t = GetCurrentTimestamp();
BufferSync(flags);
+
+ CheckpointStats.ckpt_sync_t = GetCurrentTimestamp();
smgrsync();
+ CheckpointStats.ckpt_sync_end_t = GetCurrentTimestamp();
+ }
/*
* Do whatever is needed to prepare for commit at the bufmgr and smgr levels
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.403
diff -c -r1.403 guc.c
*** src/backend/utils/misc/guc.c 28 Jun 2007 00:02:39 -0000 1.403
--- src/backend/utils/misc/guc.c 28 Jun 2007 15:51:32 -0000
***************
*** 587,592 ****
--- 587,600 ----
false, NULL, NULL
},
{
+ {"log_checkpoints", PGC_BACKEND, 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."),
NULL
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.217
diff -c -r1.217 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample 28 Jun 2007 00:02:39 -0000 1.217
--- src/backend/utils/misc/postgresql.conf.sample 28 Jun 2007 15:39:35 -0000
***************
*** 168,173 ****
--- 168,174 ----
#checkpoint_timeout = 5min # range 30s-1h
#checkpoint_completion_target = 0.5 # checkpoint target duration, 0.0 - 1.0
#checkpoint_warning = 30s # 0 is off
+ #log_checkpoints = off # logs checkpoints to server log
# - Archiving -
Index: src/include/access/xlog.h
===================================================================
RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/include/access/xlog.h,v
retrieving revision 1.79
diff -c -r1.79 xlog.h
*** src/include/access/xlog.h 28 Jun 2007 00:02:39 -0000 1.79
--- src/include/access/xlog.h 28 Jun 2007 17:22:04 -0000
***************
*** 16,21 ****
--- 16,22 ----
#include "lib/stringinfo.h"
#include "storage/buf.h"
#include "utils/pg_crc.h"
+ #include "utils/timestamp.h"
/*
***************
*** 150,155 ****
--- 151,157 ----
extern int XLogArchiveTimeout;
extern char *XLOG_sync_method;
extern const char XLOG_sync_method_default[];
+ extern bool log_checkpoints;
#define XLogArchivingActive() (XLogArchiveCommand[0] != '\0')
***************
*** 164,169 ****
--- 166,189 ----
#define CHECKPOINT_WARNONTIME 0x0008 /* Enable CheckPointWarning */
#define CHECKPOINT_WAIT 0x0010 /* Wait for completion */
+ /*
+ * 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);
extern void XLogFlush(XLogRecPtr RecPtr);