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

Logging for $lookup less complete in 3.4 than 3.2

    XMLWordPrintable

    Details

    • Operating System:
      ALL
    • Steps To Reproduce:
      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)
    • Case:

      Description

      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.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              backlog-server-query Backlog - Query Team
              Reporter:
              christopher.harris Christopher Harris
              Participants:
              Votes:
              3 Vote for this issue
              Watchers:
              19 Start watching this issue

                Dates

                Created:
                Updated: