[SERVER-55459] MongoD segmentation fault when connections increase Created: 23/Mar/21 Updated: 27/Oct/23 Resolved: 13/Apr/21 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | None |
| Affects Version/s: | 4.2.7, 4.2.11 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Wei Wu | Assignee: | Dmitry Agranat |
| Resolution: | Community Answered | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
| Operating System: | ALL |
| Participants: |
| Description |
| Comments |
| Comment by Dmitry Agranat [ 13/Apr/21 ] | |||||
|
I suspect you would end up bumping into the same issue with the Sharded cluster as you would just move the problem from mongoD to mongoS. Addressing your connection management on the driver's side is still our recommendation to address this issue. I will go ahead and close this ticket for now but if this issue reoccurs after you have addressed the connection management issue, feel free to reopen or open a new ticket and we'll be happy to take a new look. Regards, | |||||
| Comment by Wei Wu [ 12/Apr/21 ] | |||||
|
Thanks for reviewing all the log. Do you think if we convert the cluster to a shard cluster and let MongoS to manage/handle those connections will help in our situation ? Thanks a lot. Wei | |||||
| Comment by Dmitry Agranat [ 12/Apr/21 ] | |||||
|
Thanks wei.wu@newsbreak.com, all data so far points to an issue with your connection management. In each incident, we see a similar pattern of elevated TCP ListenOverflows and EstabResets counters. This means that a connection has been established at the TCP protocol level (3-way handshake), but there was no room on the queue of connections waiting to be accepted by mongod. This indicates connections are arriving faster than mongod can accept them. Your client will time out and retry with exponential backoff. You will start seeing these messages:
Shortly followed by a flood of:
All this will result in SYN flooding on the port used to connect to mongod:
If I am not mistaken, this is caused by the mgo driver (but I have not reviewed all the drivers involved):
Increasing the max_map_count even further from the current value of 262144 will not help. With the observed rate of 2100 ListenOverflows per second during your incidents, it only takes ~2 minutes (262144/2100) to hit the reported issue. Increasing this value will only delay the inevitable. We suggest reviewing your connection pool logic/configuration to avoid this from happening. Regards, | |||||
| Comment by Wei Wu [ 08/Apr/21 ] | |||||
|
Sorry, I got segfault on this 3.6.19 cluster. I will try increase `max_map_count` on this cluster. Also uploaded requested files with prefix 20210408. Wei | |||||
| Comment by Dmitry Agranat [ 08/Apr/21 ] | |||||
|
Thanks wei.wu@newsbreak.com for providing the requested information. I see this is a completely different cluster from what we've been looking at so far (we've been looking at 4.2.7 and 4.2.11 clusters while this one is 3.6.19) with a very different workload and connection management signature. This cluster also has a setting of vm.max_map_count = 65530. Did this cluster actually experienced the reported segmentation fault when it was running with the recommended setting of vm.max_map_count = 128000? If yes, can you provide mongod logs covering the time of these segfault events? | |||||
| Comment by Wei Wu [ 07/Apr/21 ] | |||||
|
All requested files are uploaded with prefix 20210407. As far as I know, we used following clients
We used this Php driver which doesn't have connection pooling and caused high connection creation. Wei
| |||||
| Comment by Dmitry Agranat [ 07/Apr/21 ] | |||||
|
Hi wei.wu@newsbreak.com, the attached image was for an internal discussion. Based on the information gathered so far, our current hypothesis is that the segmentation fault was caused by reaching the limit of max_map_count. Even though it is currently set to 262144 and based on the number of connections during the event, we should not have reached this limit, we suspect some resource is being leaked during the creation of the connections or some kernel configuration might be responsible for this. Specifically, you are creating and (presumably) destroying ~7000 connections per second, which by itself is an anti-pattern but in this case, as mentioned earlier, something is being leaked during this process. Since you've turned on the "quiet" option to suppress any information about connections in the logs, it is not possible to understand the current connection management and lifecycle. To validate this hypothesis, we'll need to gather some more data, ideally from a node where the reported segmentation fault has happened most recently. In order to understand connections management and its lifecycle, first, we will need to log these. I assume you have turned on the quiet mode because it was printing too much data in mongod log and this is understandable with 7000 connections being created and destroyed per second. As an alternative, we'd like to collect mongod logs with the quiet mode being turned off just for a couple of minutes. You can do this by using setParameter w/o the need to restart the process:
We would also need to gather kernel configuration and statistical information. Please download the mdiag.sh script from our github repository. Please run this script on one of the nodes in your replica set. Note: This script should be run from the command line/OS shell with root/sudo privileges as follows:
It will take about 5 minutes to run in each case. Once complete, please attach the resulting /tmp/mdiag-$HOSTNAME.txt from the host(s) to the support uploader. Following the observation of 7000 connections creation/destruction per second, we would also need to understand your driver settings, please provide the following per each driver currently used:
After the quiet mode was disabled for a couple of minutes and the mdiag.sh was executed, please upload the following to the support uploader:
Dima | |||||
| Comment by Wei Wu [ 07/Apr/21 ] | |||||
|
I saw you uploaded an image. Do you have more information to share ? Thanks Wei | |||||
| Comment by Wei Wu [ 06/Apr/21 ] | |||||
| |||||
| Comment by Wei Wu [ 06/Apr/21 ] | |||||
| |||||
| Comment by Wei Wu [ 06/Apr/21 ] | |||||
| |||||
| Comment by Dmitry Agranat [ 04/Apr/21 ] | |||||
|
Thanks wei.wu@newsbreak.com for the requested output. While we are still investigating this, could you please clarify a couple of points:
One more thing. We'd like to take a closer look at calls and source code inside the shared library, libpthread.so.0. So we can continue to investigate, would you please provide a version that mongod is linking against? I believe the output of the following command should be sufficient:
| |||||
| Comment by Wei Wu [ 02/Apr/21 ] | |||||
|
This host went down two times this week. Do you have more suggestions ? Wei | |||||
| Comment by Wei Wu [ 30/Mar/21 ] | |||||
|
Our host is set to 261144.
Wei Wu | |||||
| Comment by Dmitry Agranat [ 29/Mar/21 ] | |||||
|
Hi wei.wu@newsbreak.com, thank you for providing the requested information. Based on the segmentation fault, I believe that the low vm.max_map_count setting was likely the culprit. For completness, could you please post the output of this command:
And if the value is lower than 128000 as recommended by MongoDB here (128000), could you set it to 128000 and report back with the outcome? Dima | |||||
| Comment by Wei Wu [ 28/Mar/21 ] | |||||
|
Any findings from those logs ? | |||||
| Comment by Wei Wu [ 24/Mar/21 ] | |||||
|
And It hasn't happen on same host since 2021-03-23T17:40:17. | |||||
| Comment by Wei Wu [ 24/Mar/21 ] | |||||
|
Uploaded requested logs. We had 5 - 6 segmentation fault occurrences in past week on two different clusters. One is running 4.2.7 and another is 4.2.11. They are replicaset clusters. Wei | |||||
| Comment by Dmitry Agranat [ 24/Mar/21 ] | |||||
|
Would you please archive (tar or zip) and upload the following information to this support uploader location:
Files uploaded to this portal are visible only to MongoDB employees and are routinely deleted after some time. Also, was this a one-time occurrence, or has this issue happened again since 2021-03-23T17:40:17? Regards, |