[SERVER-17054] Index not being utilized, on occasion. Created: 26/Jan/15 Updated: 30/Jun/15 Resolved: 22/May/15 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Index Maintenance, Performance, Querying |
| Affects Version/s: | 2.6.5 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Critical - P2 |
| Reporter: | Kamil Keski | Assignee: | J Rassi |
| Resolution: | Duplicate | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||
| Operating System: | Linux | ||||||||||||||||||||
| Steps To Reproduce: | Sporadic issue that happens during normal and low load. We have the following query against a user collection.
The orderby is generated by Mongoid, not needed but shouldn't affect the outcome. Here are the indexes on this collection.
Most of the time the query returns in under 1ms. On occasion we run up to 2000+ms. running the query manually during these times shows the same. If I remove the orderby the query returns as expected. What is going on here? The DB is not being stressed and it seems the query is being run out of order (perhaps trying to return all _id's, ordering, then selecting the a_token). The sporadic nature is most worrying, we are having a very hard time tracking down the cause. |
||||||||||||||||||||
| Participants: | |||||||||||||||||||||
| Description |
|
Sporadic performance issue affecting a simple query.
No index misses are being reported. Most of the time the query returns in under 1ms. On occasion we run up to 2000+ms. running the query manually during these times shows the same. If I remove the orderby the query returns as expected. Seems to be running out of order. |
| Comments |
| Comment by Ramon Fernandez Marina [ 03/Jun/15 ] | |||||||||||||||||||||||||||||||||
|
ole, you may be running into a different issue. Can you please open a separate SERVER ticket with the information above? The first request from us will be to post explain(true) output for your queries as well mongod logs at loglevel 1, so it will help us diagnose your issue if you could gather this information as well. Thanks, | |||||||||||||||||||||||||||||||||
| Comment by Ole Langbehn [ 03/Jun/15 ] | |||||||||||||||||||||||||||||||||
|
Please excuse me commenting on a closed ticket. I'd like to ask a question: We're seeing this behaviour, but on a complex query like this:
We have compound indexes on {a:1,created:1} As far as we can see, we can't use hinting, since hinting only allows to provide one index. SERVER-1649 could help, or SERVER-17625 (we don't want to use index filters if they don't persist). Do you see any existing workaround for our case? | |||||||||||||||||||||||||||||||||
| Comment by Ramon Fernandez Marina [ 22/May/15 ] | |||||||||||||||||||||||||||||||||
|
enigmnaphoenix, after examining the information you sent us we've been able to understand the root cause of the behavior you're seeing and even reproduce it on our end. Here's what's happening:
Cached query plans get re-evaluated over time so this situation is only temporary, but it may re-occur as well. Some users will never run into it and others may be impacted like yourself. We've improved this area of plan ranking and the plan cache as part of I'm going to resolve this ticket as a duplicate of Regards, | |||||||||||||||||||||||||||||||||
| Comment by Ramon Fernandez Marina [ 21/May/15 ] | |||||||||||||||||||||||||||||||||
|
enigmnaphoenix, thanks for uploading the additional information we requested, and apologies for the radio silence. I still haven't been able to reproduce this issue locally, but we're still investigating what could be causing it. We'll post updates in this ticket as we have them. | |||||||||||||||||||||||||||||||||
| Comment by Michael Schmatz [ 21/Feb/15 ] | |||||||||||||||||||||||||||||||||
|
We are also seeing this behavior. An example event is
I have complete index coverage over all of those fields (individual indexes, not compound.) If I execute the query myself, it returns instantaneously. We're seeing this issue a couple of times a day. | |||||||||||||||||||||||||||||||||
| Comment by Kamil Keski [ 02/Feb/15 ] | |||||||||||||||||||||||||||||||||
|
Checking in Ramon. We keep having sporadic incidents of this behavior with another period today spanning 10 minutes. Should I continue to capture more logs from these events and submit or do you feel the data gathered last week was sufficient? Thank you, | |||||||||||||||||||||||||||||||||
| Comment by Kamil Keski [ 27/Jan/15 ] | |||||||||||||||||||||||||||||||||
|
Much appreciated Ramon. Info has been uploaded, please let me know if there is anything else we can provide to help track this down. | |||||||||||||||||||||||||||||||||
| Comment by Ramon Fernandez Marina [ 27/Jan/15 ] | |||||||||||||||||||||||||||||||||
|
enigmnaphoenix, you can now upload logs securely and privately as follows:
Any data uploaded here will only be accessible to MongoDB staff to track down this issue. When prompted for a password just hit enter. | |||||||||||||||||||||||||||||||||
| Comment by Kamil Keski [ 27/Jan/15 ] | |||||||||||||||||||||||||||||||||
|
We have captured during an event. Is there a more secure way I can get the logs to you? I will sanitize them to an extent, but still do not feel comfortable posting them here for a large audience. Thank you, | |||||||||||||||||||||||||||||||||
| Comment by Ramon Fernandez Marina [ 26/Jan/15 ] | |||||||||||||||||||||||||||||||||
|
Hi enigmnaphoenix, we'll need some more information to diagnose this behavior. Can you please run the commands below in the shell and post the output to this ticket? Please include the logs logs produced by running these commands as well:
|