[SERVER-40322] Rolling back a prepared transaction leads to a hang writing rollback files Created: 25/Mar/19  Updated: 29/Oct/23  Resolved: 22/Apr/19

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: None
Fix Version/s: 4.1.11

Type: Bug Priority: Major - P3
Reporter: Max Hirschhorn Assignee: Vesselina Ratcheva (Inactive)
Resolution: Fixed Votes: 0
Labels: prepare_durability, rbfz
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Gantt Dependency
Related
related to SERVER-40365 Write rollback file for oplog format ... Closed
is related to SERVER-40614 Rollback errors should be fatal while... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

python buildscripts/resmoke.py --suites=no_server repro_server40322.js

repro_server40322.js

(function() {
    "use strict";
 
    load("jstests/core/txns/libs/prepare_helpers.js");
    load("jstests/replsets/libs/rollback_test.js");
 
    const rollbackTest = new RollbackTest();
    const primary = rollbackTest.getPrimary();
 
    rollbackTest.transitionToRollbackOperations();
 
    const testDB = primary.getDB("test");
    assert.commandWorked(testDB.runCommand({create: "mycoll"}));
 
    const session = primary.startSession({causalConsistency: false});
    const sessionDB = session.getDatabase(testDB.getName());
 
    session.startTransaction();
    sessionDB.mycoll.insert({_id: 0});
 
    PrepareHelpers.prepareTransaction(session);
 
    rollbackTest.transitionToSyncSourceOperationsBeforeRollback();
    rollbackTest.transitionToSyncSourceOperationsDuringRollback();
    rollbackTest.transitionToSteadyStateOperations();
 
    rollbackTest.stop();
})();

Sprint: Repl 2019-04-22
Participants:
Linked BF Score: 0

 Description   

The RollbackImpl::_findDocumentById() call in RollbackImpl::_writeRollbackFileForNamespace() triggers a prepare conflict and prevents the rollback from completing.

