[SERVER-26987] Sharded find operations stall for several seconds during chunk migration Created: 10/Nov/16 Updated: 05/Apr/17 Resolved: 27/Dec/16 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Sharding |
| Affects Version/s: | 3.2.11 |
| Fix Version/s: | 3.2.12 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Yoni Douek | Assignee: | Nathan Myers |
| Resolution: | Done | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Backwards Compatibility: | Fully Compatible |
| Operating System: | ALL |
| Sprint: | Sharding 2017-01-02 |
| Participants: |
| Description |
|
Note: this is different than WT nodes, running 3.2.10. During chunk migration - we notice severe drops in mongos query ability (from 500 req/sec to 0) - rendering the cluster unusable for several seconds This is how a drop looks like (every line represents a second):
Only the balanced collection is affected during the freeze - and we see nothing special in the logs of either mongos and the source mongod when this happens. Secondary throttling does not help. This renders our cluster unusable during balancing - so currently our balancer is stopped. Any advice on the source of this issue and how we can address it will be extremely helpful. Thanks |
| Comments |
| Comment by Githook User [ 27/Dec/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {u'name': u'Nathan Myers', u'email': u'ncm@asperasoft.com'}Message: | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Yoni Douek [ 12/Dec/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks for the info. Can you fix this on the 3.2 branch? We're stuck with an unbalanced cluster and don't want to use 3.4 anytime soon until it proves to be stable. Also - what is the ETA? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 12/Dec/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi yonido, Thank you very much for the latest reproduction and the set of stacks. From there it becomes clear what the problem is. In short - during migration we are performing potentially blocking I/O while holding a mutex, which is used to protect the in-memory state for a migration and the find operations are acquiring this mutex every time. This problem is specific to 3.2 (and now 3.4 as well). There are two possible ways to fix this - (1) change the find command to not do this check every time or (2) fix the migration cloner to not do blocking I/O while holding this mutex. More detail: All the user finds are blocked in the waitTillNotInCriticalSection call, which deceptively indicates that migration might be in a critical section. However, in fact they are only stuck waiting for the mutex, which protects the migration state, but we are not in critical section yet:
The reason we are stuck waiting for this mutex is that the migration cloner process resolves record is to actual records in a loop, while holding this mutex:
This problem only happens for find operations, because they do the critical section check early in the sequence, while updates do it only if an actual version mismatch was discovered. This is specific to the implementation of the find command in 3.2. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Yoni Douek [ 12/Dec/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hey, 3.2.11 does not fix this. Attached dumps of both mongos, and the reading mongod, at times of freeze. Reproduced twice on each one (5-10sec freeze) just in case, filenames = mongod_1.txt mongod_2.txt mongos_1.txt mongo2_2.txt Please approve that you've received the files. Thanks! | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 06/Dec/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi yoni@appsee.com, Apologies for the delayed response. From looking at the diagnostic data on both shards and correlating it with the times when the chunk clone progress stalls and from when the slow queries appear, I was able to see that the number of WT pinned pages steadily increases during that period. This is an indication of a long-running transaction and is consistent with the symptoms in This bug was introduced in 3.2.0 and was fixed in 3.2.11. Would it be possible that you upgrade your shards to 3.2.11 and see if the problem still reproduces? Just in case it still occurs, would it be possible to run the same gdb command, but on one of the affected shards and include the output, because there is a possibility that we might be missing some metrics to help us better pintpoint this kind of problem. The command is:
Thank you in advance. Best regards, | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Yoni Douek [ 02/Dec/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hey, Any news? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kelsey Schubert [ 22/Nov/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi yonido, Thanks for following up, we have the required files and are investigating. We understand that this is significantly impacting your performance and will update you as we continue to diagnosis the root cause of this behavior. Please be aware that this Thursday and Friday are holidays in the United States, which will delay our investigation. Kind regards, | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Yoni Douek [ 21/Nov/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hey, Wanted to make sure you got what you need. This is pretty urgent. Thanks | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Yoni Douek [ 16/Nov/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hey, I've uploaded them to the "upload portal" that Thomas added on this thread. I don't think it's the same bug, as | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 15/Nov/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi yoni@appsee.com, You seem to have forgotten to attach the files which you listed in your comment - can you please attach them? From what you are describing, this seems like a manifestation of -Kal. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Yoni Douek [ 15/Nov/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hey, 1. I want to stress out that its not that the entire mongos freezes, only queries via mongos that target the collection that is being balanced. In the attached repro this is "Clients". same queries that are done on the source mongod at times of freeze are not affected. 2. I cannot tell if it happened before 3.2.10 since our setup was different at that time. We have 5 shards, 2 mongos servers. 3. We can reproduce it very easily. In the attached files there are 2 reproductions: @ Timestamp 2016-11-15 13:14:42 - when the chunk is being read at from its beginning. The source node at this time was db2m1. Note that after a few seconds you can see a lot of slow operations - this is due to mongos being stuck and then unstuck. This is how our request log looks like:
Attachments:
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 10/Nov/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Yoni, Just to make clear - is this something which began after you upgraded to 3.2.10 or it started happening out of nowhere? What is the number of shards that you have in your cluster? When you are attaching the logs, would it be possible to also include the time stamp of the events where you observe the drop in throughput so we can correlate with what is happening in the logs? Also, if you have the repro setup, would it be possible to execute the following command against the mongos, which gets frozen on order for us to see at what point in the execution does this happen?
Thanks in advance, -Kal. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kelsey Schubert [ 10/Nov/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi yonido, I'm sorry you're running into this issue. So we can continue to investigate, would you please provide the complete logs for the mongos and mongod? Additionally, would you please provide the diagnostic.data of the mongod? I've created a secure upload portal for you to use. Files uploaded to this portal are visible only to MongoDB employees investigating this issue and are routinely deleted after some time. Thank you for your help, |