[SERVER-8747] In explain output, per plan 'n' count is not updated after an out of order plan wins Created: 26/Feb/13  Updated: 10/Dec/14  Resolved: 04/Dec/14

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

Type: Bug Priority: Major - P3
Reporter: Aaron Staple Assignee: David Storch
Resolution: Duplicate Votes: 1
Labels: query_triage
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File server8747.js    
Issue Links:
Related
related to SERVER-10448 Revamp explain() formatting Closed
is related to SERVER-7945 use plan ordering when reporting "win... Closed
Operating System: ALL
Participants:

 Description   

If an out of order query plan (one with results that must be sorted in memory after being identified) becomes a winning plan, the 'n' value reported in per plan explain output for this plan is not updated to include matching documents identified after the query plan won. This is in contrast to other attributes like nscanned and nscannedObjects that are updated after the plan wins. And it is in contrast to the behavior of an in order query plan that wins.

Test

c = db.c;
c.drop();
c.ensureIndex( { a:1 } );
c.ensureIndex( { b:1 } );
 
for( i = 0; i < 1000; ++i ) {
    c.save( { a:i, b:i } );
}
 
printjson( c.find( { a:{ $gte:0 }, b:{ $gte:0 } } ).explain( true ) );
printjson( c.find( { a:{ $gte:0 }, b:{ $gte:0 } } ).sort( { z:1 } ).explain( true ) );

Output with bug pointed out

{
	"cursor" : "BtreeCursor a_1",
	"isMultiKey" : false,
	"n" : 1000,
	"nscannedObjects" : 1000,
	"nscanned" : 1000,
	"nscannedObjectsAllPlans" : 1202,
	"nscannedAllPlans" : 1202,
	"scanAndOrder" : false,
	"indexOnly" : false,
	"nYields" : 0,
	"nChunkSkips" : 0,
	"millis" : 33,
	"indexBounds" : {
		"a" : [
			[
				0,
				1.7976931348623157e+308
			]
		]
	},
	"allPlans" : [
		{
			"cursor" : "BtreeCursor a_1",
			"n" : 1000,                    <-- plan 'n' for whole query
			"nscannedObjects" : 1000,      <-- plan 'nscannedObjects' for whole query
			"nscanned" : 1000,             <-- plan 'nscanned' for whole query
			"indexBounds" : {
				"a" : [
					[
						0,
						1.7976931348623157e+308
					]
				]
			}
		},
		{
			"cursor" : "BtreeCursor b_1",
			"n" : 101,
			"nscannedObjects" : 101,
			"nscanned" : 101,
			"indexBounds" : {
				"b" : [
					[
						0,
						1.7976931348623157e+308
					]
				]
			}
		},
		{
			"cursor" : "BasicCursor",
			"n" : 101,
			"nscannedObjects" : 101,
			"nscanned" : 101,
			"indexBounds" : {
				
			}
		}
	],
	"server" : "Aarons-MacBook-Pro.local:27017"
}
{
	"cursor" : "BtreeCursor a_1",
	"isMultiKey" : false,
	"n" : 1000,
	"nscannedObjects" : 1000,
	"nscanned" : 1000,
	"nscannedObjectsAllPlans" : 1202,
	"nscannedAllPlans" : 1202,
	"scanAndOrder" : true,
	"indexOnly" : false,
	"nYields" : 0,
	"nChunkSkips" : 0,
	"millis" : 75,
	"indexBounds" : {
		"a" : [
			[
				0,
				1.7976931348623157e+308
			]
		]
	},
	"allPlans" : [
		{
			"cursor" : "BtreeCursor a_1",
			"n" : 101,                      <-- -bug- plan 'n' just until plan on a:1 index wins
			"nscannedObjects" : 1000,       <-- plan 'nscannedObjects' for whole query
			"nscanned" : 1000,              <-- plan 'nscanned' for whole query
			"indexBounds" : {
				"a" : [
					[
						0,
						1.7976931348623157e+308
					]
				]
			}
		},
		{
			"cursor" : "BtreeCursor b_1",
			"n" : 101,
			"nscannedObjects" : 101,
			"nscanned" : 101,
			"indexBounds" : {
				"b" : [
					[
						0,
						1.7976931348623157e+308
					]
				]
			}
		},
		{
			"cursor" : "BasicCursor",
			"n" : 101,
			"nscannedObjects" : 101,
			"nscanned" : 101,
			"indexBounds" : {
				
			}
		}
	],
	"server" : "Aarons-MacBook-Pro.local:27017"
}



 Comments   
Comment by David Storch [ 04/Dec/14 ]

This issue does not affect the revamped explain which will be released with version 2.8.0. (Work for the revamped explain was done under SERVER-10448, so please refer to this ticket and its subtasks for details.) Resolving as a duplicate.

Note that in the new explain, the executionStats.allPlansExecution field reports stats captured during the query optimizer's trial period. It contains partial execution information for both the winning plan and the rejected plans. Therefore, it is expected behavior that, using the repro in the description of the ticket, the nReturned values are 101 rather than 1000:

		"allPlansExecution" : [
			{
				"nReturned" : 101, // <===================== This is correct behavior (works this way by design).
				"executionTimeMillisEstimate" : 10,
				"totalKeysExamined" : 1000,
				"totalDocsExamined" : 1000,
				"executionStages" : {
					"stage" : "SORT",
					"nReturned" : 101,
					"executionTimeMillisEstimate" : 10,
					"works" : 1103,
					"advanced" : 101,
					"needTime" : 1001,
					"needFetch" : 0,
					"saveState" : 25,
					"restoreState" : 25,
					"isEOF" : 0,
					"invalidates" : 0,
					"sortPattern" : {
						"z" : 1
					},
					"memUsage" : 52000,
					"memLimit" : 33554432,
					"inputStage" : {
						"stage" : "KEEP_MUTATIONS",
						"nReturned" : 1000,
						"executionTimeMillisEstimate" : 10,
						"works" : 1001,
						"advanced" : 1000,
						"needTime" : 0,
						"needFetch" : 0,
						"saveState" : 25,
						"restoreState" : 25,
						"isEOF" : 1,
						"invalidates" : 0,
						"inputStage" : {
							"stage" : "FETCH",
							"filter" : {
								"b" : {
									"$gte" : 0
								}
							},
							"nReturned" : 1000,
							"executionTimeMillisEstimate" : 10,
							"works" : 1001,
							"advanced" : 1000,
							"needTime" : 0,
							"needFetch" : 0,
							"saveState" : 25,
							"restoreState" : 25,
							"isEOF" : 1,
							"invalidates" : 0,
							"docsExamined" : 1000,
							"alreadyHasObj" : 0,
							"inputStage" : {
								"stage" : "IXSCAN",
								"nReturned" : 1000,
								"executionTimeMillisEstimate" : 10,
								"works" : 1000,
								"advanced" : 1000,
								"needTime" : 0,
								"needFetch" : 0,
								"saveState" : 25,
								"restoreState" : 25,
								"isEOF" : 1,
								"invalidates" : 0,
								"keyPattern" : {
									"a" : 1
								},
								"indexName" : "a_1",
								"isMultiKey" : false,
								"direction" : "forward",
								"indexBounds" : {
									"a" : [
										"[0.0, inf.0]"
									]
								},
								"keysExamined" : 1000,
								"dupsTested" : 0,
								"dupsDropped" : 0,
								"seenInvalidated" : 0,
								"matchTested" : 0
							}
						}
					}
				}
			},
			{
				"nReturned" : 101, // <===================== This is correct behavior (works this way by design).
				"executionTimeMillisEstimate" : 0,
				"totalKeysExamined" : 1000,
				"totalDocsExamined" : 1000,
				"executionStages" : {
					"stage" : "SORT",
					"nReturned" : 101,
					"executionTimeMillisEstimate" : 0,
					"works" : 1103,
					"advanced" : 101,
					"needTime" : 1001,
					"needFetch" : 0,
					"saveState" : 17,
					"restoreState" : 17,
					"isEOF" : 0,
					"invalidates" : 0,
					"sortPattern" : {
						"z" : 1
					},
					"memUsage" : 52000,
					"memLimit" : 33554432,
					"inputStage" : {
						"stage" : "KEEP_MUTATIONS",
						"nReturned" : 1000,
						"executionTimeMillisEstimate" : 0,
						"works" : 1001,
						"advanced" : 1000,
						"needTime" : 0,
						"needFetch" : 0,
						"saveState" : 17,
						"restoreState" : 17,
						"isEOF" : 1,
						"invalidates" : 0,
						"inputStage" : {
							"stage" : "FETCH",
							"filter" : {
								"a" : {
									"$gte" : 0
								}
							},
							"nReturned" : 1000,
							"executionTimeMillisEstimate" : 0,
							"works" : 1001,
							"advanced" : 1000,
							"needTime" : 0,
							"needFetch" : 0,
							"saveState" : 17,
							"restoreState" : 17,
							"isEOF" : 1,
							"invalidates" : 0,
							"docsExamined" : 1000,
							"alreadyHasObj" : 0,
							"inputStage" : {
								"stage" : "IXSCAN",
								"nReturned" : 1000,
								"executionTimeMillisEstimate" : 0,
								"works" : 1000,
								"advanced" : 1000,
								"needTime" : 0,
								"needFetch" : 0,
								"saveState" : 17,
								"restoreState" : 17,
								"isEOF" : 1,
								"invalidates" : 0,
								"keyPattern" : {
									"b" : 1
								},
								"indexName" : "b_1",
								"isMultiKey" : false,
								"direction" : "forward",
								"indexBounds" : {
									"b" : [
										"[0.0, inf.0]"
									]
								},
								"keysExamined" : 1000,
								"dupsTested" : 0,
								"dupsDropped" : 0,
								"seenInvalidated" : 0,
								"matchTested" : 0
							}
						}
					}
				}
			}
		]

The rationale behind this behavior is that the information given by allPlansExecution can be very useful for diagnosing why a plan was chosen by the optimizer. Previous versions of explain could tell you which plan was chosen and which were rejected, but it was difficult to gain insight into why this decision was made.

Comment by Hiroaki [ 17/May/14 ]

This is really languid problem...
it prevent me from understanding its optimizer.
Especially, behavior of the index intersection from 2.6 is totally covered behind this issue.

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