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
|
/**
* 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 sleepMillisInSendResponse = 200;
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.
const prevSlowSessionWorkflowCount = getSlowLogCount(conn);
// Wait, then do a query beyond the 100ms threshold. Make sure the slow loop log line exists.
const fp = configureFailPoint(
conn, "sessionWorkflowDelaySendMessage", {millis: sleepMillisInSendResponse});
coll.find().toArray();
fp.off();
let logAndCount = getSlowLogAndCount(conn);
let slowSessionWorkflowCount = logAndCount.count;
assert.gt(slowSessionWorkflowCount,
prevSlowSessionWorkflowCount,
"Expected to find at least one 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);
});
const sendResponseElapsed = elapsedObj.sendResponseMillis;
assert.gte(sendResponseElapsed,
sleepMillisInSendResponse,
"The time reported sending a response didn't include the sleep in the failpoint.");
assert.commandWorked(
conn.adminCommand({setParameter: 1, enableDetailedConnectionHealthMetricLogLines: false}));
assert.commandWorked(conn.adminCommand({clearLog: 'global'}));
// Wait, then do a query beyond the 100ms threshold. Make sure the slow loop log line does not
// exist this time.
const fp2 = configureFailPoint(
conn, "sessionWorkflowDelaySendMessage", {millis: sleepMillisInSendResponse});
coll.find().toArray();
fp2.off();
logAndCount = getSlowLogAndCount(conn);
slowSessionWorkflowCount = logAndCount.count;
assert.eq(slowSessionWorkflowCount, 0);
}
// 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();
})();
|
