[SERVER-32876] Don't stall ftdc due to WT cache full Created: 24/Jan/18 Updated: 30/Oct/23 Resolved: 11/Apr/18 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Diagnostics, WiredTiger |
| Affects Version/s: | None |
| Fix Version/s: | 3.4.14, 3.6.5, 3.7.4 |
| Type: | Bug | Priority: | Critical - P2 |
| Reporter: | Bruce Lucas (Inactive) | Assignee: | Michael Cahill (Inactive) |
| Resolution: | Fixed | Votes: | 2 |
| Labels: | SWDI | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||||||||||||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||||||||||||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||||||||||||||||||||||||||||||
| Operating System: | ALL | ||||||||||||||||||||||||||||||||||||||||
| Backport Requested: |
v3.6, v3.4
|
||||||||||||||||||||||||||||||||||||||||
| Sprint: | Storage 2018-02-12, Storage 2018-02-26, Storage Non-NYC 2018-03-12, Storage Non-NYC 2018-03-26, Storage Non-NYC 2018-04-09, Storage Non-NYC 2018-04-23 | ||||||||||||||||||||||||||||||||||||||||
| Participants: | |||||||||||||||||||||||||||||||||||||||||
| Linked BF Score: | 45 | ||||||||||||||||||||||||||||||||||||||||
| Comments |
| Comment by Githook User [ 26/Apr/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'email': 'michael.cahill@mongodb.com', 'username': 'michaelcahill', 'name': 'Michael Cahill'}Message: (cherry picked from commit e96569ea3b7644fb7c60cb47df90e7dc369ea957) | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 11/Apr/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'email': 'michael.cahill@mongodb.com', 'name': 'Michael Cahill', 'username': 'michaelcahill'}Message: | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Esha Maharishi (Inactive) [ 16/Mar/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thank you! | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 15/Mar/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'email': 'michael.cahill@mongodb.com', 'name': 'Michael Cahill', 'username': 'michaelcahill'}Message: Revert " This reverts commit 864e2e71c39d1e39ff0d1e8575a02b8afebb8a7b. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 15/Mar/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'email': 'daniel.gottlieb@mongodb.com', 'name': 'Daniel Gottlieb', 'username': 'dgottlieb'}Message: Revert " This reverts commit 1924211418e478d1e8bb84cfdf0eab4b777371e1. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 15/Mar/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'email': 'michael.cahill@mongodb.com', 'name': 'Michael Cahill', 'username': 'michaelcahill'}Message: (cherry picked from commit 1924211418e478d1e8bb84cfdf0eab4b777371e1) | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 15/Mar/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'email': 'michael.cahill@mongodb.com', 'name': 'Michael Cahill', 'username': 'michaelcahill'}Message: | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 15/Mar/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'email': 'michael.cahill@mongodb.com', 'name': 'Michael Cahill', 'username': 'michaelcahill'}Message: | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 12/Mar/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'email': 'kelsey@mongodb.com', 'name': 'Kelsey Schubert', 'username': 'Schubes'}Message: | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 10/Mar/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'email': 'maria@mongodb.com', 'name': 'Maria van Keulen', 'username': 'mvankeulen94'}Message: Revert " This reverts commit d368f071651856039f2637202c122b1a55a44142. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 07/Mar/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'email': 'neha.khatr@mongodb.com', 'name': 'nehakhatri5'}Message: | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Cahill (Inactive) [ 21/Feb/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I think Once that change is in, getting the POC in to code review should be straightforward. cc bruce.lucas | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Cahill (Inactive) [ 29/Jan/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
alexander.gorrod, since the changes now contemplated here are storage-only, can you please figure out next steps? | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The FTDC stall repro works on master as well. The 5 POC fixes in poc36.diff apply cleanly to master, and fix the FTDC stalls. (Note that poc36.diff also includes the change to wiredtiger_open to disable LAS for testing purposes, and is not one of the 5 fixes. This does needs a small tweak to apply.) | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Another way to create FTDC stalls due to cache full is to configure a largish cache, allow it to fill, then reduce the cache size with setParameter, e.g.
This will create an FTDC stall of a few seconds (depending on the originally configured cache size and disk speed). I ran with a loop setting large cache, allowing it to fill, then reducing the cache size, and observed an FTDC stall each time on 3.6 (with LAS disabled as above). With the POC changes from poc36.diff there were no FTDC stalls through a couple dozen iterations of cache-full. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
FIX 5 FTDC is stuck waiting for access to ReplicationCoordinatorImpl to get repl info:
ReplicationCoordinatorImpl is tied up by a thread that is waiting for a lock in WiredTigerSnapshotManager:
WiredTigerSnapshotManager is tied up by a thread that's holding a lock while trying to start a transaction while the cache is full:
Looking at beginTransactionOnOplog, I'm not sure whether that lock actually needs to be held while we start the transaction, or whether it's even needed at all. Is it possible that that lock could be functionally problematic: if _txnOpen can block due to cache full while holding a lock on WiredTigerSnapshotManager (and thus on ReplicationCoordinatorImpl), could that prevent access to WiredTigerSnapshotManager and ReplicationCoordinatorImpl that will help us get unstuck? For the POC I changed beginTransactionOnOplog to drop the lock just before starting the transaction, and that prevented FTDC from getting stalled; TBD whether this is a safe change. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
FIX 4 FTDC can stall due to full cache in syncSizeInfo on releaseSession in 3.6 (and probably 3.4 as well):
I don't know why I didn't hit this one in 3.4; I couldn't readily see a difference in the code, so maybe it was just a matter of luck, and this could occur in 3.4 as well. I imagine this can't be solved by avoiding a transaction, correct? It can be avoided by a flag to opt out of doing syncSizeInfo in this case, or perhaps better opt out of haveDropsQueued entirely as processing queued drops in the FTDC thread could cause the same problem. I didn't try to work out the best way to pass such a flag, but rather just commented out the call to haveDropsQueued. This disabled syncSizeInfo entirely, but since it is only called occasionally I don't think that invalidates the test. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
So I was able to get stuck with cache full in 3.6 by setting WT_CONN_EVICTION_NO_LOOKASIDE in wiredtiger_open (thanks for the suggestion keith@wiredtiger.com) and then running the same repro as 3.4 (heavy insert workload, induce lag). I also set eviction_dirty_trigger=95,eviction_trigger=95,eviction_target=94; not completely sure why this helped with the repro, but maybe it just allowed more lag to build up before primary hit cache full, increasing changes of a hang. I hit the same 3 stalls as in 3.4, and did similar 3 fixes. Then I hit two more problems and prototyped fixes (POC attached as poc36.diff). For clarity I'll describe fixes 4 and 5 in subsequent comments. With these 5 fixes FTDC does not stall in my test when we hit cache full in 3.6. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Regarding reproducing it in 3.6 - is there a parameter setting to disable or discourage LAS use? This might give us a way to artificially create a stuck with cache full condition as this should behave similarly to 3.4. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
In 3.4 it is not hard to reproduce FTDC stall due to full WT cache: start a replica set with --enableMajorityReadConcern with a smallish cache, start a heavy insert workload, and do something to induce lag - I accomplished this by putting the secondaries on a spinning disk while the primary is on ssd. This will get the repl set stuck with primary cache full due to lag which stalls replication as well preventing it from recovering. I don't know how to do it in 3.6, but we have seen it happen.
You are correct. I made the change you suggest in 3.4, reproduced stuck with cache full as described above, and uncovered two more places (all in _txnOpen from CollectionStats) that were also fixed by using getSessionNoTxn. POC attached; with these changes FTDC does not stall with cache full in 3.4. Not at all sure this is the best way to do it, particularly the third case which addresses this stack:
TBD whether this applies to 3.6 and master. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Cahill (Inactive) [ 25/Jan/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I did some quick analysis of stack traces I have lying around from working on various issues. This isn't intended to be comprehensive, it's literally just a sample of what I had easily to hand. This makes it seem like changing getSession to getSessionNoTxn in WiredTigerRecordStore::storageSize would help a lot. We should try that, but I expect it will just uncover the next operation in FTDC that blocks when the WT cache is full. Here are some places where the FTDC thread can block:
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alexander Gorrod [ 25/Jan/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
There were some relevant questions asked about this topic off ticket - bringing the conversation here:
We can do something similar, but it's not trivial, since there are different cases that can block most of which aren't actually due to using the actual statistics cursor. A few cases I'm aware of are:
That is possible, and I've been thinking about it recently. It's quite an invasive change in terms of how applications that use WiredTiger need to do error handling, and will require a configuration setting to control the timeout period. Getting the design decisions correct will require conversation, so a fast turnaround is probably not possible on this approach. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alexander Gorrod [ 25/Jan/18 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
bruce.lucas It would be very useful to have access to either workloads that reproduce the symptoms we are trying to avoid, or call stacks from a system while it is stalled. Do you know where we could find either of those? |