[SERVER-71046] Explain is not reporting index usage properly when using a lookup with an unwind Created: 02/Nov/22  Updated: 04/Jan/24  Resolved: 25/Jan/23

Status: Closed
Project: Core Server
Component/s: Aggregation Framework
Affects Version/s: None
Fix Version/s: 6.3.0-rc0

Type: Bug Priority: Major - P3
Reporter: Conchi Bueno Assignee: Alyssa Clark
Resolution: Fixed Votes: 0
Labels: query-director-triage
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

MongoDb Version 6.0.2


Issue Links:
Backports
Related
Assigned Teams:
Query Execution
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v6.0, v5.0
Steps To Reproduce:

MongoDB version 6.0.2.

We have two collections:

1. Collection pod7sims

with document:

{ "_id" : ObjectId("6361f3964759e66f091a87e5"), "acctid" : 100121114, "activationdate" : "1629923806736", "cellidtracking" : false, "commplanid" : 313, "suspended" : "N", "dateadded" : "158839640", "datemodified" : "16142", "dateoneboxmodified" : "1652143", "dateshipped" : "16054", "documentmeta" : { "datemodified" : "16657093" }, "iccid" : "dummy", "imsi1" : "dummy", "laststatechange" : "16206729", "linepaystatus" : "CURRENT", "live" : true, "migratedsim" : "N", "msisdn" : "dummy", "networkblocked" : false, "notes" : "noteeee", "operatorid" : 25014, "overagelimit" : 30, "overagelimitoverridemode" : 1, "overagelimitreached" : false, "primarydevice" : true, "rateplanid" : 1411914, "rawsimid" : 482812113, "simid" : 522790313, "simprofileid" : 134813, "status" : 6, "testreadydatalimit" : 20480, "testreadydatastate" : 11, "testreadytimelimit" : 120, "testreadytimestate" : 11, "version" : 0 }

and index:

{ v: 2, key: { acctid: 1 }, name: 'acctid_1' },

2. Collection pod7smtdu

with document:

{ "_id" : ObjectId("636203a14759e66f091a87e9"), "billingcycleid" : 233, "scheduleid" : 1, "simid" : 522790313, "acctid" : 100057613, "billable" : false, "billablecsdusage" : 0, "billabledatausage" : 236544, "billablesmsusage" : 864, "billableussdusage" : 0, "billablevoiceusage" : 0, "csdusage" : 0, "datausage" : "236544", "dateadded" : 1646331936072, "datemodified" : "1647283182076", "operatorid" : 27014, "smsusage" : 864, "ussdusage" : 0, "voiceusage" : 0 }

and index:

{ v: 2, key: { simid: -1, billingcycleid: -1, scheduleid: -1 },  name: 'simid_-1_billingcycleid_-1_scheduleid_-1', unique: true }

If I run the following aggregation with explain:

