[SERVER-19758] Add "executionStats" and "allPlansExecution" explain modes to aggregation explain Created: 04/Aug/15  Updated: 26/Sep/22  Resolved: 13/Mar/17

Status: Closed
Project: Core Server
Component/s: Aggregation Framework, Querying
Affects Version/s: None
Fix Version/s: 3.5.5

Type: New Feature Priority: Major - P3
Reporter: David Storch Assignee: David Storch
Resolution: Done Votes: 29
Labels: usability
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
is depended on by DOCS-11777 db.collection.explain("verbosity") no... Closed
is depended on by SERVER-21784 Track 'nReturned' and 'executionTimeM... Closed
Related
related to SERVER-29421 Aggregation executionStats or allPlan... Closed
related to SERVER-35967 $sample with explain(true) hangs Closed
related to DOCS-6306 "executionStats" is not generated fo... Closed
is related to MONGOSH-1002 When executing explain on aggregate i... Waiting (Blocked)
is related to DRIVERS-375 Aggregate command's explain flag cann... Closed
is related to SERVER-10448 Revamp explain() formatting Closed
Backwards Compatibility: Minor Change
Sprint: Query 2017-02-13, Query 2017-03-27
Participants:
Case:

 Description   

We should extend aggregation explain to report the appropriate information in "executionStats" and "allPlansExecution" explain modes. In "executionStats" mode, the $cursor stage will report detailed information in the same format as used for the explaining other supported commands (find, count, etc.):

> db.c.drop();
> for (let i = 0; i < 10; i++) { db.c.insert({_id: i, a: 1, b: i}); }
> db.c.createIndex({a: 1});
> db.c.createIndex({b: 1});
 
> db.c.explain("executionStats").aggregate([{$match: {a: 1, b: {$gt: 3}}}]);
{
	"stages" : [
		{
			"$cursor" : {
				"query" : {
					"a" : 1,
					"b" : {
						"$gt" : 3
					}
				},
				"queryPlanner" : {
					"plannerVersion" : 1,
					"namespace" : "test.c",
					"indexFilterSet" : false,
					"parsedQuery" : {
						"$and" : [
							{
								"a" : {
									"$eq" : 1
								}
							},
							{
								"b" : {
									"$gt" : 3
								}
							}
						]
					},
					"winningPlan" : {
						"stage" : "FETCH",
						"filter" : {
							"a" : {
								"$eq" : 1
							}
						},
						"inputStage" : {
							"stage" : "IXSCAN",
							"keyPattern" : {
								"b" : 1
							},
							"indexName" : "b_1",
							"isMultiKey" : false,
							"multiKeyPaths" : {
								"b" : [ ]
							},
							"isUnique" : false,
							"isSparse" : false,
							"isPartial" : false,
							"indexVersion" : 2,
							"direction" : "forward",
							"indexBounds" : {
								"b" : [
									"(3.0, inf.0]"
								]
							}
						}
					},
					"rejectedPlans" : [
						{
							"stage" : "FETCH",
							"filter" : {
								"b" : {
									"$gt" : 3
								}
							},
							"inputStage" : {
								"stage" : "IXSCAN",
								"keyPattern" : {
									"a" : 1
								},
								"indexName" : "a_1",
								"isMultiKey" : false,
								"multiKeyPaths" : {
									"a" : [ ]
								},
								"isUnique" : false,
								"isSparse" : false,
								"isPartial" : false,
								"indexVersion" : 2,
								"direction" : "forward",
								"indexBounds" : {
									"a" : [
										"[1.0, 1.0]"
									]
								}
							}
						}
					]
				},
				"executionStats" : {
					"executionSuccess" : true,
					"nReturned" : 6,
					"executionTimeMillis" : 1,
					"totalKeysExamined" : 6,
					"totalDocsExamined" : 6,
					"executionStages" : {
						"stage" : "FETCH",
						"filter" : {
							"a" : {
								"$eq" : 1
							}
						},
						"nReturned" : 6,
						"executionTimeMillisEstimate" : 0,
						"works" : 8,
						"advanced" : 6,
						"needTime" : 0,
						"needYield" : 0,
						"saveState" : 1,
						"restoreState" : 1,
						"isEOF" : 1,
						"invalidates" : 0,
						"docsExamined" : 6,
						"alreadyHasObj" : 0,
						"inputStage" : {
							"stage" : "IXSCAN",
							"nReturned" : 6,
							"executionTimeMillisEstimate" : 0,
							"works" : 7,
							"advanced" : 6,
							"needTime" : 0,
							"needYield" : 0,
							"saveState" : 1,
							"restoreState" : 1,
							"isEOF" : 1,
							"invalidates" : 0,
							"keyPattern" : {
								"b" : 1
							},
							"indexName" : "b_1",
							"isMultiKey" : false,
							"multiKeyPaths" : {
								"b" : [ ]
							},
							"isUnique" : false,
							"isSparse" : false,
							"isPartial" : false,
							"indexVersion" : 2,
							"direction" : "forward",
							"indexBounds" : {
								"b" : [
									"(3.0, inf.0]"
								]
							},
							"keysExamined" : 6,
							"seeks" : 1,
							"dupsTested" : 0,
							"dupsDropped" : 0,
							"seenInvalidated" : 0
						}
					}
				}
			}
		}
	],
	"ok" : 1,
	"operationTime" : Timestamp(0, 0)
}

