Launching soon: The world's first vendor agnostic bug scrubLearn more & join waitlist
OPERATIONAL DEFECT DATABASE
...
...
The explain() winningPlan is inconsistent with the actual query plan. This is a bug to me since the explain() results should always match the actual query optimizer winningPlan. More info below...
nick.brewer commented on Mon, 13 Aug 2018 17:10:50 +0000: agolomoody The issue here appears to be that you were including the find() command in planCacheListPlans, which is not part of the syntax of the command - sorry I didn't notice that sooner. There is work going into improving the ease of use of these plan introspection helpers, to avoid some of the understandable confusion. We currently have an issue open tracking a potential change to allow explain() to not bypass the query planner, which would allow you to much more easily see if a cached plan is being executed. If this change is of interest to you, you can vote for it and follow along with its progress. Finally, thought it's a bit old, I recommend taking a look at this article on optimizing compound indexes, as there are improvements that could be made in both the indexes and queries being used here. -Nick agolomoody commented on Fri, 10 Aug 2018 14:35:06 +0000: mongo_query_planner_cache.json ^^ here's the output. What do you suggest we do? Would this be considered a bug? Missing documentation? Is this a feature request where we want mongo to bust its own cache when a better index is created?^ nick.brewer commented on Thu, 9 Aug 2018 21:09:21 +0000: agolomoody I believe you'll find the cached plan that is being used here if you run: db.clusters.getPlanCache().listQueryShapes() The log entry for your query does not include the fromMultiPlanner:1 flag, which indicates that the query planner was not invoked, and the query was likely executed from cache. -Nick agolomoody commented on Thu, 9 Aug 2018 20:25:40 +0000: Hey @Nick Brewer, I've replaced sensitive _id with "abcdefg" It appears that after we started using `hint()` the query planner is choosing the right index on its own. I think we should keep this issue open though since the queryPlanner should have picked the index without the help of a hint() Let me know if you have querstions. mongo_slowquery_log_verbose.log nick.brewer commented on Mon, 30 Jul 2018 21:29:38 +0000: agolomoody I'd like to get a better sense of what specifically is occurring when the winning plan is chosen. Could you temporarily increase the query log level via: db.setLogLevel(5, "query") Re-run the original query (without explain), and then add the results here? Thanks, Nick agolomoody commented on Sat, 28 Jul 2018 11:34:03 +0000: I'm not running an aggregate(), my query is a find(). I attached the result here which is still showing the bug. Attachment: queryplannerwithsortandlimit.json Thank you for looking into this, nick.brewer commented on Fri, 27 Jul 2018 20:51:59 +0000: agolomoody could you try running explain() on db.clusters.aggregate with the sort and limit phases included? Thanks, Nick nick.brewer commented on Tue, 24 Jul 2018 21:56:33 +0000: Thanks for your report. I'm looking into this, and should have more information for you soon. -Nick
Here are the explain() results production-database:PRIMARY> db.clusters.find({ deleted: { $ne: true }, "timestamps.cluster_timestamps.summary_last_updated": { $exists: true }, feed_id: "abcdefg", "timestamps.article_timestamps.first_article_published": { $lte: new Date(1531754990084), $gte: new Date(1531668590084) }, score: { $exists: true } }).explain("executionStats") { "queryPlanner" : { "plannerVersion" : 1, "namespace" : "production.clusters", "indexFilterSet" : false, "parsedQuery" : { "$and" : [ { "feed_id" : { "$eq" : "abcdefg" } }, { "timestamps.article_timestamps.first_article_published" : { "$lte" : ISODate("2018-07-16T15:29:50.084Z") } }, { "timestamps.article_timestamps.first_article_published" : { "$gte" : ISODate("2018-07-15T15:29:50.084Z") } }, { "score" : { "$exists" : true } }, { "timestamps.cluster_timestamps.summary_last_updated" : { "$exists" : true } }, { "$nor" : [ { "deleted" : { "$eq" : true } } ] } ] }, "winningPlan" : { "stage" : "FETCH", "filter" : { "$and" : [ { "score" : { "$exists" : true } }, { "timestamps.cluster_timestamps.summary_last_updated" : { "$exists" : true } } ] }, "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "feed_id" : 1, "timestamps.article_timestamps.first_article_published" : 1, "score" : -1, "timestamps.cluster_timestamps.summary_last_updated" : 1, "deleted" : 1 }, "indexName" : "feed_id.first_article_published.score-1.summary_last_updated.deleted", "isMultiKey" : false, "multiKeyPaths" : { "feed_id" : [ ], "timestamps.article_timestamps.first_article_published" : [ ], "score" : [ ], "timestamps.cluster_timestamps.summary_last_updated" : [ ], "deleted" : [ ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "feed_id" : [ "[\"abcdefg\", \"abcdefg\"]" ], "timestamps.article_timestamps.first_article_published" : [ "[new Date(1531668590084), new Date(1531754990084)]" ], "score" : [ "[MaxKey, MinKey]" ], "timestamps.cluster_timestamps.summary_last_updated" : [ "[MinKey, MaxKey]" ], "deleted" : [ "[MinKey, true)", "(true, MaxKey]" ] } } }, "rejectedPlans" : [ { "stage" : "FETCH", "filter" : { "$and" : [ { "timestamps.article_timestamps.first_article_published" : { "$lte" : ISODate("2018-07-16T15:29:50.084Z") } }, { "timestamps.article_timestamps.first_article_published" : { "$gte" : ISODate("2018-07-15T15:29:50.084Z") } }, { "score" : { "$exists" : true } }, { "timestamps.cluster_timestamps.summary_last_updated" : { "$exists" : true } }, { "$nor" : [ { "deleted" : { "$eq" : true } } ] } ] }, "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "feed_id" : 1 }, "indexName" : "feed_id_1", "isMultiKey" : false, "multiKeyPaths" : { "feed_id" : [ ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "feed_id" : [ "[\"abcdefg\", \"abcdefg\"]" ] } } }, { "stage" : "FETCH", "filter" : { "$and" : [ { "timestamps.article_timestamps.first_article_published" : { "$lte" : ISODate("2018-07-16T15:29:50.084Z") } }, { "timestamps.article_timestamps.first_article_published" : { "$gte" : ISODate("2018-07-15T15:29:50.084Z") } }, { "score" : { "$exists" : true } }, { "timestamps.cluster_timestamps.summary_last_updated" : { "$exists" : true } }, { "$nor" : [ { "deleted" : { "$eq" : true } } ] } ] }, "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "feed_id" : 1, "active" : 1 }, "indexName" : "feed_id_1_active_1", "isMultiKey" : false, "multiKeyPaths" : { "feed_id" : [ ], "active" : [ ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "feed_id" : [ "[\"abcdefg\", \"abcdefg\"]" ], "active" : [ "[MinKey, MaxKey]" ] } } }, { "stage" : "FETCH", "filter" : { "$and" : [ { "score" : { "$exists" : true } }, { "timestamps.article_timestamps.first_article_published" : { "$lte" : ISODate("2018-07-16T15:29:50.084Z") } }, { "timestamps.article_timestamps.first_article_published" : { "$gte" : ISODate("2018-07-15T15:29:50.084Z") } }, { "timestamps.cluster_timestamps.summary_last_updated" : { "$exists" : true } } ] }, "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "feed_id" : 1, "score" : -1, "timestamps.cluster_timestamps.last_updated" : -1, "deleted" : 1 }, "indexName" : "feed_id_1_score_-1_timestamps.cluster_timestamps.last_updated_-1_deleted_1", "isMultiKey" : false, "multiKeyPaths" : { "feed_id" : [ ], "score" : [ ], "timestamps.cluster_timestamps.last_updated" : [ ], "deleted" : [ ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "feed_id" : [ "[\"abcdefg\", \"abcdefg\"]" ], "score" : [ "[MaxKey, MinKey]" ], "timestamps.cluster_timestamps.last_updated" : [ "[MaxKey, MinKey]" ], "deleted" : [ "[MinKey, true)", "(true, MaxKey]" ] } } }, { "stage" : "FETCH", "filter" : { "$and" : [ { "timestamps.cluster_timestamps.summary_last_updated" : { "$exists" : true } }, { "timestamps.article_timestamps.first_article_published" : { "$lte" : ISODate("2018-07-16T15:29:50.084Z") } }, { "timestamps.article_timestamps.first_article_published" : { "$gte" : ISODate("2018-07-15T15:29:50.084Z") } }, { "score" : { "$exists" : true } }, { "$nor" : [ { "deleted" : { "$eq" : true } } ] } ] }, "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "feed_id" : 1, "timestamps.cluster_timestamps.summary_last_updated" : -1 }, "indexName" : "feed_id_1_timestamps.cluster_timestamps.summary_last_updated_-1", "isMultiKey" : false, "multiKeyPaths" : { "feed_id" : [ ], "timestamps.cluster_timestamps.summary_last_updated" : [ ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "feed_id" : [ "[\"abcdefg\", \"abcdefg\"]" ], "timestamps.cluster_timestamps.summary_last_updated" : [ "[MaxKey, MinKey]" ] } } }, { "stage" : "FETCH", "filter" : { "$and" : [ { "timestamps.article_timestamps.first_article_published" : { "$lte" : ISODate("2018-07-16T15:29:50.084Z") } }, { "timestamps.article_timestamps.first_article_published" : { "$gte" : ISODate("2018-07-15T15:29:50.084Z") } }, { "score" : { "$exists" : true } }, { "timestamps.cluster_timestamps.summary_last_updated" : { "$exists" : true } }, { "$nor" : [ { "deleted" : { "$eq" : true } } ] } ] }, "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "feed_id" : 1, "active" : 1, "_id" : -1 }, "indexName" : "feed_id_1_active_1__id_-1", "isMultiKey" : false, "multiKeyPaths" : { "feed_id" : [ ], "active" : [ ], "_id" : [ ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "feed_id" : [ "[\"abcdefg\", \"abcdefg\"]" ], "active" : [ "[MinKey, MaxKey]" ], "_id" : [ "[MaxKey, MinKey]" ] } } }, { "stage" : "FETCH", "filter" : { "$and" : [ { "score" : { "$exists" : true } }, { "timestamps.article_timestamps.first_article_published" : { "$lte" : ISODate("2018-07-16T15:29:50.084Z") } }, { "timestamps.article_timestamps.first_article_published" : { "$gte" : ISODate("2018-07-15T15:29:50.084Z") } }, { "timestamps.cluster_timestamps.summary_last_updated" : { "$exists" : true } } ] }, "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "feed_id" : 1, "score" : 1, "last_updated_at" : 1, "deleted" : 1 }, "indexName" : "feed_id_1_score_1_last_updated_at_1_deleted_1", "isMultiKey" : false, "multiKeyPaths" : { "feed_id" : [ ], "score" : [ ], "last_updated_at" : [ ], "deleted" : [ ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "feed_id" : [ "[\"abcdefg\", \"abcdefg\"]" ], "score" : [ "[MinKey, MaxKey]" ], "last_updated_at" : [ "[MinKey, MaxKey]" ], "deleted" : [ "[MinKey, true)", "(true, MaxKey]" ] } } }, { "stage" : "FETCH", "filter" : { "$and" : [ { "timestamps.article_timestamps.first_article_published" : { "$lte" : ISODate("2018-07-16T15:29:50.084Z") } }, { "timestamps.article_timestamps.first_article_published" : { "$gte" : ISODate("2018-07-15T15:29:50.084Z") } }, { "score" : { "$exists" : true } }, { "timestamps.cluster_timestamps.summary_last_updated" : { "$exists" : true } }, { "$nor" : [ { "deleted" : { "$eq" : true } } ] } ] }, "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "feed_id" : 1, "timestamps.cluster_timestamps.created" : 1 }, "indexName" : "feed_id_1_timestamps.cluster_timestamps.created_1", "isMultiKey" : false, "multiKeyPaths" : { "feed_id" : [ ], "timestamps.cluster_timestamps.created" : [ ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "feed_id" : [ "[\"abcdefg\", \"abcdefg\"]" ], "timestamps.cluster_timestamps.created" : [ "[MinKey, MaxKey]" ] } } }, { "stage" : "FETCH", "filter" : { "$and" : [ { "score" : { "$exists" : true } }, { "timestamps.article_timestamps.first_article_published" : { "$lte" : ISODate("2018-07-16T15:29:50.084Z") } }, { "timestamps.article_timestamps.first_article_published" : { "$gte" : ISODate("2018-07-15T15:29:50.084Z") } }, { "timestamps.cluster_timestamps.summary_last_updated" : { "$exists" : true } } ] }, "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "feed_id" : 1, "score" : -1, "timestamps.article_timestamps.latest_article_published" : 1, "deleted" : 1 }, "indexName" : "feed_id_1_score_-1_timestamps.article_timestamps.latest_article_published_1_deleted_1", "isMultiKey" : false, "multiKeyPaths" : { "feed_id" : [ ], "score" : [ ], "timestamps.article_timestamps.latest_article_published" : [ ], "deleted" : [ ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "feed_id" : [ "[\"abcdefg\", \"abcdefg\"]" ], "score" : [ "[MaxKey, MinKey]" ], "timestamps.article_timestamps.latest_article_published" : [ "[MinKey, MaxKey]" ], "deleted" : [ "[MinKey, true)", "(true, MaxKey]" ] } } } ] }, "executionStats" : { "executionSuccess" : true, "nReturned" : 0, "executionTimeMillis" : 77, "totalKeysExamined" : 1, "totalDocsExamined" : 0, "executionStages" : { "stage" : "FETCH", "filter" : { "$and" : [ { "score" : { "$exists" : true } }, { "timestamps.cluster_timestamps.summary_last_updated" : { "$exists" : true } } ] }, "nReturned" : 0, "executionTimeMillisEstimate" : 0, "works" : 2, "advanced" : 0, "needTime" : 0, "needYield" : 0, "saveState" : 4, "restoreState" : 4, "isEOF" : 1, "invalidates" : 0, "docsExamined" : 0, "alreadyHasObj" : 0, "inputStage" : { "stage" : "IXSCAN", "nReturned" : 0, "executionTimeMillisEstimate" : 0, "works" : 1, "advanced" : 0, "needTime" : 0, "needYield" : 0, "saveState" : 4, "restoreState" : 4, "isEOF" : 1, "invalidates" : 0, "keyPattern" : { "feed_id" : 1, "timestamps.article_timestamps.first_article_published" : 1, "score" : -1, "timestamps.cluster_timestamps.summary_last_updated" : 1, "deleted" : 1 }, "indexName" : "feed_id.first_article_published.score-1.summary_last_updated.deleted", "isMultiKey" : false, "multiKeyPaths" : { "feed_id" : [ ], "timestamps.article_timestamps.first_article_published" : [ ], "score" : [ ], "timestamps.cluster_timestamps.summary_last_updated" : [ ], "deleted" : [ ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "feed_id" : [ "[\"abcdefg\", \"abcdefg\"]" ], "timestamps.article_timestamps.first_article_published" : [ "[new Date(1531668590084), new Date(1531754990084)]" ], "score" : [ "[MaxKey, MinKey]" ], "timestamps.cluster_timestamps.summary_last_updated" : [ "[MinKey, MaxKey]" ], "deleted" : [ "[MinKey, true)", "(true, MaxKey]" ] }, "keysExamined" : 1, "seeks" : 1, "dupsTested" : 0, "dupsDropped" : 0, "seenInvalidated" : 0 } } }, "serverInfo" : { "host" : "shr0-production-database-1", "port" : 27017, "version" : "3.6.5", "gitVersion" : "a20ecd3e3a174162052ff99913bc2ca9a839d618" }, "ok" : 1, "operationTime" : Timestamp(1531755534, 164), "$gleStats" : { "lastOpTime" : Timestamp(0, 0), "electionId" : ObjectId("7fffffff00000000000000f9") }, "$clusterTime" : { "clusterTime" : Timestamp(1531755534, 164), "signature" : { "hash" : BinData(0,"2lW4vZhth5rPF7u+DqcD0rS2dxQ="), "keyId" : NumberLong("6526359001347653635") } }, "$configServerState" : { "opTime" : { "ts" : Timestamp(1531755530, 3), "t" : NumberLong(28) } } } The actual mongodb log looks like this 2018-07-16T15:44:11.094+0000 I COMMAND [conn1269086] command production.clusters command: find { find: "clusters", filter: { deleted: { $ne: true }, timestamps.cluster_timestamps.summary_last_updated: { $exists: true }, feed_id: "abcdefg", timestamps.article_timestamps.first_article_published: { $lte: new Date(1531755822402), $gte: new Date(1531669422402) }, score: { $exists: true } }, projection: { $sortKey: { $meta: "sortKey" } }, sort: { score: -1 }, limit: 25, shardVersion: [ Timestamp(0, 0), ObjectId('000000000000000000000000') ], $readPreference: { mode: "secondaryPreferred" }, $clusterTime: { clusterTime: Timestamp(1531755822, 9), signature: { hash: BinData(0, 9F6CEB16789530637DD0912EA461E8BC988491F5), keyId: 6526359001347653635 } }, $configServerState: { opTime: { ts: Timestamp(1531755821, 6), t: 28 } }, $db: "production" } planSummary: IXSCAN { feed_id: 1, score: -1, timestamps.cluster_timestamps.last_updated: -1, deleted: 1 } keysExamined:68069 docsExamined:68068 cursorExhausted:1 numYields:1392 nreturned:0 reslen:338 locks:{ Global: { acquireCount: { r: 2786 }, acquireWaitCount: { r: 154 }, timeAcquiringMicros: { r: 750763 } }, Database: { acquireCount: { r: 1393 } }, Collection: { acquireCount: { r: 1393 } } } protocol:op_msg 28161ms You can clearly see that the index actually used by Mongo { feed_id: 1, score: -1, timestamps.cluster_timestamps.last_updated: -1, deleted: 1 } doesn't match the winningPlan above "keyPattern" : { "feed_id" : 1, "timestamps.article_timestamps.first_article_published" : 1, "score" : -1, "timestamps.cluster_timestamps.summary_last_updated" : 1, "deleted" : 1 }, "indexName" : "feed_id.first_article_published.score-1.summary_last_updated.deleted", Also, tried checking cache for plans but it came back empty. production-database> db.runCommand({planCacheListPlans: 'clusters',query: {find: { deleted: { $ne: true }, "timestamps.cluster_timestamps.summary_last_updated": { $exists: true }, feed_id: "abcdefg", "timestamps.article_timestamps.first_article_published": { $lte: new Date(1531754990084), $gte: new Date(1531668590084) }, score: { $exists: true } },sort: {score: -1}}}) { "plans" : [ ], "ok" : 1, "operationTime" : Timestamp(1531757237, 4), "$gleStats" : { "lastOpTime" : Timestamp(0, 0), "electionId" : ObjectId("000000000000000000000000") }, "$clusterTime" : { "clusterTime" : Timestamp(1531757237, 6), "signature" : { "hash" : BinData(0,"fCM7jQjOEXae3ZanDbYq2YXo0bM="), "keyId" : NumberLong("6526359001347653635") } }, "$configServerState" : { "opTime" : { "ts" : Timestamp(1531757232, 43), "t" : NumberLong(28) } } }