Thread 55: "rsBackgroundSync" (Thread 0x7f0e12c50700 (LWP 24502))
...
#10 mongo::Interruptible::waitForConditionOrInterrupt<mongo::WiredTigerSessionCache::waitUntilPreparedUnitOfWorkCommitsOrAborts(mongo::OperationContext*, uint64_t)::<lambda()> > (pred=..., m=..., cv=..., this=0x55b20c7dfdc0) at src/mongo/util/interruptible.h:219
#11 mongo::WiredTigerSessionCache::waitUntilPreparedUnitOfWorkCommitsOrAborts (this=0x55b208218e00, opCtx=opCtx@entry=0x55b20c7dfdc0, lastCount=lastCount@entry=0) at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp:316
#12 0x000055b20440b0bc in mongo::wiredTigerPrepareConflictRetry<mongo::(anonymous namespace)::WiredTigerIndexCursorBase::seekWTCursor(const mongo::KeyString&)::<lambda()> > (f=..., opCtx=0x55b20c7dfdc0) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h:184
#13 mongo::(anonymous namespace)::WiredTigerIndexCursorBase::seekWTCursor (this=0x55b20c183c00, query=...) at src/mongo/db/storage/wiredtiger/wiredtiger_index.cpp:1029
#14 0x000055b204410456 in mongo::(anonymous namespace)::WiredTigerIndexCursorBase::seek (this=0x55b20c183c00, key=..., inclusive=<optimized out>, parts=mongo::SortedDataInterface::Cursor::kKeyAndLoc) at src/mongo/db/storage/wiredtiger/wiredtiger_index.cpp:850
#15 0x000055b204cc8ba6 in mongo::IndexScan::initIndexScan (this=0x55b20c7ad500) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/bits/unique_ptr.h:342
#16 0x000055b204cca49f in mongo::IndexScan::doWork (this=0x55b20c7ad500, out=0x7f0e12c4ddc8) at src/mongo/db/exec/index_scan.cpp:129
#17 0x000055b204cd6f88 in mongo::PlanStage::work (this=0x55b20c7ad500, out=out@entry=0x7f0e12c4ddc8) at src/mongo/db/exec/plan_stage.cpp:47
#18 0x000055b204cbe009 in mongo::FetchStage::doWork (this=0x55b210920200, out=0x7f0e12c4de80) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/bits/unique_ptr.h:342
#19 0x000055b204cd6f88 in mongo::PlanStage::work (this=0x55b210920200, out=out@entry=0x7f0e12c4de80) at src/mongo/db/exec/plan_stage.cpp:47
#20 0x000055b204d23760 in mongo::PlanExecutorImpl::_getNextImpl (this=0x55b20c7f5180, objOut=0x7f0e12c4df80, dlOut=0x0) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/bits/unique_ptr.h:342
#21 0x000055b204d2425b in mongo::PlanExecutorImpl::getNext (this=<optimized out>, objOut=0x7f0e12c4e010, dlOut=<optimized out>) at src/mongo/db/query/plan_executor_impl.cpp:381
#22 0x000055b2046dbeb1 in mongo::repl::(anonymous namespace)::<lambda()>::operator()(void) const (__closure=0x7f0e12c4e220) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/bits/unique_ptr.h:342
#23 0x000055b2046dc759 in mongo::writeConflictRetry<mongo::repl::(anonymous namespace)::_findOrDeleteDocuments(mongo::OperationContext*, const mongo::NamespaceStringOrUUID&, boost::optional<mongo::StringData>, mongo::repl::StorageInterface::ScanDirection, const mongo::BSONObj&, const mongo::BSONObj&, mongo::BoundInclusion, std::size_t, mongo::repl::(anonymous namespace)::FindDeleteMode)::<lambda()> > (f=..., ns=..., opStr=..., opCtx=0x55b20c7dfdc0) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/bits/atomic_base.h:390
#24 mongo::repl::(anonymous namespace)::_findOrDeleteDocuments (opCtx=<optimized out>, nsOrUUID=..., indexName=..., scanDirection=<optimized out>, startKey=..., endKey=owned BSONObj 15 bytes @ 0x55b20c7d83e8, boundInclusion=<optimized out>, limit=<optimized out>, mode=mongo::repl::(anonymous namespace)::FindDeleteMode::kFind) at src/mongo/db/repl/storage_interface_impl.cpp:712
#25 0x000055b2046dc88c in mongo::repl::(anonymous namespace)::_findOrDeleteById (opCtx=0x55b20c7dfdc0, nsOrUUID=..., idKey=..., mode=mongo::repl::(anonymous namespace)::FindDeleteMode::kFind) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/new:169
#26 0x000055b2046dca6c in mongo::repl::StorageInterfaceImpl::findById (this=<optimized out>, opCtx=<optimized out>, nsOrUUID=..., idKey=...) at src/mongo/db/repl/storage_interface_impl.cpp:810
#27 0x000055b2047999f1 in mongo::repl::RollbackImpl::_findDocumentById (this=<optimized out>, opCtx=0x55b20c7dfdc0, uuid="4e3f99dc-904a-451f-af3b-2f30032e67a1", nss=..., id=...) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/bits/char_traits.h:285
#28 0x000055b20479aeb4 in mongo::repl::RollbackImpl::_writeRollbackFileForNamespace (this=this@entry=0x55b2108b1000, opCtx=opCtx@entry=0x55b20c7dfdc0, uuid="4e3f99dc-904a-451f-af3b-2f30032e67a1", nss=..., idSet=absl::node_hash_set<mongo::BSONObj> with 1 elems  = {...}) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/bits/basic_string.h:927
#29 0x000055b20479a87b in mongo::repl::RollbackImpl::_writeRollbackFiles (this=0x55b2108b1000, opCtx=0x55b20c7dfdc0) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/bits/basic_string.h:927
#30 0x000055b20479f266 in mongo::repl::RollbackImpl::runRollback (this=0x55b2108b1000, opCtx=opCtx@entry=0x55b20c7dfdc0) at src/mongo/db/repl/rollback_impl.cpp:230
#31 0x000055b204774459 in mongo::repl::BackgroundSync::_runRollbackViaRecoverToCheckpoint(mongo::OperationContext*, mongo::HostAndPort const&, mongo::repl::OplogInterface*, mongo::repl::StorageInterface*, std::function<mongo::DBClientBase* ()>) (this=0x55b20c77d780, opCtx=0x55b20c7dfdc0, source=..., localOplog=<optimized out>, storageInterface=0x55b20800fcb0, getConnection=...) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/bits/unique_ptr.h:342
#32 0x000055b204775958 in mongo::repl::BackgroundSync::_runRollback (this=0x55b20c77d780, opCtx=0x55b20c7dfdc0, fetcherReturnStatus=..., source=..., requiredRBID=1, storageInterface=0x55b20800fcb0) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/bits/basic_string.h:927
#33 0x000055b2040c9533 in mongo::repl::BackgroundSync::_produce (this=0x55b20c77d780) at /opt/mongodbtoolchain/stow/gcc-v3.zr9/include/c++/8.2.0/bits/unique_ptr.h:342
#34 0x000055b204776030 in mongo::repl::BackgroundSync::_runProducer (this=0x55b20c77d780) at src/mongo/db/repl/bgsync.cpp:213
#35 0x000055b204776178 in mongo::repl::BackgroundSync::_run (this=0x55b20c77d780) at src/mongo/db/repl/bgsync.cpp:174
#36 0x000055b2060deb3f in std::execute_native_thread_routine (__p=0x55b20c199750) at ../../../../../src/combined/libstdc++-v3/src/c++11/thread.cc:80
#37 0x00007f0e32a9d6db in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#38 0x00007f0e327c688f in clone () from /lib/x86_64-linux-gnu/libc.so.6



 Comments   
