[SERVER-19715] Aggregation Loglines do not print the query plan Created: 03/Aug/15  Updated: 03/Aug/15  Resolved: 03/Aug/15

Status: Closed
Project: Core Server
Component/s: Aggregation Framework, Logging
Affects Version/s: 2.6.10, 3.0.5
Fix Version/s: None

Type: New Feature Priority: Major - P3
Reporter: Victor Hooi Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-16847 Diagnostic log output for all query c... Closed
Participants:

 Description   

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.



 Comments   
Comment by Victor Hooi [ 03/Aug/15 ]

rassi@10gen.comYup, that makes sense =). Thanks! Sorry, I didn't see SERVER-16847, I guess my JIRA-search-fu wasn't strong yesterday...lol. (I think I was also searching specifically for "log" and "aggregation"/"aggregate")

Comment by J Rassi [ 03/Aug/15 ]

Closing as a duplicate of SERVER-16847 (Victor, feel free to add a comment to that ticket if you think that any further information should be added).

Generated at Thu Feb 08 03:51:51 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.