diff options
author | Bernard Gorman <bernard.gorman@gmail.com> | 2017-03-03 14:56:40 +0000 |
---|---|---|
committer | David Storch <david.storch@10gen.com> | 2017-03-07 11:07:35 -0500 |
commit | 3cba97198638df3750e3b455e2ad57af7ee536ae (patch) | |
tree | 44a314410a2a47ca4d4ef6503a9c0b6db8614470 | |
parent | c2c8abc0a682be21c911e51ad368b09fd5d73ed7 (diff) | |
download | mongo-3cba97198638df3750e3b455e2ad57af7ee536ae.tar.gz |
SERVER-28196 Make legacy query and getMore appear in a consistent format across currentOp, profiler and logs
Closes #1139
Signed-off-by: David Storch <david.storch@10gen.com>
-rw-r--r-- | jstests/core/profile_getmore.js | 22 | ||||
-rw-r--r-- | jstests/noPassthrough/currentop_query.js | 59 | ||||
-rw-r--r-- | jstests/noPassthrough/log_find_getmore.js | 115 | ||||
-rw-r--r-- | src/mongo/db/curop.cpp | 27 | ||||
-rw-r--r-- | src/mongo/db/curop.h | 17 | ||||
-rw-r--r-- | src/mongo/db/query/find.cpp | 10 |
6 files changed, 207 insertions, 43 deletions
diff --git a/jstests/core/profile_getmore.js b/jstests/core/profile_getmore.js index 09ec72d4bd4..a72f0ea236f 100644 --- a/jstests/core/profile_getmore.js +++ b/jstests/core/profile_getmore.js @@ -8,7 +8,6 @@ var testDB = db.getSiblingDB("profile_getmore"); assert.commandWorked(testDB.dropDatabase()); var coll = testDB.getCollection("test"); - var isLegacyReadMode = (db.getMongo().readMode() === "legacy"); testDB.setProfilingLevel(2); @@ -37,11 +36,11 @@ assert.eq(profileObj.docsExamined, 2, tojson(profileObj)); assert.eq(profileObj.cursorid, cursorId, tojson(profileObj)); assert.eq(profileObj.nreturned, 2, tojson(profileObj)); + assert.eq(profileObj.query.getMore, cursorId, tojson(profileObj)); + assert.eq(profileObj.query.collection, coll.getName(), tojson(profileObj)); assert.eq(profileObj.query.batchSize, 2, tojson(profileObj)); - if (!isLegacyReadMode) { - assert.eq(profileObj.originatingCommand.filter, {a: {$gt: 0}}); - assert.eq(profileObj.originatingCommand.sort, {a: 1}); - } + assert.eq(profileObj.originatingCommand.filter, {a: {$gt: 0}}); + assert.eq(profileObj.originatingCommand.sort, {a: 1}); assert.eq(profileObj.planSummary, "IXSCAN { a: 1 }", tojson(profileObj)); assert(profileObj.execStats.hasOwnProperty("stage"), tojson(profileObj)); assert(profileObj.hasOwnProperty("responseLength"), tojson(profileObj)); @@ -110,11 +109,10 @@ assert.eq(profileObj.ns, coll.getFullName(), tojson(profileObj)); assert.eq(profileObj.op, "getmore", tojson(profileObj)); - if (!isLegacyReadMode) { - assert.eq(profileObj.originatingCommand.pipeline[0], - {$match: {a: {$gte: 0}}}, - tojson(profileObj)); - } + assert.eq(profileObj.query.getMore, cursorId, tojson(profileObj)); + assert.eq(profileObj.query.collection, coll.getName(), tojson(profileObj)); + assert.eq( + profileObj.originatingCommand.pipeline[0], {$match: {a: {$gte: 0}}}, tojson(profileObj)); assert.eq(profileObj.cursorid, cursorId, tojson(profileObj)); assert.eq(profileObj.nreturned, 20, tojson(profileObj)); assert.eq(profileObj.planSummary, "IXSCAN { a: 1 }", tojson(profileObj)); @@ -122,7 +120,5 @@ assert.eq(profileObj.keysExamined, 20, tojson(profileObj)); assert.eq(profileObj.docsExamined, 20, tojson(profileObj)); assert.eq(profileObj.appName, "MongoDB Shell", tojson(profileObj)); - if (!isLegacyReadMode) { - assert.eq(profileObj.originatingCommand.hint, {a: 1}, tojson(profileObj)); - } + assert.eq(profileObj.originatingCommand.hint, {a: 1}, tojson(profileObj)); })(); diff --git a/jstests/noPassthrough/currentop_query.js b/jstests/noPassthrough/currentop_query.js index c4e2d87c1a6..dd5c0992dbb 100644 --- a/jstests/noPassthrough/currentop_query.js +++ b/jstests/noPassthrough/currentop_query.js @@ -271,7 +271,8 @@ }); // - // Confirm currentOp content for getMore. + // Confirm currentOp content for getMore. This case tests command and legacy getMore with an + // originating find command. // coll.drop(); for (i = 0; i < 10; ++i) { @@ -284,15 +285,10 @@ TestData.commandResult = cmdRes; - var filter; - if (params.readMode === "legacy") { - filter = {"op": "getmore", "query.filter.$comment": "currentop_query"}; - } else { - filter = { - "query.getMore": TestData.commandResult.cursor.id, - "originatingCommand.filter.$comment": "currentop_query" - }; - } + var filter = { + "query.getMore": TestData.commandResult.cursor.id, + "originatingCommand.filter.$comment": "currentop_query" + }; confirmCurrentOpContents({ test: function() { @@ -306,6 +302,49 @@ delete TestData.commandResult; // + // Confirm that currentOp displays upconverted getMore and originatingCommand in the case of + // a legacy query. + // + if (params.readMode === "legacy") { + let filter = { + "query.getMore": {$gt: 0}, + "query.collection": "currentop_query", + "query.batchSize": 2, + originatingCommand: { + find: "currentop_query", + filter: {}, + ntoreturn: 2, + comment: "currentop_query" + } + }; + + confirmCurrentOpContents({ + test: function() { + // Temporarily disable hanging yields so that we can iterate the first batch. + assert.commandWorked( + db.adminCommand({configureFailPoint: "setYieldAllLocksHang", mode: "off"})); + + let cursor = + db.currentop_query.find({}).comment("currentop_query").batchSize(2); + + // Exhaust the current batch so that the next request will force a getMore. + while (cursor.objsLeftInBatch() > 0) { + cursor.next(); + } + + // Set yields to hang so that we can check currentOp output. + assert.commandWorked(db.adminCommand( + {configureFailPoint: "setYieldAllLocksHang", mode: "alwaysOn"})); + + assert.eq(cursor.itcount(), 8); + }, + operation: "getmore", + planSummary: "COLLSCAN", + currentOpFilter: filter + }); + } + + // // Confirm 512 byte size limit for currentOp query field. // coll.drop(); diff --git a/jstests/noPassthrough/log_find_getmore.js b/jstests/noPassthrough/log_find_getmore.js new file mode 100644 index 00000000000..347749bc909 --- /dev/null +++ b/jstests/noPassthrough/log_find_getmore.js @@ -0,0 +1,115 @@ +/** + * Confirms that the log output for command and legacy find and getMore are in the expected format. + * Legacy operations should be upconverted to match the format of their command counterparts. + */ +(function() { + "use strict"; + + // For checkLog and getLatestProfilerEntry. + load("jstests/libs/check_log.js"); + load("jstests/libs/profiler.js"); + + const conn = MongoRunner.runMongod(); + assert.neq(null, conn, "mongod was unable to start up"); + + const testDB = conn.getDB("log_getmore"); + const coll = testDB.test; + + assert.commandWorked(testDB.dropDatabase()); + + for (let i = 1; i <= 10; ++i) { + assert.writeOK(coll.insert({a: i})); + } + + assert.commandWorked(coll.createIndex({a: 1})); + + // Set the diagnostic logging threshold to capture all operations, and enable profiling so that + // we can easily retrieve cursor IDs in all cases. + assert.commandWorked(testDB.setProfilingLevel(2, -1)); + + // + // Command tests. + // + testDB.getMongo().forceReadMode("commands"); + + // TEST: Verify the log format of the find command. + let cursor = coll.find({a: {$gt: 0}}).sort({a: 1}).skip(1).limit(10).hint({a: 1}).batchSize(5); + cursor.next(); // Perform initial query and retrieve first document in batch. + + let cursorid = getLatestProfilerEntry(testDB).cursorid; + + let logLine = + 'command log_getmore.test appName: "MongoDB Shell" command: find { find: "test", filter:' + + ' { a: { $gt: 0.0 } }, skip: 1.0, batchSize: 5.0, limit: 10.0, singleBatch: false, sort:' + + ' { a: 1.0 }, hint: { a: 1.0 } }'; + + // Check the logs to verify that find appears as above. + checkLog.contains(conn, logLine); + + // TEST: Verify the log format of a getMore command following a find command. + + assert.eq(cursor.itcount(), 8); // Iterate the cursor established above to trigger getMore. + + logLine = 'command log_getmore.test appName: "MongoDB Shell" command: getMore { getMore: ' + + cursorid + ', collection: "test", batchSize: 5.0 } originatingCommand: { find: "test", ' + + 'filter: { a: { $gt: 0.0 } }, skip: 1.0, batchSize: 5.0, limit: 10.0, singleBatch: ' + + 'false, sort: { a: 1.0 }, hint: { a: 1.0 } }'; + + checkLog.contains(conn, logLine); + + // TEST: Verify the log format of a getMore command following an aggregation. + cursor = coll.aggregate([{$match: {a: {$gt: 0}}}], {cursor: {batchSize: 0}, hint: {a: 1}}); + cursorid = getLatestProfilerEntry(testDB).cursorid; + + assert.eq(cursor.itcount(), 10); + + logLine = 'command log_getmore.test appName: "MongoDB Shell" command: getMore { getMore: ' + + cursorid + ', collection: "test" } originatingCommand: { aggregate: "test", pipeline: ' + + '[ { $match: { a: { $gt: 0.0 } } } ], cursor: { batchSize: 0.0 }, hint: { a: 1.0 } }'; + + checkLog.contains(conn, logLine); + + // + // Legacy tests. + // + testDB.getMongo().forceReadMode("legacy"); + + // TEST: Verify the log format of a legacy find. This should be upconverted to resemble a find + // command. + cursor = coll.find({a: {$gt: 0}}).sort({a: 1}).skip(1).limit(10).hint({a: 1}).batchSize(5); + cursor.next(); + + cursorid = getLatestProfilerEntry(testDB).cursorid; + + logLine = + 'query log_getmore.test appName: "MongoDB Shell" query: { find: "test", filter: { a: { ' + + '$gt: 0.0 } }, skip: 1, ntoreturn: 5, sort: { a: 1.0 }, hint: { a: 1.0 } }'; + + checkLog.contains(conn, logLine); + + // TEST: Verify that a legacy getMore following a find is logged in the expected format. This + // should be upconverted to resemble a getMore command, with the preceding upconverted legacy + // find in the originatingCommand field. + + assert.eq(cursor.itcount(), 8); // Iterate the cursor established above to trigger getMore. + + logLine = 'getmore log_getmore.test appName: "MongoDB Shell" query: { getMore: ' + cursorid + + ', collection: "test", batchSize: 5 } originatingCommand: { find: "test", filter: { a: {' + + ' $gt: 0.0 } }, skip: 1, ntoreturn: 5, sort: { a: 1.0 }, hint: { a: 1.0 } }'; + + checkLog.contains(conn, logLine); + + // TEST: Verify that a legacy getMore following an aggregation is logged in the expected format. + // This should be upconverted to resemble a getMore command, with the preceding aggregation in + // the originatingCommand field. + cursor = coll.aggregate([{$match: {a: {$gt: 0}}}], {cursor: {batchSize: 0}, hint: {a: 1}}); + cursorid = getLatestProfilerEntry(testDB).cursorid; + + assert.eq(cursor.itcount(), 10); + + logLine = 'getmore log_getmore.test appName: "MongoDB Shell" query: { getMore: ' + cursorid + + ', collection: "test", batchSize: 0 } originatingCommand: { aggregate: "test", pipeline:' + + ' [ { $match: { a: { $gt: 0.0 } } } ], cursor: { batchSize: 0.0 }, hint: { a: 1.0 } }'; + + checkLog.contains(conn, logLine); +})(); diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp index 3b5f71f23ce..51016d486ce 100644 --- a/src/mongo/db/curop.cpp +++ b/src/mongo/db/curop.cpp @@ -39,7 +39,6 @@ #include "mongo/db/client.h" #include "mongo/db/commands.h" #include "mongo/db/commands/server_status_metric.h" -#include "mongo/db/cursor_id.h" #include "mongo/db/json.h" #include "mongo/db/query/getmore_request.h" #include "mongo/db/query/plan_summary_stats.h" @@ -69,10 +68,8 @@ const std::vector<const char*> kDollarQueryModifiers = { "$maxTimeMS", }; -/** - * For a find using the OP_QUERY protocol (as opposed to the commands protocol), upconverts the - * "query" field so that the profiling entry matches that of the find command. - */ +} // namespace + BSONObj upconvertQueryEntry(const BSONObj& query, const NamespaceString& nss, int ntoreturn, @@ -128,10 +125,6 @@ BSONObj upconvertQueryEntry(const BSONObj& query, return bob.obj(); } -/** - * For a getMore using OP_GET_MORE, as opposed to getMore command, upconverts the "query" field so - * that the profiling entry matches that of the getMore command. - */ BSONObj upconvertGetMoreEntry(const NamespaceString& nss, CursorId cursorId, int ntoreturn) { return GetMoreRequest(nss, cursorId, @@ -143,8 +136,6 @@ BSONObj upconvertGetMoreEntry(const NamespaceString& nss, CursorId cursorId, int .toBSON(); } -} // namespace - /** * This type decorates a Client object with a stack of active CurOp objects. * @@ -432,7 +423,16 @@ string OpDebug::report(Client* client, } } - auto query = curop.query(); + BSONObj query; + + // If necessary, upconvert legacy find operations so that their log lines resemble their find + // command counterpart. + if (!iscommand && networkOp == dbQuery) { + query = + upconvertQueryEntry(curop.query(), NamespaceString(curop.getNS()), ntoreturn, ntoskip); + } else { + query = curop.query(); + } if (!query.isEmpty()) { if (iscommand) { @@ -556,9 +556,6 @@ void OpDebug::append(const CurOp& curop, upconvertQueryEntry(curop.query(), nss, ntoreturn, ntoskip), maxElementSize, &b); - } else if (!iscommand && networkOp == dbGetMore) { - appendAsObjOrString( - "query", upconvertGetMoreEntry(nss, cursorid, ntoreturn), maxElementSize, &b); } else if (curop.haveQuery()) { const char* fieldName = (logicalOp == LogicalOp::opCommand) ? "command" : "query"; appendAsObjOrString(fieldName, curop.query(), maxElementSize, &b); diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h index f0aea88f81d..4e0ef0d2d7b 100644 --- a/src/mongo/db/curop.h +++ b/src/mongo/db/curop.h @@ -33,6 +33,7 @@ #include "mongo/base/disallow_copying.h" #include "mongo/db/commands.h" +#include "mongo/db/cursor_id.h" #include "mongo/db/operation_context.h" #include "mongo/db/server_options.h" #include "mongo/platform/atomic_word.h" @@ -327,7 +328,7 @@ public: } /** - * Sets the original command object. Used only by the getMore command. + * Sets the original command object. */ void setOriginatingCommand_inlock(const BSONObj& commandObj) { _originatingCommand = commandObj.getOwned(); @@ -457,4 +458,18 @@ private: std::string _planSummary; }; + +/** + * Upconverts a legacy query object such that it matches the format of the find command. + */ +BSONObj upconvertQueryEntry(const BSONObj& query, + const NamespaceString& nss, + int ntoreturn, + int ntoskip); + +/** + * Generates a getMore command object from the specified namespace, cursor ID and batchsize. + */ +BSONObj upconvertGetMoreEntry(const NamespaceString& nss, CursorId cursorId, int ntoreturn); + } // namespace mongo diff --git a/src/mongo/db/query/find.cpp b/src/mongo/db/query/find.cpp index 9fcaa7cef02..f60bbe33ae5 100644 --- a/src/mongo/db/query/find.cpp +++ b/src/mongo/db/query/find.cpp @@ -380,9 +380,11 @@ Message getMore(OperationContext* txn, stdx::lock_guard<Client> lk(*txn->getClient()); curOp.setPlanSummary_inlock(planSummary); - // Ensure that the original query or command object is available in the slow query log, - // profiler and currentOp. - curOp.setQuery_inlock(cc->getQuery()); + // Ensure that the original query object is available in the slow query log, profiler + // and currentOp. Upconvert _query to resemble a getMore command, and set the original + // command or upconverted legacy query in the originatingCommand field. + curOp.setQuery_inlock(upconvertGetMoreEntry(nss, cursorid, ntoreturn)); + curOp.setOriginatingCommand_inlock(cc->getQuery()); } PlanExecutor::ExecState state; @@ -673,7 +675,7 @@ std::string runQuery(OperationContext* txn, nss.ns(), txn->recoveryUnit()->isReadingFromMajorityCommittedSnapshot(), qr.getOptions(), - qr.getFilter()}); + upconvertQueryEntry(q.query, qr.nss(), q.ntoreturn, q.ntoskip)}); ccId = pinnedCursor.getCursor()->cursorid(); LOG(5) << "caching executor with cursorid " << ccId << " after returning " << numResults |