diff options
3 files changed, 78 insertions, 0 deletions
diff --git a/jstests/replsets/oplog_slow_sampling_logging.js b/jstests/replsets/oplog_slow_sampling_logging.js new file mode 100644 index 00000000000..70154d698af --- /dev/null +++ b/jstests/replsets/oplog_slow_sampling_logging.js @@ -0,0 +1,57 @@ +/** + * Ensure serverStatus reports the total time spent sampling the oplog for all storage engines that + * support OplogStones. + * @tags: [ requires_wiredtiger, requires_persistence, requires_fcv_44 ] + */ +(function() { +"use strict"; + +const kOplogDocs = 45000; +// kNumOplogSamples is derived from the number of oplog entries above. +const kNumOplogSamples = 15; +const kOplogSampleReadDelay = 1; +const kLoggingIntervalSeconds = 3; + +const testDB = "test"; + +// Force oplog sampling to occur on start up for small numbers of oplog inserts. +const replSet = new ReplSetTest({ + nodes: 1, + nodeOptions: { + setParameter: { + "maxOplogTruncationPointsDuringStartup": 10, + "oplogSamplingLogIntervalSeconds": kLoggingIntervalSeconds, + "failpoint.slowOplogSamplingReads": + tojson({mode: "alwaysOn", data: {"delay": kOplogSampleReadDelay}}) + } + } +}); +replSet.startSet(); +replSet.initiate(); + +let coll = replSet.getPrimary().getDB(testDB).getCollection("testcoll"); + +// Insert enough documents to force kNumOplogSamples to be taken on the following start up. +for (let i = 0; i < kOplogDocs; i++) { + assert.commandWorked(coll.insert({m: 1 + i})); +} + +// Restart replica set to load entries from the oplog for sampling. +replSet.stopSet(null /* signal */, true /* forRestart */); +replSet.startSet({restart: true}); + +assert.commandWorked(replSet.getPrimary().getDB(testDB).serverStatus()); + +// Err on the side of a smaller minExpectedLogs where fractional parts are concerned because +// kLoggingIntervalSeconds is not an exact interval. Rather, once interval seconds have elapsed +// since the last log message, a progress message will be logged after the current sample is +// completed. +const maxSamplesPerLog = Math.ceil(kLoggingIntervalSeconds / kOplogSampleReadDelay); +const minExpectedLogs = Math.floor(kNumOplogSamples / maxSamplesPerLog); + +checkLog.containsWithAtLeastCount( + replSet.getPrimary(), "Oplog sampling progress:", minExpectedLogs); +assert(checkLog.checkContainsOnce(replSet.getPrimary(), "Oplog sampling complete")); + +replSet.stopSet(); +})(); diff --git a/src/mongo/db/storage/wiredtiger/oplog_stone_parameters.idl b/src/mongo/db/storage/wiredtiger/oplog_stone_parameters.idl index 4737f234bd4..54afd12971c 100644 --- a/src/mongo/db/storage/wiredtiger/oplog_stone_parameters.idl +++ b/src/mongo/db/storage/wiredtiger/oplog_stone_parameters.idl @@ -57,3 +57,10 @@ server_parameters: cpp_varname: gOplogStoneSizeMB default: 0 validator: { gte: 0 } + oplogSamplingLogIntervalSeconds: + description: 'The approximate interval between log messages indicating oplog sampling progress during start up. Once interval seconds have elapsed since the last log message, a progress message will be logged after the current sample is completed. A value of zero will disable this logging.' + set_at: [ startup, runtime ] + cpp_vartype: 'AtomicWord<int>' + cpp_varname: gOplogSamplingLogIntervalSeconds + default: 10 + validator: { gte: 0 } diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp index efe60ad6653..e1d49b5a2ce 100644 --- a/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp +++ b/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp @@ -94,6 +94,7 @@ void checkOplogFormatVersion(OperationContext* opCtx, const std::string& uri) { MONGO_FAIL_POINT_DEFINE(WTWriteConflictException); MONGO_FAIL_POINT_DEFINE(WTWriteConflictExceptionForReads); +MONGO_FAIL_POINT_DEFINE(slowOplogSamplingReads); const std::string kWiredTigerEngineName = "wiredTiger"; @@ -445,7 +446,11 @@ void WiredTigerRecordStore::OplogStones::_calculateStonesBySampling(OperationCon // each logical section. auto cursor = _rs->getRandomCursorWithOptions(opCtx, extraConfig); std::vector<RecordId> oplogEstimates; + auto lastProgressLog = Date_t::now(); for (int i = 0; i < numSamples; ++i) { + auto samplingLogIntervalSeconds = gOplogSamplingLogIntervalSeconds.load(); + slowOplogSamplingReads.execute( + [&](const BSONObj& dataObj) { sleepsecs(dataObj["delay"].numberInt()); }); auto record = cursor->next(); if (!record) { // This shouldn't really happen unless the size storer values are far off from reality. @@ -455,8 +460,17 @@ void WiredTigerRecordStore::OplogStones::_calculateStonesBySampling(OperationCon return; } oplogEstimates.push_back(record->id); + + const auto now = Date_t::now(); + if (samplingLogIntervalSeconds > 0 && + now - lastProgressLog >= Seconds(samplingLogIntervalSeconds)) { + log() << "Oplog sampling progress: " << (i + 1) << " of " << numSamples + << " samples taken"; + lastProgressLog = now; + } } std::sort(oplogEstimates.begin(), oplogEstimates.end()); + log() << "Oplog sampling complete"; for (int i = 1; i <= wholeStones; ++i) { // Use every (kRandomSamplesPerStone)th sample, starting with the |