[SERVER-40685] Mongos often fails transactions that use "snapshot" with SnapshotTooOld Created: 16/Apr/19 Updated: 05/Nov/19 Resolved: 17/May/19 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | None |
| Affects Version/s: | 4.1.11 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Shane Harvey | Assignee: | Dianna Hohensee (Inactive) |
| Resolution: | Done | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||||||||||||||||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||||||||||||||||||||||||||
| Operating System: | ALL | ||||||||||||||||||||||||||||||||||||||||||||
| Steps To Reproduce: |
|
||||||||||||||||||||||||||||||||||||||||||||
| Sprint: | Storage NYC 2019-05-20, Sharding 2019-05-06 | ||||||||||||||||||||||||||||||||||||||||||||
| Participants: | |||||||||||||||||||||||||||||||||||||||||||||
| Linked BF Score: | 45 | ||||||||||||||||||||||||||||||||||||||||||||
| Description |
|
Various driver transaction spec tests are failing on latest sharded clusters. The one commonality between the failures is that they all use read concern "snapshot" and they all fail with SnapshotTooOld on the first operation in the transaction. Was there a recent change in how "snapshot" works? Although this issue fails consistently in Evergreen, creating a standalone repro has proven difficult. When starting a fresh sharded cluster the attached repro (PYTHON-1796.py And here's the repro failing:
I can reproduce this on the latest version: |
| Comments |
| Comment by Githook User [ 05/Nov/19 ] | |||||||
|
Author: {'username': 'mbroadst', 'email': 'mbroadst@mongodb.com', 'name': 'Matt Broadstone'}Message: test: skip broken transaction tests until | |||||||
| Comment by Githook User [ 03/Nov/19 ] | |||||||
|
Author: {'username': 'mbroadst', 'email': 'mbroadst@mongodb.com', 'name': 'Matt Broadstone'}Message: test: skip broken transaction tests until | |||||||
| Comment by Githook User [ 03/Nov/19 ] | |||||||
|
Author: {'username': 'mbroadst', 'email': 'mbroadst@mongodb.com', 'name': 'Matt Broadstone'}Message: test: skip broken transaction tests until | |||||||
| Comment by Githook User [ 03/Nov/19 ] | |||||||
|
Author: {'username': 'mbroadst', 'email': 'mbroadst@mongodb.com', 'name': 'Matt Broadstone'}Message: test: skip broken transaction tests until | |||||||
| Comment by Githook User [ 29/Jul/19 ] | |||||||
|
Author: {'name': 'Oleg Pudeyev', 'email': '39304720+p-mongo@users.noreply.github.com', 'username': 'p-mongo'}Message: | |||||||
| Comment by Githook User [ 26/Jul/19 ] | |||||||
|
Author: {'name': 'Oleg Pudeyev', 'username': 'p-mongo', 'email': '39304720+p-mongo@users.noreply.github.com'}Message: | |||||||
| Comment by Dianna Hohensee (Inactive) [ 11/Jul/19 ] | |||||||
|
So I've spoken with Aly about this, and we've determined the best course of action would be for one of you to file a HELP ticket and assign it to Aly. She has all the context to sort out what's going on, from where errors are coming and can help sort out what to do about them. One thing that's clearly weird about the error message is that it says "a non-retryable snapshot error" when SnapshotTooOld errors ("Read timestamp Timestamp(1562100752, 11) is older than the oldest available timestamp") were intended to be retryable transient transaction errors. So that seems like one thing that will need to be fixed on the mongodb side. | |||||||
| Comment by Bernie Hackett [ 11/Jul/19 ] | |||||||
|
My mistake. The failures for Python started on 7/2, not 6/27. This seems to only be happening with 4.3.x (latest at the time of the test run). This version worked fine on 6/27:
This version started the failures on 7/2:
I can't pinpoint the version any better since there were no commits to PyMongo between those two days. The error message:
| |||||||
| Comment by Dianna Hohensee (Inactive) [ 11/Jul/19 ] | |||||||
|
behackett, dmitry.lukyanov, can you specify what mongo commit you were using for those tests? So July 2nd and 4th for Dmitry, and 6/26 for Bernie. I made a change to the snapshot window size controls (which can affect the success of transactions ops run through a mongos with 'snapshot' read concern) that was committed on July 1st. We have not seen any new test failures on our end, but I want to rule out or in whether those changes had an affect on the Drivers. | |||||||
| Comment by Bernie Hackett [ 10/Jul/19 ] | |||||||
|
I'm seeing this in PyMongo's tests since 6/26. What change needs to be made in drivers? | |||||||
| Comment by Dmitry Lukyanov (Inactive) [ 08/Jul/19 ] | |||||||
|
>Perhaps we could change them all to majority without reducing driver's test coverage in a significant way. not sure that we can do it since some tests validate exactly correctness of using `snapshot` option. NOTE:
| |||||||
| Comment by Jeffrey Yemin [ 08/Jul/19 ] | |||||||
|
dmitry.lukyanov on which operations are the snapshot test options specified? Perhaps we could change them all to majority without reducing driver's test coverage in a significant way. | |||||||
| Comment by Dmitry Lukyanov (Inactive) [ 08/Jul/19 ] | |||||||
|
milkie, as we discussed a little bit in the Exception message:
NOTE: When I replaced all `snapshot` test options on `majority`, all tests have passed. Could you please advise how can I solve/work around this error? cc: rstam | |||||||
| Comment by Eric Milkie [ 26/Jun/19 ] | |||||||
|
Until SERVER-39704 is complete, drivers will need to either build-in retries for this specific error, or should adjust their test framework to avoid this error. We can work together on crafting a way to avoid this error if you still have tests that are failing. | |||||||
| Comment by Robert Stam [ 25/Jun/19 ] | |||||||
|
I'm still getting this error when using `4.2.0-rc1`.
The command was an `insert` command.
| |||||||
| Comment by Dianna Hohensee (Inactive) [ 07/Jun/19 ] | |||||||
|
rstam I would be interested in what command you were trying to run that caused that "Read timestamp Timestamp(1559767078, 78) is older than the oldest available timestamp" error. I know that transaction commands through mongos do not currently retry transient transaction errors (SERVER-39704), but your error says non-retryable, which I would not expect to be attached to a command response. | |||||||
| Comment by Jeffrey Yemin [ 05/Jun/19 ] | |||||||
|
And if it is expected, can you suggest any workarounds for automated driver tests that are encountering this issue. | |||||||
| Comment by Robert Stam [ 05/Jun/19 ] | |||||||
|
dianna.hohensee I just got this error today when running the C# driver test suite:
If this ticket is closed would you expect a client to still see this error?
| |||||||
| Comment by Robert Stam [ 05/Jun/19 ] | |||||||
|
milkie pointed out to me that if you look far enough to the right in the error message that this is actually a different error. I've created a new SERVER ticket for the new error: | |||||||
| Comment by Eric Milkie [ 05/Jun/19 ] | |||||||
|
rstam I don't think that error is related to this ticket? That error response can result from trying to read at a point-in-time that is too close to a DDL operation time (such as a drop or create index). | |||||||
| Comment by Robert Stam [ 05/Jun/19 ] | |||||||
|
dianna.hohensee I just encountered this error today using server version 4.1.11-165-g1c9d985.
| |||||||
| Comment by Shane Harvey [ 23/May/19 ] | |||||||
|
I can confirm that the python driver has not hit this issue since this ticket was closed. Thanks! | |||||||
| Comment by Dianna Hohensee (Inactive) [ 23/May/19 ] | |||||||
|
shane.harvey, could you get confirmation that the problem seen by the python driver has been resolved? I want to make sure this is all set for RC0. | |||||||
| Comment by Dianna Hohensee (Inactive) [ 17/May/19 ] | |||||||
|
Previously, any cache pressure would prevent the snapshot window size from increasing, as well as decrease the size down to zero. The cache pressure metric was also not reliable, as Randolph pointed out above. Now, SnapshotTooOld errors always cause the window size to increase (up the to max setting, which is configurable and defaults to 5 seconds), regardless of cache pressure. Also, instead of using the cache lookaside score to determine cache pressure, we are tracking writes to the cache overflow table (WT lookaside table, persisted on disk). | |||||||
| Comment by Eric Milkie [ 07/May/19 ] | |||||||
|
I linked a ticket in our backlog that will be replacing the current scoring statistic with something better. | |||||||
| Comment by Randolph Tan [ 07/May/19 ] | |||||||
|
Here's what I found while investigating the build failure. It looks like the cache lookaside score we used to determine whether WT cache is under pressure gets to a high number, and the startPeriodicThreadToDecreaseSnapshotHistoryCachePressure thread starts to decrease the snapshot window from the default of 5 seconds to eventually 0 seconds. The score doesn't appear to go down even after committing transactions. After discussing with keith.bostic and louis.williams, it appears that the score is updated during eviction and it is possible for the score to remain at a high value even though it is no longer under pressure. Sending to storage team to re-evaluate the heuristics to use in the snapshot history cache pressure thread. | |||||||
| Comment by Siyuan Zhou [ 03/May/19 ] | |||||||
|
This issue has been causing lots of failures in BF-12756 and BF-12986? matthew.saltz kaloian.manassiev, it would be great if we could prioritize the fix. | |||||||
| Comment by Dianna Hohensee (Inactive) [ 19/Apr/19 ] | |||||||
|
This lists and explains all the controls (server parameters) for the history window https://github.com/mongodb/mongo/blob/master/src/mongo/db/snapshot_window_options.h There are also serverStatus fields in the 'wiredtiger' section that will show you what the current settings are of those options at runtime, as described in this comment https://jira.mongodb.org/browse/SERVER-31767?focusedCommentId=1875613&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-1875613 Basically, we have a targetSnapshotHistoryWindowInSeconds server parameter setting that we use when going to set the oldest timestamp: the oldest timestamp lags the stable timestamp by 'targetSnapshotHistoryWindowInSeconds' seconds. The targetSnapshotHistoryWindowInSeconds will move between 0 and maxTargetSnapshotHistoryWindowInSeconds depending on cache pressure and and SnapshotTooOld cmd errors. We have a periodic task to check for cache pressure and decrease the target window size if found; and we catch SnapshotTooOld errors from commands to prompt increases of targetSnapshotHistoryWindowInSeconds – if there's no cache pressure. We were not sure what the default settings should be for the server parameters, so that might be worth altering and seeing if the problem persists. It's also possible that our cache pressure gauge is having trouble: if the snapshot window is 0 in your repro and refuses to increase, that might be the problem. | |||||||
| Comment by Kaloian Manassiev [ 19/Apr/19 ] | |||||||
|
dianna.hohensee, can you remind us how long was the default history window that WT keeps around and how is this configured? I am thinking there are two possibilities:
I am putting this on the sharding team's backlog, because it looks like legitimate problem with using sharded transactions. |