> db.pod7sims.explain("executionStats").aggregate([
...     {$match: {acctid: 100121114}}, 
... 
...     {$lookup: { from: 'pod7smtdu', 
...                 localField: 'simid', foreignField: 'simid',
...                 pipeline: [ {$match: {$expr: {$and: [ {$eq: ['$scheduleid', 1]},
...                                                       {$eq: ['$billingcycleid', 233]} ]}}}
...                           ],
...                 as: 'smtdu'
...               }
...     }, 
...     {$unwind: {path: '$smtdu'}}, 
...     {$sort: {'smtdu.datausage': -1}}, 
...     {$limit: 50}
...   ])
{
	"explainVersion" : "1",
	"stages" : [
		{
			"$cursor" : {
				"queryPlanner" : {
					"namespace" : "01021859.pod7sims",
					"indexFilterSet" : false,
					"parsedQuery" : {
						"acctid" : {
							"$eq" : 100121114
						}
					},
					"queryHash" : "598915AC",
					"planCacheKey" : "CAA53C2C",
					"maxIndexedOrSolutionsReached" : false,
					"maxIndexedAndSolutionsReached" : false,
					"maxScansToExplodeReached" : false,
					"winningPlan" : {
						"stage" : "FETCH",
						"inputStage" : {
							"stage" : "IXSCAN",
							"keyPattern" : {
								"acctid" : 1
							},
							"indexName" : "acctid_1",
							"isMultiKey" : false,
							"multiKeyPaths" : {
								"acctid" : [ ]
							},
							"isUnique" : false,
							"isSparse" : false,
							"isPartial" : false,
							"indexVersion" : 2,
							"direction" : "forward",
							"indexBounds" : {
								"acctid" : [
									"[100121114.0, 100121114.0]"
								]
							}
						}
					},
					"rejectedPlans" : [ ]
				},
				"executionStats" : {
					"executionSuccess" : true,
					"nReturned" : 1,
					"executionTimeMillis" : 0,
					"totalKeysExamined" : 1,
					"totalDocsExamined" : 1,
					"executionStages" : {
						"stage" : "FETCH",
						"nReturned" : 1,
						"executionTimeMillisEstimate" : 0,
						"works" : 2,
						"advanced" : 1,
						"needTime" : 0,
						"needYield" : 0,
						"saveState" : 1,
						"restoreState" : 1,
						"isEOF" : 1,
						"docsExamined" : 1,
						"alreadyHasObj" : 0,
						"inputStage" : {
							"stage" : "IXSCAN",
							"nReturned" : 1,
							"executionTimeMillisEstimate" : 0,
							"works" : 2,
							"advanced" : 1,
							"needTime" : 0,
							"needYield" : 0,
							"saveState" : 1,
							"restoreState" : 1,
							"isEOF" : 1,
							"keyPattern" : {
								"acctid" : 1
							},
							"indexName" : "acctid_1",
							"isMultiKey" : false,
							"multiKeyPaths" : {
								"acctid" : [ ]
							},
							"isUnique" : false,
							"isSparse" : false,
							"isPartial" : false,
							"indexVersion" : 2,
							"direction" : "forward",
							"indexBounds" : {
								"acctid" : [
									"[100121114.0, 100121114.0]"
								]
							},
							"keysExamined" : 1,
							"seeks" : 1,
							"dupsTested" : 0,
							"dupsDropped" : 0
						}
					}
				}
			},
			"nReturned" : NumberLong(1),
			"executionTimeMillisEstimate" : NumberLong(0)
		},
		{
			"$lookup" : {
				"from" : "pod7smtdu",
				"as" : "smtdu",
				"localField" : "simid",
				"foreignField" : "simid",
				"let" : {
					
				},
				"pipeline" : [
					{
						"$match" : {
							"$expr" : {
								"$and" : [
									{
										"$eq" : [
											"$scheduleid",
											1
										]
									},
									{
										"$eq" : [
											"$billingcycleid",
											233
										]
									}
								]
							}
						}
					}
				],
				"unwinding" : {
					"preserveNullAndEmptyArrays" : false
				}
			},
			"totalDocsExamined" : NumberLong(0),
			"totalKeysExamined" : NumberLong(0),
			"collectionScans" : NumberLong(0),
			"indexesUsed" : [ ],
			"nReturned" : NumberLong(1),
			"executionTimeMillisEstimate" : NumberLong(0)
		},
		{
			"$sort" : {
				"sortKey" : {
					"smtdu.datausage" : -1
				},
				"limit" : NumberLong(50)
			},
			"totalDataSizeSortedBytesEstimate" : NumberLong(1587),
			"usedDisk" : false,
			"spills" : NumberLong(0),
			"nReturned" : NumberLong(1),
			"executionTimeMillisEstimate" : NumberLong(0)
		}
	],
	"serverInfo" : {
		"host" : "M-C02CC3ZNMD6R",
		"port" : 27017,
		"version" : "6.0.2",
		"gitVersion" : "94fb7dfc8b974f1f5343e7ea394d0d9deedba50e"
	},
	"serverParameters" : {
		"internalQueryFacetBufferSizeBytes" : 104857600,
		"internalQueryFacetMaxOutputDocSizeBytes" : 104857600,
		"internalLookupStageIntermediateDocumentMaxSizeBytes" : 104857600,
		"internalDocumentSourceGroupMaxMemoryBytes" : 104857600,
		"internalQueryMaxBlockingSortMemoryUsageBytes" : 104857600,
		"internalQueryProhibitBlockingMergeOnMongoS" : 0,
		"internalQueryMaxAddToSetBytes" : 104857600,
		"internalDocumentSourceSetWindowFieldsMaxMemoryBytes" : 104857600
	},
	"command" : {
		"aggregate" : "pod7sims",
		"pipeline" : [
			{
				"$match" : {
					"acctid" : 100121114
				}
			},
			{
				"$lookup" : {
					"from" : "pod7smtdu",
					"localField" : "simid",
					"foreignField" : "simid",
					"pipeline" : [
						{
							"$match" : {
								"$expr" : {
									"$and" : [
										{
											"$eq" : [
												"$scheduleid",
												1
											]
										},
										{
											"$eq" : [
												"$billingcycleid",
												233
											]
										}
									]
								}
							}
						}
					],
					"as" : "smtdu"
				}
			},
			{
				"$unwind" : {
					"path" : "$smtdu"
				}
			},
			{
				"$sort" : {
					"smtdu.datausage" : -1
				}
			},
			{
				"$limit" : 50
			}
		],
		"cursor" : {
			
		},
		"$db" : "01021859"
	},
	"ok" : 1
}

we can see in the lookup-unwind stage reports the following which indicates no index was used:

			"totalDocsExamined" : NumberLong(0),
			"totalKeysExamined" : NumberLong(0),
			"collectionScans" : NumberLong(0),
			"indexesUsed" : [ ],
			"nReturned" : NumberLong(1),
			"executionTimeMillisEstimate" : NumberLong(0)

However, if we use index stats before and after the execution:

db.pod7smtdu.aggregate( [{$indexStats: {}}, {$project: {key: 1,'accesses.ops': 1}}] )

before:

{ "key" : { "simid" : -1, "billingcycleid" : -1, "scheduleid" : -1 }, "accesses" : { "ops" : NumberLong(4) } }

after

{ "key" : { "simid" : -1, "billingcycleid" : -1, "scheduleid" : -1 }, "accesses" : { "ops" : NumberLong(5) } }

we can see an index has been used.

Participants:
Case:

 Description   

In MongoDB version 6.0.2 when running explain on an aggregation having a `$lookup` stage followed by an `$unwind`, the executionstats metrics from the explain plan are not reported properly.

 db.pod7sims.explain("executionStats").aggregate([
    {$match: {acctid: 100121114}}, 
    {$lookup: { from: 'pod7smtdu', 
        localField: 'simid', foreignField: 'simid',
        pipeline: [ {$match: {$expr: {$and: [ {$eq: ['$scheduleid', 1]},{$eq: ['$billingcycleid', 233]} ]}}}],
        as: 'smtdu'}}, 
    {$unwind: {path: '$smtdu'}}, 
    {$sort: {'smtdu.datausage': -1}},  
    {$limit: 50}])

According to the explain,

			"totalDocsExamined" : NumberLong(0),
			"totalKeysExamined" : NumberLong(0),
			"collectionScans" : NumberLong(0),
			"indexesUsed" : [ ],
			"nReturned" : NumberLong(1),

However, when using `$indexstats` we can see an index has been used.

 

if I remove the $unwind stage, explain reports the metrics properly


Generated at Thu Feb 08 06:17:54 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.