[SERVER-27253] $lookup and $graphLookup do not increment index stats counters Created: 01/Dec/16  Updated: 02/May/18  Resolved: 16/Dec/16

Status: Closed
Project: Core Server
Component/s: Aggregation Framework
Affects Version/s: 3.4.0
Fix Version/s: 3.4.3, 3.5.2

Type: Bug Priority: Major - P3
Reporter: Charlie Swanson Assignee: Charlie Swanson
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Related
is related to SERVER-22541 Aggregation plan executors should be ... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v3.4
Steps To Reproduce:

// Set up collections for a $graphLookup.
> db.foo.drop()
true
> db.foo.insert({_id: 1})
WriteResult({ "nInserted" : 1 })
> db.bar.drop()
true
> db.bar.insert([{vertexId: 0, nextVertexId: 1}, {vertexId: 1, nextVertexId: 2}, {vertexId: 2}])
BulkWriteResult({
	"writeErrors" : [ ],
	"writeConcernErrors" : [ ],
	"nInserted" : 3,
	"nUpserted" : 0,
	"nMatched" : 0,
	"nModified" : 0,
	"nRemoved" : 0,
	"upserted" : [ ]
})
 
// Create two indexes so that a plan will be cached. The cached plan is the only evidence that $graphLookup is using an index, and if there is only one plan available, it will not be cached.
> db.bar.ensureIndex({vertexId: 1})
{
	"createdCollectionAutomatically" : false,
	"numIndexesBefore" : 1,
	"numIndexesAfter" : 2,
	"ok" : 1
}
> db.bar.ensureIndex({vertexId: -1, _id: 1})
{
	"createdCollectionAutomatically" : false,
	"numIndexesBefore" : 2,
	"numIndexesAfter" : 3,
	"ok" : 1
}
 
// There are no plans for this query yet, we will compare the cache after the $graphLookup for proof that it used an index.
> db.runCommand({planCacheListPlans: 'bar', query: {$and: [{vertexId: {$in: [1]}}]}})
{ "plans" : [ ], "ok" : 1 }
 
// There are no index accesses yet.
> db.bar.aggregate([{$indexStats: {}}, {$project: {key: 0, host: 0}}]).table()
╔═══════════════════╤═════════════════════════════════════════════════════════════════╗
║ name              │ accesses                                                        ║
║                   │          ┌───────────────┬──────────────────────────────────────╢
║                   │          │ accesses.ops  │ accesses.since                       ║
╠═══════════════════╪══════════╪═══════════════╪══════════════════════════════════════╣
║ vertexId_-1__id_1 │          │ NumberLong(0) │ Thu Dec 01 2016 12:44:11 GMT-0500 (E ║
║                   │          │               │ ST)                                  ║
╟───────────────────┼──────────┼───────────────┼──────────────────────────────────────╢
║ _id_              │          │ NumberLong(0) │ Thu Dec 01 2016 12:43:55 GMT-0500 (E ║
║                   │          │               │ ST)                                  ║
╟───────────────────┼──────────┼───────────────┼──────────────────────────────────────╢
║ vertexId_1        │          │ NumberLong(0) │ Thu Dec 01 2016 12:44:03 GMT-0500 (E ║
║                   │          │               │ ST)                                  ║
╚═══════════════════╧══════════╧═══════════════╧══════════════════════════════════════╝
// Do the $graphLookup.
> db.foo.aggregate([{$graphLookup: {from: "bar", startWith: "$_id", connectFromField: "nextVertexId", connectToField: "vertexId", as: "results"}}])
{ "_id" : 1, "results" : [ { "_id" : ObjectId("5840615bca13c1414d96ceb3"), "vertexId" : 2 }, { "_id" : ObjectId("5840615bca13c1414d96ceb2"), "vertexId" : 1, "nextVertexId" : 2 } ] }
 
// Still no index accesses!
> db.bar.aggregate([{$indexStats: {}}, {$project: {key: 0, host: 0}}]).table()
╔═══════════════════╤═════════════════════════════════════════════════════════════════╗
║ name              │ accesses                                                        ║
║                   │          ┌───────────────┬──────────────────────────────────────╢
║                   │          │ accesses.ops  │ accesses.since                       ║
╠═══════════════════╪══════════╪═══════════════╪══════════════════════════════════════╣
║ vertexId_-1__id_1 │          │ NumberLong(0) │ Thu Dec 01 2016 12:44:11 GMT-0500 (E ║
║                   │          │               │ ST)                                  ║
╟───────────────────┼──────────┼───────────────┼──────────────────────────────────────╢
║ _id_              │          │ NumberLong(0) │ Thu Dec 01 2016 12:43:55 GMT-0500 (E ║
║                   │          │               │ ST)                                  ║
╟───────────────────┼──────────┼───────────────┼──────────────────────────────────────╢
║ vertexId_1        │          │ NumberLong(0) │ Thu Dec 01 2016 12:44:03 GMT-0500 (E ║
║                   │          │               │ ST)                                  ║
╚═══════════════════╧══════════╧═══════════════╧══════════════════════════════════════╝
 
