-
Type: New Feature
-
Resolution: Duplicate
-
Priority: Major - P3
-
None
-
Affects Version/s: 2.6.10, 3.0.5
-
Component/s: Aggregation Framework, Logging
-
None
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.
- duplicates
-
SERVER-16847 Diagnostic log output for all query clients should include plan summary string
- Closed