Deadlock over TxRecoveryManager lock

Description

While tracking down problems with crash recovery in Jonathan's test case, I found a deadlock involving the TxRecoveryManager lock. One thread is trying to perform transaction recovery and owns the lock. It has called down through TxRecoveryManager::RecoveryTask:erformTask to sendDecisionRpc and on into ObjectFinder::lookup to find the object. The object in question happens to be in a table that was on the crashed server, so ObjectFinder keeps calling the coordinator with a getTableConfig RPC to find out where the object ends up after recovery. However, this call can't complete until recovery completes, and meanwhile this thread is holding the TxRecoveryManager lock.

At the same time, the same server is also one of the recovery Masters. It is replaying the log, found a transaction-related entry, and invoked TxRecoveryManager::recoverRecovery. This method is now looping, trying to acquire the lock. Thus, recovery can't complete.
Here arethe stack traces for the two threads:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 #0 0x00000000007d356c in RAMCloud::RpcWrapper::getState (this=0x7fc55cefa660) at /home/ouster/remote/ramcloud/src/RpcWrapper.h:202 #1 0x00000000008da77a in RAMCloud::RpcWrapper::isReady (this=0x7fc55cefa660) at /home/ouster/remote/ramcloud/src/RpcWrapper.cc:156 #2 0x00000000008db38b in RAMCloud::RpcWrapper::waitInternal ( this=0x7fc55cefa660, dispatch=0x23b79f0, abortTime=18446744073709551615) at /home/ouster/remote/ramcloud/src/RpcWrapper.cc:374 #3 0x00000000007d7ae6 in RAMCloud::GetTableConfigRpc::wait ( this=0x7fc55cefa660, tableConfig=0x7fc55cefafd0) at /home/ouster/remote/ramcloud/src/CoordinatorClient.cc:432 #4 0x00000000007d79ec in RAMCloud::CoordinatorClient::getTableConfig ( context=0x7ffe2616b5b0, tableId=2, tableConfig=0x7fc55cefafd0) at /home/ouster/remote/ramcloud/src/CoordinatorClient.cc:396 #5 0x000000000088698f in RAMCloud::RealTableConfigFetcher::getTableConfig ( this=0x23ba150, tableId=2, tableMap=0x23b7388, tableIndexMap=0x23b73b8) at /home/ouster/remote/ramcloud/src/ObjectFinder.cc:43 #6 0x0000000000885a41 in RAMCloud::ObjectFinder::lookupTablet ( this=0x23b7380, tableId=2, keyHash=4910609688264772) at /home/ouster/remote/ramcloud/src/ObjectFinder.cc:370 #7 0x0000000000885539 in RAMCloud::ObjectFinder::lookup (this=0x23b7380, tableId=2, keyHash=4910609688264772) at /home/ouster/remote/ramcloud/src/ObjectFinder.cc:232 #8 0x000000000091d361 in RAMCloud::TxRecoveryManager::RecoveryTask::sendDecisionRpc (this=0x7fc55007b660) at /home/ouster/remote/ramcloud/src/TxRecoveryManager.cc:549 #9 0x000000000091c9f3 in RAMCloud::TxRecoveryManager::RecoveryTask::performTask (this=0x7fc55007b660) at /home/ouster/remote/ramcloud/src/TxRecoveryManager.cc:306 #10 0x000000000091be92 in RAMCloud::TxRecoveryManager::handleTimerEvent ( this=0x7ffe26176b70) at /home/ouster/remote/ramcloud/src/TxRecoveryManager.cc:55 #11 0x00000000009308f2 in RAMCloud::WorkerTimer::Manager::checkTimers ( this=0x30d7b30, lock=...) at /home/ouster/remote/ramcloud/src/WorkerTimer.cc:291 #12 0x00000000009309e4 in RAMCloud::WorkerTimer::Manager::workerThreadMain ( manager=0x30d7b30) at /home/ouster/remote/ramcloud/src/WorkerTimer.cc:313 #13 0x0000000000933a48 in std::_Bind_simple<void (*(RAMCloud::WorkerTimer::Manager*))(RAMCloud::WorkerTimer::Manager*)>::_M_invoke<0ul>(std::_Index_tuple<0ul>) (this=0x30d7c18) at /usr/include/c++/4.9/functional:1700 #14 0x0000000000933941 in std::_Bind_simple<void (*(RAMCloud::WorkerTimer::Manager*))(RAMCloud::WorkerTimer::Manager*)>::operator()() (this=0x30d7c18) at /usr/include/c++/4.9/functional:1688 #15 0x00000000009338be in std::thread::_Impl<std::_Bind_simple<void (*(RAMCloud::WorkerTimer::Manager*))(RAMCloud::WorkerTimer::Manager*)> >::_M_run() ( this=0x30d7c00) at /usr/include/c++/4.9/thread:115 #16 0x00007fc58ac31970 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6 #17 0x00007fc58b9040a4 in start_thread (arg=0x7fc55cefc700) at pthread_create.c:309 #18 0x00007fc58a3a104d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 #0 0x00000000008fc58c in RAMCloud::SpinLock::lock (this=0x7ffe26176bd8) at /home/ouster/remote/ramcloud/src/SpinLock.cc:98 #1 0x000000000078aa5e in std::lock_guard<RAMCloud::SpinLock>::lock_guard ( this=0x7fc55e17c0a0, __m=...) at /usr/include/c++/4.9/mutex:377 #2 0x000000000091c388 in RAMCloud::TxRecoveryManager::recoverRecovery ( this=0x7ffe26176b70, record=...) at /home/ouster/remote/ramcloud/src/TxRecoveryManager.cc:152 #3 0x000000000088dbfb in RAMCloud::ObjectManager::replaySegment ( this=0x7ffe2616ba30, sideLog=0x7fc55e17d790, it=..., nextNodeIdMap=0x7fc55e181730) at /home/ouster/remote/ramcloud/src/ObjectManager.cc:1062 #4 0x00000000008619a2 in RAMCloud::MasterService::recover ( this=0x7ffe2616ba10, recoveryId=13827232012829796904, masterId=..., partitionId=0, replicas=std::vector of length 2, capacity 2 = {...}, nextNodeIdMap=std::unordered_map with 0 elements) at /home/ouster/remote/ramcloud/src/MasterService.cc:3431 #5 0x00000000008642b8 in RAMCloud::MasterService::recover ( this=0x7ffe2616ba10, reqHdr=0x7fc56f1a9008, respHdr=0x7fc54c6fbd74, rpc=0x7fc55e182a70) at /home/ouster/remote/ramcloud/src/MasterService.cc:3667 #6 0x00000000008693d9 in RAMCloud::Service::callHandler<RAMCloud::WireFormat::Recover, RAMCloud::MasterService, &RAMCloud::MasterService::recover> ( this=0x7ffe2616ba10, rpc=0x7fc55e182a70) at /home/ouster/remote/ramcloud/src/Service.h:135 #7 0x0000000000855a16 in RAMCloud::MasterService::dispatch ( this=0x7ffe2616ba10, opcode=RAMCloud::WireFormat::RECOVER, rpc=0x7fc55e182a70) at /home/ouster/remote/ramcloud/src/MasterService.cc:253 #8 0x00000000008f4f26 in RAMCloud::Service::handleRpc ( context=0x7ffe2616b5b0, rpc=0x7fc55e182a70) at /home/ouster/remote/ramcloud/src/Service.cc:159 #9 0x0000000000929907 in RAMCloud::WorkerManager::workerMain ( worker=0x23c4ff0) at /home/ouster/remote/ramcloud/src/WorkerManager.cc:433 #10 0x000000000092e96e in std::_Bind_simple<void (*(RAMCloud::Worker*))(RAMCloud::Worker*)>::_M_invoke<0ul>(std::_Index_tuple<0ul>) (this=0x23d26c8) at /usr/include/c++/4.9/functional:1700 #11 0x000000000092e867 in std::_Bind_simple<void (*(RAMCloud::Worker*))(RAMCloud::Worker*)>::operator()() (this=0x23d26c8) at /usr/include/c++/4.9/functional:1688 #12 0x000000000092e7e4 in std::thread::_Impl<std::_Bind_simple<void (*(RAMCloud::Worker*))(RAMCloud::Worker*)> >::_M_run() (this=0x23d26b0) at /usr/include/c++/4.9/thread:115 #13 0x00007fc58ac31970 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6 #14 0x00007fc58b9040a4 in start_thread (arg=0x7fc55e183700) at pthread_create.c:309 #15 0x00007fc58a3a104d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Environment

None

Status

Assignee

John Ousterhout

Reporter

John Ousterhout

Labels

None

Priority

Medium
Configure