[SERVER-20571] mongod invoked oom-killer in 3.0.6 Created: 22/Sep/15 Updated: 15/Nov/21 Resolved: 28/Oct/15 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | WiredTiger |
| Affects Version/s: | None |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Aditya Ivaturi | Assignee: | Ramon Fernandez Marina |
| Resolution: | Incomplete | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
| Operating System: | ALL |
| Participants: |
| Description |
|
We have a single replica set with 3 nodes running 3.0.6 with WiredTiger. The hosts are running 14.04 LTS Ubuntu in AWS. The instance that we use is I2.8xlarge with 240GB RAM. Today we had a primary crash with oom-killer. Another primary was elected and within about 5 minutes even that server invoked oom-killer. Here is one those server's syslog output : http://pastebin.com/Q7bQP34V |
| Comments |
| Comment by Ramon Fernandez Marina [ 28/Oct/15 ] | ||||||||||
|
ivaturipan, I'm going to close this ticket for now as there's not enough information for us to investigate the issue. If you manage to reproduce the OOM kill while capturing the serverStatus data requested above please upload such data and we'll reopen the ticket. Regards, | ||||||||||
| Comment by Aditya Ivaturi [ 05/Oct/15 ] | ||||||||||
|
Not yet, at least not where it mattered. The oom-killer happened, but on an arbiter and I wasn't running these scripts there. Although the arbiter had only 1GB RAM and nothing else was running on it, it still is surprising that oom is getting invoked in arbiters as well. | ||||||||||
| Comment by Ramon Fernandez Marina [ 03/Oct/15 ] | ||||||||||
|
ivaturipan, where you able to reproduce this behavior while collecting serverStatus metrics? Thanks, | ||||||||||
| Comment by Ramon Fernandez Marina [ 25/Sep/15 ] | ||||||||||
|
ivaturipan, unfortunately without the serverStatus metrics we asked for it's not possible for us to tell if the behavior you're seeing is due to a bug in memory management or a consequence of your specific configuration. Since it seems the problem does appear often enough I think the best way forward is to start collecting serverStatus metrics and wait for another crash – then upload the ss.log, iostat.log and mongod.log files. Thanks, | ||||||||||
| Comment by Aditya Ivaturi [ 25/Sep/15 ] | ||||||||||
|
No, I was not collecting those metrics at the time of crash. I will get the log file for rs0-2 as you requested. | ||||||||||
| Comment by Ramon Fernandez Marina [ 25/Sep/15 ] | ||||||||||
|
ivaturipan, the atop information shows increased memory and CPU utilization, but it's not enough to investigate where that memory is going or why CPU usage grows. This information is provided by the serverStatus metrics that are being collected in the ss.log file (the data in iostat.log is only only useful when correlated with the data in ss.log). If you were collecting serverStatus metrics at the time rs0-2 crashed then the ss.log file may already contain enough information for us to investigate further. Can you please upload the ss.log and iostat.log files from rs0-2 so we can take a look? Can you also include the mongod.log file from rs0-2 from the last startup to the time of the crash? You can use this upload portal to send files privately and securely (i.e.: they won't be publicly visible in JIRA). Thanks, | ||||||||||
| Comment by Aditya Ivaturi [ 25/Sep/15 ] | ||||||||||
|
I'm still running the commands that you requested and will upload the output tomorrow morning. But in the meantime, I managed to grab the atop output around the time when rs0-2 crashed. To view this file, you need to install atop (http://atoptool.nl/). The only problem is that I was capturing at 5 minute interval, which still gives us what happened with mongod, but the granularity suffers a bit. Here are the steps to view the snapshot:
At 20:00, you can see that PAG (Page scans) has already kicked in.
and mongod resident memory is growing
Now press "t" to skip ahead 5 minutes (unfortunately that is the granularity that it was configured with, which I will change):
As you can see the RGROW is at 3.5G now. And with another couple of jumps of snapshot and you end up with at this state:
By this time, mongod has go from 78% memory utilization to 90% and still growing. Kernel is really freaking out and trying really hard with page scans. Notice how the slab also went down from 1.9G to 1.7G at this point. Also there was appreciable disk activity in those 15 minutes as well. After this snapshot, the next snapshot shows a calm system as oom-killer has already kicked in. You can also press "g" to get a more generic system snapshot with CPU. Even those show mongod process going crazy. | ||||||||||
| Comment by Aditya Ivaturi [ 23/Sep/15 ] | ||||||||||
|
BTW, I do have atop running on both those machines. Would that help? It will get you more data than iostat anyway. | ||||||||||
| Comment by Ramon Fernandez Marina [ 23/Sep/15 ] | ||||||||||
|
Yes, the wiredTigerCacheSizeGB parameter limits exactly that: the amount of memory used for WT cache. mongod needs additional memory for other things. There are users running with 16GB, so it's not clear yet whether the issue is from the WT cache setting. Hopefully the data collection will help us in this respect. | ||||||||||
| Comment by Aditya Ivaturi [ 23/Sep/15 ] | ||||||||||
|
Sure, I'll run those. I do have a followup question. Almost all the RAM was being consumed by mongod process. We did set the cache size limit to 224GB. In our case, where the system RAM is 240GB, is that too hight a limit? Does mongod process consume more memory than the maximum limit set in cache size? | ||||||||||
| Comment by Ramon Fernandez Marina [ 23/Sep/15 ] | ||||||||||
|
ivaturipan, looks like the memory consumption was already quite high on these nodes, and some operation pushed them over the edge enough to trigger the OOM killer. Unfortunately without the ability to reproduce this behavior it will be difficult to understand what's causing it. What we ask users in these cases is that they collect server data by running the commands below on affected nodes from an OS shell:
These commands will gather data every 10 seconds and save it on the ss.log and iostat.log files. If the problem reappears while data is being collected that may tell us what's causing this issue; if the problem doesn't reappear there may still be useful information in the collected data that can help us understand why these nodes are consuming the amount of memory they are consuming. Could you please run the above commands in all nodes of this replica set? I would let them run for a couple of days, or shorter if the problem described in this ticket reproduces earlier. Thanks, | ||||||||||
| Comment by Ramon Fernandez Marina [ 23/Sep/15 ] | ||||||||||
|
Thanks for the information you sent ivaturipan. We've seen issues with excessive memory consumptions during index builds ( We're looking at the logs and MMS info to see what we find, stay tuned. | ||||||||||
| Comment by Aditya Ivaturi [ 23/Sep/15 ] | ||||||||||
|
rs0-2 was initially primary, it crashed and then rs0-1 became primary, which was the second one to crash. I had to clean up the logs to remove the actual update statements, but the actual command log line is still there. If you need the actual query, please reach out to me directly and I'll share them that way. The update commands showed taking insane amount of time in the logs. They normally don't. This could be related to the spike in CPU load, but the query themselves shouldn't have caused the load - at least we haven't seen that before. | ||||||||||
| Comment by Aditya Ivaturi [ 23/Sep/15 ] | ||||||||||
|
Sure, I prefer to send it via email. Which email can I send it to? | ||||||||||
| Comment by Ramon Fernandez Marina [ 22/Sep/15 ] | ||||||||||
|
Sorry you've run into this ivaturipan. We'll need more information to find out what's going on:
Thanks, | ||||||||||
| Comment by Aditya Ivaturi [ 22/Sep/15 ] | ||||||||||
|
Two other curious things:
| ||||||||||
| Comment by Aditya Ivaturi [ 22/Sep/15 ] | ||||||||||
|
The screenshot of MMS shows the increase in memory and when the oom triggers |