-
Type:
New Feature
-
Resolution: Duplicate
-
Priority:
Major - P3
-
None
-
Affects Version/s: 2.6.10, 3.0.5
-
Component/s: Aggregation Framework, Logging
-
Labels: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
-