[SERVER-37423] query does not use same execution plan w/wo explain(executionStats) Created: 02/Oct/18  Updated: 06/Dec/22  Resolved: 25/Oct/18

Status: Closed
Project: Core Server
Component/s: Index Maintenance
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jose MORALES ARAGON Assignee: Backlog - Triage Team
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-16895 Users should be able to request that ... Open
Assigned Teams:
Server Triage
Operating System: ALL
Participants:

 Description   

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



 Comments   
Comment by Nick Brewer [ 02/Oct/18 ]

jose.morales What you've described does have the symptoms of a cached plan issue - however SERVER-32943 is specific to queries where the index is being built in the background at the same time that the query is running, and only applies if the index being built in the background would better handle the query. If the index was built before the query was run, you're most likely not hitting this issue.

I believe the issue detailed in SERVER-32452 is more likely to cause the behavior you're seeing.

-Nick

Comment by Jose MORALES ARAGON [ 02/Oct/18 ]

Actually, to help to find the root cause of my issue Ive added all the information I had (comparaison between the query with and without the explain), and this may be a distraction from the source of the problem.

 

If I may reformulate the problem it would be: The query I run (db.myCollection.filter({...}).sort({}) does not use the right execution plan. It takes 5 minutes, when it should take less than 1 second.

More details:

1/ It uses an index built in the background (this issue could be related to https://jira.mongodb.org/browse/SERVER-32943)

2/ A clean up of the cache plan solves the issue.

 

This issue is not a duplicate of SERVER-16895, even if the description of the problem is related. Can we reopen it ?

 

Thanks,

 

Jose M Aragon

 

 

 

Comment by Nick Brewer [ 02/Oct/18 ]

jose.morales This is currently expected - explain() does not use cached plans. There's an existing ticket open to add functionality that would tell explain() not to bypass the cache: SERVER-16895

You can vote for that ticket, and follow along with it for updates.

-Nick

Generated at Thu Feb 08 04:45:57 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.