diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index ae9ed8f..6adc139 100644 *** a/src/backend/access/transam/xlog.c --- b/src/backend/access/transam/xlog.c *************** LogCheckpointEnd(bool restartpoint) *** 6955,6964 **** { long write_secs, sync_secs, ! total_secs; int write_usecs, sync_usecs, ! total_usecs; CheckpointStats.ckpt_end_t = GetCurrentTimestamp(); --- 6955,6969 ---- { long write_secs, sync_secs, ! total_secs, ! longest_secs, ! average_secs; int write_usecs, sync_usecs, ! total_usecs, ! longest_usecs, ! average_usecs; ! double average_sync_time; CheckpointStats.ckpt_end_t = GetCurrentTimestamp(); *************** LogCheckpointEnd(bool restartpoint) *** 6974,6991 **** CheckpointStats.ckpt_sync_end_t, &sync_secs, &sync_usecs); if (restartpoint) elog(LOG, "restartpoint complete: wrote %d buffers (%.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); else 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, --- 6979,7017 ---- CheckpointStats.ckpt_sync_end_t, &sync_secs, &sync_usecs); + /* + * Timing values returned from CheckpointStats are in milliseconds. + * Convert to the second plus microsecond form that TimestampDifference + * returns for homogeneous printing. + */ + longest_secs = (long) (CheckpointStats.ckpt_longest_sync / 1000); + longest_usecs = 1000 * (CheckpointStats.ckpt_longest_sync - + longest_secs * 1000); + + average_sync_time = 0; + if (CheckpointStats.ckpt_sync_rels > 0) + average_sync_time = CheckpointStats.ckpt_agg_sync_time / + CheckpointStats.ckpt_sync_rels; + average_secs = (long) (average_sync_time / 1000); + average_usecs = 1000 * (average_sync_time - average_secs * 1000); + if (restartpoint) elog(LOG, "restartpoint complete: wrote %d buffers (%.1f%%); " ! "write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; " ! "sync files=%d, longest=%ld.%03d s, average=%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, ! CheckpointStats.ckpt_sync_rels, ! longest_secs, longest_usecs / 1000, ! average_secs, average_usecs / 1000); else 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; " ! "sync files=%d, longest=%ld.%03d s, average=%ld.%03d s", CheckpointStats.ckpt_bufs_written, (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers, CheckpointStats.ckpt_segs_added, *************** LogCheckpointEnd(bool restartpoint) *** 6993,6999 **** CheckpointStats.ckpt_segs_recycled, write_secs, write_usecs / 1000, sync_secs, sync_usecs / 1000, ! total_secs, total_usecs / 1000); } /* --- 7019,7028 ---- CheckpointStats.ckpt_segs_recycled, write_secs, write_usecs / 1000, sync_secs, sync_usecs / 1000, ! total_secs, total_usecs / 1000, ! CheckpointStats.ckpt_sync_rels, ! longest_secs, longest_usecs / 1000, ! average_secs, average_usecs / 1000); } /* diff --git a/src/backend/storage/smgr/md.c b/src/backend/storage/smgr/md.c index 604db21..1f602a7 100644 *** a/src/backend/storage/smgr/md.c --- b/src/backend/storage/smgr/md.c *************** *** 20,25 **** --- 20,26 ---- #include "catalog/catalog.h" #include "miscadmin.h" + #include "portability/instr_time.h" #include "postmaster/bgwriter.h" #include "storage/fd.h" #include "storage/bufmgr.h" *************** mdsync(void) *** 927,932 **** --- 928,940 ---- PendingOperationEntry *entry; int absorb_counter; + /* Statistics on sync times */ + int processed = 0; + instr_time sync_start, sync_end, sync_diff; + double elapsed; + double longest = 0; + double total_elapsed = 0; + /* * This is only called during checkpoints, and checkpoints should only * occur in processes that have created a pendingOpsTable. *************** mdsync(void) *** 1069,1077 **** --- 1077,1107 ---- seg = _mdfd_getseg(reln, entry->tag.forknum, entry->tag.segno * ((BlockNumber) RELSEG_SIZE), false, EXTENSION_RETURN_NULL); + + if (log_checkpoints) + INSTR_TIME_SET_CURRENT(sync_start); + else + INSTR_TIME_SET_ZERO(sync_start); + if (seg != NULL && FileSync(seg->mdfd_vfd) >= 0) + { + if (log_checkpoints && (! INSTR_TIME_IS_ZERO(sync_start))) + { + INSTR_TIME_SET_CURRENT(sync_end); + sync_diff = sync_end; + INSTR_TIME_SUBTRACT(sync_diff, sync_start); + elapsed = (double) INSTR_TIME_GET_MICROSEC(sync_diff) / 1000.0; + if (elapsed > longest) + longest = elapsed; + total_elapsed += elapsed; + processed++; + elog(DEBUG1, "checkpoint sync: number=%d file=%s time=%f msec", + processed, FilePathName(seg->mdfd_vfd), elapsed); + } + break; /* success; break out of retry loop */ + } /* * XXX is there any point in allowing more than one retry? *************** mdsync(void) *** 1113,1118 **** --- 1143,1153 ---- elog(ERROR, "pendingOpsTable corrupted"); } /* end loop over hashtable entries */ + /* Return sync performance metrics for report at checkpoint end */ + CheckpointStats.ckpt_sync_rels = processed; + CheckpointStats.ckpt_longest_sync = longest; + CheckpointStats.ckpt_agg_sync_time = total_elapsed; + /* Flag successful completion of mdsync */ mdsync_in_progress = false; } diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h index fa7ae2a..d95f843 100644 *** a/src/include/access/xlog.h --- b/src/include/access/xlog.h *************** typedef struct CheckpointStatsData *** 257,262 **** --- 257,269 ---- 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 */ + + int ckpt_sync_rels; /* # of relations synced */ + double ckpt_longest_sync; /* Longest sync for one relation */ + double ckpt_agg_sync_time; /* The sum of all the individual sync + times, which is not necessarily the + same as the total elapsed time for + the entire sync phase. */ } CheckpointStatsData; extern CheckpointStatsData CheckpointStats;