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
|
/**
* Verifies that the SessionWorkflow provides a slow loop log when appropriate.
* @tags: [
* requires_sharding,
* multiversion_incompatible
* ]
*/
(function() {
'use strict';
load("jstests/libs/fail_point_util.js");
load("jstests/libs/log.js"); // For findMatchingLogLine
const expectedLogId = 6983000;
const sleepMillisInQueryFilter = 200;
const sleepMillisBetweenQueries = 100;
// This specific test doesn't care about precision in the times reported by the server. Since the
// server may be doing some extra work before listening for another message, and since the server
// and this test may vary in the precision by which they convert ticks to milliseconds, we allow
// some error when comparing local times to server times.
const errorAllowance = 0.9;
const expectedFields = [
"totalMillis",
"activeMillis",
"receiveWorkMillis",
"processWorkMillis",
"sendResponseMillis",
"finalizeMillis",
];
function getSlowLogAndCount(conn) {
let allLogLines = checkLog.getGlobalLog(conn);
let slowSessionWorkflowLines = findMatchingLogLines(allLogLines, {id: expectedLogId});
let slowLinesArr = [];
if (slowSessionWorkflowLines !== null) {
slowLinesArr = Array.from(slowSessionWorkflowLines);
}
return {log: slowLinesArr.at(-1), count: slowLinesArr.length};
}
function getSlowLogCount(conn) {
return getSlowLogAndCount(conn).count;
}
function runTest(conn) {
let coll = conn.getCollection("test.foo");
coll.drop();
assert.commandWorked(assert.commandWorked(coll.insert({_id: 1})));
// In order to find the new log lines, a baseline needs to be established.
let slowSessionWorkflowCount = getSlowLogCount(conn);
// Do a query that we would expect to be fast. Expect no new slow SessionWorkflows are logged.
let count = coll.find({}).toArray();
assert.eq(count.length, 1, "expected 1 document");
let prevSlowSessionWorkflowCount = slowSessionWorkflowCount;
slowSessionWorkflowCount = getSlowLogCount(conn);
assert.eq(slowSessionWorkflowCount,
prevSlowSessionWorkflowCount,
"There should not be a slow SessionWorkflow log at this point but one was found.");
// Wait, then do a query beyond the 100ms threshold. Make sure the slow loop log line exists.
sleep(sleepMillisBetweenQueries);
coll.find({$where: 'function() { sleep(' + sleepMillisInQueryFilter + '); return true; }'})
.toArray();
let logAndCount = getSlowLogAndCount(conn);
prevSlowSessionWorkflowCount = slowSessionWorkflowCount;
slowSessionWorkflowCount = logAndCount.count;
assert.eq(slowSessionWorkflowCount,
prevSlowSessionWorkflowCount + 1,
"Expected to find a slow SessionWorkflow log.");
// Do some sanity checks over the actual contents of the log.
const slowLoopObj = JSON.parse(logAndCount.log);
jsTest.log(slowLoopObj);
let elapsedObj = slowLoopObj.attr.elapsed;
expectedFields.forEach((expectedField) => {
assert(expectedField in elapsedObj,
"Expected to find field but couldn't: " + expectedField);
});
let totalElapsed = elapsedObj.totalMillis;
let activeElapsed = elapsedObj.activeMillis;
let sourceWorkElapsed = elapsedObj.receiveWorkMillis;
let processWorkElapsed = elapsedObj.processWorkMillis;
assert.gte(
sourceWorkElapsed,
sleepMillisBetweenQueries * errorAllowance,
"The time reported sourcing a message didn't include the time sleeping between queries.");
assert.gte(processWorkElapsed,
sleepMillisInQueryFilter,
"The time reported processing work didn't include the sleep in the find filter.");
// When comparing server time to another server time, there is no reason to expect error.
assert.gte(activeElapsed,
processWorkElapsed,
"The time reported as active time didn't include the time processing work.");
assert.gte(
totalElapsed,
sourceWorkElapsed + activeElapsed,
"The total time reported didn't include the sum of active time and message sourcing time.");
}
// Test standalone.
const m = MongoRunner.runMongod();
runTest(m);
MongoRunner.stopMongod(m);
// Test sharded.
const st = new ShardingTest({shards: 1, mongos: 1});
runTest(st.s0);
st.stop();
})();
|
