summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
Diffstat
-rw-r--r--jstests/noPassthrough/awaitable_ismaster.js31
-rw-r--r--src/mongo/db/repl/replication_info.cpp9
-rw-r--r--src/mongo/db/service_entry_point_common.cpp7
-rw-r--r--src/mongo/s/commands/cluster_is_master_cmd.cpp6
-rw-r--r--src/mongo/s/service_entry_point_mongos.cpp11
5 files changed, 36 insertions, 28 deletions
diff --git a/jstests/noPassthrough/awaitable_ismaster.js b/jstests/noPassthrough/awaitable_ismaster.js
index c0d25590771..5a9fb358964 100644
--- a/jstests/noPassthrough/awaitable_ismaster.js
+++ b/jstests/noPassthrough/awaitable_ismaster.js
@@ -4,6 +4,7 @@
*/
(function() {
"use strict";
+load("jstests/libs/fail_point_util.js");
load("jstests/libs/parallel_shell_helpers.js");
function runTest(db) {
@@ -22,16 +23,25 @@ function runTest(db) {
assert.commandWorked(
db.runCommand({isMaster: 1, topologyVersion: topologyVersionField, maxAwaitTimeMS: 0}));
- // Ensure isMaster waits for at least maxAwaitTimeMS before returning.
+ // Ensure the command waits for at least maxAwaitTimeMS before returning, and doesn't appear in
+ // slow query log even if it takes many seconds.
+ assert.commandWorked(db.adminCommand({clearLog: 'global'}));
let now = new Date();
+ jsTestLog(`Running slow isMaster`);
assert.commandWorked(
- db.runCommand({isMaster: 1, topologyVersion: topologyVersionField, maxAwaitTimeMS: 2000}));
+ db.runCommand({isMaster: 1, topologyVersion: topologyVersionField, maxAwaitTimeMS: 20000}));
let isMasterDuration = new Date() - now;
// Allow for some clock imprecision between the server and the jstest.
assert.gte(
isMasterDuration,
- 1000,
- `isMaster should have taken at least 1000ms, but completed in ${isMasterDuration}ms`);
+ 10000,
+ `isMaster should have taken at least 10000ms, but completed in ${isMasterDuration}ms`);
+
+ assert(!checkLog.checkContainsOnceJson(db.getMongo(), 51803, {
+ 'command': function(obj) {
+ return obj.hasOwnProperty('isMaster');
+ }
+ }));
// Check that when a different processId is given, the server responds immediately.
now = new Date();
@@ -148,18 +158,25 @@ function runTest(db) {
[31373, 51759]);
}
-const conn = MongoRunner.runMongod({});
+// Set command log verbosity to 0 to avoid logging *all* commands in the "slow query" log.
+const conn = MongoRunner.runMongod({setParameter: {logComponentVerbosity: tojson({command: 0})}});
assert.neq(null, conn, "mongod was unable to start up");
runTest(conn.getDB("admin"));
MongoRunner.stopMongod(conn);
-const replTest = new ReplSetTest({nodes: 1});
+const replTest = new ReplSetTest(
+ {nodes: 1, nodeOptions: {setParameter: {logComponentVerbosity: tojson({command: 0})}}});
replTest.startSet();
replTest.initiate();
runTest(replTest.getPrimary().getDB("admin"));
replTest.stopSet();
-const st = new ShardingTest({mongos: 1, shards: [{nodes: 1}], config: 1});
+const st = new ShardingTest({
+ mongos: 1,
+ shards: [{nodes: 1}],
+ config: 1,
+ other: {mongosOptions: {setParameter: {logComponentVerbosity: tojson({command: 0})}}}
+});
runTest(st.s.getDB("admin"));
st.stop();
})();
diff --git a/src/mongo/db/repl/replication_info.cpp b/src/mongo/db/repl/replication_info.cpp
index 3602c6cf9d5..0248c4f5b6c 100644
--- a/src/mongo/db/repl/replication_info.cpp
+++ b/src/mongo/db/repl/replication_info.cpp
@@ -40,6 +40,7 @@
#include "mongo/db/auth/sasl_mechanism_registry.h"
#include "mongo/db/client.h"
#include "mongo/db/commands/server_status.h"
+#include "mongo/db/curop.h"
#include "mongo/db/db_raii.h"
#include "mongo/db/dbhelpers.h"
#include "mongo/db/exec/working_set_common.h"
@@ -452,8 +453,10 @@ public:
// present if and only if topologyVersion is present in the request.
auto topologyVersionElement = cmdObj["topologyVersion"];
auto maxAwaitTimeMSField = cmdObj["maxAwaitTimeMS"];
+ auto curOp = CurOp::get(opCtx);
boost::optional<TopologyVersion> clientTopologyVersion;
boost::optional<long long> maxAwaitTimeMS;
+ boost::optional<ScopeGuard<std::function<void()>>> timerGuard;
if (topologyVersionElement && maxAwaitTimeMSField) {
clientTopologyVersion = TopologyVersion::parse(IDLParserErrorContext("TopologyVersion"),
topologyVersionElement.Obj());
@@ -472,8 +475,8 @@ public:
LOGV2_DEBUG(23904, 3, "Using maxAwaitTimeMS for awaitable isMaster protocol.");
- // Awaitable isMaster commands have high latency by design.
- opCtx->setShouldIncrementLatencyStats(false);
+ curOp->pauseTimer();
+ timerGuard.emplace([curOp]() { curOp->resumeTimer(); });
} else {
uassert(31368,
(topologyVersionElement
@@ -486,6 +489,8 @@ public:
auto currentTopologyVersion = appendReplicationInfo(
opCtx, result, 0, useLegacyResponseFields(), clientTopologyVersion, maxAwaitTimeMS);
+ timerGuard.reset(); // Resume curOp timer.
+
if (serverGlobalParams.clusterRole == ClusterRole::ConfigServer) {
const int configServerModeNumber = 2;
result.append("configsvr", configServerModeNumber);
diff --git a/src/mongo/db/service_entry_point_common.cpp b/src/mongo/db/service_entry_point_common.cpp
index 6e02dc9af25..31f0d3acbe9 100644
--- a/src/mongo/db/service_entry_point_common.cpp
+++ b/src/mongo/db/service_entry_point_common.cpp
@@ -1717,13 +1717,6 @@ DbResponse ServiceEntryPointCommon::handleRequest(OperationContext* opCtx,
DbResponse dbresponse;
if (op == dbMsg || (op == dbQuery && isCommand)) {
dbresponse = receivedCommands(opCtx, m, behaviors);
- // The hello/isMaster commands should take kMaxAwaitTimeMs at most, log if it takes twice
- // that.
- if (auto command = currentOp.getCommand();
- command && (command->getName() == "hello" || command->getName() == "isMaster")) {
- slowMsOverride =
- 2 * durationCount<Milliseconds>(SingleServerIsMasterMonitor::kMaxAwaitTime);
- }
} else if (op == dbQuery) {
invariant(!isCommand);
opCtx->markKillOnClientDisconnect();
diff --git a/src/mongo/s/commands/cluster_is_master_cmd.cpp b/src/mongo/s/commands/cluster_is_master_cmd.cpp
index 8f399ca650e..0401d196be5 100644
--- a/src/mongo/s/commands/cluster_is_master_cmd.cpp
+++ b/src/mongo/s/commands/cluster_is_master_cmd.cpp
@@ -35,6 +35,7 @@
#include "mongo/db/auth/sasl_mechanism_registry.h"
#include "mongo/db/client.h"
#include "mongo/db/commands.h"
+#include "mongo/db/curop.h"
#include "mongo/db/logical_session_id.h"
#include "mongo/db/operation_context.h"
#include "mongo/db/ops/write_ops.h"
@@ -139,6 +140,7 @@ public:
// present if and only if topologyVersion is present in the request.
auto topologyVersionElement = cmdObj["topologyVersion"];
auto maxAwaitTimeMSField = cmdObj["maxAwaitTimeMS"];
+ auto curOp = CurOp::get(opCtx);
boost::optional<TopologyVersion> clientTopologyVersion;
if (topologyVersionElement && maxAwaitTimeMSField) {
clientTopologyVersion = TopologyVersion::parse(IDLParserErrorContext("TopologyVersion"),
@@ -153,8 +155,8 @@ public:
LOGV2_DEBUG(23871, 3, "Using maxAwaitTimeMS for awaitable isMaster protocol.");
- // Awaitable isMaster commands have high latency by design. Ignore them.
- opCtx->setShouldIncrementLatencyStats(false);
+ curOp->pauseTimer();
+ ON_BLOCK_EXIT([curOp]() { curOp->resumeTimer(); });
if (clientTopologyVersion->getProcessId() == mongosTopologyVersion.getProcessId()) {
uassert(51761,
diff --git a/src/mongo/s/service_entry_point_mongos.cpp b/src/mongo/s/service_entry_point_mongos.cpp
index 8d17c402840..1ae4667c4a3 100644
--- a/src/mongo/s/service_entry_point_mongos.cpp
+++ b/src/mongo/s/service_entry_point_mongos.cpp
@@ -95,18 +95,9 @@ DbResponse ServiceEntryPointMongos::handleRequest(OperationContext* opCtx, const
if (op == dbMsg || (op == dbQuery && NamespaceString(dbm.getns()).isCommand())) {
auto dbResponse = Strategy::clientCommand(opCtx, message);
- // The hello/isMaster commands should take kMaxAwaitTimeMs at most, log if it takes twice
- // that.
- boost::optional<long long> slowMsOverride;
- if (auto command = CurOp::get(opCtx)->getCommand();
- command && (command->getName() == "hello" || command->getName() == "isMaster")) {
- slowMsOverride =
- 2 * durationCount<Milliseconds>(SingleServerIsMasterMonitor::kMaxAwaitTime);
- }
-
// Mark the op as complete, populate the response length, and log it if appropriate.
CurOp::get(opCtx)->completeAndLogOperation(
- opCtx, logv2::LogComponent::kCommand, dbResponse.response.size(), slowMsOverride);
+ opCtx, logv2::LogComponent::kCommand, dbResponse.response.size());
return dbResponse;
}
View Lorry Controller Status