The stages[0].$cursor.executionStats section is entirely new. In "allPlansExecution" mode, the executionStats section is extended with information on all candidate plans evaluated by the plan ranker:

> db.c.explain("allPlansExecution").aggregate([{$match: {a: 1, b: {$gt: 3}}}])
{
> db.c.explain("allPlansExecution").aggregate([{$match: {a: 1, b: {$gt: 3}}}])
{
	"stages" : [
		{
			"$cursor" : {
				"query" : {
					"a" : 1,
					"b" : {
						"$gt" : 3
					}
				},
				"queryPlanner" : {
					"plannerVersion" : 1,
					"namespace" : "test.c",
					"indexFilterSet" : false,
					"parsedQuery" : {
						"$and" : [
							{
								"a" : {
									"$eq" : 1
								}
							},
							{
								"b" : {
									"$gt" : 3
								}
							}
						]
					},
					"winningPlan" : {
						"stage" : "FETCH",
						"filter" : {
							"a" : {
								"$eq" : 1
							}
						},
						"inputStage" : {
							"stage" : "IXSCAN",
							"keyPattern" : {
								"b" : 1
							},
							"indexName" : "b_1",
							"isMultiKey" : false,
							"multiKeyPaths" : {
								"b" : [ ]
							},
							"isUnique" : false,
							"isSparse" : false,
							"isPartial" : false,
							"indexVersion" : 2,
							"direction" : "forward",
							"indexBounds" : {
								"b" : [
									"(3.0, inf.0]"
								]
							}
						}
					},
					"rejectedPlans" : [
						{
							"stage" : "FETCH",
							"filter" : {
								"b" : {
									"$gt" : 3
								}
							},
							"inputStage" : {
								"stage" : "IXSCAN",
								"keyPattern" : {
									"a" : 1
								},
								"indexName" : "a_1",
								"isMultiKey" : false,
								"multiKeyPaths" : {
									"a" : [ ]
								},
								"isUnique" : false,
								"isSparse" : false,
								"isPartial" : false,
								"indexVersion" : 2,
								"direction" : "forward",
								"indexBounds" : {
									"a" : [
										"[1.0, 1.0]"
									]
								}
							}
						}
					]
				},
				"executionStats" : {
					"executionSuccess" : true,
					"nReturned" : 6,
					"executionTimeMillis" : 0,
					"totalKeysExamined" : 6,
					"totalDocsExamined" : 6,
					"executionStages" : {
						"stage" : "FETCH",
						"filter" : {
							"a" : {
								"$eq" : 1
							}
						},
						"nReturned" : 6,
						"executionTimeMillisEstimate" : 0,
						"works" : 8,
						"advanced" : 6,
						"needTime" : 0,
						"needYield" : 0,
						"saveState" : 1,
						"restoreState" : 1,
						"isEOF" : 1,
						"invalidates" : 0,
						"docsExamined" : 6,
						"alreadyHasObj" : 0,
						"inputStage" : {
							"stage" : "IXSCAN",
							"nReturned" : 6,
							"executionTimeMillisEstimate" : 0,
							"works" : 7,
							"advanced" : 6,
							"needTime" : 0,
							"needYield" : 0,
							"saveState" : 1,
							"restoreState" : 1,
							"isEOF" : 1,
							"invalidates" : 0,
							"keyPattern" : {
								"b" : 1
							},
							"indexName" : "b_1",
							"isMultiKey" : false,
							"multiKeyPaths" : {
								"b" : [ ]
							},
							"isUnique" : false,
							"isSparse" : false,
							"isPartial" : false,
							"indexVersion" : 2,
							"direction" : "forward",
							"indexBounds" : {
								"b" : [
									"(3.0, inf.0]"
								]
							},
							"keysExamined" : 6,
							"seeks" : 1,
							"dupsTested" : 0,
							"dupsDropped" : 0,
							"seenInvalidated" : 0
						}
					},
					"allPlansExecution" : [
						{
							"nReturned" : 3,
							"executionTimeMillisEstimate" : 0,
							"totalKeysExamined" : 7,
							"totalDocsExamined" : 7,
							"executionStages" : {
								"stage" : "FETCH",
								"filter" : {
									"b" : {
										"$gt" : 3
									}
								},
								"nReturned" : 3,
								"executionTimeMillisEstimate" : 0,
								"works" : 7,
								"advanced" : 3,
								"needTime" : 4,
								"needYield" : 0,
								"saveState" : 1,
								"restoreState" : 1,
								"isEOF" : 0,
								"invalidates" : 0,
								"docsExamined" : 7,
								"alreadyHasObj" : 0,
								"inputStage" : {
									"stage" : "IXSCAN",
									"nReturned" : 7,
									"executionTimeMillisEstimate" : 0,
									"works" : 7,
									"advanced" : 7,
									"needTime" : 0,
									"needYield" : 0,
									"saveState" : 1,
									"restoreState" : 1,
									"isEOF" : 0,
									"invalidates" : 0,
									"keyPattern" : {
										"a" : 1
									},
									"indexName" : "a_1",
									"isMultiKey" : false,
									"multiKeyPaths" : {
										"a" : [ ]
									},
									"isUnique" : false,
									"isSparse" : false,
									"isPartial" : false,
									"indexVersion" : 2,
									"direction" : "forward",
									"indexBounds" : {
										"a" : [
											"[1.0, 1.0]"
										]
									},
									"keysExamined" : 7,
									"seeks" : 1,
									"dupsTested" : 0,
									"dupsDropped" : 0,
									"seenInvalidated" : 0
								}
							}
						},
						{
							"nReturned" : 6,
							"executionTimeMillisEstimate" : 0,
							"totalKeysExamined" : 6,
							"totalDocsExamined" : 6,
							"executionStages" : {
								"stage" : "FETCH",
								"filter" : {
									"a" : {
										"$eq" : 1
									}
								},
								"nReturned" : 6,
								"executionTimeMillisEstimate" : 0,
								"works" : 7,
								"advanced" : 6,
								"needTime" : 0,
								"needYield" : 0,
								"saveState" : 1,
								"restoreState" : 1,
								"isEOF" : 1,
								"invalidates" : 0,
								"docsExamined" : 6,
								"alreadyHasObj" : 0,
								"inputStage" : {
									"stage" : "IXSCAN",
									"nReturned" : 6,
									"executionTimeMillisEstimate" : 0,
									"works" : 7,
									"advanced" : 6,
									"needTime" : 0,
									"needYield" : 0,
									"saveState" : 1,
									"restoreState" : 1,
									"isEOF" : 1,
									"invalidates" : 0,
									"keyPattern" : {
										"b" : 1
									},
									"indexName" : "b_1",
									"isMultiKey" : false,
									"multiKeyPaths" : {
										"b" : [ ]
									},
									"isUnique" : false,
									"isSparse" : false,
									"isPartial" : false,
									"indexVersion" : 2,
									"direction" : "forward",
									"indexBounds" : {
										"b" : [
											"(3.0, inf.0]"
										]
									},
									"keysExamined" : 6,
									"seeks" : 1,
									"dupsTested" : 0,
									"dupsDropped" : 0,
									"seenInvalidated" : 0
								}
							}
						}
					]
				}
			}
		}
	],
	"ok" : 1,
	"operationTime" : Timestamp(0, 0)
}

Here, the stages[0].$cursor.executionStats.allPlansExecution section is entirely new. This is implemented by allowing the explain command to accept a nested aggregate command:

{explain: {aggregate: ...}, verbosity: "allPlansExecution"}

The aggregate command's explain parameter is still supported, as in {aggregate: "myCollection", pipeline: [], explain: true}. However, the explain command format is preferred. It is illegal to combine the two formats, as in

{explain: {aggregate: "myCollection", pipeline: [], explain: true}, verbosity: "allPlansExecution"}

Finally, since the explain command has never supported readConcern or writeConcern, we have made it an error to use readConcern or writeConcern in combination with the aggregate command explain flag. All of the following examples are illegal:

{aggregate: "myCollection", pipeline: [{$out: "foo"}], explain: true, writeConcern: {w: 1}}
{explain: {aggregate: "myCollection", pipeline: [{$out: "foo"}]}, writeConcern: {w: 1}}
{aggregate: "myCollection", pipeline: [{$out: "foo"}], explain: true, readConcern: {level: "majority"}}
{explain: {aggregate: "myCollection", pipeline: [{$out: "foo"}]}, readConcern: {level: "majority"}}

This is a minor breaking change in 3.6 which will have to be accommodated by drivers.

Note that aggregation stages other than $cursor do not currently report execution stats. Implementing this is further work tracked by SERVER-21784.



 Comments   
Comment by Githook User [ 13/Mar/17 ]

Author:

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

Message: SERVER-19758 add support for "executionStats" and "allPlansExecution" to agg explain

Like other explainable commands, aggregate can now be
explained using the explain command, e.g.
db.runCommand({explain:

{aggregate: ...}

, verbosity:
"executionStats"}). The existing explain:true flag
corresponds to "queryPlanner" mode and is still supported.
However, explain:true cannot be specified when explaining
aggregate via the explain command.

Additional execution information is provided only in the
$cursor section of the aggregation explain output. Having
aggregation stages themselves track and report execution
info is further work.
Branch: master
https://github.com/mongodb/mongo/commit/82b16740f8a66093b453a73a04b3b9bd00e5d7a0

Comment by Shakir Sadikali [ 19/Jan/16 ]

I've run into a similar issue with aggregation against geo queries. For example, i get the following

MongoDB Enterprise > var exp = db.geodataLegacyAggregate.explain("executionStats")
MongoDB Enterprise > exp.aggregate([{
...     $geoNear : {
...         spherical : true,
...         limit : 100000,
...         maxDistance : 500,
...         near : {
...             type : "Point",
...             coordinates : [ -3.7441665999999998, 40.3628599999999980 ],
...         },
...         includeLocs : "dist.location",
...         distanceField : "dist.distance",
...         query : { },
...     }
... },
... {
...     $group : {
...         _id : {
...             customerId : "$_id.customerId",
...             shardDateTime : "$_id.shardDateTime",
...             assetId : "$_id.assetId",
...         },
...         count : { $sum : 1 }
...     }
... }])
{
	"waitedMS" : NumberLong(0),
	"stages" : [
		{
			"$geoNear" : {
				"near" : {
					"type" : "Point",
					"coordinates" : [
						-3.7441666,
						40.36286
					]
				},
				"distanceField" : "dist.distance",
				"limit" : NumberLong(100000),
				"maxDistance" : 500,
				"query" : {
					
				},
				"spherical" : true,
				"distanceMultiplier" : 1,
				"includeLocs" : "dist.location"
			}
		},
		{
			"$group" : {
				"_id" : {
					"customerId" : "$_id.customerId",
					"shardDateTime" : "$_id.shardDateTime",
					"assetId" : "$_id.assetId"
				},
				"count" : {
					"$sum" : {
						"$const" : 1
					}
				}
			}
		}
	],
	"ok" : 1
}

The above output is not particularly helpful.

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