[SERVER-14071] For queries with .sort(), bad non-blocking plan can be cached if there are zero results Created: 27/May/14  Updated: 18/Sep/15  Resolved: 19/Feb/15

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: 2.6.1, 2.7.1
Fix Version/s: 2.6.9, 3.0.0-rc9, 3.1.0

Type: Bug Priority: Major - P3
Reporter: J Rassi Assignee: David Storch
Resolution: Done Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
related to SERVER-15005 Connections Spike on Secondary, Load ... Closed
related to SERVER-17260 Wrong index is often chosen for query... Closed
is related to SERVER-14034 Sorted $in query with large number of... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Completed:
Participants:

 Description   

Suppose indexes {a:1} and {b:1} exist on a collection, and the user issues the following query:

find({a: {$gt: 0}, b: {$gt: 0}}).sort({b: 1})

The query planner will unconditionally choose (and cache) the plan using the {b:1} index if no documents match either the {a: {$gt: 0}} or {b: {$gt: 0}} predicates.

This is because both the {a:1} index plan and the {b:1} index plan have the same "productivity", but the plan using {b:1} hits EOF first because it does not have a blocking SORT stage.

Note that this issue is not limited to range predicates; it is reproducible with any bounds-generating predicates.

Reproduce with the following:

> db.foo.ensureIndex({a:1})
{
	"createdCollectionAutomatically" : true,
	"numIndexesBefore" : 1,
	"numIndexesAfter" : 2,
	"ok" : 1
}
> db.foo.ensureIndex({b:1})
{
	"createdCollectionAutomatically" : false,
	"numIndexesBefore" : 2,
	"numIndexesAfter" : 3,
	"ok" : 1
}
> db.foo.find({a:{$gt:0},b:{$gt:0}}).sort({b:1}).explain().cursor
BtreeCursor b_1

Plan cache detailed info:

> db.foo.find({a:{$gt:0},b:{$gt:0}}).sort({b:1})
> db.foo.getPlanCache().getPlansByQuery({a:{$gt:0},b:{$gt:0}},{},{b:1})
[
	{
		"details" : {
			"solution" : "(index-tagged expression tree: tree=Node\n---Leaf \n---Leaf { b: 1.0 }, pos: 0\n)"
		},
		"reason" : {
			"score" : 1.0003000000000002,
			"stats" : {
				"type" : "FETCH",
				"works" : 1,
				"yields" : 0,
				"unyields" : 0,
				"invalidates" : 0,
				"advanced" : 0,
				"needTime" : 0,
				"needFetch" : 0,
				"isEOF" : 1,
				"alreadyHasObj" : 0,
				"forcedFetches" : 0,
				"matchTested" : 0,
				"children" : [
					{
						"type" : "IXSCAN",
						"works" : 1,
						"yields" : 0,
						"unyields" : 0,
						"invalidates" : 0,
						"advanced" : 0,
						"needTime" : 0,
						"needFetch" : 0,
						"isEOF" : 1,
						"keyPattern" : "{ b: 1.0 }",
						"boundsVerbose" : "field #0['b']: (0.0, inf.0]",
						"isMultiKey" : 0,
						"yieldMovedCursor" : 0,
						"dupsTested" : 0,
						"dupsDropped" : 0,
						"seenInvalidated" : 0,
						"matchTested" : 0,
						"keysExamined" : 0,
						"children" : [ ]
					}
				]
			}
		},
		"feedback" : {
			"nfeedback" : 0,
			"averageScore" : 0,
			"stdDevScore" : 0,
			"scores" : [ ]
		},
		"filterSet" : false
	},
	{
		"details" : {
			"solution" : "(index-tagged expression tree: tree=Node\n---Leaf { a: 1.0 }, pos: 0\n---Leaf { b: 1.0 }, pos: 0\n)"
		},
		"reason" : {
			"score" : 1.0002,
			"stats" : {
				"type" : "FETCH",
				"works" : 1,
				"yields" : 0,
				"unyields" : 0,
				"invalidates" : 0,
				"advanced" : 0,
				"needTime" : 0,
				"needFetch" : 0,
				"isEOF" : 1,
				"alreadyHasObj" : 0,
				"forcedFetches" : 0,
				"matchTested" : 0,
				"children" : [
					{
						"type" : "AND_HASH",
						"works" : 1,
						"yields" : 0,
						"unyields" : 0,
						"invalidates" : 0,
						"advanced" : 0,
						"needTime" : 0,
						"needFetch" : 0,
						"isEOF" : 1,
						"flaggedButPassed" : 0,
						"flaggedInProgress" : 0,
						"memUsage" : 0,
						"memLimit" : 33554432,
						"children" : [
							{
								"type" : "IXSCAN",
								"works" : 1,
								"yields" : 0,
								"unyields" : 0,
								"invalidates" : 0,
								"advanced" : 0,
								"needTime" : 0,
								"needFetch" : 0,
								"isEOF" : 1,
								"keyPattern" : "{ a: 1.0 }",
								"boundsVerbose" : "field #0['a']: (0.0, inf.0]",
								"isMultiKey" : 0,
								"yieldMovedCursor" : 0,
								"dupsTested" : 0,
								"dupsDropped" : 0,
								"seenInvalidated" : 0,
								"matchTested" : 0,
								"keysExamined" : 0,
								"children" : [ ]
							},
							{
								"type" : "IXSCAN",
								"works" : 0,
								"yields" : 0,
								"unyields" : 0,
								"invalidates" : 0,
								"advanced" : 0,
								"needTime" : 0,
								"needFetch" : 0,
								"isEOF" : 0,
								"keyPattern" : "{}",
								"boundsVerbose" : "field #0['b']: (0.0, inf.0]",
								"isMultiKey" : 0,
								"yieldMovedCursor" : 0,
								"dupsTested" : 0,
								"dupsDropped" : 0,
								"seenInvalidated" : 0,
								"matchTested" : 0,
								"keysExamined" : 0,
								"children" : [ ]
							}
						]
					}
				]
			}
		},
		"feedback" : {
 
		},
		"filterSet" : false
	},
	{
		"details" : {
			"solution" : "(index-tagged expression tree: tree=Node\n---Leaf { a: 1.0 }, pos: 0\n---Leaf \n)"
		},
		"reason" : {
			"score" : 1.0002,
			"stats" : {
				"type" : "SORT",
				"works" : 1,
				"yields" : 0,
				"unyields" : 0,
				"invalidates" : 0,
				"advanced" : 0,
				"needTime" : 0,
				"needFetch" : 0,
				"isEOF" : 0,
				"forcedFetches" : 0,
				"memUsage" : 0,
				"memLimit" : 33554432,
				"children" : [
					{
						"type" : "KEEP_MUTATIONS",
						"works" : 0,
						"yields" : 0,
						"unyields" : 0,
						"invalidates" : 0,
						"advanced" : 0,
						"needTime" : 0,
						"needFetch" : 0,
						"isEOF" : 0,
						"children" : [
							{
								"type" : "FETCH",
								"works" : 0,
								"yields" : 0,
								"unyields" : 0,
								"invalidates" : 0,
								"advanced" : 0,
								"needTime" : 0,
								"needFetch" : 0,
								"isEOF" : 0,
								"alreadyHasObj" : 0,
								"forcedFetches" : 0,
								"matchTested" : 0,
								"children" : [
									{
										"type" : "IXSCAN",
										"works" : 0,
										"yields" : 0,
										"unyields" : 0,
										"invalidates" : 0,
										"advanced" : 0,
										"needTime" : 0,
										"needFetch" : 0,
										"isEOF" : 0,
										"keyPattern" : "{}",
										"boundsVerbose" : "field #0['a']: (0.0, inf.0]",
										"isMultiKey" : 0,
										"yieldMovedCursor" : 0,
										"dupsTested" : 0,
										"dupsDropped" : 0,
										"seenInvalidated" : 0,
										"matchTested" : 0,
										"keysExamined" : 0,
										"children" : [ ]
									}
								]
							}
						]
					}
				]
			}
		},
		"feedback" : {
 
		},
		"filterSet" : false
	}
]
>



 Comments   
