[SERVER-37795] WiredTiger again uses way more memory than instructed by cache limit in 3.6 Created: 29/Oct/18 Updated: 27/Oct/23 Resolved: 22/Nov/18 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | WiredTiger |
| Affects Version/s: | 3.6.7, 3.6.8 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Adrien Jarthon | Assignee: | Alexander Gorrod |
| Resolution: | Works as Designed | Votes: | 0 |
| Labels: | dmd-perf, storage-engines | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||
| Issue Links: |
|
||||||||||||
| Operating System: | ALL | ||||||||||||
| Sprint: | Storage Engines 2018-11-19, Storage Engines 2018-12-03 | ||||||||||||
| Participants: | |||||||||||||
| Case: | (copied to CRM) | ||||||||||||
| Description |
|
As I said in https://jira.mongodb.org/browse/SERVER-17424?focusedCommentId=2044120&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-2044120 I noticed yet another regression in 3.6 about memory usage this time (after the secondary CPU × 4 increase and the IO usage × 5 increase), I now have almost twice the configured cacheSize used by mongo, and it increased a lot since 3.4.15:
I first upgraded to 3.6.7 and then 3.6.8 after https://jira.mongodb.org/browse/SERVER-35958?focusedCommentId=2007204&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-2007204 My configured max cache is 10G (server has 32G RAM):
And my actual usage is 19G RES (21G VIRT):
Here is the full serverStatus: server_status.json |
| Comments |
| Comment by Alexander Gorrod [ 22/Nov/18 ] | ||||||
|
bigbourin@gmail.com sorry the 3.6 release of MongoDB had worse performance characteristics for your application. Thanks very much for your help in understanding and addressing those issues in more recent versions of MongoDB. I'm going to close this ticket since I don't believe we can do any further work to change the behavior you report. If either the workaround or upgrading don't help please do let us know and we will investigate further. | ||||||
| Comment by Adrien Jarthon [ 19/Nov/18 ] | ||||||
|
Haha ok, well considering the amount of regressions there was in 3.6 I'm probably not gonna install 4.0 anytime soon. I just lost my PSA cluster thanks to https://docs.mongodb.com/manual/reference/read-concern-majority/#disable-read-concern-majority (as many other people will, good job about that) so I'll try to give my customers a bit a stability for now. | ||||||
| Comment by Donald Anderson [ 14/Nov/18 ] | ||||||
|
Hello bigbourin@gmail.com, I have worked on some of the cursor issues at a couple layers in the MongoDB stack. It looks like your path to upgrade should be to first use 3.6.8 with mongod --setParameter wiredTigerCursorCacheSize=0 as michael.cahill suggested. As for getting to 4.0, we have identified a different issue in 4.0.3 that has a different memory growth problem. That problem is in the WiredTiger cursor layer and is exacerbated for use cases with many updates of large records. A coding fix has been made ( | ||||||
| Comment by Adrien Jarthon [ 08/Nov/18 ] | ||||||
|
I confirm that with the wiredTigerCursorCacheSize change, the memory is back to stable levels (11G). | ||||||
| Comment by Adrien Jarthon [ 05/Nov/18 ] | ||||||
|
Hi Michael, thanks for the details, I've just restarted with the option to see how far it goes now. About the improvement in 4.0, this is good but with so many regressions in 3.6 it's not easy to upgrade or even test 4.0 | ||||||
| Comment by Michael Cahill (Inactive) [ 05/Nov/18 ] | ||||||
|
bigbourin@gmail.com, as bruce.lucas explained, the memory MongoDB is using in your case is associated with cursors. The difference you are seeing in 3.6 is that MongoDB is representing small changes to documents as "modify" operations in WiredTiger, which causes a buffer to be allocated in cursors that read those documents. The caching behavior of cursors has been significantly changed in MongoDB 4.0 and above and you should see far fewer active cursors. In 3.6, please test with:
This will disable one layer of cursor caching inside MongoDB. There is potential for some performance impact, but in our testing that impact has been small. What you should see is far fewer cursors open, and thus less memory allocated to buffers that hold documents. | ||||||
| Comment by Adrien Jarthon [ 04/Nov/18 ] | ||||||
|
I'm back at 19G now, I've just uploaded the following 4 days of diagnostic data (10/31 to 11/04) and the updated log file from 10/29 to 11/04 (now) in case it helps. | ||||||
| Comment by Adrien Jarthon [ 31/Oct/18 ] | ||||||
|
Ok thx | ||||||
| Comment by Bruce Lucas (Inactive) [ 31/Oct/18 ] | ||||||
|
Thanks for the data Adrien. You are correct, the excess allocated memory at this point is sufficient to get a good signal:
The excess is accounted for by the following allocation sites, all in __wt_modify_apply or __wt_modify_apply_api. I imagine this may be either scratch memory that is kept around too long, or memory in cache that is not properly accounted for. I'll pass this off to a storage expert to take a look.
| ||||||
| Comment by Adrien Jarthon [ 31/Oct/18 ] | ||||||
|
Ok I've restarted the primary on the 29th at 9pm UTC, it's not back to 19G yet but still 15G which is already much more than 3.4 | ||||||
| Comment by Adrien Jarthon [ 29/Oct/18 ] | ||||||
|
I'll try to do that | ||||||
| Comment by Bruce Lucas (Inactive) [ 29/Oct/18 ] | ||||||
|
Hi Adrien, Thanks for reporting this. The serverStatus output that you uploaded tells us that the memory usage is not due to the WiredTiger cache, but rather is allocated memory outside the cache:
The diagnostic data that you uploaded confirms that but in this case it doesn't tell us much about what is allocating the memory. Over the course of the 4 days covered by the data the amount of excess memory has remained fairly constant, which is also consistent with the graphs that you provided. Would you be in a position to enable the built-in heap profiler on an affected node by setting the heapProfilingEnabled parameter to true, e.g. on the command line:
(or equivalent in the config file). Note that this may have some small impact on performance, so please monitor the node(s) where you have enabled this. Please allow maybe a day or two of runtime to get a good signal in the data, then upload both the diagnostic.data and the complete log file(s) since the restart of the node to the portal. (It's important to have the complete log files because they have the crucial allocating stack information.) Thanks, | ||||||
| Comment by Adrien Jarthon [ 29/Oct/18 ] | ||||||
|
@Eric I'm not saying it's the WT cache itself but that the totally should not use substantially more than the max WT cache size we can configure. So it seems this issue has been present, improved and then regressed. @Kelsey I've uploaded web1_diagnostic.data.tgz to the portal. BTW the tool you're using to read these diagnostic data is proprietary I guess? no chance we can use it as end users? It could be pretty useful for monitoring and performance analysis aside from bug reports. | ||||||
| Comment by Kelsey Schubert [ 29/Oct/18 ] | ||||||
|
bigbourin@gmail.com, would you please upload an archive of the diagnostic.data directory to this upload portal? | ||||||
| Comment by Eric Milkie [ 29/Oct/18 ] | ||||||
|
I see now – the ticket | ||||||
| Comment by Eric Milkie [ 29/Oct/18 ] | ||||||
|
Adrien, how do you know that the physical RAM in use by tcmalloc in the mongod process is all attributable to the WiredTiger page cache? Also, what do you mean by "again" – can you link the original ticket, as I'm not familiar with it? | ||||||
| Comment by Adrien Jarthon [ 29/Oct/18 ] | ||||||
|
Sorry it seems my first image upload lacks labels and I can't edit the description so here is the fixed version: |