// But it did use the index!
> db.runCommand({planCacheListPlans: 'bar', query: {$and: [{vertexId: {$in: [1]}}]}})
{
	"plans" : [
		{
			"details" : {
				"solution" : "(index-tagged expression tree: tree=Leaf { vertexId: 1.0 }, pos: 0, can combine? 1\n)"
			},
			"reason" : {
				"score" : 1.5003000000000002,
				"stats" : {
					"stage" : "FETCH",
					"nReturned" : 1,
					"executionTimeMillisEstimate" : 0,
					"works" : 2,
					"advanced" : 1,
					"needTime" : 0,
					"needYield" : 0,
					"saveState" : 0,
					"restoreState" : 0,
					"isEOF" : 1,
					"invalidates" : 0,
					"docsExamined" : 1,
					"alreadyHasObj" : 0,
					"inputStage" : {
						"stage" : "IXSCAN",
						"nReturned" : 1,
						"executionTimeMillisEstimate" : 0,
						"works" : 2,
						"advanced" : 1,
						"needTime" : 0,
						"needYield" : 0,
						"saveState" : 0,
						"restoreState" : 0,
						"isEOF" : 1,
						"invalidates" : 0,
						"keyPattern" : {
							"vertexId" : 1
						},
						"indexName" : "vertexId_1",
						"isMultiKey" : false,
						"isUnique" : false,
						"isSparse" : false,
						"isPartial" : false,
						"indexVersion" : 2,
						"direction" : "forward",
						"indexBounds" : {
							"vertexId" : [
								"[1.0, 1.0]"
							]
						},
						"keysExamined" : 1,
						"seeks" : 1,
						"dupsTested" : 0,
						"dupsDropped" : 0,
						"seenInvalidated" : 0
					}
				}
			},
			"feedback" : {
				"nfeedback" : 1,
				"scores" : [
					{
						"score" : 1.5003
					}
				]
			},
			"filterSet" : false
		},
		{
			"details" : {
				"solution" : "(index-tagged expression tree: tree=Leaf { vertexId: -1.0, _id: 1.0 }, pos: 0, can combine? 1\n)"
			},
			"reason" : {
				"score" : 1.5003000000000002,
				"stats" : {
					"stage" : "FETCH",
					"nReturned" : 1,
					"executionTimeMillisEstimate" : 0,
					"works" : 2,
					"advanced" : 1,
					"needTime" : 0,
					"needYield" : 0,
					"saveState" : 0,
					"restoreState" : 0,
					"isEOF" : 1,
					"invalidates" : 0,
					"docsExamined" : 1,
					"alreadyHasObj" : 0,
					"inputStage" : {
						"stage" : "IXSCAN",
						"nReturned" : 1,
						"executionTimeMillisEstimate" : 0,
						"works" : 2,
						"advanced" : 1,
						"needTime" : 0,
						"needYield" : 0,
						"saveState" : 0,
						"restoreState" : 0,
						"isEOF" : 1,
						"invalidates" : 0,
						"keyPattern" : {
							"vertexId" : -1,
							"_id" : 1
						},
						"indexName" : "vertexId_-1__id_1",
						"isMultiKey" : false,
						"isUnique" : false,
						"isSparse" : false,
						"isPartial" : false,
						"indexVersion" : 2,
						"direction" : "forward",
						"indexBounds" : {
							"vertexId" : [
								"[1.0, 1.0]"
							],
							"_id" : [
								"[MinKey, MaxKey]"
							]
						},
						"keysExamined" : 1,
						"seeks" : 1,
						"dupsTested" : 0,
						"dupsDropped" : 0,
						"seenInvalidated" : 0
					}
				}
			},
			"feedback" : {
				
			},
			"filterSet" : false
		}
	],
	"ok" : 1
}

Sprint: Query 2017-01-23
Participants:
Case:

 Description   

The $lookup and $graphLookup stages can take advantage of indexes to perform their lookups, but they do not increment the statistics kept about the number of index access that are exposed via $indexStats.

This happens because the index access counter(s) are incremented at the level of the pipeline command processing, not at the level of each PlanExecutor involved in the pipeline. Currently the tally/ies is/are bumped in PipelineCommand::run() just before generating the results. This logic should instead happen at a lower level, perhaps inside PipelineD::prepareCursorSource() or inside DocumentSourceCursor itself.

This issue does not affect $lookup in 3.2.



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

Author:

{u'username': u'cswanson310', u'name': u'Charlie Swanson', u'email': u'charlie.swanson@mongodb.com'}

Message: SERVER-27253 Bump index usage stats during $lookup.

(cherry picked from commit 15fc05860775df882b588ce64764dd59e773af84)
Branch: v3.4
https://github.com/mongodb/mongo/commit/a29259892f0577dfb045b5eeb351bff7ee721116

Comment by Githook User [ 16/Dec/16 ]

Author:

{u'username': u'cswanson310', u'name': u'Charlie Swanson', u'email': u'charlie.swanson@mongodb.com'}

Message: SERVER-27253 Bump index usage stats during $lookup.
Branch: master
https://github.com/mongodb/mongo/commit/15fc05860775df882b588ce64764dd59e773af84

Comment by Charlie Swanson [ 05/Dec/16 ]

Nope, see the last line of the description.

Comment by Asya Kamsky [ 05/Dec/16 ]

For $lookup this affects 3.2.x also, correct?

Comment by Charlie Swanson [ 01/Dec/16 ]

I'm marking this as related to SERVER-22541 since a patch in development would resolve this issue.

Generated at Thu Feb 08 04:14:36 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.