summaryrefslogtreecommitdiff
path: root/jstests/replsets/oplog_slow_sampling_logging.js
blob: 87767ad234efec473362aebec88fa3043e796a83 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
/**
 * Ensure serverStatus reports the total time spent sampling the oplog for all storage engines that
 * support OplogStones.
 * @tags: [
 *   requires_persistence,
 *   requires_wiredtiger,
 * ]
 */
(function() {
"use strict";

const kOplogDocs = 47500;
// kNumOplogSamples is derived from the number of oplog entries above.
// Formula is kRandomSamplesPerStone * numRecords / estRecordsPerStone, where
// kRandomSamplesPerStone = 10
// numRecords = kOplogDocs + some small number of bookkeeping records
// estRecordsPerStone = (16MB / average oplog record size), empirically about 28700 records.
// The number of samples is picked to NOT be divisible by kLoggingIntervalSeconds so we can
// safely miss a logging interval without failing; this can sometimes happen due to clock
// adjustment.
const kNumOplogSamples = 16;
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}}),
            logComponentVerbosity: tojson({storage: {verbosity: 2}}),
        }
    }
});
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.
let docsRemaining = kOplogDocs;
let docsDone = 0;
while (docsRemaining) {
    let batchDocs = docsRemaining > 1000 ? 1000 : docsRemaining;
    let bulk = coll.initializeUnorderedBulkOp();
    for (let i = 0; i < batchDocs; i++) {
        bulk.insert({m: 1 + i + docsDone});
    }
    assert.commandWorked(bulk.execute());
    docsRemaining -= batchDocs;
    docsDone += batchDocs;
}

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