diff options
author | Irina Yatsenko <irina.yatsenko@mongodb.com> | 2021-05-17 18:14:08 +0000 |
---|---|---|
committer | Evergreen Agent <no-reply@evergreen.mongodb.com> | 2021-06-17 14:32:32 +0000 |
commit | 5b58572d3112935f0b2bf38f1dc1dfb90ea3a25c (patch) | |
tree | 12c394306ac10ef43c480c32c76486971c37baf8 | |
parent | 676f6aed12f9f56143223ab8c6a04439d02e94a8 (diff) | |
download | mongo-5b58572d3112935f0b2bf38f1dc1dfb90ea3a25c.tar.gz |
SERVER-56501 Add into serverStatus().opcounters a subsection for deprecated opcodes
(cherry picked from commit 7465d0acdc0096ed7d966c6ed623a11e8d6199d6)
(cherry picked from commit e779656ef9c8509ec8838d4019b95c5fc4a9e81a)
-rw-r--r-- | jstests/noPassthrough/deprecated_wire_ops_lib.js | 537 | ||||
-rw-r--r-- | jstests/noPassthrough/deprecated_wire_ops_serverStatus_mongod.js | 31 | ||||
-rw-r--r-- | jstests/noPassthrough/deprecated_wire_ops_serverStatus_mongos.js | 35 | ||||
-rw-r--r-- | src/mongo/db/service_entry_point_common.cpp | 14 | ||||
-rw-r--r-- | src/mongo/db/stats/counters.cpp | 85 | ||||
-rw-r--r-- | src/mongo/db/stats/counters.h | 15 | ||||
-rw-r--r-- | src/mongo/s/commands/strategy.cpp | 10 |
7 files changed, 695 insertions, 32 deletions
diff --git a/jstests/noPassthrough/deprecated_wire_ops_lib.js b/jstests/noPassthrough/deprecated_wire_ops_lib.js new file mode 100644 index 00000000000..d12117913b2 --- /dev/null +++ b/jstests/noPassthrough/deprecated_wire_ops_lib.js @@ -0,0 +1,537 @@ +/** + * Helper routines for deprecated_wire_ops_mongod.js and deprecated_wire_ops_mongos.js. + */ +const DeprecatedWireOpsTest = function() { + "use strict"; + + if (!(this instanceof DeprecatedWireOpsTest)) { + return new DeprecatedWireOpsTest(); + } + + // Warning code for deprecated op codes or getLastError command in log. + const kDeprecatedWireOpWarningCode = 5578800; + + /** + * Extracts deprecation warning messages from server log. Returns the extracted logging + * message(s). + * + * If 'assertOpKindMatch' is true, asserts that all log entries' operations are same as + * 'expectedOpKind'. + */ + const extractDeprecationMsgFromLog = + (testDB, connId, expectedOpKind, assertOpKindMatch = false) => { + const log = assert.commandWorked(testDB.adminCommand({"getLog": "global"})).log; + const connIdStr = `conn${connId}`; + let logEntries = []; + + log.forEach((line) => { + if (line.indexOf(`"id":${kDeprecatedWireOpWarningCode}`) >= 0) { + const logEntry = JSON.parse(line); + + assert.eq(logEntry.ctx, connIdStr); + assert.eq(logEntry.id, kDeprecatedWireOpWarningCode); + assert.eq(logEntry.s, "W"); + assert.eq(logEntry.c, "COMMAND"); + if (logEntry.attr.op == expectedOpKind) { + logEntries.push(logEntry); + } else { + assert.eq(assertOpKindMatch, + false, + `Expected ${expectedOpKind} only but found ${logEntry.attr.op}`); + } + } + }); + + return logEntries; + }; + + /** + * Asserts that the warning message for legacy op codes and getLastError command is logged only + * once for 'expectedOpKind'. + */ + const assertLegacyOpWarnedOnlyOnceOn = (testDB, connId, expectedOpKind) => { + const logEntries = extractDeprecationMsgFromLog( + testDB, connId, expectedOpKind, /*assertOpKindMatch*/ true); + + // Verifies that the legacy op is logged with a warning message. + assert.eq(logEntries.length, 1); + }; + + /** + * Asserts that the number of log entries for warning messages for 'expectedOpKind' is same as + * 'expectedCount' and all log entries are triggered under 'connId' connection. + */ + const assertLegacyOpWarningMsgCountOn = (testDB, connId, expectedOpKind, expectedCount) => { + const logEntries = extractDeprecationMsgFromLog(testDB, connId, expectedOpKind); + + // Verifies that the legacy op is logged with a warning message. + assert.eq(logEntries.length, expectedCount); + }; + + /** + * Sleeps for 'ms' milliseconds with logging messages. + */ + const sleepWithLogging = (ms) => { + jsTestLog(new Date().toString() + `: sleeping for ${ms}ms...`); + sleep(ms); + jsTestLog(new Date().toString() + ": woke up"); + }; + + /** + * Gets a legacy cursor on 'coll' collection so that we can send OP_GET_MORE or + * OP_KILL_CURSORS. This can be done as follows. + * 1. Sends a OP_MSG find command with a small batch size to create a cursor. + * 2. Gets a legacy cursor object using cursorFromId() method which always uses OP_GET_MORE op + * code when hasNext() or next() is called, and OP_KILL_CURSORS op code when close() is + * called. + */ + const getLegacyCursor = (db, coll) => { + const findRes = assert.commandWorked(db.runCommand({find: coll.getName(), batchSize: 1})); + // cursor.id == 0 means the cursor reached the end of data, which must not happen. + assert.neq(findRes.cursor.id, 0); + return db.getMongo().cursorFromId(findRes.cursor.ns, findRes.cursor.id, /*batchSize*/ 2); + }; + + /** + * Runs a basic test case for log warning behavior for legacy op codes or getLastError command. + * The basic behavior is that only one warning message must be logged for the first legacy op + * or getLastError command in a period for multiple legacy op codes and/or getLastError command + * requests per each client. + * + * - 'legacyOpAction1': The first action to execute legacy ops or commands. This action is + * executed twice. + * - 'legacyOpAction2': The second action to execute legacy ops or commands. This action is + * executed only once. + * - 'verifyAction': An action to verify the results. This action is executed after every + * 'legacyOpAction1' or 'legacyOpAction2'. + */ + const runBasicLoggingBehaviorTest = (legacyOpAction1, legacyOpAction2, verifyAction) => { + legacyOpAction1(); + verifyAction(); + + legacyOpAction1(); + verifyAction(); + + legacyOpAction2(); + verifyAction(); + }; + + const nop = () => {}; + + /** + * - 'testCaseSetUp': An action to set up the test case. + * - 'legacyOpAction': An action to execute legacy ops or commands. This is executed twice. + * - 'verifyAction': An action to verify the results. This is executed after every + * 'legacyOpAction'. + * - 'sleepAction': An action on how to sleep. 'runLogAllDeprecatedWireOpsTest' sets this + * argument to 'nop' to verify the log-all behavior because the log-all behavior is only + * valid when period = 0 and when period = 0, we should not sleep at all. + */ + const runPeriodTestCase = (testCaseSetUp, legacyOpAction, verifyAction, sleepAction = nop) => { + testCaseSetUp(); + + legacyOpAction(); + verifyAction(); + + sleepAction(); + + legacyOpAction(); + verifyAction(); + }; + + /** + * Gets a setParameter document for deprecation warning period 'periodInSeconds'. + * The returned doc will be used to start up mongod or mongos. + */ + this.getParamDoc = (periodInSeconds) => { + return {setParameter: `deprecatedWireOpsWarningPeriodInSeconds=${periodInSeconds}`}; + }; + + /** + * Sets up the test environment and returns a connection 'conn', a test db 'testDB', a + * connection id 'connId', and a collection 'coll'. + * + * 'startUp' is supposed to start a mongod or sharded cluster and returns a connection to it and + * a test db. + * + * 'conn' is used to tear down the server, which means it's an input argument for tear down + * callback. + */ + this.setUp = (startUp, periodInSeconds) => { + const[conn, testDB] = startUp(periodInSeconds); + + // Figures out the connection ID. + const connId = assert.commandWorked(testDB.runCommand("hello")).connectionId; + + const coll = testDB.getCollection("a"); + coll.drop(); + + // Prepares some data for OP_QUERY, OP_GET_MORE, and OP_KILL_CURSORS. + assert.commandWorked(coll.insert({a: 0})); + assert.commandWorked(coll.insert({a: 1})); + assert.commandWorked(coll.insert({a: 2})); + + // Need to set the legacy read and write mode to issue deprecated op codes or command. + const mongo = testDB.getMongo(); + mongo.forceReadMode("legacy"); + mongo.forceWriteMode("legacy"); + + return [conn, testDB, connId, coll]; + }; + + /** + * Verifies the basic logging behavior for legacy op codes and getLastError command which is to + * log a warning messages for the first legacy op code or getLastError command in 60-minutes + * period per each client. + * + * 'setUp' is used to set up a test environment such as starting up mongod or a sharded cluster + * and getting a test database object and etc. 'tearDown' is used to tear down the test + * environment which is started by 'setUp'. + */ + this.runDeprecatedWireOpBasicLoggingBehaviorTest = (setUp, tearDown) => { + const assertLegacyOpWarnedOnlyOnceForOpKind = (expectedOpKind) => + assertLegacyOpWarnedOnlyOnceOn(testDB, connId, expectedOpKind); + + // Verifies that the server logs a warning message only once for two OP_INSERTs and one + // OP_QUERY. + let [conn, testDB, connId, coll] = setUp(); + runBasicLoggingBehaviorTest(() => coll.insert({a: 2, b: 3}), + () => coll.find().toArray(), + () => assertLegacyOpWarnedOnlyOnceForOpKind("insert")); + tearDown(conn); + + // Verifies that the server logs a warning message only once for two OP_UPDATEs and one + // OP_QUERY. + [conn, testDB, connId, coll] = setUp(); + runBasicLoggingBehaviorTest(() => coll.updateOne({a: 3}, {$set: {b: -1}}), + () => coll.find().toArray(), + () => assertLegacyOpWarnedOnlyOnceForOpKind("update")); + tearDown(conn); + + // Verifies that the server logs a warning message only once for two OP_DELETEs and one + // OP_QUERY. + [conn, testDB, connId, coll] = setUp(); + runBasicLoggingBehaviorTest(() => coll.deleteOne({a: 3}), + () => coll.find().toArray(), + () => assertLegacyOpWarnedOnlyOnceForOpKind("remove")); + tearDown(conn); + + // Verifies that the server logs a warning message for two getLastError commands and one + // OP_QUERY. + [conn, testDB, connId, coll] = setUp(); + runBasicLoggingBehaviorTest( + () => assert.commandWorked(testDB.adminCommand({getLastError: 1})), + () => coll.find().toArray(), + () => assertLegacyOpWarnedOnlyOnceForOpKind("getLastError")); + tearDown(conn); + + // Verifies that the server logs a warning message only once for two OP_QUERYs and one + // OP_INSERT. + [conn, testDB, connId, coll] = setUp(); + runBasicLoggingBehaviorTest(() => assert.eq(coll.find().toArray().length, 3), + () => coll.insert({a: 4}), + () => assertLegacyOpWarnedOnlyOnceForOpKind("query")); + tearDown(conn); + + // Verifies that the server logs a warning message only once for two OP_GET_MOREs and one + // OP_UPDATE. + [conn, testDB, connId, coll] = setUp(); + runBasicLoggingBehaviorTest( + () => { + let legacyCursor = getLegacyCursor(testDB, coll); + assert.eq(legacyCursor.hasNext(), true); + }, + () => coll.updateOne({a: 1}, {$set: {b: -1}}), + () => assertLegacyOpWarnedOnlyOnceForOpKind("getmore")); + tearDown(conn); + + // Verifies that the server logs a warning message only once for two OP_KILL_CURSORS and one + // OP_DELETE. + [conn, testDB, connId, coll] = setUp(); + runBasicLoggingBehaviorTest( + () => { + let legacyCursor = getLegacyCursor(testDB, coll); + legacyCursor.close(); + }, + () => coll.deleteOne({a: 1}), + () => assertLegacyOpWarnedOnlyOnceForOpKind("killcursors")); + tearDown(conn); + }; + + /** + * Verifies that every legacy op code and getLastError command request is logged with a warning + * message when the warning period is set to 0 seconds. + * + * 'setUp' is used to set up a test environment such as starting up mongod or a sharded cluster + * and getting a test database object and etc. 'tearDown' is used to tear down the test + * environment which is started by 'setUp'. + */ + this.runLogAllDeprecatedWireOpsTest = (setUp, tearDown) => { + const[conn, testDB, connId, coll] = setUp(); + const assertLegacyOpWarningMsgCount = (expectedOpKind, expectedCount) => + assertLegacyOpWarningMsgCountOn(testDB, connId, expectedOpKind, expectedCount); + + let nLegacyOpMsgExpected = 0; + + // Verifies that the server logs a warning message for every OP_INSERT. + runPeriodTestCase( + /*testCaseSetUp*/ + () => { + nLegacyOpMsgExpected = 0; + }, + /*legacyOpAction*/ + () => { + coll.insert({a: 1, b: 2}); + ++nLegacyOpMsgExpected; + }, + /*verifyAction*/ + () => assertLegacyOpWarningMsgCount("insert", nLegacyOpMsgExpected)); + + // Verifies that the server logs a warning message for every OP_UPDATE. + runPeriodTestCase( + /*testCaseSetUp*/ + () => { + nLegacyOpMsgExpected = 0; + }, + /*legacyOpAction*/ + () => { + coll.updateOne({a: 1}, {$set: {b: -1}}); + ++nLegacyOpMsgExpected; + }, + /*verifyAction*/ + () => assertLegacyOpWarningMsgCount("update", nLegacyOpMsgExpected)); + + // Verifies that the server logs a warning message for every OP_DELETE. + runPeriodTestCase( + /*testCaseSetUp*/ + () => { + nLegacyOpMsgExpected = 0; + }, + /*legacyOpAction*/ + () => { + coll.deleteOne({a: 1}); + ++nLegacyOpMsgExpected; + }, + /*verifyAction*/ + () => assertLegacyOpWarningMsgCount("remove", nLegacyOpMsgExpected)); + + // Verifies that the server logs a warning message for every getLastError. + runPeriodTestCase( + /*testCaseSetUp*/ + () => { + // First figure out how many getLastError commands have already been issued since + // we're in "legacy" write mode. + nLegacyOpMsgExpected = + extractDeprecationMsgFromLog(testDB, + connId, + /*expectedOpKind*/ "getLastError") + .length; + }, + /*legacyOpAction*/ + () => { + assert.commandWorked(testDB.adminCommand({getLastError: 1})); + ++nLegacyOpMsgExpected; + }, + /*verifyAction*/ + () => assertLegacyOpWarningMsgCount("getLastError", nLegacyOpMsgExpected)); + + // Verifies that the server logs a warning message for every OP_QUERY. + runPeriodTestCase( + /*testCaseSetUp*/ + () => { + nLegacyOpMsgExpected = 0; + coll.drop(); + testDB.getMongo().forceWriteMode("commands"); + assert.commandWorked(coll.insert({a: 1})); + assert.commandWorked(coll.insert({a: 2})); + assert.commandWorked(coll.insert({a: 3})); + testDB.getMongo().forceWriteMode("legacy"); + }, + /*legacyOpAction*/ + () => { + const data = coll.find().toArray(); + assert.eq(data.length, 3); + ++nLegacyOpMsgExpected; + }, + /*verifyAction*/ + () => assertLegacyOpWarningMsgCount("query", nLegacyOpMsgExpected)); + + // Verifies that the server logs a warning message for every OP_GET_MORE & OP_KILL_CURSORS. + runPeriodTestCase( + /*testCaseSetUp*/ + () => { + nLegacyOpMsgExpected = 0; + }, + /*legacyOpAction*/ + () => { + const legacyCursor = getLegacyCursor(testDB, coll); + legacyCursor.hasNext(); + legacyCursor.close(); + ++nLegacyOpMsgExpected; + }, + /*verifyAction*/ + () => { + assertLegacyOpWarningMsgCount("getmore", nLegacyOpMsgExpected); + assertLegacyOpWarningMsgCount("killcursors", nLegacyOpMsgExpected); + }); + + tearDown(conn); + }; + + /** + * Verifies that the warning period value is honored. The focus here is to verify that after the + * period expires, any legacy op code or getLastError command is logged with a warning message. + * + * 'setUp' is used to set up a test environment such as starting up mongod or a sharded cluster + * and getting a test database object and etc. 'tearDown' is used to tear down the test + * environment which is started by 'setUp'. + */ + this.runDeprecatedWireOpPeriodTest = (setUp, tearDown, periodInSeconds) => { + const[conn, testDB, connId, coll] = setUp(periodInSeconds); + const periodInMs = periodInSeconds * 1000 + 200; + const assertLegacyOpWarningMsgCount = (expectedOpKind, expectedCount) => + assertLegacyOpWarningMsgCountOn(testDB, connId, expectedOpKind, expectedCount); + + let nLegacyOpMsgExpected = 0; + + // Verifies that the server logs a warning message only once in 'periodInSeconds' for + // multiple OP_INSERTs. + runPeriodTestCase( + /*testCaseSetUp*/ + () => { + nLegacyOpMsgExpected = 0; + }, + /*legacyOpAction*/ + () => { + coll.insert({a: 1, b: 2}); + ++nLegacyOpMsgExpected; + coll.insert({a: 1, b: 2}); + coll.insert({a: 1, b: 2}); + coll.insert({a: 1, b: 2}); + }, + /*verifyAction*/ + () => assertLegacyOpWarningMsgCount("insert", nLegacyOpMsgExpected), + /*sleepAction*/ + () => sleepWithLogging(periodInMs)); + + // Verifies that the server logs a warning message only once in 'periodInSeconds' for + // multiple OP_QUERYs. + runPeriodTestCase( + /*testCaseSetUp*/ + () => { + nLegacyOpMsgExpected = 0; + coll.drop(); + testDB.getMongo().forceWriteMode("commands"); + assert.commandWorked(coll.insert({a: 1})); + assert.commandWorked(coll.insert({a: 1})); + testDB.getMongo().forceWriteMode("legacy"); + + // Sleeps to make sure the previous period expires. + sleepWithLogging(periodInMs); + }, + /*legacyOpAction*/ + () => { + assert.eq(coll.find().toArray().length, 2); + ++nLegacyOpMsgExpected; + assert.eq(coll.find().toArray().length, 2); + assert.eq(coll.find().toArray().length, 2); + }, + /*verifyAction*/ + () => assertLegacyOpWarningMsgCount("query", nLegacyOpMsgExpected), + /*sleepAction*/ + () => sleepWithLogging(periodInMs)); + + tearDown(conn); + }; + + this.runDeprecatedOpcountersInServerStatusTest = (setUp, tearDown) => { + const[conn, dbTest] = setUp(); + + const insertCount = 5; + const batchSize = 3; + + function exerciseOperations(collection) { + // Insert (each document is counted as separate insert op) + let docs = []; + for (let i = 0; i < insertCount; i++) { + docs.push({a: i}); + } + assert.commandWorked(collection.insertMany(docs)); + + // Query and getmore (one query op, count of getmore ops depends on ratio of insertCount + // to batchSize) + collection.find().batchSize(batchSize).toArray(); + + // Update (one update op even if multiple doucuments match) + assert.commandWorked(collection.updateMany({a: {$lt: insertCount}}, {$set: {b: 42}})); + + // Delete (one delete op even if multiple documents match) + // Delete everything so we can compare results of consecutive exerciseOperations. + assert.commandWorked(collection.deleteMany({a: {$lt: insertCount}})); + } + + const coll = dbTest.getCollection("opcounters"); + coll.drop(); + + const initialOpcounters = dbTest.serverStatus().opcounters; + jsTestLog("opcounters before running tests: " + tojson(initialOpcounters)); + + // Execute operations in commands mode against "coll" collection and cache the counters. + exerciseOperations(coll); + const afterCommands = dbTest.serverStatus().opcounters; + jsTestLog("opcounters after running in commands mode: " + tojson(afterCommands)); + assert.eq(undefined, afterCommands.deprecated, "should have no deprecated ops yet"); + + const queryCommands = afterCommands.query - initialOpcounters.query; + const insertCommands = afterCommands.insert - initialOpcounters.insert; + const getmoreCommands = afterCommands.getmore - initialOpcounters.getmore; + const deleteCommands = afterCommands.delete - initialOpcounters.delete; + const updateCommands = afterCommands.update - initialOpcounters.update; + + // Switch to legacy mode and execute exactly the same operations. This should add deprecated + // section to serverStatus with the same counts as we got in `afterCommands` and it should + // double the base counts. + const mongo = dbTest.getMongo(); + mongo.forceReadMode("legacy"); + mongo.forceWriteMode("legacy"); + exerciseOperations(coll); + + const afterLegacyOps = dbTest.serverStatus().opcounters; + jsTestLog("opcounters after running in legacy mode: " + tojson(afterLegacyOps)); + + const queryDeprecated = afterLegacyOps.deprecated.query; + const insertDeprecated = afterLegacyOps.deprecated.insert; + const getmoreDeprecated = afterLegacyOps.deprecated.getmore; + const deleteDeprecated = afterLegacyOps.deprecated.delete; + const updateDeprecated = afterLegacyOps.deprecated.update; + const totalDeprecated = insertDeprecated + queryDeprecated + getmoreDeprecated + + updateDeprecated + deleteDeprecated; + + // Check that the legacy operations have been accounted for in the deprecated counters and + // that they've produced the same numbers as command-based ops. + assert.eq(insertCommands, insertDeprecated, "deprecated insert"); + assert.eq(queryCommands, queryDeprecated, "deprecated query"); + assert.eq(getmoreCommands, getmoreDeprecated, "deprecated getmore"); + assert.eq(updateCommands, updateDeprecated, "deprecated update"); + assert.eq(deleteCommands, deleteDeprecated, "deprecated delete"); + assert.eq(0, afterLegacyOps.deprecated.killcursors, "deprecated killcursors"); + assert.eq(totalDeprecated, afterLegacyOps.deprecated.total, "deprecated total"); + + // Check that the legacy operations have been added to the main counters. + assert.eq(afterCommands.insert + insertDeprecated, afterLegacyOps.insert, "main insert"); + assert.eq(afterCommands.query + queryDeprecated, afterLegacyOps.query, "main query"); + assert.eq( + afterCommands.getmore + getmoreDeprecated, afterLegacyOps.getmore, "main getmore"); + assert.eq(afterCommands.update + updateDeprecated, afterLegacyOps.update, "main update"); + assert.eq(afterCommands.delete + deleteDeprecated, afterLegacyOps.delete, "main delete"); + + // Check killcursors separately to make the math above simpler. + assert.commandWorked(coll.insertMany([{a: 0}, {a: 1}, {a: 2}, {a: 3}, {a: 4}])); + let cursor = getLegacyCursor(dbTest, coll); + assert.eq(cursor.hasNext(), true); + cursor.close(); + assert.eq(1, dbTest.serverStatus().opcounters.deprecated.killcursors, "killcursors"); + + tearDown(conn); + }; +}; diff --git a/jstests/noPassthrough/deprecated_wire_ops_serverStatus_mongod.js b/jstests/noPassthrough/deprecated_wire_ops_serverStatus_mongod.js new file mode 100644 index 00000000000..876d9ede2d4 --- /dev/null +++ b/jstests/noPassthrough/deprecated_wire_ops_serverStatus_mongod.js @@ -0,0 +1,31 @@ +/** + * Verifies that the mongod accounts for the legacy opcodes in serverStatus.opcounters. + */ + +(function() { + "use strict"; + + load("jstests/noPassthrough/deprecated_wire_ops_lib.js"); + + const testHelper = new DeprecatedWireOpsTest(); + + /** + * The opcounters test switches read and write mode to legacy for the mongod instance so it's + * better + * to run the test in its own sandbox. + */ + const startUpMongod = () => { + const conn = MongoRunner.runMongod({}); + assert.neq(conn, null, `mongod failed to start up`); + const testDB = conn.getDB(jsTestName()); + assert.commandWorked(testDB.dropDatabase()); + + return [conn, testDB]; + }; + + const tearDownMongod = (conn) => { + MongoRunner.stopMongod(conn); + }; + + testHelper.runDeprecatedOpcountersInServerStatusTest(startUpMongod, tearDownMongod); +})(); diff --git a/jstests/noPassthrough/deprecated_wire_ops_serverStatus_mongos.js b/jstests/noPassthrough/deprecated_wire_ops_serverStatus_mongos.js new file mode 100644 index 00000000000..9532adffd65 --- /dev/null +++ b/jstests/noPassthrough/deprecated_wire_ops_serverStatus_mongos.js @@ -0,0 +1,35 @@ +/** + * Verifies that the mongos accounts for the legacy opcodes in serverStatus.opcounters. + * + * Without the following tag, this test suite fails on a linux-64-duroff build variant since the + * build variant does not support sharding. + * @tags: [requires_sharding] + */ + +(function() { + "use strict"; + + load("jstests/noPassthrough/deprecated_wire_ops_lib.js"); + + const testHelper = new DeprecatedWireOpsTest(); + + /** + * The opcounters test switches read and write mode to legacy for the mongos instance so it's + * better + * to run the test in its own sandbox. + */ + const startUpMongos = () => { + const st = new ShardingTest({mongos: 1, shards: 1, mongosOptions: {}}); + + const testDB = st.s.getDB(jsTestName()); + assert.commandWorked(testDB.dropDatabase()); + + return [st, testDB]; + }; + + const tearDownMongos = (shardedCluster) => { + shardedCluster.stop(); + }; + + testHelper.runDeprecatedOpcountersInServerStatusTest(startUpMongos, tearDownMongos); +})(); diff --git a/src/mongo/db/service_entry_point_common.cpp b/src/mongo/db/service_entry_point_common.cpp index b29c38a6f26..b9d737e4e06 100644 --- a/src/mongo/db/service_entry_point_common.cpp +++ b/src/mongo/db/service_entry_point_common.cpp @@ -1082,7 +1082,12 @@ DbResponse receivedQuery(OperationContext* opCtx, const Message& m, const ServiceEntryPointCommon::Hooks& behaviors) { invariant(!nss.isCommand()); + + // The legacy opcodes should be counted twice: as part of the overall opcodes' counts and on + // their own to highlight that they are being used. globalOpCounters.gotQuery(); + globalOpCounters.gotQueryDeprecated(); + ServerReadConcernMetrics::get(opCtx)->recordReadConcern(repl::ReadConcernArgs::get(opCtx)); DbMessage d(m); @@ -1110,6 +1115,8 @@ DbResponse receivedQuery(OperationContext* opCtx, } void receivedKillCursors(OperationContext* opCtx, const Message& m) { + globalOpCounters.gotKillCursorsDeprecated(); + LastError::get(opCtx->getClient()).disable(); DbMessage dbmessage(m); int n = dbmessage.pullInt(); @@ -1138,6 +1145,8 @@ void receivedInsert(OperationContext* opCtx, const NamespaceString& nsString, co auto insertOp = InsertOp::parseLegacy(m); invariant(insertOp.getNamespace() == nsString); + globalOpCounters.gotInsertsDeprecated(insertOp.getDocuments().size()); + for (const auto& obj : insertOp.getDocuments()) { Status status = AuthorizationSession::get(opCtx->getClient())->checkAuthForInsert(opCtx, nsString, obj); @@ -1148,6 +1157,7 @@ void receivedInsert(OperationContext* opCtx, const NamespaceString& nsString, co } void receivedUpdate(OperationContext* opCtx, const NamespaceString& nsString, const Message& m) { + globalOpCounters.gotUpdateDeprecated(); auto updateOp = UpdateOp::parseLegacy(m); auto& singleUpdate = updateOp.getUpdates()[0]; invariant(updateOp.getNamespace() == nsString); @@ -1171,6 +1181,7 @@ void receivedUpdate(OperationContext* opCtx, const NamespaceString& nsString, co } void receivedDelete(OperationContext* opCtx, const NamespaceString& nsString, const Message& m) { + globalOpCounters.gotDeleteDeprecated(); auto deleteOp = DeleteOp::parseLegacy(m); auto& singleDelete = deleteOp.getDeletes()[0]; invariant(deleteOp.getNamespace() == nsString); @@ -1187,7 +1198,10 @@ DbResponse receivedGetMore(OperationContext* opCtx, const Message& m, CurOp& curop, bool* shouldLogOpDebug) { + // The legacy opcodes should be counted twice: as part of the overall opcodes' counts and on + // their own to highlight that they are being used. globalOpCounters.gotGetMore(); + globalOpCounters.gotGetMoreDeprecated(); DbMessage d(m); const char* ns = d.getns(); diff --git a/src/mongo/db/stats/counters.cpp b/src/mongo/db/stats/counters.cpp index 6e8bbfdadb2..a39a7946a4e 100644 --- a/src/mongo/db/stats/counters.cpp +++ b/src/mongo/db/stats/counters.cpp @@ -80,48 +80,54 @@ void OpCounters::gotCommand() { _command.fetchAndAdd(1); } -void OpCounters::gotOp(int op, bool isCommand) { - switch (op) { - case dbInsert: /*gotInsert();*/ - break; // need to handle multi-insert - case dbQuery: - if (isCommand) - gotCommand(); - else - gotQuery(); - break; - - case dbUpdate: - gotUpdate(); - break; - case dbDelete: - gotDelete(); - break; - case dbGetMore: - gotGetMore(); - break; - case dbKillCursors: - case opReply: - break; - default: - log() << "OpCounters::gotOp unknown op: " << op << endl; - } +void OpCounters::gotInsertsDeprecated(int n) { + RARELY _checkWrap(); + _insertDeprecated.fetchAndAdd(n); +} +void OpCounters::gotQueryDeprecated() { + RARELY _checkWrap(); + _queryDeprecated.fetchAndAdd(1); +} +void OpCounters::gotUpdateDeprecated() { + RARELY _checkWrap(); + _updateDeprecated.fetchAndAdd(1); +} +void OpCounters::gotDeleteDeprecated() { + RARELY _checkWrap(); + _deleteDeprecated.fetchAndAdd(1); +} +void OpCounters::gotGetMoreDeprecated() { + RARELY _checkWrap(); + _getmoreDeprecated.fetchAndAdd(1); +} +void OpCounters::gotKillCursorsDeprecated() { + RARELY _checkWrap(); + _killcursorsDeprecated.fetchAndAdd(1); } void OpCounters::_checkWrap() { const unsigned MAX = 1 << 30; - - bool wrap = _insert.loadRelaxed() > MAX || _query.loadRelaxed() > MAX || + const bool wrap = _insert.loadRelaxed() > MAX || _query.loadRelaxed() > MAX || _update.loadRelaxed() > MAX || _delete.loadRelaxed() > MAX || _getmore.loadRelaxed() > MAX || _command.loadRelaxed() > MAX; - if (wrap) { + const bool wrapDeprecated = _insertDeprecated.loadRelaxed() > MAX || + _queryDeprecated.loadRelaxed() > MAX || _updateDeprecated.loadRelaxed() > MAX || + _deleteDeprecated.loadRelaxed() > MAX || _getmoreDeprecated.loadRelaxed() > MAX; + + if (wrap || wrapDeprecated) { _insert.store(0); _query.store(0); _update.store(0); _delete.store(0); _getmore.store(0); _command.store(0); + + _insertDeprecated.store(0); + _queryDeprecated.store(0); + _updateDeprecated.store(0); + _deleteDeprecated.store(0); + _getmoreDeprecated.store(0); } } @@ -133,6 +139,27 @@ BSONObj OpCounters::getObj() const { b.append("delete", _delete.loadRelaxed()); b.append("getmore", _getmore.loadRelaxed()); b.append("command", _command.loadRelaxed()); + + auto queryDep = _queryDeprecated.loadRelaxed(); + auto getmoreDep = _getmoreDeprecated.loadRelaxed(); + auto killcursorsDep = _killcursorsDeprecated.loadRelaxed(); + auto updateDep = _updateDeprecated.loadRelaxed(); + auto deleteDep = _deleteDeprecated.loadRelaxed(); + auto insertDep = _insertDeprecated.loadRelaxed(); + auto totalDep = queryDep + getmoreDep + killcursorsDep + updateDep + deleteDep + insertDep; + + if (totalDep > 0) { + BSONObjBuilder d(b.subobjStart("deprecated")); + + d.append("total", totalDep); + d.append("insert", insertDep); + d.append("query", queryDep); + d.append("update", updateDep); + d.append("delete", deleteDep); + d.append("getmore", getmoreDep); + d.append("killcursors", killcursorsDep); + } + return b.obj(); } diff --git a/src/mongo/db/stats/counters.h b/src/mongo/db/stats/counters.h index e30efaca25a..e2431510cea 100644 --- a/src/mongo/db/stats/counters.h +++ b/src/mongo/db/stats/counters.h @@ -58,7 +58,12 @@ public: void gotGetMore(); void gotCommand(); - void gotOp(int op, bool isCommand); + void gotInsertsDeprecated(int n); + void gotQueryDeprecated(); + void gotUpdateDeprecated(); + void gotDeleteDeprecated(); + void gotGetMoreDeprecated(); + void gotKillCursorsDeprecated(); BSONObj getObj() const; @@ -91,6 +96,14 @@ private: CacheAligned<AtomicUInt32> _delete; CacheAligned<AtomicUInt32> _getmore; CacheAligned<AtomicUInt32> _command; + + // Counters for deprecated opcodes. + CacheAligned<AtomicUInt32> _insertDeprecated; + CacheAligned<AtomicUInt32> _queryDeprecated; + CacheAligned<AtomicUInt32> _updateDeprecated; + CacheAligned<AtomicUInt32> _deleteDeprecated; + CacheAligned<AtomicUInt32> _getmoreDeprecated; + CacheAligned<AtomicUInt32> _killcursorsDeprecated; }; extern OpCounters globalOpCounters; diff --git a/src/mongo/s/commands/strategy.cpp b/src/mongo/s/commands/strategy.cpp index 82f364e6ae3..b4005289cc1 100644 --- a/src/mongo/s/commands/strategy.cpp +++ b/src/mongo/s/commands/strategy.cpp @@ -421,6 +421,7 @@ void runCommand(OperationContext* opCtx, DbResponse Strategy::queryOp(OperationContext* opCtx, const NamespaceString& nss, DbMessage* dbm) { globalOpCounters.gotQuery(); + globalOpCounters.gotQueryDeprecated(); const QueryMessage q(*dbm); @@ -610,6 +611,7 @@ DbResponse Strategy::getMore(OperationContext* opCtx, const NamespaceString& nss const long long cursorId = dbm->pullInt64(); globalOpCounters.gotGetMore(); + globalOpCounters.gotGetMoreDeprecated(); // TODO: Handle stale config exceptions here from coll being dropped or sharded during op for // now has same semantics as legacy request. @@ -667,7 +669,7 @@ void Strategy::killCursors(OperationContext* opCtx, DbMessage* dbm) { << ".", numCursors >= 1 && numCursors < 30000); - globalOpCounters.gotOp(dbKillCursors, false); + globalOpCounters.gotKillCursorsDeprecated(); ConstDataCursor cursors(dbm->getArray(numCursors)); @@ -714,12 +716,16 @@ void Strategy::writeOp(OperationContext* opCtx, DbMessage* dbm) { switch (msg.operation()) { case dbInsert: { - return InsertOp::parseLegacy(msg).serialize({}); + auto op = InsertOp::parseLegacy(msg); + globalOpCounters.gotInsertsDeprecated(op.getDocuments().size()); + return op.serialize({}); } case dbUpdate: { + globalOpCounters.gotUpdateDeprecated(); return UpdateOp::parseLegacy(msg).serialize({}); } case dbDelete: { + globalOpCounters.gotDeleteDeprecated(); return DeleteOp::parseLegacy(msg).serialize({}); } default: |