Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-36160

explain() winningPlan inconsistent with actual query plan

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Works as Designed
    • Affects Version/s: 3.6.5
    • Fix Version/s: None
    • Component/s: Querying
    • Labels:
      None
    • Operating System:
      ALL
    • Steps To Reproduce:
      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) } } }
      

      Show
      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 ) } } }

      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...

        Attachments

        1. mongo_query_planner_cache.json
          6 kB
        2. mongo_slowquery_log_verbose.log
          6 kB
        3. queryplannerwithsortandlimit.json
          24 kB

          Activity

            People

            Assignee:
            nick.brewer Nick Brewer
            Reporter:
            agolomoody Moody Saada
            Participants:
            Votes:
            0 Vote for this issue
            Watchers:
            10 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: