[SERVER-14610] Detailed explain does not list rejected plans Created: 18/Jul/14  Updated: 10/Dec/14  Resolved: 15/Oct/14

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: 2.7.1, 2.7.2, 2.7.3
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jonathan Abrahams Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: 28qa
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-10448 Revamp explain() formatting Closed
is duplicated by SERVER-14627 explain().allPlans lists only the cho... Closed
Related
is related to SERVER-14628 Aggregation explain "cursor" field tr... Closed
is related to SERVER-13674 Refactor CachedPlanRunner and MultiPl... Closed
Operating System: ALL
Steps To Reproduce:

db.getSiblingDB("admin").runCommand( { setParameter: 1, logLevel: 3 } )
db.foo.ensureIndex({a: 1})
db.foo.ensureIndex({b: 1})
db.foo.insert({a: 1, b: 3})
db.foo.insert({a: 2, b: 5})
db.foo.insert({a: 3, b: 7})
db.foo.find({a: {$gt: 2}, b: {$gt: 3}}).explain(true)

Result produced:

{
	"cursor" : "BtreeCursor a_1",
	"isMultiKey" : false,
	"n" : 1,
	"nscannedObjects" : 1,
	"nscanned" : 1,
	"nscannedObjectsAllPlans" : 1,
	"nscannedAllPlans" : 1,
	"scanAndOrder" : false,
	"indexOnly" : false,
	"nYields" : 0,
	"nChunkSkips" : 0,
	"millis" : 0,
	"indexBounds" : {
		"a" : [
			[
				2,
				Infinity
			]
		]
	},
	"allPlans" : [
		{
			"cursor" : "BtreeCursor a_1",
			"isMultiKey" : false,
			"n" : 1,
			"nscannedObjects" : 1,
			"nscanned" : 1,
			"scanAndOrder" : false,
			"indexOnly" : false,
			"nChunkSkips" : 0,
			"indexBounds" : {
				"a" : [
					[
						2,
						Infinity
					]
				]
			}
		}
	],
	"server" : "Jonathans-MacBook-Pro.local:27017",
	"filterSet" : false,
	"stats" : {
		"type" : "KEEP_MUTATIONS",
		"works" : 3,
		"yields" : 0,
		"unyields" : 0,
		"invalidates" : 0,
		"advanced" : 1,
		"needTime" : 0,
		"isEOF" : 1,
		"children" : [
			{
				"type" : "FETCH",
				"works" : 2,
				"yields" : 0,
				"unyields" : 0,
				"invalidates" : 0,
				"advanced" : 1,
				"needTime" : 0,
				"isEOF" : 1,
				"alreadyHasObj" : 0,
				"forcedFetches" : 0,
				"matchTested" : 1,
				"children" : [
					{
						"type" : "IXSCAN",
						"works" : 1,
						"yields" : 0,
						"unyields" : 0,
						"invalidates" : 0,
						"advanced" : 1,
						"needTime" : 0,
						"isEOF" : 1,
						"keyPattern" : "{ a: 1.0 }",
						"isMultiKey" : 0,
						"boundsVerbose" : "field #0['a']: (2.0, inf.0]",
						"yieldMovedCursor" : 0,
						"dupsTested" : 0,
						"dupsDropped" : 0,
						"seenInvalidated" : 0,
						"matchTested" : 0,
						"keysExamined" : 1,
						"children" : [ ]
					}
				]
			}
		]
	}
}

Observed in mongod log:

2014-07-18T10:27:58.768-0400 [conn1] Running query: query: { a: { $gt: 2.0 }, b: { $gt: 3.0 } } sort: {} projection: {}
2014-07-18T10:27:58.768-0400 [conn1] Relevant index 0 is kp: { a: 1.0 } io: { v: 1, key: { a: 1.0 }, name: "a_1", ns: "test.foo" }
2014-07-18T10:27:58.768-0400 [conn1] Relevant index 1 is kp: { b: 1.0 } io: { v: 1, key: { b: 1.0 }, name: "b_1", ns: "test.foo" }
2014-07-18T10:27:58.768-0400 [conn1] Scoring query plan: IXSCAN { a: 1.0 } planHitEOF=1
2014-07-18T10:27:58.769-0400 [conn1] score(1.5003) = baseScore(1) + productivity((1 advanced)/(2 works) = 0.5) + tieBreakers(0.0001 noFetchBonus + 0.0001 noSortBonus + 0.0001 noIxisectBonus = 0.0003)
2014-07-18T10:27:58.769-0400 [conn1] Scoring query plan: IXSCAN { b: 1.0 } planHitEOF=0
2014-07-18T10:27:58.769-0400 [conn1] score(1.5003) = baseScore(1) + productivity((1 advanced)/(2 works) = 0.5) + tieBreakers(0.0001 noFetchBonus + 0.0001 noSortBonus + 0.0001 noIxisectBonus = 0.0003)
2014-07-18T10:27:58.769-0400 [conn1] Scoring query plan: IXSCAN { a: 1.0 }, IXSCAN { b: 1.0 } planHitEOF=0
2014-07-18T10:27:58.769-0400 [conn1] score(1.0002) = baseScore(1) + productivity((0 advanced)/(2 works) = 0) + tieBreakers(0.0001 noFetchBonus + 0.0001 noSortBonus + 0 noIxisectBonus = 0.0002)
2014-07-18T10:27:58.769-0400 [conn1] Winning plan: IXSCAN { a: 1.0 }
2014-07-18T10:27:58.769-0400 [conn1] query test.foo query: { query: { a: { $gt: 2.0 }, b: { $gt: 3.0 } }, $explain: true } planSummary: IXSCAN { a: 1.0 } ntoreturn:0 ntoskip:0 nscanned:1 nscannedObjects:1 keyUpdates:0 numYields:0 locks(micros) r:789 nreturned:1 reslen:1214 0ms

Participants:

 Description   

A query with explain(true) should list all considered plans. It is only showing the winning plan.



 Comments   
Comment by J Rassi [ 15/Oct/14 ]

The "allPlans" field has been removed from the explain output, and replaced with new fields in the query planner and execution stats explain sections. Resolving as dup of SERVER-10448.

Comment by J Rassi [ 21/Jul/14 ]

david.storch: it is not the case that this issue is limited to the master branch. See SERVER-14627, which includes a repro for 2.6.2+. (edit: my mistake, this is actually only limited to the master branch. I had my 2.6.x binaries replaced with 2.7.x binaries by accident)

Comment by David Storch [ 18/Jul/14 ]

This is a 2.7-only bug which I believe was introduced by the following commit for SERVER-13674:

https://github.com/mongodb/mongo/commit/6ada135a2dfb937106736e37885efc08dadc23f9

The MultiPlanRunner::getInfo() method used to be responsible for calling explainMultiPlan() in order to properly generate the allPlans output. In master right now, explainMultiPlan() is dead code due to the removal of the multi plan runner.

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