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
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
|
/**
* Test that latency reported in the profiler and logs include lock acquisition time for various
* CRUD operations.
* @tags: [requires_profiling]
*/
(function() {
"use strict";
load("jstests/libs/logv2_helpers.js");
/**
* Configures the server to wait for 'millis' while acquiring locks in the CRUD path, then
* invokes the no-arguments function 'func', then disables the aforementioned lock wait
* behavior.
*/
function runWithWait(millis, func) {
assert.commandWorked(testDB.adminCommand({
configureFailPoint: "setAutoGetCollectionWait",
mode: "alwaysOn",
data: {waitForMillis: millis}
}));
func();
assert.commandWorked(testDB.adminCommand({
configureFailPoint: "setAutoGetCollectionWait",
mode: "off",
}));
}
load("jstests/libs/profiler.js");
let hangMillis = 200;
let padding = hangMillis / 10;
let conn = MongoRunner.runMongod({});
assert.neq(null, conn, "mongod was unable to start up");
let testDB = conn.getDB("test");
let testColl = testDB.lock_acquisition_time;
// Profile all operations.
assert.commandWorked(testDB.setProfilingLevel(0));
testDB.system.profile.drop();
assert.commandWorked(testDB.setProfilingLevel(2));
// Test that insert profiler/logs include lock acquisition time. Rather than parsing the log
// lines, we are just verifying that the log line appears, which implies that the recorded
// latency exceeds slowms.
runWithWait(hangMillis, function() {
assert.commandWorked(testColl.insert({a: 1}));
});
let profileEntry = getLatestProfilerEntry(testDB, {
ns: testColl.getFullName(),
"command.insert": testColl.getName(),
});
assert.gte(profileEntry.millis, hangMillis - padding);
checkLog.contains(conn,
!isJsonLog(conn) ? "insert { insert: \"lock_acquisition_time\""
: /"ns":"test.lock_acquisition_time".*"command":{"insert"/);
// Test that update profiler/logs include lock acquisition time.
runWithWait(hangMillis, function() {
assert.commandWorked(testColl.update({}, {$set: {b: 1}}));
});
profileEntry = getLatestProfilerEntry(testDB, {
ns: testColl.getFullName(),
"command.u": {$eq: {$set: {b: 1}}},
});
assert.gte(profileEntry.millis, hangMillis - padding);
checkLog.contains(conn,
!isJsonLog(conn)
? "update { update: \"lock_acquisition_time\""
: /"ns":"test.\$cmd".*"command":{"update":"lock_acquisition_time"/);
// Test that find profiler/logs include lock acquisition time.
runWithWait(hangMillis, function() {
assert.eq(1, testColl.find({b: 1}).itcount());
});
profileEntry = getLatestProfilerEntry(testDB, {
ns: testColl.getFullName(),
"command.find": testColl.getName(),
});
assert.gte(profileEntry.millis, hangMillis - padding);
checkLog.contains(conn,
!isJsonLog(conn) ? "find { find: \"lock_acquisition_time\""
: '"command":{"find":"lock_acquisition_time"');
// Test that getMore profiler/logs include lock acquisition time.
assert.commandWorked(testColl.insert([{a: 2}, {a: 3}]));
runWithWait(hangMillis, function() {
// Include a batchSize in order to ensure that a getMore is issued.
assert.eq(3, testColl.find().batchSize(2).itcount());
});
profileEntry = getLatestProfilerEntry(testDB, {
ns: testColl.getFullName(),
"command.getMore": {$exists: true},
});
assert.gte(profileEntry.millis, hangMillis - padding);
checkLog.contains(conn,
!isJsonLog(conn) ? "originatingCommand: { find: \"lock_acquisition_time\""
: '"originatingCommand":{"find":"lock_acquisition_time"');
assert.commandWorked(testColl.remove({a: {$gt: 1}}));
// Test that aggregate profiler/logs include lock acquisition time.
runWithWait(hangMillis, function() {
assert.eq(1, testColl.aggregate([{$match: {b: 1}}]).itcount());
});
profileEntry = getLatestProfilerEntry(testDB, {
ns: testColl.getFullName(),
"command.aggregate": testColl.getName(),
});
assert.gte(profileEntry.millis, hangMillis - padding);
checkLog.contains(conn,
!isJsonLog(conn) ? "aggregate { aggregate: \"lock_acquisition_time\""
: '"command":{"aggregate":"lock_acquisition_time"');
// Test that count profiler/logs include lock acquisition time.
runWithWait(hangMillis, function() {
assert.eq(1, testColl.count());
});
profileEntry = getLatestProfilerEntry(testDB, {
ns: testColl.getFullName(),
"command.count": testColl.getName(),
});
assert.gte(profileEntry.millis, hangMillis - padding);
checkLog.contains(conn,
!isJsonLog(conn) ? "count { count: \"lock_acquisition_time\""
: '"command":{"count":"lock_acquisition_time"');
// Test that distinct profiler/logs include lock acquisition time.
runWithWait(hangMillis, function() {
assert.eq([1], testColl.distinct("a"));
});
profileEntry = getLatestProfilerEntry(testDB, {
ns: testColl.getFullName(),
"command.distinct": testColl.getName(),
});
assert.gte(profileEntry.millis, hangMillis - padding);
checkLog.contains(conn,
!isJsonLog(conn) ? "distinct { distinct: \"lock_acquisition_time\""
: '"command":{"distinct":"lock_acquisition_time"');
// Test that delete profiler/logs include lock acquisition time.
runWithWait(hangMillis, function() {
assert.commandWorked(testColl.remove({b: 1}));
});
profileEntry = getLatestProfilerEntry(testDB, {
ns: testColl.getFullName(),
"command.q": {b: 1},
});
assert.gte(profileEntry.millis, hangMillis - padding);
checkLog.contains(conn,
!isJsonLog(conn) ? "delete { delete: \"lock_acquisition_time\""
: '"command":{"delete":"lock_acquisition_time"');
MongoRunner.stopMongod(conn);
}());
|
