[SERVER-26018] Inconsistency between the LockManager grantedList and grantedCount Created: 08/Sep/16 Updated: 10/May/23 Resolved: 11/Oct/16 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Stability |
| Affects Version/s: | 3.0.12, 3.2.10, 3.4.0-rc0 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | xiaost | Assignee: | Kaloian Manassiev |
| Resolution: | Done | Votes: | 1 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||
| Issue Links: |
|
||||||||
| Operating System: | ALL | ||||||||
| Steps To Reproduce: | unpredictable, seems to be produce on secondary |
||||||||
| Sprint: | Sharding 2016-09-19, Sharding 2016-10-10, Sharding 2016-10-31 | ||||||||
| Participants: | |||||||||
| Linked BF Score: | 5 | ||||||||
| Description |
|
All threads hang on waiting locks. The state of the LockHead indicates that there is inconsistency between the grantedList and grantedCount where there are not granted requests, but the granted counts are non-zero:
Attachment shows stacks of all threads and the output of db.currentOp(). Here is our cluster info:
|
| Comments |
| Comment by xiaost [ 24/Jan/17 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
FYI: here is the changelog of libc in debian 8.7 which released on 20170114:
| ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xiaost [ 12/Oct/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
hi, geert.bosch, it is identical except microcode version. here is the cpuinfo:
| ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Geert Bosch [ 12/Oct/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi xiaost, I've tried to see what the specific CPU/microcode versions are that might expose the issue. In your comment on Sep 22 2016, you listed the /proc/cpuinfo output for the old and the new processor versions. Could you give us the /proc/cpuinfo for the new processor after you applied the microcode update? I'm particularly curious if the "rtm" flag is still set, and what the new version of the new microcode is. Thanks again! | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 11/Oct/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thank you for all the help, xiaost. We have filed | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xiaost [ 11/Oct/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
after we spent a lot of time on debugging multi-threaded issue on mongod, we found out:
after debugging, we started to focus on hardware issue, including memory / CPU. With the help of Google, we found the TSX feature, speeding up execution of multi-threaded software through lock elision, seems to be evil of everything since 2014:
we checkout our microcode changelog. In the latest release:
so we try it, and work it out.
Best regards, | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 11/Oct/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi xiaost, Thank you for providing us with this information. CPU problem and memory corruption was something we did consider, but weren't sure how to diagnose and also discounted as highly improbable. May I ask how did you come to the conclusion that it is a microcode issue and decide to upgrade? This will greatly help us when trying to diagnose any future reports of this kind which we might get. Best regards, | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xiaost [ 11/Oct/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
hello, all. seems to be Intel CPU issue (TSX), after we upgrading microcode of CPUs, the issue gone. (E5-2630 v4 with microcode 0xb000010 => 0xb00001d ) | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xihui he [ 08/Oct/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
FYI: when slaves are on a high load, we can easily reproduce the issue on our new slave machines with 3.2.8, 3.2.9 debian build, 3.2.9 linux build and 3.2.9 built on our new machine by ourself. Regards, | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 28/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi bydsky, Thank you very much for the reproduction. I will take it from here and try figure out what happened from the call stack. By debug file - do you mean the symbols or a debug variant of the build? Symbols are here. In either case I can resolve the call stack myself from the backtrace you pasted and I will post it in the ticket. Thanks again for the help. Best regards, | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xihui he [ 28/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Could you please provide the debug file for the build? Many Thanks, | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xihui he [ 28/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Attached is serverStatus. | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xihui he [ 28/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Below is the bt in the log:
| ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 27/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}Message: Also adds concurrency stress tests to exercise the lock head migrations | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xihui he [ 27/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I have replaced our production slaves with the binary you provided. Will let you know if it happens again. | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 26/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
EDIT: I was notified that the link I had attached requires password, so instead I have attached the diff in a file called LockMgrInvariants.diff. Certainly, sorry about that - I should have included them originally. Please find the code changes along with this run through our continuous integration system: https://evergreen.mongodb.com/version/57e566ff3ff12239ba009729 Please note that the change is not yet committed to the official branch (and other releases) because we have not found the underlying cause of the bug and we also have not fully tested the possible performance impact of including the extra invariants. In particular this change:
| ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xihui he [ 26/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Could you please add the corresponding commit if possible? Thanks, | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 23/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The build with the additional assertions is available here. It is built on top of the 3.2.9 release. Thank you again for your help. Best regards, | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 22/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thank you for providing me with the machine information. We are now testing the binary with the extended checks and I will provide you with download links when it is ready. Many thanks again for all your help with diagnosing this problem. Best regards, | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xihui he [ 22/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Another difference is till now the issue only happens on our new machine (we upgraded to 3.2.9 meanwhile we add new machines to the cluster).
old machine
| ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xihui he [ 22/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
1. The issue happened on different hosts, however it happened after we upgrade to 3.2.9, and till now it only happened on slaves. Thanks, | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 21/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thank you very much for the detailed reports and investigation, and apologies for the delayed response. The information that you provided is really helpful, but also extremely puzzling. After inspecting the code, I was unable to find a case where there are no entries on the grantedList, but the grantedCounts/grantedModes bitmask is not zero and I have a couple of questions:
In order to help investigate this more I am working on a change which adds more invariant checks to the lock manager and also rearranging the code a little to make it easier to follow. Would you be willing to take a 3.2.9-based debian8.1 patch build with these changes and run it on one such machine in order to see whether any of the invariants get hit? Thank you again for your help investigating this issue. Best regards, | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xihui he [ 21/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Seems grantedCounts is not clear on unlock again.
| ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xihui he [ 21/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
From bt, it seems this time (Sep 20) is different from last time (Sep 12) For Sep 20 hang, it seems:
| ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xiaost [ 20/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
we gotcha ! the currentOp output. seems rsSync holding the global W lock | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xihui he [ 14/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Below is the LockHead which blocks all requests.
| ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xiaost [ 13/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
uploaded gdb bt output which is more readable | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by xiaost [ 12/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
>> Can you tell me exactly which distribution of mongodb 3.2.9 are you running (i.e., platform/OS and OS version)? package : mongodb-linux-x86_64-debian81-3.2.9 lsb_release -a Distributor ID: Debian >> Can you confirm whether all stacks in the attached list are from the same mongod process? yes. >> It would be very helpful if we had a list of the operations, which were running at the time of the hang. If it occurs again, would it be possible to run the db.currentOp(true) command and attach the output? I would like to, but once mongodb hangs I can do nothing. >>>>>>>>>>>>>>>>>>>>>>>>>>>> the issue reproduce again yesterday, I had dump memory to file. What can I do next to help debugging? | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Teemu Sirkiä [ 08/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Could this be related to this https://jira.mongodb.org/browse/SERVER-25700 bug? Did you notice high CPU usage after this issue occurred? | ||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 08/Sep/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi xiaost, Thank you for reporting this issue and for attaching the thread stacks. I have a couple of follow-up questions to help us track it:
Thank you in advance. -Kal. |