Hello,

I open this ticket adviced by Renato.

We have an slow query (find+sort) that takes 5 minutes. The collection has 1.2million documents:

db.PassengerNameRecord.find({     "value.airSegments.serviceProviderCode" : "AC4",     "value.airSegments.identifier.code" : "123",     "value.airSegments.start.locationCode" : "CDG",     "value.airSegments.end.locationCode" : "YVR",     "value.airSegments.start.date" : "2018-09-25",     "value.airSegments.identifier.suffix" : "A" }).sort({fid:1})

The same query with an explanation plan takes less than 1 second:

db.PassengerNameRecord.find({     "value.airSegments.serviceProviderCode" : "AC4",     "value.airSegments.identifier.code" : "123",     "value.airSegments.start.locationCode" : "CDG",     "value.airSegments.end.locationCode" : "YVR",     "value.airSegments.start.date" : "2018-09-25",     "value.airSegments.identifier.suffix" : "A" }).sort({fid:1}).explain("executionStats")

Seems the query does not execute in the same way when we use or not the explain.

This is the output logged on the console from mongoD:

2018-10-02T08:41:57.913+0000 I COMMAND [conn352677] command sampledb.PassengerNameRecord appName: "MongoDB Shell" command: find { find: "PassengerNameRecord", filter: { value.airSegments.serviceProviderCode: "AC4", value.airSegments.identifier.code: "123", value.airSegments.start.locationCode: "CDG", value.airSegments.end.locationCode: "YVR", value.airSegments.start.date: "2018-09-25", value.airSegments.identifier.suffix: "A" }, sort: { fid: 1.0 }, $db: "sampledb" } planSummary: IXSCAN { fid: 1 } keysExamined:1284240 docsExamined:1284240 cursorExhausted:1 numYields:13909 nreturned:0 reslen:101 locks:{ Global: { acquireCount: { r: 27820 } }, Database: { acquireCount: { r: 13910 } }, Collection: { acquireCount: { r: 13910 } } } protocol:op_msg 225041ms

And here the output of the explain plan with the sort predicate:

