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

$lookup and $graphLookup do not increment index stats counters

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: 3.4.0
    • Fix Version/s: 3.4.3, 3.5.2
    • Component/s: Aggregation Framework
    • Labels:
      None
    • Backwards Compatibility:
      Fully Compatible
    • Operating System:
      ALL
    • Backport Requested:
      v3.4
    • Steps To Reproduce:
      Hide

      // 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
      }
      

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

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                7 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: