[SERVER-17364] Idle cursors shouldn't hold storage engine resources Created: 24/Feb/15 Updated: 07/Apr/23 Resolved: 16/Jul/15 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Querying, WiredTiger |
| Affects Version/s: | None |
| Fix Version/s: | 3.1.6 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Bruce Lucas (Inactive) | Assignee: | Mathias Stearn |
| Resolution: | Done | Votes: | 5 |
| Labels: | WTplaybook | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Issue Links: |
|
||||||||||||||||||||||||||||||||||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||||||||||||||||||||||||||||||||||
| Operating System: | ALL | ||||||||||||||||||||||||||||||||||||||||||||
| Sprint: | Quint Iteration 5, Quint Iteration 6 | ||||||||||||||||||||||||||||||||||||||||||||
| Participants: | |||||||||||||||||||||||||||||||||||||||||||||
| Description |
|
Currently each idle ClientCursor holds on to it's original RecoveryUnit, so that getMores use the same session as the operation that created the cursor. This is a problem because they are relatively heavy-weight and there are a finite supply of them, at least for WiredTiger. We will change this to have getMores always use their own RU rather than swapping in the original. This requires some changes to the WT SDI::Cursor and RecordIterator implementations to be prepared for changes to the RU. ORIGINAL TITLE AND DESCRIPTION: Too many open WT_SESSIONs causes fassert Too many open cursors results in too many open sessions and an fassert. Probably we should just fail the cursor open in this case, not fassert.
|
| Comments |
| Comment by Ramon Fernandez Marina [ 11/Nov/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
grant@teambanjo.com, please open a new ticket so we can investigate your issue separately. Also please upload full logs for the affected node. Thanks, | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Grant Ridder [ 10/Nov/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
I am seeing this in a 3.0.7 cluster
| |||||||||||||||||||||||||||||||||||||||||||
| Comment by a zhifan [ 03/Sep/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
hi @redbeard0531, could you explain the relationship for the following 3 things: ComputedCartRS:SECONDARY> db.serverStatus().wiredTiger.session { "open cursor count" : 48476, "open session count" : 14742 }
I though the number should be same, but in fact, it is not. Per your statements above, "once you have established 20k ClientCursors the server is stuck", )". If there is not socket communication between client and server for 60 seconds, the cursor will be closed due to this? if so, if all the operation can be completed in 60 seconds, this change will not hurt anything at all? then I set it to 60 seconds, after 10 minutes, I didn't see the count decreased, is it expected? | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 28/Aug/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
Author: {u'username': u'GeertBosch', u'name': u'Geert Bosch', u'email': u'geert@mongodb.com'}Message: | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Ramon Fernandez Marina [ 20/Aug/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
Thanks for the additional information yangzheng, and sorry you run into this problem. We found additional issues with the cursor cache in 3.0.5 as described in Seeing that you can trigger this error, would you be willing to try 3.0.6-rc2 and make sure it solves this problem for you? Thanks, | |||||||||||||||||||||||||||||||||||||||||||
| Comment by yz [ 20/Aug/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
hi Ramón it is still this problem in 3.0.5
| |||||||||||||||||||||||||||||||||||||||||||
| Comment by Ramon Fernandez Marina [ 03/Aug/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
yangzheng, excessive memory consumption by cursor cache was fixed in Regards, | |||||||||||||||||||||||||||||||||||||||||||
| Comment by yz [ 03/Aug/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
why do not fix this bug in 3.0.5 ??? | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 16/Jul/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
Author: {u'username': u'RedBeard0531', u'name': u'Mathias Stearn', u'email': u'mathias@10gen.com'}Message: We now tell PlanExecutors to detach from their OperationContexts and to shed | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 16/Jul/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
Author: {u'username': u'RedBeard0531', u'name': u'Mathias Stearn', u'email': u'mathias@10gen.com'}Message: This is prep for adding more methods that need to propagate to children. | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Glen Miner [ 23/Jun/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
Just as a follow up about our use of cursorTimeoutMillis – we tried extensively to eliminate all orphaned cursors from our system (PHP and Mongo JS shell) and ultimately could not eliminate enough leaks to prevent an alarming numbers of cursors being kept around (1000's). We have run into problems with cursor timeouts as a result of our change however we can work around these problems. Perhaps if | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Ramon Fernandez Marina [ 21/Jun/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
Users running into this issue may try setting a low value for the idle cursor timeout as a workaround.
NOTE: using this workaround may affect the way your application works if it relies on cursors being opened for longer than 60 seconds. The preferred way to work around this issue is to make sure cursors are properly closed. | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Glen Miner [ 01/Jun/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
I did manage to get a serverStats out of death #4 just now – it's attached to SERVER-18747 as stats2_ss.txt | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Glen Miner [ 29/May/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
Actually things are pretty grim; we've had 3 cascading failures – all similar – over the last week. I just spent some time analyzing the logs from the first failure and we have exonerated backups from suspicion – we're now utterly convinced that something is very rotton and leading to some sort of deadlock or massive lock bubble that causes us to fall over (even with massively increased limits). SERVER-18747 | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 28/May/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
Hi Glen, How are things progressing? As you surmised setting the WT session_max parameter is indeed a potential workaround for this. If you do still encounter issues related to this can you please give us db.serverStatus() output? A single point in time when the server is experiencing problems would be helpful, even better would be to collect a timeseries of db.serverStatus() while you reproduce the issue:
Thanks, | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Glen Miner [ 22/May/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
This problem caused a cascade of failures for us this morning; one node after another fell down until I got the panic phone call; we're not sure where the cursors are coming from but backup task is prime suspect; we just completed upgrade from 2.6 and the last secondary node had finished replicating maybe 12 hrs before disaster struck. For posterity: countermeasures we've tried: 1) mongd.conf setParameter: The default of 10 minutes seems to be very bad for us; 30 seconds seems to have caused some problems but working around those seems preferred to having things fall over. 2) apache spare clients were set aggressively high; we use prefork and are currently on PHP mongo driver ver 1.6.8; we found that having a pool of 2000 preforked worker processes meant that we'd end up with thousands of connections lingering around (it seems the connection pool is per process). Prior to WiredTiger this was only memory; now it's a threat to stability. We cranked this down to around 200 workers * 3 PHP servers and this means we get far fewer dormant workers holding on to cursors (however in a rush we will still fork up to 3000/server so this is not enough). One interesting thing was that after I "sudo service apache2 restart" on all web servers to bring the number of processes down to ~500 it took a long time for Mongo to flush the connections out. I watched the log on the database machine and you could see the connection count going down and down very slowly – we went from "6746 connections now open" to around 700. This was not a CPU-limit; these are 32-core beasts and were 95% idle. These measures seemed to have helped a lot; currently we're under pretty heavy load and no node is holding onto more than a few dozen cursors and the number of connections is nearly 1/10th what it was. However, we're nervous that in the event of a failover there will be a thundering herd of requests after the handoff – we estimate the max number of clients will peak around 9000; somehow this resulted in > 20010 sessions; I'm guessing this is somehow related to the latency I observed in the connections being expired by the server. We're obviously concerned that while we've reduced the risk of saturation we haven't eliminated the threat that saturation causes to stability. The last thing we're going to try is some undocumented hackery in the config to double session_max: storage: I tested this on a dev machine and as far as I can tell it's making its way down into to WT. I'm not sure if this will have memory risks – the DB servers all have 128GB of ram and the database itself is maybe 60GB resident so I think this is low-risk for us. Since we can't change this without a restart we're going to have to ride out the weekend storm without it. | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Mathias Stearn [ 21/Apr/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
I looked into making this non-fatal, but now I don't think it is a good idea without other large changes to mongod. Note that this is actually a failure to allocate a new WT_SESSION not a WT_CURSOR. There is (roughly) one WT_SESSION per active operation + one per ClientCursor. The problem with making this error non-fatal is that once you have established 20k ClientCursors the server is stuck. You can't send any new operations to the server, even OpKillCursor since every new op needs to create an OperationContext. Given that, I think we are better off killing the server and failing over, rather than leaving it around as a zombie. I think the correct solution is to make idle ClientCursors not hold any WT resources, but that is a fairly large change and definitely won't be backportable. | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Vanni Fan [ 09/Apr/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
----- BEGIN BACKTRACE ----- , {"b":"400000","o":"B09881"}, {"b":"400000","o":"AEFFBA"}, {"b":"400000","o":"98C570"}, {"b":"400000","o":"98CA46"}, {"b":"400000","o":"987E7E"}, {"b":"400000","o":"987EC5"}, {"b":"400000","o":"976B25"}, {"b":"400000","o":"6A0728"}, {"b":"400000","o":"62A6C2"}, {"b":"400000","o":"62ADFD"}, {"b":"400000","o":"61EB7D"}, {"b":"400000","o":"6410D5"}, {"b":"400000","o":"7EC054"}, {"b":"400000","o":"7EC404"}, {"b":"400000","o":"7BAA0C"}, {"b":"400000","o":"6D0AB0"}, {"b":"400000","o":"42A50D"}, {"b":"400000","o":"B1CC7B"}, {"b":"7FA581676000","o":"7E9A"}, {"b":"7FA580075000","o":"F42ED"}],"processInfo":{ "mongodbVersion" : "3.0.1", "gitVersion" : "534b5a3f9d10f00cd27737fbcd951032248b5952", "uname" : { "sysname" : "Linux", "release" : "3.2.0-23-generic", "version" : "#36-Ubuntu SMP Tue Apr 10 20:39:51 UTC 2012", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000", "buildId" : "7F7D0BB0BFBF6B9A69384E0AB86648732D9C5BA8" }, { "b" : "7FFF272D9000", "elfType" : 3, "buildId" : "0C0CC7757C6933FC35A55C90475D300ADAF970C5" }, { "b" : "7FA581676000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "C340AF9DEE97C17C730F7D03693286C5194A46B8" }, { "b" : "7FA58141A000", "path" : "/lib/x86_64-linux-gnu/libssl.so.1.0.0", "elfType" : 3, "buildId" : "110068FEAE2CA610641E122FFC1B883C015CF46D" }, { "b" : "7FA581052000", "path" : "/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", "elfType" : 3, "buildId" : "7FF6D799EC2B13199AA63204D944E2D6420A3960" }, { "b" : "7FA580E4A000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "352C5B373A50E6C4AB881A5DB6F5766FDF81EEE0" }, { "b" : "7FA580C46000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "D181AF551DBBC43E9D55913D532635FDE18E7C4E" }, { "b" : "7FA580946000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3, "buildId" : "B534DA725D06A04267EB2FEB92B9CC14C838B57B" }, { "b" : "7FA58064A000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "817AA99B3DD02501F8BC04A3E9A9358A08F20D7D" }, { "b" : "7FA580434000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "ECF322A96E26633C5D10F18215170DD4395AF82C" }, { "b" : "7FA580075000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "57B3EB388FB6FE036D1E708259DACA7FCE990462" }, { "b" : "7FA581893000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "E25AD1A11CCF57E734116B8EC9C69F643DCA9F18" }, { "b" : "7FA57FE5E000", "path" : "/lib/x86_64-linux-gnu/libz.so.1", "elfType" : 3, "buildId" : "F695ECFCF3918D5D34989398A14B7ECDD9F46CD0" } ] }} | |||||||||||||||||||||||||||||||||||||||||||
| Comment by Vanni Fan [ 09/Apr/15 ] | |||||||||||||||||||||||||||||||||||||||||||
|
When I use Jmeter load test my WebService(Nginx + PHP-FPM [mongo-php-driver-1.6.6] ) services from time to time, I got this error too. Mongodb Server: Linux hk-radar-mongo-slave1 3.2.0-23-generic #36-Ubuntu SMP Tue Apr 10 20:39:51 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux ------------------------------- , {"b":"400000","o":"B09881"}, {"b":"400000","o":"AEFFBA"}, {"b":"400000","o":"98C570"}, {"b":"400000","o":"98CA46"}, {"b":"400000","o":"987E7E"}, {"b":"400000","o":"987EC5"},{"b":"400000"," ***aborting after invariant() failure |