[SERVER-31101] WT table not dropped after collection is dropped due to long-running OperationContext Created: 15/Sep/17 Updated: 30/Oct/23 Resolved: 16/Nov/17 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Storage |
| Affects Version/s: | 3.2.13, 3.4.9 |
| Fix Version/s: | 3.2.18, 3.4.11, 3.6.0-rc1 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Bruce Lucas (Inactive) | Assignee: | Eric Milkie |
| Resolution: | Fixed | Votes: | 4 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Operating System: | ALL | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Backport Completed: | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Participants: | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Case: | (copied to CRM) | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Description |
|
In a replica set
On the primary the corresponding WT tables will be dropped, but on the secondaries the index table will be dropped but not the collection table - the .wt file will remain, and the ftdc data will show a steady stream of 10 failed table drops per second. |
| Comments |
| Comment by Githook User [ 17/Nov/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'name': 'Katherine Walker', 'username': 'kvwalker', 'email': 'katherine.walker@mongodb.com'}Message: (cherry picked from commit 0f9d6085526921dd8edaffce827ffd07653ee4cd) | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 17/Nov/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'name': 'Katherine Walker', 'username': 'kvwalker', 'email': 'katherine.walker@mongodb.com'}Message: (cherry picked from commit 0f9d6085526921dd8edaffce827ffd07653ee4cd) | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Eric Milkie [ 16/Nov/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
At this moment the fixes are in the 3.6 and master branches, but not yet in the 3.4 or 3.2 branches. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Eric Milkie [ 07/Nov/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The work for the subtickets has been completed and pushed into the master branch in preparation for the 3.6 release. The 3.4 release will be fixed as soon as | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Eric Milkie [ 18/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
It turns out my idea wasn't so easy, as our code assumes you can hold cursors outside of a transaction and return it to the cache later on. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Eric Milkie [ 18/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
My POC for this will be to return the RecoveryUnit's session back to the cache when a transaction finishes. I believe that this will actually fix the problem described in the ticket with minimal code changes, and the performance repercussions will be minimal. It would really only possibly affect operations that do many transactions using the same OperationContext, and I can't think of any situations that do this enough that it would be noticeable. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 18/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Moving back to 3.6 Required (can be downgraded to 3.5 Desired if that's the decision). It was only moved to RC1 when the ticket was (temporarily) resolved. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Cahill (Inactive) [ 18/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
First up, I don't believe this issue is an RC1 blocker. It exists in earlier versions of MongoDB, I don't see any evidence that 3.6 work has made it worse or that anything else in 3.6 relies on this being resolve. Like daniel.gottlieb and bruce.lucas, I have been thinking about whether we can disable caching to avoid these issues. I like the idea above of flagging long-running operations and treating them differently. donald.anderson has also been working on improving the performance of opening WiredTiger cursors with the goal of disabling cursor caching in the MongoDB layer entirely. I ran some tests yesterday of disabling cursor caching between operations. This is orthogonal to Dan's approach above. If a long-running operation opens a cursor, that would still block a drop until the operation releases the session with my changes, but a session doesn't come from the cache with baggage that would block unrelated drops. Hare are patch builds of microbenchmarks and sys-perf. There is a lot of red, but in the detail, many workloads slowed by 5-10%, and only a small set of tight loops (such as inserting empty documents) saw 20% or more impact. I suspect that if we provided a parameter to control this, merging Dan's approach with this one, some customers would be prepared to pay ~10% of performance to avoid the stalls / uncertainty around drops. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 17/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I put together this patch as a POC for opting out of using cached sessions. There's still some ways where a client of an OperationContext can get into an undesirable state. For example, this patch still uses cursor caching on the long running operation context. What could happen, for example, if a long running operation context first accesses some (user) tables before blocking, those tables that were accessed would not be drop-able until the session is destroyed when it goes out of scope. I don't believe any of the recently identified long running operation contexts fall into this category. One (of the few?) example of an internal thread that accesses user collections would be the TTL thread. However, in that case the OperationContext is only kept for a single pass and is outside of any sleeping (but will block getting DB/Collection locks).
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 17/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
bruce.lucas I like the idea of letting applications from opting out of the WT session cache. Much of the machinery is already in place. The session cache is presumably most useful for client cursors. We haven't identified those to be problematic. I believe a method on the RecoveryUnit API and its resulting small implementation for the WTRecoveryUnit would give us an alternative one line fix for each of these long-running OperationContexts. Also looping in michael.cahill. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 17/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Looking at the linked tickets required to get rid of long-running OperationContexts it looks to me like it's going to be messy to some of them, and is possibly problematic to avoid creating more. I think the issue on this ticket could be avoided if long-running OperationContexts obtained fresh sessions rather than using a cached session, or in some way reset the session that they got from the cache, because that would avoid holding a session that had a cached WT cursor that prevented the WT table from being dropped. Adding such an option to support long-running OperationContexts seems fairly straightforward (even if not completely trivial). Should we consider such a fix as an alternative to stamping out all current and future long-running OperationContexts? cc: schwerin, milkie, daniel.gottlieb. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 17/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The HMAC thread mentioned above has been positively identified on | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 16/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Yep. I know geert.bosch and milkie wanted to have OperationContexts timed. I don't remember if a ticket was made for it. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 16/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
If part of the contract of operation contexts is that they shouldn't run indefinitely, should that condition be detected - as a start maybe when operation context is destroyed if it has been running for more than some reasonable time? And reported, maybe with an abort (and test failure) during testing, and with a message in the log in production? | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 16/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
And assigning back to katherine.walker for credit! | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 16/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Resolving this ticket as it solved the first cause of a table drop failing due to an open cursor the reproducers were exposing. Creating follow-up tickets for the additional long-running operation contexts, and will link them here. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 14/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Yes, all of those should be addressed. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 14/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
daniel.gottlieb, by adding some logging in OperationContext contructor and destructor to track OperationContext lifetime, I identified the following threads that appear to create long-lasting OperationContexts - created but never destroyed, even after ~5 minutes of uptime:
One of them is ReplBatcher as you identified. If long-lasting OperationContexts can in general cause this problem, do these all need to be addressed, regardless of which one happens to be responsible for this particular repro? | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 14/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I opened | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 13/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
This OperationContext from ReplBatcher seems to be the new culprit: https://github.com/mongodb/mongo/blob/8210549ab754524b155ea45eb6675d717873cb21/src/mongo/db/repl/sync_tail.cpp#L753 This one is a bit too complicated for me to POC hack, but it's pretty obvious that's a long-lasting OperationContext. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 13/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I gave spencer more of the details of what this fix does (explained the session and cursor caching), and how, in general, a fix might not result in the test passing. What I've done so far: Reproduced that on master prior to katherine.walker's patch, I was getting a failure. My next step is to the apply my "debug" patch that tracks sessions/cursors to see if the committed patch is simply unlucky and if there's another abusive consumer of OperationContexts. FWIW: I believe Katherine's patch is an incremental improvement, even if it didn't catch this repro. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Spencer Brody (Inactive) [ 13/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
So with Katherine's patch in we should no longer be waiting on the OplogFetcher with an OperationContext still in scope. So I think we need to re-visit the root cause analysis. Handing back to daniel.gottlieb for further investigation. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 13/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Yes, I'm still seeing failed table drops on the secondary. What's more I'm also seeing failed table drops now on the primary, like with | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Spencer Brody (Inactive) [ 13/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
bruce.lucas, Katherine just pushed a change that limits the lifetime of the OperationContext used by the rsBackgroundSync thread. If the root cause of this issue is indeed what daniel.gottlieb believed it to be, that should fix the issue. In Katherine's local testing based on Geert's script, however, the issue still seems to show up. Can you run your repro on master and see if it still triggers? If so, we might have to re-evaluate our root cause analysis. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 13/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'email': 'katherine.walker@mongodb.com', 'name': 'Katherine Walker', 'username': 'kvwalker'}Message: This reverts commit 285ea409456815f5d36b07e301328e136d04374e. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 06/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
spencer, that script was geert.bosch's, but I think you are correct. I also separately provided a shell script. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Spencer Brody (Inactive) [ 06/Oct/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
bruce.lucas, looking at the test you uploaded:
^ shouldn't that be "() => !pathExists(wtFileOnPrimary)," (checking that the path does not exist)? | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Spencer Brody (Inactive) [ 26/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The problem is that bgsync keep an OperationContext around for a long time, and across network i/o. The OperationContext should be destroyed when it is not in use, and a new one created later if needed | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 25/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
My original assessment of the rsBackgroundSync thread was half-wrong, but put us in the right direction. Ultimately the problem is that the rsBackgroundSync thread, which spawns and joins the OplogFetcher thread does so while holding onto an OperationContext. This keeps the WT_SESSION from being returned to the cache and having its cursors closed via the usual mechanisms. https://github.com/mongodb/mongo/blob/fbea0197073ec8e8fb4f9588b4d3f01fd80514ca/src/mongo/db/repl/bgsync.cpp#L496 | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 25/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
geert.bosch suspicion was right. There was code for closing cursors from a previous epoch. In fact there still is code to do so, but it got more sophisticated with https://github.com/mongodb/mongo/commit/b9739a9b4bf02790d427a8e4910629f8c378c5fb Currently investigating if the patch unintentionally broke something. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 25/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
In the meantime, I'm going to investigate a question geert.bosch had. Geert was under the impression that a failed table drop would increment the WiredTigerSessionCache epoch. What this does, is sessions being returned to the cache from the previous epoch would instead be closed. I'm going to look and see if that code ever existed and if it accidentally got removed with some other change. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Daniel Gottlieb (Inactive) [ 25/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
With the repro geert.bosch provided me, the rsBackgroundSync thread seems to be in a loop that:
Because the session seems to released after the sleep, the following iteration of the loop immediately gets the same session back. Dropping a table attempts to close existing cursors, but it can only do so on cached sessions. Thus the drop is highly unlikely to get inbetween the iterations of the loop. spencer Given the description of what I'm seeing, do you know off the top of your head what the rsBackgroundSync is doing that would cause this? | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 19/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Here's a Linux shell script that seems to reproduce it reliably for me.
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 15/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
This presumably has a similar cause to |