summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
Diffstat
-rw-r--r--jstests/libs/check_log.js28
-rw-r--r--jstests/replsets/log_secondary_oplog_application.js81
-rw-r--r--src/mongo/db/repl/SConscript1
-rw-r--r--src/mongo/db/repl/sync_tail.cpp59
-rw-r--r--src/mongo/db/repl/sync_tail_test.cpp72
-rw-r--r--src/mongo/util/clock_source_mock.h18
6 files changed, 237 insertions, 22 deletions
diff --git a/jstests/libs/check_log.js b/jstests/libs/check_log.js
index ee05375b7c6..8977ce95223 100644
--- a/jstests/libs/check_log.js
+++ b/jstests/libs/check_log.js
@@ -29,23 +29,19 @@ var checkLog;
* the provided 'msg' is found in the logs, or 5 minutes have elapsed. Throws an exception
* on timeout.
*/
- var contains = function(conn, msg) {
- assert.soon(
- function() {
- var logMessages = getGlobalLog(conn);
- if (logMessages === null) {
- return false;
- }
- for (var i = 0; i < logMessages.length; i++) {
- if (logMessages[i].indexOf(msg) != -1) {
- return true;
- }
- }
+ var contains = function(conn, msg, timeout = 5 * 60 * 1000) {
+ assert.soon(function() {
+ var logMessages = getGlobalLog(conn);
+ if (logMessages === null) {
return false;
- },
- 'Could not find log entries containing the following message: ' + msg,
- 5 * 60 * 1000,
- 300);
+ }
+ for (var i = 0; i < logMessages.length; i++) {
+ if (logMessages[i].indexOf(msg) != -1) {
+ return true;
+ }
+ }
+ return false;
+ }, 'Could not find log entries containing the following message: ' + msg, timeout, 300);
};
/*
diff --git a/jstests/replsets/log_secondary_oplog_application.js b/jstests/replsets/log_secondary_oplog_application.js
new file mode 100644
index 00000000000..39df90a068f
--- /dev/null
+++ b/jstests/replsets/log_secondary_oplog_application.js
@@ -0,0 +1,81 @@
+/**
+ * Tests that the server logs ops on the secondary if and only if they are slow to apply.
+ * We should only report ops if they take longer than "slowMS" to apply on a secondary.
+ * We intentionally target CRUD ops in this test, since we know we should be the only ones
+ * issuing them. See below for details on how we simulate quickness and slowness.
+ */
+
+(function() {
+ "use strict";
+ load("jstests/libs/check_log.js");
+
+ let name = "log_secondary_oplog_application";
+ let rst = ReplSetTest({name: name, nodes: 2});
+ rst.startSet();
+
+ let nodes = rst.nodeList();
+ rst.initiate({
+ "_id": name,
+ "members": [{"_id": 0, "host": nodes[0]}, {"_id": 1, "host": nodes[1], "priority": 0}]
+ });
+
+ let primary = rst.getPrimary();
+ let secondary = rst.getSecondary();
+
+ /**
+ * Part 1: Issue a fast op and make sure that we do *not* log it.
+ * We ensure the op is always considered fast by vastly increasing the "slowMS" threshold.
+ */
+
+ // Create collection explicitly so the insert doesn't have to do it.
+ assert.commandWorked(primary.getDB(name).createCollection("fastOp"));
+ rst.awaitReplication();
+
+ // Set "slowMS" to a very high value (in milliseconds).
+ assert.commandWorked(secondary.getDB(name).setProfilingLevel(1, 60 * 60 * 1000));
+
+ // Issue a write and make sure we replicate it.
+ assert.commandWorked(primary.getDB(name)["fastOp"].insert({"fast": "cheetah"}));
+ rst.awaitReplication();
+
+ // The op should not have been logged.
+ assert.throws(function() {
+ checkLog.contains(secondary, "applied op: CRUD", 1 * 1000);
+ });
+
+ /**
+ * Part 2: Issue a slow op and make sure that we *do* log it.
+ * We use a failpoint in SyncTail::syncApply which blocks after we read the time at the start
+ * of the application of the op, and we wait there to simulate slowness.
+ */
+
+ // Create collection explicitly so the insert doesn't have to do it.
+ assert.commandWorked(primary.getDB(name).createCollection("slowOp"));
+ rst.awaitReplication();
+
+ // Set "slowMS" to a low value (in milliseconds).
+ assert.commandWorked(secondary.getDB(name).setProfilingLevel(1, 20));
+
+ // Hang right after taking note of the start time of the application.
+ assert.commandWorked(secondary.adminCommand(
+ {configureFailPoint: "hangAfterRecordingOpApplicationStartTime", mode: "alwaysOn"}));
+
+ // Issue a write and make sure we've hit the failpoint before moving on.
+ assert.commandWorked(primary.getDB(name)["slowOp"].insert({"slow": "sloth"}));
+ checkLog.contains(secondary,
+ "syncApply - fail point hangAfterRecordingOpApplicationStartTime enabled");
+
+ // Wait for an amount of time safely above the "slowMS" we set.
+ sleep(0.5 * 1000);
+
+ // Disable the failpoint so the op finish can applying.
+ assert.commandWorked(secondary.adminCommand(
+ {configureFailPoint: "hangAfterRecordingOpApplicationStartTime", mode: "off"}));
+
+ // Make sure we log that insert op.
+ rst.awaitReplication();
+ checkLog.contains(secondary, "applied op: CRUD");
+
+ rst.stopSet();
+
+})(); \ No newline at end of file
diff --git a/src/mongo/db/repl/SConscript b/src/mongo/db/repl/SConscript
index cdb85f50644..7508f0d75f2 100644
--- a/src/mongo/db/repl/SConscript
+++ b/src/mongo/db/repl/SConscript
@@ -725,6 +725,7 @@ env.CppUnitTest(
'$BUILD_DIR/mongo/db/auth/authmocks',
'$BUILD_DIR/mongo/db/dbdirectclient',
'$BUILD_DIR/mongo/db/commands/mongod_fcv',
+ '$BUILD_DIR/mongo/util/clock_source_mock',
'idempotency_test_fixture',
'oplog_buffer_blocking_queue',
'oplog_interface_local',
diff --git a/src/mongo/db/repl/sync_tail.cpp b/src/mongo/db/repl/sync_tail.cpp
index f5e11dda175..e848471f83c 100644
--- a/src/mongo/db/repl/sync_tail.cpp
+++ b/src/mongo/db/repl/sync_tail.cpp
@@ -88,6 +88,7 @@ namespace repl {
namespace {
MONGO_FAIL_POINT_DEFINE(pauseBatchApplicationBeforeCompletion);
+MONGO_FAIL_POINT_DEFINE(hangAfterRecordingOpApplicationStartTime);
// The oplog entries applied
Counter64 opsAppliedStats;
@@ -227,6 +228,41 @@ NamespaceStringOrUUID getNsOrUUID(const NamespaceString& nss, const BSONObj& op)
return nss;
}
+/**
+ * Used for logging a report of ops that take longer than "slowMS" to apply. This is called
+ * right before returning from syncApply, and it returns the same status.
+ */
+Status finishAndLogApply(ClockSource* clockSource,
+ Status finalStatus,
+ Date_t applyStartTime,
+ OpTypeEnum opType,
+ const BSONObj& op) {
+
+ if (finalStatus.isOK()) {
+ auto applyEndTime = clockSource->now();
+ auto diffMS = durationCount<Milliseconds>(applyEndTime - applyStartTime);
+
+ // This op was slow to apply, so we should log a report of it.
+ if (diffMS > serverGlobalParams.slowMS) {
+
+ StringBuilder s;
+ s << "applied op: ";
+
+ if (opType == OpTypeEnum::kCommand) {
+ s << "command ";
+ } else {
+ s << "CRUD ";
+ }
+
+ s << redact(op);
+ s << ", took " << diffMS << "ms";
+
+ log() << s.str();
+ }
+ }
+ return finalStatus;
+}
+
} // namespace
// static
@@ -263,17 +299,30 @@ Status SyncTail::syncApply(OperationContext* opCtx,
return status;
};
+ auto clockSource = opCtx->getServiceContext()->getFastClockSource();
+ auto applyStartTime = clockSource->now();
+
+ if (MONGO_FAIL_POINT(hangAfterRecordingOpApplicationStartTime)) {
+ log() << "syncApply - fail point hangAfterRecordingOpApplicationStartTime enabled. "
+ << "Blocking until fail point is disabled. ";
+ MONGO_FAIL_POINT_PAUSE_WHILE_SET(hangAfterRecordingOpApplicationStartTime);
+ }
+
auto opType = OpType_parse(IDLParserErrorContext("syncApply"), op["op"].valuestrsafe());
+ auto finishApply = [&](Status status) {
+ return finishAndLogApply(clockSource, status, applyStartTime, opType, op);
+ };
+
if (opType == OpTypeEnum::kNoop) {
if (nss.db() == "") {
return Status::OK();
}
Lock::DBLock dbLock(opCtx, nss.db(), MODE_X);
OldClientContext ctx(opCtx, nss.ns());
- return applyOp(ctx.db());
+ return finishApply(applyOp(ctx.db()));
} else if (OplogEntry::isCrudOpType(opType)) {
- return writeConflictRetry(opCtx, "syncApply_CRUD", nss.ns(), [&] {
+ return finishApply(writeConflictRetry(opCtx, "syncApply_CRUD", nss.ns(), [&] {
// Need to throw instead of returning a status for it to be properly ignored.
try {
AutoGetCollection autoColl(opCtx, getNsOrUUID(nss, op), MODE_IX);
@@ -300,9 +349,9 @@ Status SyncTail::syncApply(OperationContext* opCtx,
ex.addContext(str::stream() << "Failed to apply operation: " << redact(op));
throw;
}
- });
+ }));
} else if (opType == OpTypeEnum::kCommand) {
- return writeConflictRetry(opCtx, "syncApply_command", nss.ns(), [&] {
+ return finishApply(writeConflictRetry(opCtx, "syncApply_command", nss.ns(), [&] {
// A command may need a global write lock. so we will conservatively go
// ahead and grab one for non-transaction commands.
// Transactions have to acquire the same locks on secondaries as on primary.
@@ -322,7 +371,7 @@ Status SyncTail::syncApply(OperationContext* opCtx,
Status status = applyCommand_inlock(opCtx, op, entry, oplogApplicationMode);
incrementOpsAppliedStats();
return status;
- });
+ }));
}
MONGO_UNREACHABLE;
diff --git a/src/mongo/db/repl/sync_tail_test.cpp b/src/mongo/db/repl/sync_tail_test.cpp
index f85242ecd42..14f73d4d0dc 100644
--- a/src/mongo/db/repl/sync_tail_test.cpp
+++ b/src/mongo/db/repl/sync_tail_test.cpp
@@ -68,6 +68,7 @@
#include "mongo/stdx/mutex.h"
#include "mongo/unittest/death_test.h"
#include "mongo/unittest/unittest.h"
+#include "mongo/util/clock_source_mock.h"
#include "mongo/util/md5.hpp"
#include "mongo/util/scopeguard.h"
#include "mongo/util/string_map.h"
@@ -1558,6 +1559,77 @@ TEST_F(SyncTailTest, DropDatabaseSucceedsInRecovering) {
ASSERT_OK(runOpSteadyState(op));
}
+TEST_F(SyncTailTest, LogSlowOpApplicationWhenSuccessful) {
+ // This duration is greater than "slowMS", so the op would be considered slow.
+ auto applyDuration = serverGlobalParams.slowMS * 10;
+ getServiceContext()->setFastClockSource(
+ stdx::make_unique<AutoAdvancingClockSourceMock>(Milliseconds(applyDuration)));
+
+ // We are inserting into an existing collection.
+ const NamespaceString nss("test.t");
+ createCollection(_opCtx.get(), nss, {});
+ auto entry = makeOplogEntry(OpTypeEnum::kInsert, nss, {});
+
+ startCapturingLogMessages();
+ ASSERT_OK(
+ SyncTail::syncApply(_opCtx.get(), entry.toBSON(), OplogApplication::Mode::kSecondary));
+
+ // Use a builder for easier escaping. We expect the operation to be logged.
+ StringBuilder expected;
+ expected << "applied op: CRUD { op: \"i\", ns: \"test.t\", o: { _id: 0 }, ts: Timestamp(1, 1), "
+ "t: 1, h: 1, v: 2 }, took "
+ << applyDuration << "ms";
+ ASSERT_EQUALS(1, countLogLinesContaining(expected.str()));
+}
+
+TEST_F(SyncTailTest, DoNotLogSlowOpApplicationWhenFailed) {
+ // This duration is greater than "slowMS", so the op would be considered slow.
+ auto applyDuration = serverGlobalParams.slowMS * 10;
+ getServiceContext()->setFastClockSource(
+ stdx::make_unique<AutoAdvancingClockSourceMock>(Milliseconds(applyDuration)));
+
+ // We are trying to insert into a non-existing database.
+ NamespaceString nss("test.t");
+ auto entry = makeOplogEntry(OpTypeEnum::kInsert, nss, {});
+
+ startCapturingLogMessages();
+ ASSERT_THROWS(
+ SyncTail::syncApply(_opCtx.get(), entry.toBSON(), OplogApplication::Mode::kSecondary),
+ ExceptionFor<ErrorCodes::NamespaceNotFound>);
+
+ // Use a builder for easier escaping. We expect the operation to *not* be logged
+ // even thought it was slow, since we couldn't apply it successfully.
+ StringBuilder expected;
+ expected << "applied op: CRUD { op: \"i\", ns: \"test.t\", o: { _id: 0 }, ts: Timestamp(1, 1), "
+ "t: 1, h: 1, v: 2 }, took "
+ << applyDuration << "ms";
+ ASSERT_EQUALS(0, countLogLinesContaining(expected.str()));
+}
+
+TEST_F(SyncTailTest, DoNotLogNonSlowOpApplicationWhenSuccessful) {
+ // This duration is below "slowMS", so the op would *not* be considered slow.
+ auto applyDuration = serverGlobalParams.slowMS / 10;
+ getServiceContext()->setFastClockSource(
+ stdx::make_unique<AutoAdvancingClockSourceMock>(Milliseconds(applyDuration)));
+
+ // We are inserting into an existing collection.
+ const NamespaceString nss("test.t");
+ createCollection(_opCtx.get(), nss, {});
+ auto entry = makeOplogEntry(OpTypeEnum::kInsert, nss, {});
+
+ startCapturingLogMessages();
+ ASSERT_OK(
+ SyncTail::syncApply(_opCtx.get(), entry.toBSON(), OplogApplication::Mode::kSecondary));
+
+ // Use a builder for easier escaping. We expect the operation to *not* be logged,
+ // since it wasn't slow to apply.
+ StringBuilder expected;
+ expected << "applied op: CRUD { op: \"i\", ns: \"test.t\", o: { _id: 0 }, ts: Timestamp(1, 1), "
+ "t: 1, h: 1, v: 2 }, took "
+ << applyDuration << "ms";
+ ASSERT_EQUALS(0, countLogLinesContaining(expected.str()));
+}
+
class SyncTailTxnTableTest : public SyncTailTest {
public:
void setUp() override {
diff --git a/src/mongo/util/clock_source_mock.h b/src/mongo/util/clock_source_mock.h
index 0fc968a430e..a257775bb7c 100644
--- a/src/mongo/util/clock_source_mock.h
+++ b/src/mongo/util/clock_source_mock.h
@@ -43,7 +43,7 @@ namespace mongo {
/**
* Mock clock source that returns a fixed time until explicitly advanced.
*/
-class ClockSourceMock final : public ClockSource {
+class ClockSourceMock : public ClockSource {
public:
/**
* Constructs a ClockSourceMock with the current time set to the Unix epoch.
@@ -75,6 +75,22 @@ private:
std::vector<Alarm> _alarms;
};
+/**
+ * Mock clock source where reading the clock also advances the current time by a fixed interval.
+ */
+class AutoAdvancingClockSourceMock : public ClockSourceMock {
+public:
+ AutoAdvancingClockSourceMock(Milliseconds increment) : _increment(increment) {}
+
+ Date_t now() override {
+ ClockSourceMock::advance(_increment);
+ return ClockSourceMock::now();
+ }
+
+private:
+ const Milliseconds _increment;
+};
+
class SharedClockSourceAdapter final : public ClockSource {
public:
explicit SharedClockSourceAdapter(std::shared_ptr<ClockSource> source)
View Lorry Controller Status