diff options
author | Alex Li <98560274+lia394126@users.noreply.github.com> | 2022-10-31 19:24:03 +0000 |
---|---|---|
committer | Evergreen Agent <no-reply@evergreen.mongodb.com> | 2022-10-31 20:07:11 +0000 |
commit | a17d06871696dcd5f7e9e35ecac54b205e29297b (patch) | |
tree | cf251f0abdcf6ca9af814b3addedbfccc1d6ebcd | |
parent | bdac91fc1f43a22c361a846bd2e84957d4642a98 (diff) | |
download | mongo-a17d06871696dcd5f7e9e35ecac54b205e29297b.tar.gz |
SERVER-70103 Add mirroredReads succeeded and processed server status metrics
-rw-r--r-- | jstests/noPassthrough/ftdc_mirrored_reads.js | 123 | ||||
-rw-r--r-- | jstests/noPassthrough/mirror_reads.js | 127 | ||||
-rw-r--r-- | src/mongo/db/commands/find_cmd.cpp | 1 | ||||
-rw-r--r-- | src/mongo/db/mirror_maestro.cpp | 29 |
4 files changed, 191 insertions, 89 deletions
diff --git a/jstests/noPassthrough/ftdc_mirrored_reads.js b/jstests/noPassthrough/ftdc_mirrored_reads.js index 8d998d91414..613fe6ca5e2 100644 --- a/jstests/noPassthrough/ftdc_mirrored_reads.js +++ b/jstests/noPassthrough/ftdc_mirrored_reads.js @@ -3,6 +3,7 @@ * * @tags: [ * requires_replication, + * requires_fcv_62 * ] */ load('jstests/libs/ftdc.js'); @@ -18,6 +19,7 @@ const rst = new ReplSetTest({nodes: 3}); rst.startSet(); rst.initiateWithHighElectionTimeout(); const primary = rst.getPrimary(); +const secondaries = rst.getSecondaries(); function getMirroredReadsStats(node) { return node.getDB(kDbName).serverStatus({mirroredReads: 1}).mirroredReads; @@ -30,21 +32,13 @@ function getDiagnosticData(node) { return stats.mirroredReads; } -function waitForSecondariesToReceiveMirroredReads() { - const mirroredReadsSent = getMirroredReadsStats(primary).sent; - assert.soon(() => { - jsTestLog("Verifying that secondaries received " + mirroredReadsSent + - " mirrored operations"); - const secondaries = rst.getSecondaries(); - // The reads received across all secondaries. - let readsReceived = 0; - for (let i = 0; i < secondaries.length; i++) { - const stats = getMirroredReadsStats(secondaries[i]); - jsTestLog("Secondary " + secondaries[i] + " metrics: " + tojson(stats)); - readsReceived += stats.received; - } - return readsReceived == mirroredReadsSent; - }); +function getMirroredReadsProcessedAsSecondary() { + let readsProcessed = 0; + for (let i = 0; i < secondaries.length; i++) { + const stats = getMirroredReadsStats(secondaries[i]); + readsProcessed += stats.processedAsSecondary; + } + return readsProcessed; } function waitForPrimaryToSendMirroredReads(expectedReadsSeen, expectedReadsSent) { @@ -73,10 +67,11 @@ function sendAndCheckReads(rst) { primary.getDB(kDbName).runCommand({find: kCollName, filter: {}}); } + const expectedReadsSeen = mirrorableReadsSeenBefore + kOperations; + const expectedReadsSent = mirroredReadsSentBefore + (2 * kOperations); + // Wait for primary to have sent out all mirrored reads. - waitForPrimaryToSendMirroredReads(mirrorableReadsSeenBefore + kOperations, - mirroredReadsSentBefore + (2 * kOperations)); - waitForSecondariesToReceiveMirroredReads(); + waitForPrimaryToSendMirroredReads(expectedReadsSeen, expectedReadsSent); } function activateFailPoint(node) { @@ -89,45 +84,61 @@ function activateFailPoint(node) { // Mirror every mirror-able command. assert.commandWorked(primary.adminCommand({setParameter: 1, mirrorReads: {samplingRate: 1.0}})); +{ + // Send and check reads with mirrorMaestroExpectsResponse failpoint disabled by default. + jsTestLog("Verifying diagnostic collection for mirrored reads on primary"); + let primaryStatsBeforeReads = getDiagnosticData(primary); + let initialMirrorableReadsSeen = primaryStatsBeforeReads.seen; + // The following metrics are not included by default. + assert(!primaryStatsBeforeReads.hasOwnProperty('resolved')); + assert(!primaryStatsBeforeReads.hasOwnProperty('resolvedBreakdown')); -jsTestLog("Verifying diagnostic collection for mirrored reads on primary"); -let statsBeforeReads = getDiagnosticData(primary); -// The following metrics are not included by default. -assert(!statsBeforeReads.hasOwnProperty('resolved')); -assert(!statsBeforeReads.hasOwnProperty('resolvedBreakdown')); - -let initialMirrorableReadsSeen = statsBeforeReads.seen; -sendAndCheckReads(rst); -assert.soon(() => { - let mirrorableReadsSeen = getDiagnosticData(primary).seen; - jsTestLog(`Seen ${mirrorableReadsSeen} mirrored reads so far`); - return initialMirrorableReadsSeen + kOperations <= mirrorableReadsSeen; -}, "Failed to update FTDC metrics within time limit", 30000); - -jsTestLog("Verifying diagnostic collection when mirrorMaestroExpectsResponse"); -activateFailPoint(primary); -assert.soon(() => { - return getDiagnosticData(primary).hasOwnProperty('resolved'); -}, "Failed to find 'resolved' in mirrored reads FTDC metrics within time limit", 30000); -let resolvedBeforeReads = getDiagnosticData(primary).resolved; -sendAndCheckReads(rst); -assert.soon(() => { - let resolvedAfterReads = getDiagnosticData(primary).resolved; - jsTestLog(`Mirrored ${resolvedAfterReads} reads so far`); - // There are two secondaries, so `kOperations * 2` reads must be resolved. - return resolvedBeforeReads + kOperations * 2 <= resolvedAfterReads; -}, "Failed to update extended FTDC metrics within time limit", 10000); - -jsTestLog("Verifying diagnostic collection for mirrored reads on secondaries"); -assert.soon(() => { - const mirroredReadsSent = getDiagnosticData(primary).sent; - let mirroredReadsReceived = 0; - for (const secondary of rst.getSecondaries()) { - mirroredReadsReceived += getDiagnosticData(secondary).received; - } - jsTestLog(`Sent: ${mirroredReadsSent}, Received: ${mirroredReadsReceived}`); - return mirroredReadsSent == Number(mirroredReadsReceived); -}, "Failed to observe mirrored operations on secondaries in FTDC metrics", 10000); + sendAndCheckReads(rst); + + assert.soon(() => { + let mirrorableReadsSeen = getDiagnosticData(primary).seen; + jsTestLog(`Seen ${mirrorableReadsSeen} mirrored reads so far`); + return initialMirrorableReadsSeen + kOperations <= mirrorableReadsSeen; + }, "Failed to update FTDC metrics within time limit", 30000); +} + +{ + // Send and check reads after activating mirrorMaestroExpectsResponse fail point. + jsTestLog("Verifying diagnostic collection when mirrorMaestroExpectsResponse"); + activateFailPoint(primary); + assert.soon(() => { + return getDiagnosticData(primary).hasOwnProperty('resolved'); + }, "Failed to find 'resolved' in mirrored reads FTDC metrics within time limit", 30000); + + let primaryStatsBeforeReads = getDiagnosticData(primary); + let mirroredReadsProcessedBefore = getMirroredReadsProcessedAsSecondary(); + let primaryResolvedBeforeReads = primaryStatsBeforeReads.resolved; + let primarySentBeforeReads = primaryStatsBeforeReads.sent; + + sendAndCheckReads(rst); + assert.soon(() => { + let primaryResolvedAfterReads = getDiagnosticData(primary).resolved; + jsTestLog(`Mirrored ${primaryResolvedAfterReads} reads so far`); + for (let i = 0; i < secondaries.length; i++) { + jsTestLog("Secondary " + secondaries[i] + + " metrics: " + tojson(getMirroredReadsStats(secondaries[i]))); + } + // There are two secondaries, so `kOperations * 2` reads must be resolved. + return primaryResolvedBeforeReads + kOperations * 2 <= primaryResolvedAfterReads; + }, "Failed to update extended FTDC metrics within time limit", 10000); + + const primaryDataAfterReads = getDiagnosticData(primary); + const primarySentAfterReads = primaryDataAfterReads.sent; + const primaryResolvedAfterReads = primaryDataAfterReads.resolved; + assert.eq(primaryResolvedAfterReads - primaryResolvedBeforeReads, + primarySentAfterReads - primarySentBeforeReads, + primaryDataAfterReads); + + jsTestLog("Verifying diagnostic collection for mirrored reads on secondaries"); + let mirroredReadsSucceeded = getDiagnosticData(primary).succeeded; + let mirroredReadsProcessedAfter = getMirroredReadsProcessedAsSecondary(); + assert.eq(mirroredReadsSucceeded, mirroredReadsProcessedAfter - mirroredReadsProcessedBefore); +} rst.stopSet(); })(); diff --git a/jstests/noPassthrough/mirror_reads.js b/jstests/noPassthrough/mirror_reads.js index 6315c4df9b1..4a27724aeef 100644 --- a/jstests/noPassthrough/mirror_reads.js +++ b/jstests/noPassthrough/mirror_reads.js @@ -3,7 +3,7 @@ * * @tags: [ * requires_replication, - * requires_fcv_61 + * requires_fcv_62 * ] */ @@ -17,24 +17,28 @@ function setParameter({rst, value}) { const kBurstCount = 1000; const kDbName = "mirrored_reads_test"; const kCollName = "test"; +// We use an arbitrarily large maxTimeMS to avoid timing out when processing the mirrored read +// on slower builds. Otherwise, on slower builds, the primary.mirroredReads.sent metric could +// be incremented but not the secondary.mirroredReads.processedAsSecondary metric. +const kLargeMaxTimeMS = 100000000; function getMirroredReadsStats(node) { return node.getDB(kDbName).serverStatus({mirroredReads: 1}).mirroredReads; } -function sendAndCheckReads({rst, cmd, minRate, maxRate}) { +function sendAndCheckReads({rst, cmd, minRate, maxRate, burstCount}) { const primary = rst.getPrimary(); const secondaries = rst.getSecondaries(); let initialPrimaryStats = getMirroredReadsStats(primary); - let initialSecondariesReceived = []; + let initialProcessedAsSecondary = []; for (const secondary of rst.getSecondaries()) { - let secondaryMirroredReadsReceived = getMirroredReadsStats(secondary).received; - initialSecondariesReceived.push(secondaryMirroredReadsReceived); + let secondaryMirroredReadsProcessed = getMirroredReadsStats(secondary).processedAsSecondary; + initialProcessedAsSecondary.push(secondaryMirroredReadsProcessed); } - jsTestLog(`Sending ${kBurstCount} request burst of ${tojson(cmd)} to primary`); + jsTestLog(`Sending ${burstCount} request burst of ${tojson(cmd)} to primary`); - for (var i = 0; i < kBurstCount; ++i) { + for (var i = 0; i < burstCount; ++i) { rst.getPrimary().getDB(kDbName).runCommand(cmd); } @@ -43,18 +47,20 @@ function sendAndCheckReads({rst, cmd, minRate, maxRate}) { // Verify that the commands have been observed on the primary { const currentPrimaryStats = getMirroredReadsStats(primary); - assert.lte(initialPrimaryStats.seen + kBurstCount, currentPrimaryStats.seen); + assert.lte(initialPrimaryStats.seen + burstCount, currentPrimaryStats.seen); } // Verify that the reads mirrored to the secondaries have responded and secondaries receive the // same amount of mirrored reads that were sent by the primary. let currentPrimaryMirroredReadsStats; let readsSent; + let readsSucceeded; assert.soon(() => { currentPrimaryMirroredReadsStats = getMirroredReadsStats(primary); readsSent = currentPrimaryMirroredReadsStats.sent - initialPrimaryStats.sent; let readsResolved = currentPrimaryMirroredReadsStats.resolved - initialPrimaryStats.resolved; + readsSucceeded = currentPrimaryMirroredReadsStats.succeeded - initialPrimaryStats.succeeded; // The number of reads the primary has decided to mirror to secondaries, but hasn't yet // sent. let readsPending = currentPrimaryMirroredReadsStats.pending; @@ -64,23 +70,25 @@ function sendAndCheckReads({rst, cmd, minRate, maxRate}) { tojson({ sent: readsSent, resolved: readsResolved, + succeeded: readsSucceeded, pending: readsPending, seen: readsSeen })); return ((readsPending == 0) && (readsSent === readsResolved)); }, "Did not resolve all requests within time limit", 10000); - // The number of mirrored reads received across all secondaries. - let readsReceived = 0; + // The number of mirrored reads processed across all secondaries. + let readsProcessedAsSecondaryTotal = 0; for (let i = 0; i < secondaries.length; i++) { const currentSecondaryMirroredReadsStats = getMirroredReadsStats(secondaries[i]); - const received = - currentSecondaryMirroredReadsStats.received - initialSecondariesReceived[i]; - jsTestLog("Verifying number of reads received by secondary " + secondaries[i] + ": " + - tojson({received: received})); - readsReceived += received; + const processedAsSecondary = currentSecondaryMirroredReadsStats.processedAsSecondary - + initialProcessedAsSecondary[i]; + jsTestLog("Verifying number of reads processed by secondary " + secondaries[i] + ": " + + tojson({processedAsSecondary: processedAsSecondary})); + readsProcessedAsSecondaryTotal += processedAsSecondary; } - assert.eq(readsReceived, readsSent); + assert.eq(readsProcessedAsSecondaryTotal, readsSucceeded); + assert.eq(readsProcessedAsSecondaryTotal, readsSent); jsTestLog("Verifying primary statistics: " + tojson({current: currentPrimaryMirroredReadsStats, start: initialPrimaryStats})); @@ -91,7 +99,7 @@ function sendAndCheckReads({rst, cmd, minRate, maxRate}) { let rate = readsMirrored / readsSeen / numNodes; // Check that the primary has seen all the mirrored-read supporting operations we've sent it - assert.gte(readsSeen, kBurstCount); + assert.gte(readsSeen, burstCount); // Check that the rate of mirroring meets the provided criteria assert.gte(rate, minRate); assert.lte(rate, maxRate); @@ -105,7 +113,13 @@ function verifyMirrorReads(rst, cmd) { let samplingRate = 0.0; assert.commandWorked(setParameter({rst: rst, value: {samplingRate: samplingRate}})); - sendAndCheckReads({rst: rst, cmd: cmd, minRate: samplingRate, maxRate: samplingRate}); + sendAndCheckReads({ + rst: rst, + cmd: cmd, + minRate: samplingRate, + maxRate: samplingRate, + burstCount: kBurstCount + }); } { @@ -113,7 +127,13 @@ function verifyMirrorReads(rst, cmd) { let samplingRate = 1.0; assert.commandWorked(setParameter({rst: rst, value: {samplingRate: samplingRate}})); - sendAndCheckReads({rst: rst, cmd: cmd, minRate: samplingRate, maxRate: samplingRate}); + sendAndCheckReads({ + rst: rst, + cmd: cmd, + minRate: samplingRate, + maxRate: samplingRate, + burstCount: kBurstCount + }); } { @@ -124,7 +144,40 @@ function verifyMirrorReads(rst, cmd) { let min = samplingRate - gaussDeviation; assert.commandWorked(setParameter({rst: rst, value: {samplingRate: samplingRate}})); - sendAndCheckReads({rst: rst, cmd: cmd, minRate: min, maxRate: max}); + sendAndCheckReads( + {rst: rst, cmd: cmd, minRate: min, maxRate: max, burstCount: kBurstCount}); + } +} + +function verifyProcessedAsSecondary(rst) { + // Mirror every mirror-able command. + const samplingRate = 1.0; + assert.commandWorked(setParameter({rst: rst, value: {samplingRate: samplingRate}})); + + for (const secondary of rst.getSecondaries()) { + assert.commandWorked(secondary.getDB(kDbName).adminCommand({ + configureFailPoint: "failCommand", + mode: "alwaysOn", + data: { + errorCode: ErrorCodes.MaxTimeMSExpired, + failCommands: ["find"], + } + })); + } + + // With enabled fail point, check that no commands succeed or are processed, but all are + // resolved. + sendAndCheckReads({ + rst: rst, + cmd: {find: kCollName, filter: {}}, + minRate: samplingRate, + maxRate: samplingRate, + burstCount: kBurstCount + }); + + for (const secondary of rst.getSecondaries()) { + assert.commandWorked(secondary.getDB(kDbName).adminCommand( + {configureFailPoint: "failCommand", mode: "off"})); } } @@ -156,20 +209,32 @@ function verifyMirrorReads(rst, cmd) { } jsTestLog("Verifying mirrored reads for 'find' commands"); - verifyMirrorReads(rst, {find: kCollName, filter: {}}); + verifyMirrorReads(rst, {find: kCollName, filter: {}, maxTimeMS: kLargeMaxTimeMS}); jsTestLog("Verifying mirrored reads for 'count' commands"); - verifyMirrorReads(rst, {count: kCollName, query: {}}); + verifyMirrorReads(rst, {count: kCollName, query: {}, maxTimeMS: kLargeMaxTimeMS}); jsTestLog("Verifying mirrored reads for 'distinct' commands"); - verifyMirrorReads(rst, {distinct: kCollName, key: "x"}); + verifyMirrorReads(rst, {distinct: kCollName, key: "x", maxTimeMS: kLargeMaxTimeMS}); jsTestLog("Verifying mirrored reads for 'findAndModify' commands"); - verifyMirrorReads(rst, {findAndModify: kCollName, query: {}, update: {'$inc': {x: 1}}}); + verifyMirrorReads(rst, { + findAndModify: kCollName, + query: {}, + update: {'$inc': {x: 1}}, + maxTimeMS: kLargeMaxTimeMS + }); jsTestLog("Verifying mirrored reads for 'update' commands"); - verifyMirrorReads( - rst, {update: kCollName, updates: [{q: {_id: 1}, u: {'$inc': {x: 1}}}], ordered: false}); + verifyMirrorReads(rst, { + update: kCollName, + updates: [{q: {_id: 1}, u: {'$inc': {x: 1}}}], + ordered: false, + maxTimeMS: kLargeMaxTimeMS + }); + + jsTestLog("Verifying processedAsSecondary field for 'find' commands"); + verifyProcessedAsSecondary(rst); rst.stopSet(); } @@ -221,7 +286,15 @@ function verifyMirroringDistribution(rst) { let before = getMirroredReadsStats(rst.getPrimary()); - sendAndCheckReads({rst: rst, cmd: {find: kCollName, filter: {}}, minRate: min, maxRate: max}); + sendAndCheckReads({ + rst: rst, + cmd: {find: kCollName, filter: {}}, + minRate: min, + maxRate: max, + burstCount: kBurstCount, + checkExpectedReadsProcessed: false, + expectedReadsProcessed: 0 + }); let after = getMirroredReadsStats(rst.getPrimary()); diff --git a/src/mongo/db/commands/find_cmd.cpp b/src/mongo/db/commands/find_cmd.cpp index 81d6c3a5ac8..0566bc19387 100644 --- a/src/mongo/db/commands/find_cmd.cpp +++ b/src/mongo/db/commands/find_cmd.cpp @@ -65,6 +65,7 @@ #include "mongo/db/transaction/transaction_participant.h" #include "mongo/logv2/log.h" #include "mongo/rpc/get_status_from_command_result.h" +#include "mongo/util/assert_util.h" #include "mongo/util/database_name_util.h" #include "mongo/util/fail_point.h" diff --git a/src/mongo/db/mirror_maestro.cpp b/src/mongo/db/mirror_maestro.cpp index 172b7ce6bda..cf801a8947a 100644 --- a/src/mongo/db/mirror_maestro.cpp +++ b/src/mongo/db/mirror_maestro.cpp @@ -32,6 +32,7 @@ #include "mongo/db/mirror_maestro.h" +#include "mongo/rpc/get_status_from_command_result.h" #include <cmath> #include <cstdlib> #include <utility> @@ -72,9 +73,10 @@ constexpr auto kMirroredReadsParamName = "mirrorReads"_sd; constexpr auto kMirroredReadsSeenKey = "seen"_sd; constexpr auto kMirroredReadsSentKey = "sent"_sd; -constexpr auto kMirroredReadsReceivedKey = "received"_sd; +constexpr auto kMirroredReadsProcessedAsSecondaryKey = "processedAsSecondary"_sd; constexpr auto kMirroredReadsResolvedKey = "resolved"_sd; constexpr auto kMirroredReadsResolvedBreakdownKey = "resolvedBreakdown"_sd; +constexpr auto kMirroredReadsSucceededKey = "succeeded"_sd; constexpr auto kMirroredReadsPendingKey = "pending"_sd; MONGO_FAIL_POINT_DEFINE(mirrorMaestroExpectsResponse); @@ -185,12 +187,13 @@ public: BSONObjBuilder section; section.append(kMirroredReadsSeenKey, seen.loadRelaxed()); section.append(kMirroredReadsSentKey, sent.loadRelaxed()); - section.append(kMirroredReadsReceivedKey, received.loadRelaxed()); + section.append(kMirroredReadsProcessedAsSecondaryKey, processedAsSecondary.loadRelaxed()); if (MONGO_unlikely(mirrorMaestroExpectsResponse.shouldFail())) { // We only can see if the command resolved if we got a response section.append(kMirroredReadsResolvedKey, resolved.loadRelaxed()); section.append(kMirroredReadsResolvedBreakdownKey, resolvedBreakdown.toBSON()); + section.append(kMirroredReadsSucceededKey, succeeded.loadRelaxed()); } if (MONGO_unlikely(mirrorMaestroTracksPending.shouldFail())) { section.append(kMirroredReadsPendingKey, pending.loadRelaxed()); @@ -232,13 +235,22 @@ public: ResolvedBreakdownByHost resolvedBreakdown; + // Counts the number of operations (as primary) recognized as "to be mirrored". AtomicWord<CounterT> seen; + // Counts the number of remote requests (for mirroring as primary) sent over the network. AtomicWord<CounterT> sent; + // Counts the number of responses (as primary) from secondaries after mirrored operations. AtomicWord<CounterT> resolved; - // Counts the number of operations that are scheduled to be mirrored, but haven't yet been sent. + // Counts the number of responses (as primary) of successful mirrored operations. Disabled by + // default, hidden behind the mirrorMaestroExpectsResponse fail point. + AtomicWord<CounterT> succeeded; + // Counts the number of operations (as primary) that are scheduled to be mirrored, but + // haven't yet been sent. Disabled by default, hidden behind the mirrorMaestroTracksPending + // fail point. AtomicWord<CounterT> pending; - // Counts the number of mirrored operations received by this node as a secondary. - AtomicWord<CounterT> received; + // Counts the number of mirrored operations processed successfully by this node as a + // secondary. Disabled by default, hidden behind the mirrorMaestroExpectsResponse fail point. + AtomicWord<CounterT> processedAsSecondary; } gMirroredReadsSection; auto parseMirroredReadsParameters(const BSONObj& obj) { @@ -306,7 +318,7 @@ void MirrorMaestro::tryMirrorRequest(OperationContext* opCtx) noexcept { void MirrorMaestro::onReceiveMirroredRead(OperationContext* opCtx) noexcept { const auto& invocation = CommandInvocation::get(opCtx); if (MONGO_unlikely(invocation->isMirrored())) { - gMirroredReadsSection.received.fetchAndAddRelaxed(1); + gMirroredReadsSection.processedAsSecondary.fetchAndAddRelaxed(1); } } @@ -418,6 +430,11 @@ void MirrorMaestroImpl::_mirror(const std::vector<HostAndPort>& hosts, // Count both failed and successful reads as resolved gMirroredReadsSection.resolved.fetchAndAdd(1); gMirroredReadsSection.resolvedBreakdown.onResponseReceived(host); + + if (getStatusFromCommandResult(args.response.data).isOK()) { + gMirroredReadsSection.succeeded.fetchAndAdd(1); + } + LOGV2_DEBUG( 31457, 4, "Response received", "host"_attr = host, "response"_attr = args.response); |