[SERVER-17821] Query planner prefers suboptimal index to using index intersection Created: 31/Mar/15  Updated: 16/Jun/15  Resolved: 16/Jun/15

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: 3.0.1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: William Richards Assignee: David Storch
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File test_mongo.out     File test_mongo.py    
Issue Links:
Duplicate
duplicates SERVER-13740 Improve plan ranking for index inters... Backlog
Operating System: ALL
Participants:

 Description   

find() with the $all keyword is slow even on indexed fields. The query planner chooses a plan requiring examining many extra documents, even though it could use an index intersection. It seems that the collection scan is the first to return the 101 entries, but the executionTimeMillisEstimate is much higher (2060 vs 10) than for the AND_SORTED query, which should be the fastest. I'm not sure why the collection scan is beating the AND_SORTED query, given the radically different executionTimeMillisEstimate.

{
	"queryPlanner" : {
		"plannerVersion" : 1,
		"namespace" : "shangrila.materials",
		"indexFilterSet" : false,
		"parsedQuery" : {
			"$and" : [
				{
					"elements" : {
						"$eq" : "Li"
					}
				},
				{
					"elements" : {
						"$eq" : "F"
					}
				},
				{
					"elements" : {
						"$eq" : "Mn"
					}
				}
			]
		},
		"winningPlan" : {
			"stage" : "FETCH",
			"filter" : {
				"$and" : [
					{
						"elements" : {
							"$eq" : "F"
						}
					},
					{
						"elements" : {
							"$eq" : "Mn"
						}
					}
				]
			},
			"inputStage" : {
				"stage" : "IXSCAN",
				"keyPattern" : {
					"elements" : 1
				},
				"indexName" : "elements_1",
				"isMultiKey" : true,
				"direction" : "forward",
				"indexBounds" : {
					"elements" : [
						"[\"Li\", \"Li\"]"
					]
				}
			}
		},
		"rejectedPlans" : [
			{
				"stage" : "FETCH",
				"filter" : {
					"$and" : [
						{
							"elements" : {
								"$eq" : "F"
							}
						},
						{
							"elements" : {
								"$eq" : "Mn"
							}
						}
					]
				},
				"inputStage" : {
					"stage" : "IXSCAN",
					"keyPattern" : {
						"elements" : 1,
						"nelements" : 1
					},
					"indexName" : "elements_1_nelements_1",
					"isMultiKey" : true,
					"direction" : "forward",
					"indexBounds" : {
						"elements" : [
							"[\"Li\", \"Li\"]"
						],
						"nelements" : [
							"[MinKey, MaxKey]"
						]
					}
				}
			},
			{
				"stage" : "FETCH",
				"filter" : {
					"$and" : [
						{
							"elements" : {
								"$eq" : "Li"
							}
						},
						{
							"elements" : {
								"$eq" : "F"
							}
						},
						{
							"elements" : {
								"$eq" : "Mn"
							}
						}
					]
				},
				"inputStage" : {
					"stage" : "AND_SORTED",
					"inputStages" : [
						{
							"stage" : "IXSCAN",
							"keyPattern" : {
								"elements" : 1
							},
							"indexName" : "elements_1",
							"isMultiKey" : true,
							"direction" : "forward",
							"indexBounds" : {
								"elements" : [
									"[\"Li\", \"Li\"]"
								]
							}
						},
						{
							"stage" : "IXSCAN",
							"keyPattern" : {
								"elements" : 1
							},
							"indexName" : "elements_1",
							"isMultiKey" : true,
							"direction" : "forward",
							"indexBounds" : {
								"elements" : [
									"[\"F\", \"F\"]"
								]
							}
						},
						{
							"stage" : "IXSCAN",
							"keyPattern" : {
								"elements" : 1
							},
							"indexName" : "elements_1",
							"isMultiKey" : true,
							"direction" : "forward",
							"indexBounds" : {
								"elements" : [
									"[\"Mn\", \"Mn\"]"
								]
							}
						}
					]
				}
			}
		]
	},
	"executionStats" : {
		"executionSuccess" : true,
		"nReturned" : 1297,
		"executionTimeMillis" : 77874,
		"totalKeysExamined" : 59901,
		"totalDocsExamined" : 59901,
		"executionStages" : {
			"stage" : "FETCH",
			"filter" : {
				"$and" : [
					{
						"elements" : {
							"$eq" : "F"
						}
					},
					{
						"elements" : {
							"$eq" : "Mn"
						}
					}
				]
			},
			"nReturned" : 1297,
			"executionTimeMillisEstimate" : 74860,
			"works" : 59902,
			"advanced" : 1297,
			"needTime" : 58604,
			"needFetch" : 0,
			"saveState" : 3878,
			"restoreState" : 3878,
			"isEOF" : 1,
			"invalidates" : 0,
			"docsExamined" : 59901,
			"alreadyHasObj" : 0,
			"inputStage" : {
				"stage" : "IXSCAN",
				"nReturned" : 59901,
				"executionTimeMillisEstimate" : 220,
				"works" : 59902,
				"advanced" : 59901,
				"needTime" : 0,
				"needFetch" : 0,
				"saveState" : 3878,
				"restoreState" : 3878,
				"isEOF" : 1,
				"invalidates" : 0,
				"keyPattern" : {
					"elements" : 1
				},
				"indexName" : "elements_1",
				"isMultiKey" : true,
				"direction" : "forward",
				"indexBounds" : {
					"elements" : [
						"[\"Li\", \"Li\"]"
					]
				},
				"keysExamined" : 59901,
				"dupsTested" : 59901,
				"dupsDropped" : 0,
				"seenInvalidated" : 0,
				"matchTested" : 0
			}
		},
		"allPlansExecution" : [
			{
				"nReturned" : 88,
				"executionTimeMillisEstimate" : 2471,
				"totalKeysExamined" : 3985,
				"totalDocsExamined" : 3985,
				"executionStages" : {
					"stage" : "FETCH",
					"filter" : {
						"$and" : [
							{
								"elements" : {
									"$eq" : "F"
								}
							},
							{
								"elements" : {
									"$eq" : "Mn"
								}
							}
						]
					},
					"nReturned" : 88,
					"executionTimeMillisEstimate" : 2471,
					"works" : 3985,
					"advanced" : 88,
					"needTime" : 3897,
					"needFetch" : 0,
					"saveState" : 3878,
					"restoreState" : 3878,
					"isEOF" : 0,
					"invalidates" : 0,
					"docsExamined" : 3985,
					"alreadyHasObj" : 0,
					"inputStage" : {
						"stage" : "IXSCAN",
						"nReturned" : 3985,
						"executionTimeMillisEstimate" : 0,
						"works" : 3985,
						"advanced" : 3985,
						"needTime" : 0,
						"needFetch" : 0,
						"saveState" : 3878,
						"restoreState" : 3878,
						"isEOF" : 0,
						"invalidates" : 0,
						"keyPattern" : {
							"elements" : 1,
							"nelements" : 1
						},
						"indexName" : "elements_1_nelements_1",
						"isMultiKey" : true,
						"direction" : "forward",
						"indexBounds" : {
							"elements" : [
								"[\"Li\", \"Li\"]"
							],
							"nelements" : [
								"[MinKey, MaxKey]"
							]
						},
						"keysExamined" : 3985,
						"dupsTested" : 3985,
						"dupsDropped" : 0,
						"seenInvalidated" : 0,
						"matchTested" : 0
					}
				}
			},
			{
				"nReturned" : 62,
				"executionTimeMillisEstimate" : 10,
				"totalKeysExamined" : 3985,
				"totalDocsExamined" : 62,
				"executionStages" : {
					"stage" : "FETCH",
					"filter" : {
						"$and" : [
							{
								"elements" : {
									"$eq" : "Li"
								}
							},
							{
								"elements" : {
									"$eq" : "F"
								}
							},
							{
								"elements" : {
									"$eq" : "Mn"
								}
							}
						]
					},
					"nReturned" : 62,
					"executionTimeMillisEstimate" : 10,
					"works" : 3985,
					"advanced" : 62,
					"needTime" : 3923,
					"needFetch" : 0,
					"saveState" : 3878,
					"restoreState" : 3878,
					"isEOF" : 0,
					"invalidates" : 0,
					"docsExamined" : 62,
					"alreadyHasObj" : 21,
					"inputStage" : {
						"stage" : "AND_SORTED",
						"nReturned" : 62,
						"executionTimeMillisEstimate" : 10,
						"works" : 3985,
						"advanced" : 62,
						"needTime" : 3923,
						"needFetch" : 0,
						"saveState" : 3878,
						"restoreState" : 3878,
						"isEOF" : 0,
						"invalidates" : 0,
						"flagged" : 0,
						"matchTested" : 0,
						"failedAnd_0" : 347,
						"failedAnd_1" : 278,
						"failedAnd_2" : 109,
						"inputStages" : [
							{
								"stage" : "IXSCAN",
								"nReturned" : 2215,
								"executionTimeMillisEstimate" : 0,
								"works" : 2215,
								"advanced" : 2215,
								"needTime" : 0,
								"needFetch" : 0,
								"saveState" : 3878,
								"restoreState" : 3878,
								"isEOF" : 0,
								"invalidates" : 0,
								"keyPattern" : {
									"elements" : 1
								},
								"indexName" : "elements_1",
								"isMultiKey" : true,
								"direction" : "forward",
								"indexBounds" : {
									"elements" : [
										"[\"Li\", \"Li\"]"
									]
								},
								"keysExamined" : 2215,
								"dupsTested" : 2215,
								"dupsDropped" : 0,
								"seenInvalidated" : 0,
								"matchTested" : 0
							},
							{
								"stage" : "IXSCAN",
								"nReturned" : 1083,
								"executionTimeMillisEstimate" : 10,
								"works" : 1083,
								"advanced" : 1083,
								"needTime" : 0,
								"needFetch" : 0,
								"saveState" : 3878,
								"restoreState" : 3878,
								"isEOF" : 0,
								"invalidates" : 0,
								"keyPattern" : {
									"elements" : 1
								},
								"indexName" : "elements_1",
								"isMultiKey" : true,
								"direction" : "forward",
								"indexBounds" : {
									"elements" : [
										"[\"F\", \"F\"]"
									]
								},
								"keysExamined" : 1083,
								"dupsTested" : 1083,
								"dupsDropped" : 0,
								"seenInvalidated" : 0,
								"matchTested" : 0
							},
							{
								"stage" : "IXSCAN",
								"nReturned" : 687,
								"executionTimeMillisEstimate" : 0,
								"works" : 687,
								"advanced" : 687,
								"needTime" : 0,
								"needFetch" : 0,
								"saveState" : 3878,
								"restoreState" : 3878,
								"isEOF" : 0,
								"invalidates" : 0,
								"keyPattern" : {
									"elements" : 1
								},
								"indexName" : "elements_1",
								"isMultiKey" : true,
								"direction" : "forward",
								"indexBounds" : {
									"elements" : [
										"[\"Mn\", \"Mn\"]"
									]
								},
								"keysExamined" : 687,
								"dupsTested" : 687,
								"dupsDropped" : 0,
								"seenInvalidated" : 0,
								"matchTested" : 0
							}
						]
					}
				}
			},
			{
				"nReturned" : 101,
				"executionTimeMillisEstimate" : 2060,
				"totalKeysExamined" : 3985,
				"totalDocsExamined" : 3985,
				"executionStages" : {
					"stage" : "FETCH",
					"filter" : {
						"$and" : [
							{
								"elements" : {
									"$eq" : "F"
								}
							},
							{
								"elements" : {
									"$eq" : "Mn"
								}
							}
						]
					},
					"nReturned" : 101,
					"executionTimeMillisEstimate" : 2060,
					"works" : 3985,
					"advanced" : 101,
					"needTime" : 3884,
					"needFetch" : 0,
					"saveState" : 233,
					"restoreState" : 233,
					"isEOF" : 0,
					"invalidates" : 0,
					"docsExamined" : 3985,
					"alreadyHasObj" : 0,
					"inputStage" : {
						"stage" : "IXSCAN",
						"nReturned" : 3985,
						"executionTimeMillisEstimate" : 10,
						"works" : 3985,
						"advanced" : 3985,
						"needTime" : 0,
						"needFetch" : 0,
						"saveState" : 233,
						"restoreState" : 233,
						"isEOF" : 0,
						"invalidates" : 0,
						"keyPattern" : {
							"elements" : 1
						},
						"indexName" : "elements_1",
						"isMultiKey" : true,
						"direction" : "forward",
						"indexBounds" : {
							"elements" : [
								"[\"Li\", \"Li\"]"
							]
						},
						"keysExamined" : 3985,
						"dupsTested" : 3985,
						"dupsDropped" : 0,
						"seenInvalidated" : 0,
						"matchTested" : 0
					}
				}
			}
		]
	},
	"serverInfo" : {
		"host" : "xxxx",
		"port" : 27017,
		"version" : "3.0.1",
		"gitVersion" : "534b5a3f9d10f00cd27737fbcd951032248b5952"
	},
	"ok" : 1
}



 Comments   
