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

Logging for $lookup less complete in 3.4 than 3.2

    • Query Execution
    • ALL
    • Hide

      db.setProfilingLevel(0,-1) on a 3.4 mongod and then review the log file after issuing a `$lookup` (which returns results)

      Show
      db.setProfilingLevel(0,-1) on a 3.4 mongod and then review the log file after issuing a `$lookup` (which returns results)

      In 3.2, we log all of the find() queries that are generated from a $lookup. For example (with profile level of (0,-1)):

      2016-10-26T08:33:30.400-0500 I COMMAND  [conn1] query test.bar query: { y: { $eq: 1.0 } } planSummary: IXSCAN { y: 1.0 } cursorid:15498909484 ntoreturn:0 ntoskip:0 keysExamined:101 docsExamined:101 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:101 reslen:3359 locks:{ Global: { acquireCount: { r: 10 } }, Database: { acquireCount: { r: 5 } }, Collection: { acquireCount: { r: 5 } } } 0ms
      2016-10-26T08:33:30.402-0500 I COMMAND  [conn1] getmore test.bar query: { y: { $eq: 1.0 } } cursorid:15498909484 ntoreturn:0 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:3 nreturned:449 reslen:14837 locks:{ Global: { acquireCount: { r: 18 } }, Database: { acquireCount: { r: 9 } }, Collection: { acquireCount: { r: 9 } } } 2ms
      2016-10-26T08:33:30.403-0500 I COMMAND  [conn1] query test.bar query: { y: { $eq: 2.0 } } planSummary: IXSCAN { y: 1.0 } cursorid:16804514490 ntoreturn:0 ntoskip:0 keysExamined:101 docsExamined:101 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:101 reslen:3353 locks:{ Global: { acquireCount: { r: 22 } }, Database: { acquireCount: { r: 11 } }, Collection: { acquireCount: { r: 11 } } } 0ms
      2016-10-26T08:33:30.404-0500 I COMMAND  [conn1] getmore test.bar query: { y: { $eq: 2.0 } } cursorid:16804514490 ntoreturn:0 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:3 nreturned:449 reslen:14837 locks:{ Global: { acquireCount: { r: 30 } }, Database: { acquireCount: { r: 15 } }, Collection: { acquireCount: { r: 15 } } } 0ms
      2016-10-26T08:33:30.405-0500 I COMMAND  [conn1] query test.bar query: { y: { $eq: 3.0 } } planSummary: IXSCAN { y: 1.0 } cursorid:14652587107 ntoreturn:0 ntoskip:0 keysExamined:101 docsExamined:101 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:101 reslen:3353 locks:{ Global: { acquireCount: { r: 34 } }, Database: { acquireCount: { r: 17 } }, Collection: { acquireCount: { r: 17 } } } 0ms
      2016-10-26T08:33:30.405-0500 I COMMAND  [conn1] getmore test.bar query: { y: { $eq: 3.0 } } cursorid:14652587107 ntoreturn:0 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:3 nreturned:449 reslen:14837 locks:{ Global: { acquireCount: { r: 42 } }, Database: { acquireCount: { r: 21 } }, Collection: { acquireCount: { r: 21 } } } 0ms
      2016-10-26T08:33:30.406-0500 I COMMAND  [conn1] command test.foo command: aggregate { aggregate: "foo", pipeline: [ { $lookup: { from: "bar", localField: "x", foreignField: "y", as: "output" } }, { $limit: 3.0 } ], cursor: {} } keyUpdates:0 writeConflicts:0 numYields:1 reslen:62622 locks:{ Global: { acquireCount: { r: 44 } }, Database: { acquireCount: { r: 22 } }, Collection: { acquireCount: { r: 22 } } } protocol:op_command 7ms
      

      I do not see the corresponding entries in 3.4

      2016-10-26T07:45:10.733-0500 I COMMAND  [conn1] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0 } numYields:0 reslen:174 locks:{} protocol:op_command 0ms
      2016-10-26T07:45:16.039-0500 I COMMAND  [conn1] command test.bar appName: "MongoDB Shell" command: aggregate { aggregate: "foo", pipeline: [ { $lookup: { from: "bar", localField: "x", foreignField: "y", as: "output" } }, { $match: { output.val: true } }, { $limit: 1.0 } ], cursor: {} } planSummary: COLLSCAN keysExamined:0 docsExamined:199 cursorExhausted:1 numYields:6 nreturned:1 reslen:20926 locks:{ Global: { acquireCount: { r: 26 } }, Database: { acquireCount: { r: 13 } }, Collection: { acquireCount: { r: 12 } } } protocol:op_command 5ms
      

      Same data set used for both environments.

            Assignee:
            backlog-query-execution [DO NOT USE] Backlog - Query Execution
            Reporter:
            christopher.harris@mongodb.com Chris Harris
            Votes:
            5 Vote for this issue
            Watchers:
            23 Start watching this issue

              Created:
              Updated: