diff options
| -rw-r--r-- | dist/stat_data.py | 6 | ||||
| -rw-r--r-- | src/include/stat.h | 6 | ||||
| -rw-r--r-- | src/include/wiredtiger.in | 104 | ||||
| -rw-r--r-- | src/log/log.c | 26 | ||||
| -rw-r--r-- | src/support/stat.c | 21 | ||||
| -rw-r--r-- | src/txn/txn_ckpt.c | 14 |
6 files changed, 133 insertions, 44 deletions
diff --git a/dist/stat_data.py b/dist/stat_data.py index 4f42e70ba27..c1862779946 100644 --- a/dist/stat_data.py +++ b/dist/stat_data.py @@ -250,6 +250,8 @@ connection_stats = [ LogStat('log_slot_unbuffered', 'consolidated slot unbuffered writes'), LogStat('log_sync', 'log sync operations'), LogStat('log_sync_dir', 'log sync_dir operations'), + LogStat('log_sync_dir_duration', 'log sync_dir time duration (usecs)'), + LogStat('log_sync_duration', 'log sync time duration (usecs)'), LogStat('log_write_lsn', 'log server thread advances write LSN'), LogStat('log_write_lsn_skip', 'log server thread write LSN walk skipped'), LogStat('log_writes', 'log write operations'), @@ -278,6 +280,10 @@ connection_stats = [ TxnStat('txn_checkpoint_time_total', 'transaction checkpoint total time (msecs)', 'no_clear,no_scale'), TxnStat('txn_commit', 'transactions committed'), TxnStat('txn_fail_cache', 'transaction failures due to cache overflow'), + TxnStat('txn_fsync_post', 'transaction fsync calls for checkpoint after allocating the transaction ID'), + TxnStat('txn_fsync_post_duration', 'transaction fsync duration for checkpoint after allocating the transaction ID'), + TxnStat('txn_fsync_pre', 'transaction fsync calls for checkpoint before allocating the transaction ID'), + TxnStat('txn_fsync_pre_duration', 'transaction fsync duration for checkpoint before allocating the transaction ID'), TxnStat('txn_pinned_checkpoint_range', 'transaction range of IDs currently pinned by a checkpoint', 'no_clear,no_scale'), TxnStat('txn_pinned_range', 'transaction range of IDs currently pinned', 'no_clear,no_scale'), TxnStat('txn_pinned_snapshot_range', 'transaction range of IDs currently pinned by named snapshots', 'no_clear,no_scale'), diff --git a/src/include/stat.h b/src/include/stat.h index c84bedd3fab..3af63b5b2d7 100644 --- a/src/include/stat.h +++ b/src/include/stat.h @@ -359,7 +359,9 @@ struct __wt_connection_stats { int64_t log_write_lsn; int64_t log_write_lsn_skip; int64_t log_sync; + int64_t log_sync_duration; int64_t log_sync_dir; + int64_t log_sync_dir_duration; int64_t log_writes; int64_t log_slot_consolidated; int64_t log_max_filesize; @@ -397,6 +399,10 @@ struct __wt_connection_stats { int64_t txn_checkpoint_time_total; int64_t txn_checkpoint; int64_t txn_fail_cache; + int64_t txn_fsync_post; + int64_t txn_fsync_pre; + int64_t txn_fsync_post_duration; + int64_t txn_fsync_pre_duration; int64_t txn_pinned_range; int64_t txn_pinned_checkpoint_range; int64_t txn_pinned_snapshot_range; diff --git a/src/include/wiredtiger.in b/src/include/wiredtiger.in index 48cd8bd6b96..690f6becb7d 100644 --- a/src/include/wiredtiger.in +++ b/src/include/wiredtiger.in @@ -4468,95 +4468,111 @@ extern int wiredtiger_extension_terminate(WT_CONNECTION *connection); #define WT_STAT_CONN_LOG_WRITE_LSN_SKIP 1130 /*! log: log sync operations */ #define WT_STAT_CONN_LOG_SYNC 1131 +/*! log: log sync time duration (usecs) */ +#define WT_STAT_CONN_LOG_SYNC_DURATION 1132 /*! log: log sync_dir operations */ -#define WT_STAT_CONN_LOG_SYNC_DIR 1132 +#define WT_STAT_CONN_LOG_SYNC_DIR 1133 +/*! log: log sync_dir time duration (usecs) */ +#define WT_STAT_CONN_LOG_SYNC_DIR_DURATION 1134 /*! log: log write operations */ -#define WT_STAT_CONN_LOG_WRITES 1133 +#define WT_STAT_CONN_LOG_WRITES 1135 /*! log: logging bytes consolidated */ -#define WT_STAT_CONN_LOG_SLOT_CONSOLIDATED 1134 +#define WT_STAT_CONN_LOG_SLOT_CONSOLIDATED 1136 /*! log: maximum log file size */ -#define WT_STAT_CONN_LOG_MAX_FILESIZE 1135 +#define WT_STAT_CONN_LOG_MAX_FILESIZE 1137 /*! log: number of pre-allocated log files to create */ -#define WT_STAT_CONN_LOG_PREALLOC_MAX 1136 +#define WT_STAT_CONN_LOG_PREALLOC_MAX 1138 /*! log: pre-allocated log files not ready and missed */ -#define WT_STAT_CONN_LOG_PREALLOC_MISSED 1137 +#define WT_STAT_CONN_LOG_PREALLOC_MISSED 1139 /*! log: pre-allocated log files prepared */ -#define WT_STAT_CONN_LOG_PREALLOC_FILES 1138 +#define WT_STAT_CONN_LOG_PREALLOC_FILES 1140 /*! log: pre-allocated log files used */ -#define WT_STAT_CONN_LOG_PREALLOC_USED 1139 +#define WT_STAT_CONN_LOG_PREALLOC_USED 1141 /*! log: records processed by log scan */ -#define WT_STAT_CONN_LOG_SCAN_RECORDS 1140 +#define WT_STAT_CONN_LOG_SCAN_RECORDS 1142 /*! log: total in-memory size of compressed records */ -#define WT_STAT_CONN_LOG_COMPRESS_MEM 1141 +#define WT_STAT_CONN_LOG_COMPRESS_MEM 1143 /*! log: total log buffer size */ -#define WT_STAT_CONN_LOG_BUFFER_SIZE 1142 +#define WT_STAT_CONN_LOG_BUFFER_SIZE 1144 /*! log: total size of compressed records */ -#define WT_STAT_CONN_LOG_COMPRESS_LEN 1143 +#define WT_STAT_CONN_LOG_COMPRESS_LEN 1145 /*! log: written slots coalesced */ -#define WT_STAT_CONN_LOG_SLOT_COALESCED 1144 +#define WT_STAT_CONN_LOG_SLOT_COALESCED 1146 /*! log: yields waiting for previous log file close */ -#define WT_STAT_CONN_LOG_CLOSE_YIELDS 1145 +#define WT_STAT_CONN_LOG_CLOSE_YIELDS 1147 /*! reconciliation: fast-path pages deleted */ -#define WT_STAT_CONN_REC_PAGE_DELETE_FAST 1146 +#define WT_STAT_CONN_REC_PAGE_DELETE_FAST 1148 /*! reconciliation: page reconciliation calls */ -#define WT_STAT_CONN_REC_PAGES 1147 +#define WT_STAT_CONN_REC_PAGES 1149 /*! reconciliation: page reconciliation calls for eviction */ -#define WT_STAT_CONN_REC_PAGES_EVICTION 1148 +#define WT_STAT_CONN_REC_PAGES_EVICTION 1150 /*! reconciliation: pages deleted */ -#define WT_STAT_CONN_REC_PAGE_DELETE 1149 +#define WT_STAT_CONN_REC_PAGE_DELETE 1151 /*! reconciliation: split bytes currently awaiting free */ -#define WT_STAT_CONN_REC_SPLIT_STASHED_BYTES 1150 +#define WT_STAT_CONN_REC_SPLIT_STASHED_BYTES 1152 /*! reconciliation: split objects currently awaiting free */ -#define WT_STAT_CONN_REC_SPLIT_STASHED_OBJECTS 1151 +#define WT_STAT_CONN_REC_SPLIT_STASHED_OBJECTS 1153 /*! session: open cursor count */ -#define WT_STAT_CONN_SESSION_CURSOR_OPEN 1152 +#define WT_STAT_CONN_SESSION_CURSOR_OPEN 1154 /*! session: open session count */ -#define WT_STAT_CONN_SESSION_OPEN 1153 +#define WT_STAT_CONN_SESSION_OPEN 1155 /*! thread-yield: page acquire busy blocked */ -#define WT_STAT_CONN_PAGE_BUSY_BLOCKED 1154 +#define WT_STAT_CONN_PAGE_BUSY_BLOCKED 1156 /*! thread-yield: page acquire eviction blocked */ -#define WT_STAT_CONN_PAGE_FORCIBLE_EVICT_BLOCKED 1155 +#define WT_STAT_CONN_PAGE_FORCIBLE_EVICT_BLOCKED 1157 /*! thread-yield: page acquire locked blocked */ -#define WT_STAT_CONN_PAGE_LOCKED_BLOCKED 1156 +#define WT_STAT_CONN_PAGE_LOCKED_BLOCKED 1158 /*! thread-yield: page acquire read blocked */ -#define WT_STAT_CONN_PAGE_READ_BLOCKED 1157 +#define WT_STAT_CONN_PAGE_READ_BLOCKED 1159 /*! thread-yield: page acquire time sleeping (usecs) */ -#define WT_STAT_CONN_PAGE_SLEEP 1158 +#define WT_STAT_CONN_PAGE_SLEEP 1160 /*! transaction: number of named snapshots created */ -#define WT_STAT_CONN_TXN_SNAPSHOTS_CREATED 1159 +#define WT_STAT_CONN_TXN_SNAPSHOTS_CREATED 1161 /*! transaction: number of named snapshots dropped */ -#define WT_STAT_CONN_TXN_SNAPSHOTS_DROPPED 1160 +#define WT_STAT_CONN_TXN_SNAPSHOTS_DROPPED 1162 /*! transaction: transaction begins */ -#define WT_STAT_CONN_TXN_BEGIN 1161 +#define WT_STAT_CONN_TXN_BEGIN 1163 /*! transaction: transaction checkpoint currently running */ -#define WT_STAT_CONN_TXN_CHECKPOINT_RUNNING 1162 +#define WT_STAT_CONN_TXN_CHECKPOINT_RUNNING 1164 /*! transaction: transaction checkpoint generation */ -#define WT_STAT_CONN_TXN_CHECKPOINT_GENERATION 1163 +#define WT_STAT_CONN_TXN_CHECKPOINT_GENERATION 1165 /*! transaction: transaction checkpoint max time (msecs) */ -#define WT_STAT_CONN_TXN_CHECKPOINT_TIME_MAX 1164 +#define WT_STAT_CONN_TXN_CHECKPOINT_TIME_MAX 1166 /*! transaction: transaction checkpoint min time (msecs) */ -#define WT_STAT_CONN_TXN_CHECKPOINT_TIME_MIN 1165 +#define WT_STAT_CONN_TXN_CHECKPOINT_TIME_MIN 1167 /*! transaction: transaction checkpoint most recent time (msecs) */ -#define WT_STAT_CONN_TXN_CHECKPOINT_TIME_RECENT 1166 +#define WT_STAT_CONN_TXN_CHECKPOINT_TIME_RECENT 1168 /*! transaction: transaction checkpoint total time (msecs) */ -#define WT_STAT_CONN_TXN_CHECKPOINT_TIME_TOTAL 1167 +#define WT_STAT_CONN_TXN_CHECKPOINT_TIME_TOTAL 1169 /*! transaction: transaction checkpoints */ -#define WT_STAT_CONN_TXN_CHECKPOINT 1168 +#define WT_STAT_CONN_TXN_CHECKPOINT 1170 /*! transaction: transaction failures due to cache overflow */ -#define WT_STAT_CONN_TXN_FAIL_CACHE 1169 +#define WT_STAT_CONN_TXN_FAIL_CACHE 1171 +/*! transaction: transaction fsync calls for checkpoint after allocating + * the transaction ID */ +#define WT_STAT_CONN_TXN_FSYNC_POST 1172 +/*! transaction: transaction fsync calls for checkpoint before allocating + * the transaction ID */ +#define WT_STAT_CONN_TXN_FSYNC_PRE 1173 +/*! transaction: transaction fsync duration for checkpoint after + * allocating the transaction ID */ +#define WT_STAT_CONN_TXN_FSYNC_POST_DURATION 1174 +/*! transaction: transaction fsync duration for checkpoint before + * allocating the transaction ID */ +#define WT_STAT_CONN_TXN_FSYNC_PRE_DURATION 1175 /*! transaction: transaction range of IDs currently pinned */ -#define WT_STAT_CONN_TXN_PINNED_RANGE 1170 +#define WT_STAT_CONN_TXN_PINNED_RANGE 1176 /*! transaction: transaction range of IDs currently pinned by a checkpoint */ -#define WT_STAT_CONN_TXN_PINNED_CHECKPOINT_RANGE 1171 +#define WT_STAT_CONN_TXN_PINNED_CHECKPOINT_RANGE 1177 /*! transaction: transaction range of IDs currently pinned by named * snapshots */ -#define WT_STAT_CONN_TXN_PINNED_SNAPSHOT_RANGE 1172 +#define WT_STAT_CONN_TXN_PINNED_SNAPSHOT_RANGE 1178 /*! transaction: transaction sync calls */ -#define WT_STAT_CONN_TXN_SYNC 1173 +#define WT_STAT_CONN_TXN_SYNC 1179 /*! transaction: transactions committed */ -#define WT_STAT_CONN_TXN_COMMIT 1174 +#define WT_STAT_CONN_TXN_COMMIT 1180 /*! transaction: transactions rolled back */ -#define WT_STAT_CONN_TXN_ROLLBACK 1175 +#define WT_STAT_CONN_TXN_ROLLBACK 1181 /*! * @} diff --git a/src/log/log.c b/src/log/log.c index 073dc5b2025..364447b874b 100644 --- a/src/log/log.c +++ b/src/log/log.c @@ -95,9 +95,11 @@ __wt_log_background(WT_SESSION_IMPL *session, WT_LSN *lsn) int __wt_log_force_sync(WT_SESSION_IMPL *session, WT_LSN *min_lsn) { + struct timespec fsync_start, fsync_stop; WT_DECL_RET; WT_FH *log_fh; WT_LOG *log; + uint64_t fsync_duration_usecs; log = S2C(session)->log; @@ -124,9 +126,14 @@ __wt_log_force_sync(WT_SESSION_IMPL *session, WT_LSN *min_lsn) "log_force_sync: sync directory %s to LSN %" PRIu32 "/%" PRIu32, log->log_dir_fh->name, min_lsn->l.file, min_lsn->l.offset)); + WT_ERR(__wt_epoch(session, &fsync_start)); WT_ERR(__wt_fsync(session, log->log_dir_fh, true)); + WT_ERR(__wt_epoch(session, &fsync_stop)); + fsync_duration_usecs = WT_TIMEDIFF_US(fsync_stop, fsync_start); log->sync_dir_lsn = *min_lsn; WT_STAT_FAST_CONN_INCR(session, log_sync_dir); + WT_STAT_FAST_CONN_INCRV(session, + log_sync_dir_duration, fsync_duration_usecs); } /* * Sync the log file if needed. @@ -143,9 +150,14 @@ __wt_log_force_sync(WT_SESSION_IMPL *session, WT_LSN *min_lsn) WT_ERR(__wt_verbose(session, WT_VERB_LOG, "log_force_sync: sync %s to LSN %" PRIu32 "/%" PRIu32, log_fh->name, min_lsn->l.file, min_lsn->l.offset)); + WT_ERR(__wt_epoch(session, &fsync_start)); WT_ERR(__wt_fsync(session, log_fh, true)); + WT_ERR(__wt_epoch(session, &fsync_stop)); + fsync_duration_usecs = WT_TIMEDIFF_US(fsync_stop, fsync_start); log->sync_lsn = *min_lsn; WT_STAT_FAST_CONN_INCR(session, log_sync); + WT_STAT_FAST_CONN_INCRV(session, + log_sync_duration, fsync_duration_usecs); WT_ERR(__wt_close(session, &log_fh)); WT_ERR(__wt_cond_signal(session, log->log_sync_cond)); } @@ -1272,11 +1284,13 @@ err: __wt_free(session, buf); int __wt_log_release(WT_SESSION_IMPL *session, WT_LOGSLOT *slot, bool *freep) { + struct timespec fsync_start, fsync_stop; WT_CONNECTION_IMPL *conn; WT_DECL_RET; WT_LOG *log; WT_LSN sync_lsn; int64_t release_buffered, release_bytes; + uint64_t fsync_duration_usecs; int yield_count; bool locked; @@ -1406,9 +1420,15 @@ __wt_log_release(WT_SESSION_IMPL *session, WT_LOGSLOT *slot, bool *freep) "/%" PRIu32, log->log_dir_fh->name, sync_lsn.l.file, sync_lsn.l.offset)); + WT_ERR(__wt_epoch(session, &fsync_start)); WT_ERR(__wt_fsync(session, log->log_dir_fh, true)); + WT_ERR(__wt_epoch(session, &fsync_stop)); + fsync_duration_usecs = + WT_TIMEDIFF_US(fsync_stop, fsync_start); log->sync_dir_lsn = sync_lsn; WT_STAT_FAST_CONN_INCR(session, log_sync_dir); + WT_STAT_FAST_CONN_INCRV(session, + log_sync_dir_duration, fsync_duration_usecs); } /* @@ -1422,7 +1442,13 @@ __wt_log_release(WT_SESSION_IMPL *session, WT_LOGSLOT *slot, bool *freep) log->log_fh->name, sync_lsn.l.file, sync_lsn.l.offset)); WT_STAT_FAST_CONN_INCR(session, log_sync); + WT_ERR(__wt_epoch(session, &fsync_start)); WT_ERR(__wt_fsync(session, log->log_fh, true)); + WT_ERR(__wt_epoch(session, &fsync_stop)); + fsync_duration_usecs = + WT_TIMEDIFF_US(fsync_stop, fsync_start); + WT_STAT_FAST_CONN_INCRV(session, + log_sync_duration, fsync_duration_usecs); log->sync_lsn = sync_lsn; WT_ERR(__wt_cond_signal(session, log->log_sync_cond)); } diff --git a/src/support/stat.c b/src/support/stat.c index 3d7c4fc71d9..c1ee6cc2031 100644 --- a/src/support/stat.c +++ b/src/support/stat.c @@ -646,7 +646,9 @@ static const char * const __stats_connection_desc[] = { "log: log server thread advances write LSN", "log: log server thread write LSN walk skipped", "log: log sync operations", + "log: log sync time duration (usecs)", "log: log sync_dir operations", + "log: log sync_dir time duration (usecs)", "log: log write operations", "log: logging bytes consolidated", "log: maximum log file size", @@ -684,6 +686,10 @@ static const char * const __stats_connection_desc[] = { "transaction: transaction checkpoint total time (msecs)", "transaction: transaction checkpoints", "transaction: transaction failures due to cache overflow", + "transaction: transaction fsync calls for checkpoint after allocating the transaction ID", + "transaction: transaction fsync calls for checkpoint before allocating the transaction ID", + "transaction: transaction fsync duration for checkpoint after allocating the transaction ID", + "transaction: transaction fsync duration for checkpoint before allocating the transaction ID", "transaction: transaction range of IDs currently pinned", "transaction: transaction range of IDs currently pinned by a checkpoint", "transaction: transaction range of IDs currently pinned by named snapshots", @@ -852,7 +858,9 @@ __wt_stat_connection_clear_single(WT_CONNECTION_STATS *stats) stats->log_write_lsn = 0; stats->log_write_lsn_skip = 0; stats->log_sync = 0; + stats->log_sync_duration = 0; stats->log_sync_dir = 0; + stats->log_sync_dir_duration = 0; stats->log_writes = 0; stats->log_slot_consolidated = 0; /* not clearing log_max_filesize */ @@ -890,6 +898,10 @@ __wt_stat_connection_clear_single(WT_CONNECTION_STATS *stats) /* not clearing txn_checkpoint_time_total */ stats->txn_checkpoint = 0; stats->txn_fail_cache = 0; + stats->txn_fsync_post = 0; + stats->txn_fsync_pre = 0; + stats->txn_fsync_post_duration = 0; + stats->txn_fsync_pre_duration = 0; /* not clearing txn_pinned_range */ /* not clearing txn_pinned_checkpoint_range */ /* not clearing txn_pinned_snapshot_range */ @@ -1078,7 +1090,10 @@ __wt_stat_connection_aggregate( to->log_write_lsn += WT_STAT_READ(from, log_write_lsn); to->log_write_lsn_skip += WT_STAT_READ(from, log_write_lsn_skip); to->log_sync += WT_STAT_READ(from, log_sync); + to->log_sync_duration += WT_STAT_READ(from, log_sync_duration); to->log_sync_dir += WT_STAT_READ(from, log_sync_dir); + to->log_sync_dir_duration += + WT_STAT_READ(from, log_sync_dir_duration); to->log_writes += WT_STAT_READ(from, log_writes); to->log_slot_consolidated += WT_STAT_READ(from, log_slot_consolidated); @@ -1128,6 +1143,12 @@ __wt_stat_connection_aggregate( WT_STAT_READ(from, txn_checkpoint_time_total); to->txn_checkpoint += WT_STAT_READ(from, txn_checkpoint); to->txn_fail_cache += WT_STAT_READ(from, txn_fail_cache); + to->txn_fsync_post += WT_STAT_READ(from, txn_fsync_post); + to->txn_fsync_pre += WT_STAT_READ(from, txn_fsync_pre); + to->txn_fsync_post_duration += + WT_STAT_READ(from, txn_fsync_post_duration); + to->txn_fsync_pre_duration += + WT_STAT_READ(from, txn_fsync_pre_duration); to->txn_pinned_range += WT_STAT_READ(from, txn_pinned_range); to->txn_pinned_checkpoint_range += WT_STAT_READ(from, txn_pinned_checkpoint_range); diff --git a/src/txn/txn_ckpt.c b/src/txn/txn_ckpt.c index c1b435d9897..2930856fd7c 100644 --- a/src/txn/txn_ckpt.c +++ b/src/txn/txn_ckpt.c @@ -350,6 +350,7 @@ __checkpoint_verbose_track(WT_SESSION_IMPL *session, static int __txn_checkpoint(WT_SESSION_IMPL *session, const char *cfg[]) { + struct timespec fsync_start, fsync_stop; struct timespec start, stop, verb_timer; WT_CONNECTION_IMPL *conn; WT_DECL_RET; @@ -359,6 +360,7 @@ __txn_checkpoint(WT_SESSION_IMPL *session, const char *cfg[]) WT_TXN_STATE *txn_state; void *saved_meta_next; u_int i; + uint64_t fsync_duration_usecs; bool full, idle, logging, tracking; const char *txn_cfg[] = { WT_CONFIG_BASE(session, WT_SESSION_begin_transaction), "isolation=snapshot", NULL }; @@ -424,7 +426,13 @@ __txn_checkpoint(WT_SESSION_IMPL *session, const char *cfg[]) * completion. Do it after flushing the pages to give the * asynchronous flush as much time as possible before we wait. */ + WT_ERR(__wt_epoch(session, &fsync_start)); WT_ERR(__checkpoint_apply(session, cfg, __wt_checkpoint_sync)); + WT_ERR(__wt_epoch(session, &fsync_stop)); + fsync_duration_usecs = WT_TIMEDIFF_US(fsync_stop, fsync_start); + WT_STAT_FAST_CONN_INCR(session, txn_fsync_pre); + WT_STAT_FAST_CONN_INCRV(session, + txn_fsync_pre_duration, fsync_duration_usecs); /* Tell logging that we are about to start a database checkpoint. */ if (full && logging) @@ -523,7 +531,13 @@ __txn_checkpoint(WT_SESSION_IMPL *session, const char *cfg[]) * Checkpoints have to hit disk (it would be reasonable to configure for * lazy checkpoints, but we don't support them yet). */ + WT_ERR(__wt_epoch(session, &fsync_start)); WT_ERR(__checkpoint_apply(session, cfg, __wt_checkpoint_sync)); + WT_ERR(__wt_epoch(session, &fsync_stop)); + fsync_duration_usecs = WT_TIMEDIFF_US(fsync_stop, fsync_start); + WT_STAT_FAST_CONN_INCR(session, txn_fsync_post); + WT_STAT_FAST_CONN_INCRV(session, + txn_fsync_post_duration, fsync_duration_usecs); WT_ERR(__checkpoint_verbose_track(session, "sync completed", &verb_timer)); |