-
Type:
Bug
-
Resolution: Works as Designed
-
Priority:
Major - P3
-
None
-
Affects Version/s: 3.6.5
-
Component/s: Querying
-
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 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) } } }
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) } } } -
None
-
3
-
None
-
None
-
None
-
None
-
None
-
None
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...
- mongo_query_planner_cache.json
- 6 kB
- Moody Saada
- mongo_slowquery_log_verbose.log
- 6 kB
- Moody Saada
- queryplannerwithsortandlimit.json
- 24 kB
- Moody Saada