[SERVER-23778] All user requests are queued because all foreground threads are stuck in __wt_evict() Created: 18/Apr/16 Updated: 08/Feb/23 Resolved: 08/Jun/16 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Internal Code, WiredTiger |
| Affects Version/s: | 3.2.3, 3.2.4, 3.2.5 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Critical - P2 |
| Reporter: | 아나 하리 | Assignee: | Michael Cahill (Inactive) |
| Resolution: | Duplicate | Votes: | 1 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||
| Issue Links: |
|
||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||
| Operating System: | ALL | ||||||||||||
| Steps To Reproduce: | I can't prepare simple re-procduce script. |
||||||||||||
| Participants: | |||||||||||||
| Description |
|
I am doing performance test with 4-shard(3 members for each replica-set). But some shard(primary) is stuck and can't process user request in 10~24 hours after restart. Once this case happen then user requests are blocked for a few hours or never released. Sometimes they released in 10~30 minutes. I found this case happens when WiredTiger cache usage is getting over 95%. And during this time, all foreground threads which have "write ticket" are doing __wt_evict() => __wt_txn_update_oldest(). According to checking some wiredtiger source code, I am not sure suppressing cache usage with eviction_trigger is planned, But all foreground threads and eviction server starting LRU eviction at the same time might be trouble. (e.g. All ticket holder foreground threads are doing scan all sessions at the same time, and updating oldest transaction is more difficult becuase scan_count is getting high at maximum ticket count). Usually cache usage is 80% and during this time everything is fine, But once cache usage is getting over 80% increasing usage is not stopped up to 96~97%. after that Queued writer and reader is increasing, and active reader and writers are scanning oldest transaction. Attached pstack_primary.txt is stack trace of primary when this case happen. |
| Comments |
| Comment by Michael Cahill (Inactive) [ 08/Jun/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The original issue reported here was fixed in | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Cahill (Inactive) [ 30/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi matt.lee, here are binaries that I believe will work on your system: This is the tip of the MongoDB 3.2 branch with the latest WiredTiger changes added. We have now updated MongoDB master with the latest WiredTiger changes, so if you have any trouble with those binaries, you could build the MongoDB master branch and see whether it resolves your issues. We expect to update the MongoDB 3.2 branch soon, but these eviction changes may not make it into MongoDB 3.2.7. Again, apologies for the delay but I hope these changes address the performance issues you have found. I would like to close the GitHub pull requests against MongoDB: if we need additional changes to WiredTiger, please follow up here and we can open pull requests against the WiredTiger repository. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 26/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Thanks. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Cahill (Inactive) [ 26/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
matt.lee, I have just started the build that includes the latest WiredTiger changes with MongoDB 3.2.6. Can you tell me what Linux variant you run so I can make sure the right binaries are created? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 25/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
When do you expect I can get a development code for test. ? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 25/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Michael Cahill. >> Would you be able to test that development code to see whether it addresses the performance issues you have reported? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Cahill (Inactive) [ 25/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
matt.lee, my apologies that your requests went quiet. My whole team has been travelling for the past two weeks. We have some active work in progress to improve eviction performance that I think should help with your workloads. There have been several changes to the eviction code since the version in mongodb:master. Also, our development process is to make changes first to WiredTiger (https://github.com/wiredtiger/wiredtiger), then update MongoDB when the WiredTiger tree is stable. Given all of that, what I would like to suggest is that we produce MongoDB 3.2.x binaries updated to the latest version of WiredTiger. Would you be able to test that development code to see whether it addresses the performance issues you have reported? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 05/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Michael Cahill. I think I found the reason why original mongodb doesn't evict internal pages. https://github.com/mongodb/mongo/pull/1079 And I've patched and run our service traffic. And now cache usage of wiredtiger and mongodb query processing is looks good. But still I think candidate cutoff point should be more aggressive than original code. Thanks. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 05/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I have tested MongoDB 3.2.6 + Wiredtiger cache usage was not stable, it's going up to 100% and throughput is decreased.
Still there were really small internal page eviction even though cache usage was getting upto 100%. Matt. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 04/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Same issue happens on another shard server. Still not sure rare internal page eviction is the cause of this issue. (I am saying rare internal page eviction as one of symptoms). Thanks. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 04/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I've done the test with original mongod 3.2.5. In the graphs, Something weird is that there's almost no internal page eviction with original mongodb, But with patched mongodb there's about 2~3K internal page eviction this time yesterday.
Thanks. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 04/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Michael Cahill. I have thought about your question last night. Actually I am not sure about this. I have focused on internal page eviction,
But original mongodb, they generate only 30 candidates (out of 300 entries by __evict_walk call) each __evict_lru_walk() call.
What I am wondering is that maybe full eviction throughput of original mongodb is not sufficient FYI,
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Cahill (Inactive) [ 04/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
matt.lee, I have attached the patch for | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Cahill (Inactive) [ 03/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
matt.lee, thanks, I understand the pull request, and it is certainly interesting to look at making more pages available for eviction. However, in the common case, your change will mean that there is very little selectivity on LRU. In other words, we will be selecting pages from cache more or less at random. For some workloads that may help, but for others it will lead to lower performance due to eviction of hot pages (such as _id index pages). We have tried several different policies for eviction of internal pages. Do you have any sense of how important that part of the change was? If internal pages have to be evicted for the workload to run, is that because the data size is much larger than the cache size? The changes from https://github.com/wiredtiger/wiredtiger/commit/2389dbb24ccad4a4eb06bd9418fc56d0da51f58c These need to be applied to src/third_party/wiredtiger in a MongoDB tree. I will turn them into a MongoDB patch and run it through testing overnight. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 03/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Michael Cahill. In my thread stack, all foreground threads were running "__wt_txn_update_oldest()". And __wt_txn_update_oldest must be optimized. I have seen the reason you patched internal page eviction threshold, But that is performance issue, But my issue is server hang for a long time. >> Note that the fix for And I have experienced one more issue last night. Matt. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Cahill (Inactive) [ 03/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
matt.lee, thanks again for reporting this issue and supplying all the information. As alexander.gorrod said earlier, from our analysis, this looks like a duplicate of In pstack_primary.txt, we see:
and in pstack_secondary:
(where the "??" is most likely also __evict_server). That means the thread responsible for queuing pages for eviction is stuck due to While I can see where you are going with the patch, I suspect it may be masking the problem by making more progress each time eviction runs, rather than fixing the underlying issue. Note that the fix for | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 02/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I have singed the contributor agreement. Matt. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Ramon Fernandez Marina [ 02/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
matt.lee, please note that before we can consider your pull request you'll need to sign the contributor agreement. Thanks, | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 02/May/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Ramon, I think I found some sloppy solution. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 19/Apr/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Alexander, According to my observation, very few threads were processing user requests. And everytime when this case happen, A little bit weird thing is the result of db.currentOp().
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alexander Gorrod [ 19/Apr/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
This appears very similar to | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 아나 하리 [ 18/Apr/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Ramon, I attached "metrics.2016-04-18T09-51-46Z-00000.tar.gz" which is today metrics file of diagnostics.data/. And I changed wiredtiger engine config string from "2016-04-18T09-51-46". eviction_trigger=85 | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Ramon Fernandez Marina [ 18/Apr/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
matt.lee, can you please upload the contents of the diagnostic.data directory for the affected node(s)? That should help us better understand what's going on. Thanks, |