Comment by David Storch [ 16/Jun/15 ]

Hi wrichard,

Apologies for the delay in our response to this issue. The attached .explain() output indicates that an indexed plan using index { elements: 1 } with bounds [["Li", "Li"]] is chosen as the winner instead of the sort-based index intersection plan. The non-intersection plan is winning because it produces more result documents than the index intersection plan during the plan ranking trial period. (For a description of how plans are selected by the MongoDB query engine, see the documentation here.)

However, the explain also shows that, during the plan ranking trial period, the winning plan spent about 2 seconds fetching 3985 documents from storage. In comparison, the index intersection plan spent only a few milliseconds fetching just 62 documents from storage. Clearly the index intersection plan is less costly because it requires less IO. However, the reduced IO associated with this plan is not recognized by the query plan ranking subsystem. This is a known problem that is being tracked by SERVER-13740.

I am closing this ticket as a duplicate of SERVER-13740, but please let me know if you have any further questions.

Best,
Dave

Comment by William Richards [ 15/Apr/15 ]

I've attached a python script that should reproduce the problem. The outputs are the results on my machine of the query.explain() and the database and collection stats.

Comment by Sam Kleinman (Inactive) [ 15/Apr/15 ]

Thanks for this report, and sorry for not getting back to this sooner. To help us debug this, would it be possible to provide the data set, or the procedure you used to generate, or a sample document and the output of db.stats{ and db.<collection>.stats() so that we can work on generating a more narrow reproduction.

Cheers,
sam

Comment by William Richards [ 01/Apr/15 ]

This seems to only be a real issue when using wiredtiger. I believe its caused by judging the query time by the "works" field, but in wiredtiger this number is not well correlated with the execution time (FETCH can take >100x longer per document/key than IXSCAN when the documents are large).

Generated at Thu Feb 08 03:45:42 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.