Thank you @Peter_Hubbard for your helpful answers.
I’ve just dug a little more into the subject and my issue comes down to the following comparison.
When I run explain on very basic find queries on the activities collection (which is the joined collection of my OP with the veryHeavyField), the executionTimeMillis depends a lot on the _id range I query (for about the same number of documents returned).
For example, this query:
db.getCollection("activities").explain("executionStats")
.find({_id: {
$gte: ObjectId('577000000000000000000000'),
$lte: ObjectId('578000000000000000000000')
}});
is very slow: “executionTimeMillis” : 8751 for “nReturned” : 81951.
detailed explain here
{
"explainVersion" : "1",
"queryPlanner" : {
"namespace" : "activities",
"indexFilterSet" : false,
"parsedQuery" : {
"$and" : [
{
"_id" : {
"$lte" : ObjectId("578000000000000000000000")
}
},
{
"_id" : {
"$gte" : ObjectId("577000000000000000000000")
}
}
]
},
"maxIndexedOrSolutionsReached" : false,
"maxIndexedAndSolutionsReached" : false,
"maxScansToExplodeReached" : false,
"winningPlan" : {
"stage" : "FETCH",
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"_id" : 1.0
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [
]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2.0,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[ObjectId('577000000000000000000000'), ObjectId('578000000000000000000000')]"
]
}
}
},
"rejectedPlans" : [
]
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 81951.0,
"executionTimeMillis" : 8751.0,
"totalKeysExamined" : 81951.0,
"totalDocsExamined" : 81951.0,
"executionStages" : {
"stage" : "FETCH",
"nReturned" : 81951.0,
"executionTimeMillisEstimate" : 8603.0,
"works" : 81952.0,
"advanced" : 81951.0,
"needTime" : 0.0,
"needYield" : 0.0,
"saveState" : 527.0,
"restoreState" : 527.0,
"isEOF" : 1.0,
"docsExamined" : 81951.0,
"alreadyHasObj" : 0.0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 81951.0,
"executionTimeMillisEstimate" : 132.0,
"works" : 81952.0,
"advanced" : 81951.0,
"needTime" : 0.0,
"needYield" : 0.0,
"saveState" : 527.0,
"restoreState" : 527.0,
"isEOF" : 1.0,
"keyPattern" : {
"_id" : 1.0
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [
]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2.0,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[ObjectId('577000000000000000000000'), ObjectId('578000000000000000000000')]"
]
},
"keysExamined" : 81951.0,
"seeks" : 1.0,
"dupsTested" : 0.0,
"dupsDropped" : 0.0
}
}
},
"command" : {
"find" : "activities",
"filter" : {
"_id" : {
"$gte" : ObjectId("577000000000000000000000"),
"$lte" : ObjectId("578000000000000000000000")
}
},
}
}
Whereas this query (same query with a different range of _id):
db.getCollection("activities").explain("executionStats")
.find({_id: {
$gte: ObjectId('579000000000000000000000'),
$lte: ObjectId('600000000000000000000000')
}});
which returns more documents is more than 10 times faster: “executionTimeMillis” : 654 for “nReturned” : 105448.
Detailed explain here
{
"explainVersion" : "1",
"queryPlanner" : {
"namespace" : "activities",
"indexFilterSet" : false,
"parsedQuery" : {
"$and" : [
{
"_id" : {
"$lte" : ObjectId("600000000000000000000000")
}
},
{
"_id" : {
"$gte" : ObjectId("579000000000000000000000")
}
}
]
},
"maxIndexedOrSolutionsReached" : false,
"maxIndexedAndSolutionsReached" : false,
"maxScansToExplodeReached" : false,
"winningPlan" : {
"stage" : "FETCH",
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"_id" : 1.0
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [
]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2.0,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[ObjectId('579000000000000000000000'), ObjectId('600000000000000000000000')]"
]
}
}
},
"rejectedPlans" : [
]
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 105448.0,
"executionTimeMillis" : 654.0,
"totalKeysExamined" : 105448.0,
"totalDocsExamined" : 105448.0,
"executionStages" : {
"stage" : "FETCH",
"nReturned" : 105448.0,
"executionTimeMillisEstimate" : 361.0,
"works" : 105449.0,
"advanced" : 105448.0,
"needTime" : 0.0,
"needYield" : 0.0,
"saveState" : 108.0,
"restoreState" : 108.0,
"isEOF" : 1.0,
"docsExamined" : 105448.0,
"alreadyHasObj" : 0.0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 105448.0,
"executionTimeMillisEstimate" : 37.0,
"works" : 105449.0,
"advanced" : 105448.0,
"needTime" : 0.0,
"needYield" : 0.0,
"saveState" : 108.0,
"restoreState" : 108.0,
"isEOF" : 1.0,
"keyPattern" : {
"_id" : 1.0
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [
]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2.0,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[ObjectId('579000000000000000000000'), ObjectId('600000000000000000000000')]"
]
},
"keysExamined" : 105448.0,
"seeks" : 1.0,
"dupsTested" : 0.0,
"dupsDropped" : 0.0
}
}
},
"command" : {
"find" : "activities",
"filter" : {
"_id" : {
"$gte" : ObjectId("579000000000000000000000"),
"$lte" : ObjectId("600000000000000000000000")
}
},
},
}
Since the range of _id from the 1st query contains a lot of veryHeavyField whereas this field is mostly empty for the range of _id of the 2nd query, I thought this was the reason why the 1st query spent so much time on the FETCH stage, where the 2nd query was really fast for this FETCH stage.
Is this the reason why FETCH stage durations are so much different ?
Or could there be another reason (like cache since the 2nd query queries more recent documents or anything else) ?