Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-71046

Explain is not reporting index usage properly when using a lookup with an unwind

    • Query Execution
    • Fully Compatible
    • ALL
    • v6.0, v5.0
    • Hide

      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.

      Show
      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.

      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

            Assignee:
            alyssa.clark@mongodb.com Alyssa Clark
            Reporter:
            conchi.bueno@mongodb.com Conchi Bueno
            Votes:
            0 Vote for this issue
            Watchers:
            10 Start watching this issue

              Created:
              Updated:
              Resolved: