Dear all,
We are having issues with the aggregate pipeline doing optimization steps which harm the queries performance. It is choosing to do the $sort before the $match stage (my assumption is because the $sort has a better index than the $match stage) which is causing the query to sort the whole database instead of a filtered set.
I have added examples with explain executionStats below to provide more detail. The first example uses an $sort on _id which is indexed making it the first stage in the aggregate. The second example uses an $sort on header.receiverNode (own created field) which is also indexed.
The first example using _id is doing $sort first while the second example is doing the $match first.
db.records.explain("executionStats").aggregate([
{
"$match":{
"$and":[
{
"status":"new",
"messageDeleted":{
"$exists":false
}
},
{
"header.receiverNode":{
"$in":[
"224572"
]
}
}
]
}
},
{
"$sort":{
"_id":1
}
},
{
"$limit":100
}
]");"{
"stages":[
{
"$cursor":{
"query":{
"$and":[
{
"status":"new",
"messageDeleted":{
"$exists":false
}
},
{
"header.receiverNode":{
"$in":[
"224572"
]
}
}
]
},
"sort":{
"_id":1
},
"limit":NumberLong(100),
"queryPlanner":{
"plannerVersion":1,
"namespace":"hdnapi.records",
"indexFilterSet":false,
"parsedQuery":{
"$and":[
{
"header.receiverNode":{
"$eq":"224572"
}
},
{
"status":{
"$eq":"new"
}
},
{
"messageDeleted":{
"$not":{
"$exists":true
}
}
}
]
},
"queryHash":"6D467E3F",
"planCacheKey":"28A44C04",
"winningPlan":{
"stage":"FETCH",
"filter":{
"$and":[
{
"header.receiverNode":{
"$eq":"224572"
}
},
{
"status":{
"$eq":"new"
}
},
{
"messageDeleted":{
"$not":{
"$exists":true
}
}
}
]
},
"inputStage":{
"stage":"IXSCAN",
"keyPattern":{
"_id":1
},
"indexName":"_id_",
"isMultiKey":false,
"multiKeyPaths":{
"_id":[
]
},
"isUnique":true,
"isSparse":false,
"isPartial":false,
"indexVersion":2,
"direction":"forward",
"indexBounds":{
"_id":[
"[MinKey, MaxKey]"
]
}
}
},
"rejectedPlans":[
]
},
"executionStats":{
"executionSuccess":true,
"nReturned":100,
"executionTimeMillis":23729,
"totalKeysExamined":2530452,
"totalDocsExamined":2530452,
"executionStages":{
"stage":"FETCH",
"filter":{
"$and":[
{
"header.receiverNode":{
"$eq":"224572"
}
},
{
"status":{
"$eq":"new"
}
},
{
"messageDeleted":{
"$not":{
"$exists":true
}
}
}
]
},
"nReturned":100,
"executionTimeMillisEstimate":6277,
"works":2530452,
"advanced":100,
"needTime":2530352,
"needYield":0,
"saveState":19838,
"restoreState":19838,
"isEOF":0,
"docsExamined":2530452,
"alreadyHasObj":0,
"inputStage":{
"stage":"IXSCAN",
"nReturned":2530452,
"executionTimeMillisEstimate":481,
"works":2530452,
"advanced":2530452,
"needTime":0,
"needYield":0,
"saveState":19838,
"restoreState":19838,
"isEOF":0,
"keyPattern":{
"_id":1
},
"indexName":"_id_",
"isMultiKey":false,
"multiKeyPaths":{
"_id":[
]
},
"isUnique":true,
"isSparse":false,
"isPartial":false,
"indexVersion":2,
"direction":"forward",
"indexBounds":{
"_id":[
"[MinKey, MaxKey]"
]
},
"keysExamined":2530452,
"seeks":1,
"dupsTested":0,
"dupsDropped":0
}
}
}
}
}
],
"serverInfo":{
"host":"cse04-mongo",
"port":27017,
"version":"4.2.20",
"gitVersion":"15c0712952c356cb711c13a42cb3bca8617d4ebc"
},
"ok":1,
"$clusterTime":{
"clusterTime":Timestamp(1666614215,
1),
"signature":{
"hash":BinData(0,
"AAAAAAAAAAAAAAAAAAAAAAAAAAA="")",
"keyId":NumberLong(0)
}
},
"operationTime":Timestamp(1666614215,
1)
}
Here we can see “totalKeysExamined” : 2530452 which is the same number as the amount of records in the database. And for total time “executionTimeMillis”:23729.
db.records.explain("executionStats").aggregate([
{
"$match":{
"$and":[
{
"status":"new",
"messageDeleted":{
"$exists":false
}
},
{
"header.receiverNode":{
"$in":[
"224572"
]
}
}
]
}
},
{
"$sort":{
"header.receiverNode":1
}
},
{
"$limit":100
}
]");"{
"stages":[
{
"$cursor":{
"query":{
"$and":[
{
"status":"new",
"messageDeleted":{
"$exists":false
}
},
{
"header.receiverNode":{
"$in":[
"224572"
]
}
}
]
},
"sort":{
"header.receiverNode":1
},
"limit":NumberLong(100),
"queryPlanner":{
"plannerVersion":1,
"namespace":"hdnapi.records",
"indexFilterSet":false,
"parsedQuery":{
"$and":[
{
"header.receiverNode":{
"$eq":"224572"
}
},
{
"status":{
"$eq":"new"
}
},
{
"messageDeleted":{
"$not":{
"$exists":true
}
}
}
]
},
"queryHash":"CBB00445",
"planCacheKey":"8B2613FA",
"winningPlan":{
"stage":"FETCH",
"filter":{
"$and":[
{
"status":{
"$eq":"new"
}
},
{
"messageDeleted":{
"$not":{
"$exists":true
}
}
}
]
},
"inputStage":{
"stage":"IXSCAN",
"keyPattern":{
"header.receiverNode":1
},
"indexName":"header.receiverNode_1",
"isMultiKey":false,
"multiKeyPaths":{
"header.receiverNode":[
]
},
"isUnique":false,
"isSparse":false,
"isPartial":false,
"indexVersion":2,
"direction":"forward",
"indexBounds":{
"header.receiverNode":[
"[\"224572\", \"224572\"]"
]
}
}
},
"rejectedPlans":[
]
},
"executionStats":{
"executionSuccess":true,
"nReturned":100,
"executionTimeMillis":21,
"totalKeysExamined":1316,
"totalDocsExamined":1316,
"executionStages":{
"stage":"FETCH",
"filter":{
"$and":[
{
"status":{
"$eq":"new"
}
},
{
"messageDeleted":{
"$not":{
"$exists":true
}
}
}
]
},
"nReturned":100,
"executionTimeMillisEstimate":9,
"works":1316,
"advanced":100,
"needTime":1216,
"needYield":0,
"saveState":11,
"restoreState":11,
"isEOF":0,
"docsExamined":1316,
"alreadyHasObj":0,
"inputStage":{
"stage":"IXSCAN",
"nReturned":1316,
"executionTimeMillisEstimate":0,
"works":1316,
"advanced":1316,
"needTime":0,
"needYield":0,
"saveState":11,
"restoreState":11,
"isEOF":0,
"keyPattern":{
"header.receiverNode":1
},
"indexName":"header.receiverNode_1",
"isMultiKey":false,
"multiKeyPaths":{
"header.receiverNode":[
]
},
"isUnique":false,
"isSparse":false,
"isPartial":false,
"indexVersion":2,
"direction":"forward",
"indexBounds":{
"header.receiverNode":[
"[\"224572\", \"224572\"]"
]
},
"keysExamined":1316,
"seeks":1,
"dupsTested":0,
"dupsDropped":0
}
}
}
}
}
],
"serverInfo":{
"host":"cse04-mongo",
"port":27017,
"version":"4.2.20",
"gitVersion":"15c0712952c356cb711c13a42cb3bca8617d4ebc"
},
"ok":1,
"$clusterTime":{
"clusterTime":Timestamp(1666616755,
1),
"signature":{
"hash":BinData(0,
"AAAAAAAAAAAAAAAAAAAAAAAAAAA="")",
"keyId":NumberLong(0)
}
},
"operationTime":Timestamp(1666616755,
1)
}
Here we can see “totalKeysExamined”: 1316 which is the matched subset. And for total time “executionTimeMillis”:21.
So the same query is behaving different with a sort on _id or “header.receiverNode”. The query with the sort on _id is doing the sort first which leads to teriible performance and the query with “header.receiverNode” is working just fine.
What is causing the different behaviour between these queries? Why is the first query doing a sort before the match?