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

Aggregation Loglines do not print the query plan

    XMLWordPrintable

    Details

    • Type: New Feature
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Duplicate
    • Affects Version/s: 2.6.10, 3.0.5
    • Fix Version/s: None
    • Labels:
      None

      Description

      When we log aggregation operations, we do not log the query plan used (for the $match component). This information would be fairly useful when debugging any performance issues with aggregation queries.

      For example, I have the following collection, cats.mycats, containing a single document:

      > db.mycats.find()
      { "_id" : ObjectId("55bef95c1091b2ef1816b6eb"), "name" : "ernie", "age" : 5 }
      

      and a single index (on top of the in-built _id index):

      > db.mycats.getIndexes()
      [
              {
                      "v" : 1,
                      "key" : {
                              "_id" : 1
                      },
                      "name" : "_id_",
                      "ns" : "cats.mycats"
              },
              {
                      "v" : 1,
                      "key" : {
                              "name" : 1
                      },
                      "name" : "name_1",
                      "ns" : "cats.mycats"
              }
      ]
      

      I issue a find query:

      > db.mycats.find({name: 'ernie'})
      { "_id" : ObjectId("55bef95c1091b2ef1816b6eb"), "name" : "ernie", "age" : 5 }
      

      which produces these loglines, telling me that the name: 1 index was used:

      2015-08-03T16:52:36.043+1000 I QUERY    [conn3] query cats.mycats query: { name: "ernie" } planSummary: IXSCAN { name: 1.0 } ntoreturn:0 ntoskip:0 nscanned:1 nscannedObjects:1 keyUp
      dates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:71 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 }
      }, Collection: { acquireCount: { R: 1 } } } 0ms
      2015-08-03T16:52:36.044+1000 I COMMAND  [conn3] command cats.$cmd command: isMaster { isMaster: 1.0, forShell: 1.0 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:178 locks:{} 0m
      s
      

      I then issue an analogous aggregation query:

      > db.mycats.aggregate([{$match: {name: 'ernie'}}])
      { "_id" : ObjectId("55bef95c1091b2ef1816b6eb"), "name" : "ernie", "age" : 5 }
      

      which produces this logline, which does not tell me which query plan was used:

      2015-08-03T16:53:35.427+1000 I COMMAND  [conn3] command cats.$cmd command: aggregate { aggregate: "mycats", pipeline: [ { $match: { name: "ernie" } } ], cursor: {} } keyUpdates:0 wr
      iteConflicts:0 numYields:0 reslen:153 locks:{ Global: { acquireCount: { r: 6 } }, MMAPV1Journal: { acquireCount: { r: 3 } }, Database: { acquireCount: { r: 3 } }, Collection: { acqu
      ireCount: { R: 3 } } } 0ms
      

      There is no information about the query plan used.

      If I use the explain option for aggregate, I can confirm that an index is being used:

      > db.mycats.aggregate([{$match: {name: 'ernie'}}], {explain:true})
      {
              "stages" : [
                      {
                              "$cursor" : {
                                      "query" : {
                                              "name" : "ernie"
                                      },
                                      "queryPlanner" : {
                                              "plannerVersion" : 1,
                                              "namespace" : "cats.mycats",
                                              "indexFilterSet" : false,
                                              "parsedQuery" : {
                                                      "name" : {
                                                              "$eq" : "ernie"
                                                      }
                                              },
                                              "winningPlan" : {
                                                      "stage" : "FETCH",
                                                      "inputStage" : {
                                                              "stage" : "IXSCAN",
                                                              "keyPattern" : {
                                                                      "name" : 1
                                                              },
                                                              "indexName" : "name_1",
                                                              "isMultiKey" : false,
                                                              "direction" : "forward",
                                                              "indexBounds" : {
                                                                      "name" : [
                                                                              "[\"ernie\", \"ernie\"]"
                                                                      ]
                                                              }
                                                      }
                                              },
                                              "rejectedPlans" : [ ]
                                      }
                              }
                      }
              ],
              "ok" : 1
      }
      

      However, there is no way to actually find out the query plan used for running aggregation operations in a Production instance of MongoDB.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              Unassigned Unassigned
              Reporter:
              victor.hooi Victor Hooi
              Participants:
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: