[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: |
|
||||||||
| 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")
Mongo version: bash-4.2$ mongod --version
After cleaning the plan cache the problem dissappears: 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 I believe the issue detailed in -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 |