Comment by Paul Nock [ 21/Apr/15 ]

Thanks David,

I created SERVER-18148 ticket to track. 2.6.10 will probably be ok if it fixes the problem, unless it starts affecting more queries before then. It would be nice to confirm this is my issue first though. It is a bit awkward since it's not reliably reproduced, but I have seen it a few times across 3 similar queries since upgrading last week - so far it comes back fairly regularly for me, unfortunately.

thanks
Paul

Comment by David Storch [ 20/Apr/15 ]

pnock, thanks for reporting this issue. From the available information, it is difficult to determine the root cause of this issue. One hypothesis is that it is a duplicate of SERVER-17815, a fix for which will be available in the upcoming 2.6.10 release. A see two options for next steps:

  1. Wait for 2.6.10 and see if an upgrade fixes the issue.
  2. Open a new SERVER ticket to track this problem, assigned to me. I will ask for further debug information to see if we can determine the root cause. This may prove to be tricky if you have no way to reliably reproduce the problem. If it is a novel plan selection bug, however, it would be great to track it down!

Please let me know your preference for moving forward.

Best,
Dave

Comment by Paul Nock [ 20/Apr/15 ]

(I posted this at https://jira.mongodb.org/browse/SERVER-13866 too, not sure if I know enough to say for sure if it's the same thing...)

I'm seeing something that looks like this with 2.6.9:
2015-04-20T16:26:05.147+0000 [conn61829] query *****.followings query: { $query:

{ user_id: ObjectId('*********') }

, $orderby:

{ _id: 1 }

} planSummary: IXSCAN

{ _id: 1 }

ntoskip:0 nscanned:125454 nscannedObjects:125454 keyUpdates:0 numYields:0 locks(micros) r:181778 nreturned:0 reslen:20 181ms
db.followings.getIndexes()
[
{
"v" : 1,
"name" : "id",
"key" :

{ "_id" : 1 }

,
"ns" : "*****.followings"
},
{
"v" : 1,
"key" :

{ "user_id" : 1 }

,
"name" : "user_id_1",
"ns" : "***********.followings"
}
]
The query at the console on the primary always uses the 'user_id_1' index, but intermittently, the query will start running very slowly on slaves in the replica set. The behavior started after upgrading from 2.4 last week, and happens on some other simple collections too. If I drop and regenerate the index the problem resets itself, but I assume that's similar to just restarting mongod. What is normally a 1ms query jumps to 100ms or more.

Comment by Githook User [ 03/Mar/15 ]

Author:

{u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'}

Message: SERVER-14071 do not cache plans which return zero results
Branch: v2.6
https://github.com/mongodb/mongo/commit/ff64c70f6994520827dceeaf4c82c7061ff10b8c

Comment by Githook User [ 19/Feb/15 ]

Author:

{u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'}

Message: SERVER-14071 do not cache plans which return zero results

(cherry picked from commit ae341c89d09b634047dd080af0f9e173e6d8b6e5)
Branch: v3.0
https://github.com/mongodb/mongo/commit/2a59d43f714ac4b4464dab4158165ea818850f5d

Comment by Githook User [ 19/Feb/15 ]

Author:

{u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'}

Message: SERVER-14071 do not cache plans which return zero results
Branch: master
https://github.com/mongodb/mongo/commit/ae341c89d09b634047dd080af0f9e173e6d8b6e5

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