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
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
|
/**
* Tests that the server logs ops on the secondary if and only if they are slow to apply.
* We should only report ops if they take longer than "slowMS" to apply on a secondary.
* We intentionally target CRUD ops in this test, since we know we should be the only ones
* issuing them. See below for details on how we simulate quickness and slowness.
*/
(function() {
"use strict";
load("jstests/replsets/rslib.js");
load("jstests/libs/fail_point_util.js");
let name = "log_secondary_oplog_application";
let rst = ReplSetTest({name: name, nodes: 2});
rst.startSet();
let nodes = rst.nodeList();
rst.initiate({
"_id": name,
"members": [{"_id": 0, "host": nodes[0]}, {"_id": 1, "host": nodes[1], "priority": 0}]
});
let primary = rst.getPrimary();
let secondary = rst.getSecondary();
/**
* Part 1: Issue a fast op and make sure that we do *not* log it.
* We ensure the op is always considered fast by vastly increasing the "slowMS" threshold.
*/
// Create collection explicitly so the insert doesn't have to do it.
assert.commandWorked(primary.getDB(name).createCollection("fastOp"));
rst.awaitReplication();
// Set "slowMS" to a very high value (in milliseconds).
assert.commandWorked(secondary.getDB(name).setProfilingLevel(1, 60 * 60 * 1000));
// Issue a write and make sure we replicate it.
assert.commandWorked(primary.getDB(name)["fastOp"].insert({"fast": "cheetah"}));
rst.awaitReplication();
// The op should not have been logged.
assert.throws(function() {
checkLog.contains(secondary, "cheetah", 1 * 1000);
});
/**
* Part 2: Issue a slow op and make sure that we *do* log it when the sample rate is set to 1.
* We use a failpoint in applyOplogEntryOrGroupedInserts which blocks after we read the time at the
* start of the application of the op, and we wait there to simulate slowness.
*/
// Create collection explicitly so the insert doesn't have to do it.
assert.commandWorked(primary.getDB(name).createCollection("slowOp"));
rst.awaitReplication();
// Set "sampleRate" to 1 and "slowMS" to a low value (in milliseconds).
assert.commandWorked(secondary.getDB(name).setProfilingLevel(1, {sampleRate: 1, slowms: 20}));
// Hang right after taking note of the start time of the application.
let hangAfterRecordingOpApplicationsStartTimeFailPoint =
configureFailPoint(secondary, "hangAfterRecordingOpApplicationStartTime");
// Issue a write and make sure we've hit the failpoint before moving on.
assert.commandWorked(primary.getDB(name)["slowOp"].insert({"slow": "sloth"}));
hangAfterRecordingOpApplicationsStartTimeFailPoint.wait();
// Wait for an amount of time safely above the "slowMS" we set.
sleep(0.5 * 1000);
// Disable the hangAfterRecordingOpApplicationsStartTime failpoint so the op finish can applying.
hangAfterRecordingOpApplicationsStartTimeFailPoint.off();
// Make sure we log that insert op.
rst.awaitReplication();
checkLog.contains(secondary, "sloth");
/**
* Part 3: Issue a slow op and make sure that we do *not* log it when the sample rate is set to 0.
*/
// Set "sampleRate" to 0 and "slowMS" to a low value (in milliseconds).
assert.commandWorked(secondary.getDB(name).setProfilingLevel(1, {sampleRate: 0, slowms: 20}));
// Hang right after taking note of the start time of the application.
hangAfterRecordingOpApplicationsStartTimeFailPoint =
configureFailPoint(secondary, "hangAfterRecordingOpApplicationStartTime");
// Issue a write and make sure we've hit the failpoint before moving on.
assert.commandWorked(primary.getDB(name)["slowOp"].insert({"slow": "turtle"}));
hangAfterRecordingOpApplicationsStartTimeFailPoint.wait();
// Wait for an amount of time safely above the "slowMS" we set.
sleep(0.5 * 1000);
// Disable the hangAfterRecordingOpApplicationsStartTime failpoint so the op finish can applying.
hangAfterRecordingOpApplicationsStartTimeFailPoint.off();
// Ensure that the write was replicated.
rst.awaitReplication();
// The op should not have been logged.
assert.throws(function() {
checkLog.contains(secondary, "turtle", 1 * 1000);
});
/**
* Part 4: Issue a slow op and verify that we log it when the sample rate is 0 but log verbosity
* is set to 1.
*/
// Set the log verbosity for the replication component to 1.
setLogVerbosity(rst.nodes, {"replication": {"verbosity": 1}});
// Hang right after taking note of the start time of the application.
hangAfterRecordingOpApplicationsStartTimeFailPoint =
configureFailPoint(secondary, "hangAfterRecordingOpApplicationStartTime");
// Issue a write and make sure we've hit the failpoint before moving on.
assert.commandWorked(primary.getDB(name)["slowOp"].insert({"slow": "snail"}));
hangAfterRecordingOpApplicationsStartTimeFailPoint.wait();
// Wait for an amount of time safely above the "slowMS" we set.
sleep(0.5 * 1000);
// Disable the hangAfterRecordingOpApplicationsStartTime failpoint so the op finish can applying.
hangAfterRecordingOpApplicationsStartTimeFailPoint.off();
// Ensure that the write was replicated.
rst.awaitReplication();
// Make sure we log that insert op.
checkLog.contains(secondary, "snail");
rst.stopSet();
})();
|
