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
|
/**
* Tests that 'totalOplogSlotDurationMicros' is included in "Slow query" logs and the profiler.
* 'totalOplogSlotDurationMicros' indicates how long an oplog hole is held open by an operation: it
* is the time between acquiring a commit timestamp for a write and committing/rolling back that
* write.
*/
(function() {
"use strict";
load("jstests/libs/log.js");
load("jstests/libs/profiler.js");
const dbName = "testDB";
const collName = jsTestName();
const writeComment = "updateSomething";
const rst = new ReplSetTest({nodes: 1});
rst.startSet();
rst.initiate();
const conn = rst.getPrimary();
const testDB = conn.getDB(dbName);
const testColl = testDB.getCollection(collName);
// Set up some data and up the profiling (and 'Slow query') threshold to log everything.
assert.commandWorked(testColl.insert({_id: "doc"}));
assert.commandWorked(testDB.runCommand({profile: 1, slowms: 0}));
jsTest.log("Run an identifiable (when logged) write operation.");
assert.commandWorked(testDB.runCommand({
update: collName,
updates: [{'q': {}, 'u': {'updateField': 1}}],
writeConcern: {w: "majority"},
comment: writeComment,
}));
function getOplogSlotDuration(logLine) {
const pattern = /totalOplogSlotDurationMicros"?:([0-9]+)/;
const match = logLine.match(pattern);
assert(match, `pattern ${pattern} did not match line: ${logLine}`);
const micros = parseInt(match[1]);
assert.gte(micros, 0, match);
return micros;
}
const mongodLog = assert.commandWorked(testDB.adminCommand({getLog: "global"})).log;
const slowQueryLogLine = findMatchingLogLine(
mongodLog, {msg: "Slow query", comment: writeComment, "u": {"updateField": 1}});
assert(slowQueryLogLine, "Expected to find a 'Slow query' log msg for an update operation.");
assert(getOplogSlotDuration(slowQueryLogLine),
"Expected to find a 'totalOplogSlotDurationMicros' entry in a 'Slow query' log msg.");
profilerHasAtLeastOneMatchingEntryOrThrow({
profileDB: testDB,
filter: {
"ns": testColl.getFullName(),
"op": "update",
"command.comment": writeComment,
"totalOplogSlotDurationMicros": {"$exists": true},
}
});
rst.stopSet();
}());
|
