-
Type:
Bug
-
Resolution: Unresolved
-
Priority:
Major - P3
-
None
-
Affects Version/s: None
-
Component/s: Aggregation Framework, Logging
-
Labels:
-
Query Execution
-
ALL
-
-
(copied to CRM)
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.
- is related to
-
SERVER-25005 Execute queries in $lookup and $graphLookup with an explicit Pipeline instead of DBDirectClient
-
- Closed
-
-
SERVER-22622 Improve $lookup explain to indicate query plan on the "from" collection
-
- Needs Scheduling
-