Details
-
Bug
-
Resolution: Works as Designed
-
Major - P3
-
None
-
3.6.5
-
None
-
ALL
-
Hide
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 28161msYou 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) } } }
ShowHere 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 ) } } }
Description
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...