> db.PassengerNameRecord.find({ "value.airSegments.serviceProviderCode" : "AC4", "value.airSegments.identifier.code" : "123", "value.airSegments.start.locationCode" : "CDG", "value.airSegments.end.locationCode" : "YVR", "value.airSegments.start.date" : "2018-09-25", "value.airSegments.identifier.suffix" : "A" }).sort({fid:1}).explain("executionStats")
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "sampledb.PassengerNameRecord",
"indexFilterSet" : false,
"parsedQuery" : {
"$and" : [
{
"value.airSegments.end.locationCode" : { "$eq" : "YVR" }
},
{
"value.airSegments.identifier.code" : { "$eq" : "123" }
},
{
"value.airSegments.identifier.suffix" : { "$eq" : "A" }
},
{
"value.airSegments.serviceProviderCode" : { "$eq" : "AC4" }
},
{
"value.airSegments.start.date" : { "$eq" : "2018-09-25" }
},
{
"value.airSegments.start.locationCode" : { "$eq" : "CDG" }
}
]
},
"winningPlan" : {
"stage" : "SORT",
"sortPattern" : { "fid" : 1 },
"inputStage" : {
"stage" : "SORT_KEY_GENERATOR",
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$and" : [
{
"value.airSegments.end.locationCode" : { "$eq" : "YVR" }
},
{
"value.airSegments.identifier.code" : { "$eq" : "123" }
},
{
"value.airSegments.identifier.suffix" : { "$eq" : "A" }
},
{
"value.airSegments.start.date" : { "$eq" : "2018-09-25" }
},
{
"value.airSegments.start.locationCode" : { "$eq" : "CDG" }
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : { "value.airSegments.serviceProviderCode" : 1, "value.airSegments.identifier.code" : 1, "value.airSegments.start.locationCode" : 1, "value.airSegments.end.locationCode" : 1, "value.airSegments.start.date" : -1, "value.airSegments.identifier.suffix" : 1 },
"indexName" : "pnrFlightDetailsIdx",
"isMultiKey" : true,
"multiKeyPaths" : { "value.airSegments.serviceProviderCode" : [ "value.airSegments" ], "value.airSegments.identifier.code" : [ "value.airSegments" ], "value.airSegments.start.locationCode" : [ "value.airSegments" ], "value.airSegments.end.locationCode" : [ "value.airSegments" ], "value.airSegments.start.date" : [ "value.airSegments" ], "value.airSegments.identifier.suffix" : [ "value.airSegments" ] },
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : { "value.airSegments.serviceProviderCode" : [ "[\"AC4\", \"AC4\"]" ], "value.airSegments.identifier.code" : [ "[MinKey, MaxKey]" ], "value.airSegments.start.locationCode" : [ "[MinKey, MaxKey]" ], "value.airSegments.end.locationCode" : [ "[MinKey, MaxKey]" ], "value.airSegments.start.date" : [ "[MaxKey, MinKey]" ], "value.airSegments.identifier.suffix" : [ "[MinKey, MaxKey]" ] }
}
}
}
},
"rejectedPlans" : [
{
"stage" : "FETCH",
"filter" : {
"$and" : [
{
"value.airSegments.end.locationCode" : { "$eq" : "YVR" }
},
{
"value.airSegments.identifier.code" : { "$eq" : "123" }
},
{
"value.airSegments.identifier.suffix" : { "$eq" : "A" }
},
{
"value.airSegments.serviceProviderCode" : { "$eq" : "AC4" }
},
{
"value.airSegments.start.date" : { "$eq" : "2018-09-25" }
},
{
"value.airSegments.start.locationCode" : { "$eq" : "CDG" }
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : { "fid" : 1 },
"indexName" : "fid_1",
"isMultiKey" : false,
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 1,
"direction" : "forward",
"indexBounds" : { "fid" : [ "[MinKey, MaxKey]" ] }
}
}
]
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 0,
"executionTimeMillis" : 0,
"totalKeysExamined" : 0,
"totalDocsExamined" : 0,
"executionStages" : {
"stage" : "SORT",
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 4,
"advanced" : 0,
"needTime" : 2,
"needYield" : 0,
"saveState" : 0,
"restoreState" : 0,
"isEOF" : 1,
"invalidates" : 0,
"sortPattern" : { "fid" : 1 },
"memUsage" : 0,
"memLimit" : 33554432,
"inputStage" : {
"stage" : "SORT_KEY_GENERATOR",
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 2,
"advanced" : 0,
"needTime" : 1,
"needYield" : 0,
"saveState" : 0,
"restoreState" : 0,
"isEOF" : 1,
"invalidates" : 0,
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$and" : [
{
"value.airSegments.end.locationCode" : { "$eq" : "YVR" }
},
{
"value.airSegments.identifier.code" : { "$eq" : "123" }
},
{
"value.airSegments.identifier.suffix" : { "$eq" : "A" }
},
{
"value.airSegments.start.date" : { "$eq" : "2018-09-25" }
},
{
"value.airSegments.start.locationCode" : { "$eq" : "CDG" }
}
]
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 1,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 0,
"restoreState" : 0,
"isEOF" : 1,
"invalidates" : 0,
"docsExamined" : 0,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 1,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 0,
"restoreState" : 0,
"isEOF" : 1,
"invalidates" : 0,
"keyPattern" : { "value.airSegments.serviceProviderCode" : 1, "value.airSegments.identifier.code" : 1, "value.airSegments.start.locationCode" : 1, "value.airSegments.end.locationCode" : 1, "value.airSegments.start.date" : -1, "value.airSegments.identifier.suffix" : 1 },
"indexName" : "pnrFlightDetailsIdx",
"isMultiKey" : true,
"multiKeyPaths" : { "value.airSegments.serviceProviderCode" : [ "value.airSegments" ], "value.airSegments.identifier.code" : [ "value.airSegments" ], "value.airSegments.start.locationCode" : [ "value.airSegments" ], "value.airSegments.end.locationCode" : [ "value.airSegments" ], "value.airSegments.start.date" : [ "value.airSegments" ], "value.airSegments.identifier.suffix" : [ "value.airSegments" ] },
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : { "value.airSegments.serviceProviderCode" : [ "[\"AC4\", \"AC4\"]" ], "value.airSegments.identifier.code" : [ "[MinKey, MaxKey]" ], "value.airSegments.start.locationCode" : [ "[MinKey, MaxKey]" ], "value.airSegments.end.locationCode" : [ "[MinKey, MaxKey]" ], "value.airSegments.start.date" : [ "[MaxKey, MinKey]" ], "value.airSegments.identifier.suffix" : [ "[MinKey, MaxKey]" ] },
"keysExamined" : 0,
"seeks" : 1,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
}
}
}
},
"serverInfo" : { "host" : "mongodb-5-9c8hd", "port" : 27017, "version" : "3.6.3", "gitVersion" : "nogitversion" },
"ok" : 1
}
>

Mongo version:

bash-4.2$ mongod --version
db version v3.6.3
git version: nogitversion
OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013
allocator: tcmalloc
modules: none
build environment:
distarch: x86_64
target_arch: x86_64

After cleaning the plan cache the problem dissappears:
db.PassengerNameRecord.getPlanCache().clear()
The collection has 1 index on the filter criteria (that was build on background), and one index on sort criteria.

This record may be related to

: https://jira.mongodb.org/browse/SERVER-32943

Thanks a lot.

Jose MORALES ARAGON