Comment by Githook User [ 22/Apr/19 ]

Author:

{'email': 'vesselina.ratcheva@10gen.com', 'name': 'Vesselina Ratcheva', 'username': 'vessy-mongodb'}

Message: SERVER-40322 Prevent unnecessary prepare conflicts when writing out rollback files
Branch: master
https://github.com/mongodb/mongo/commit/d5f8a6a510d1f3db0ad7f737488979a751e9df95

Comment by Judah Schvimer [ 03/Apr/19 ]

My previous comment was not complete.

It is also not ideal that we are generating rollback files simply because we prepare a transaction on a document.

We do not generate rollback file data from prepare oplog entries.

If we commit a transaction on a document we have to generate rollback files for the ops in the transaction

We aren't processing commitTransaction oplog entries at all. We should be writing rollback files for changes made in a transaction and doing any other processing needed on the ops in the transaction.

This ticket should fix this or file a separate ticket for it.

This hang should only ever happen if we roll back ops like in the following sequence:
Common point at ts=1
ts=2: insert a:1 into collection foo
ts=3: prepare a transaction that updates or removes the document a:1 in collection foo

We will need to write rollback files for the non-transactional insert, but will get a prepare conflict from the prepared transaction on the document on retrieving the most recent version for the rollback files. Swapping the order of writing rollback files and aborting prepared transactions should fix this.

Comment by Siyuan Zhou [ 27/Mar/19 ]

judah.schvimer, thanks! SERVER-40365 is filed for that.

Comment by Judah Schvimer [ 27/Mar/19 ]

siyuan.zhou, Larger Transactions may also need to do some work here when the oplog format changes.

Comment by Judah Schvimer [ 27/Mar/19 ]

I think we should ignore prepare conflicts on reads for generating data files. We could also investigate creating rollback files after aborting prepared transactions, which is the next step in rollback. I do not think there is any ordering requirement between those two steps.

It is also not ideal that we are generating rollback files simply because we prepare a transaction on a document. If we commit a transaction on a document we have to generate rollback files for the ops in the transaction, but rolling back a prepare doesn't mean we actually rolled back a write, just the intention to maybe do a write. We should investigate the difficulty of fixing this, since we may be essentially saying we rolled back writes that were not guaranteed to commit.

max.hirschhorn, we can use the createRollbackDataFiles server parameter in the rollback fuzzer and test suites hitting this to get around this issue for now.

Generated at Thu Feb 08 04:54:38 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.