[SERVER-22011] Direct writes to the local database can cause deadlock involving the WiredTiger write throttle Created: 23/Dec/15  Updated: 04/Jan/17  Resolved: 01/Feb/16

Status: Closed
Project: Core Server
Component/s: Storage
Affects Version/s: 3.0.8, 3.2.0
Fix Version/s: 3.2.3, 3.3.2

Type: Bug Priority: Major - P3
Reporter: Kaloian Manassiev Assignee: Geert Bosch
Resolution: Done Votes: 0
Labels: code-and-test
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Duplicate
Related
related to SERVER-21859 The globalLock.currentQueue stat does... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Completed:
Sprint: Integration F (02/01/16), Integration 10 (02/22/16)
Participants:

 Description   

In MongoDB 3.0 we introduced the WiredTiger write throttle parameter, which limits the number of concurrent threads running inside the WT storage engine. The write throttle works by acquiring a 'ticket' just before entering in the WT storage engine and releasing the ticket when the WT transaction is done.

The write throttle tickets are in most cases acquired before the 'local' database is locked for replication writes. However, if an operation writes to the local database directly, the order of ticket acquisition reverses and the local database lock is acquired first.

Because of this reversal of the locking order, if there is sufficiently high write load and the number of available tickets is approaching zero, it is possible for a deadlock to occur between a thread which directly writes to the local database and a thread, which just acquired the last ticket. The default value for the WT write throttle is 128, so this would happen when the number of concurrent threads exceeds this value.

Once the server enters into this state, there is no way to get out of it without restarting it.

A preventative workaround (in the sense that it should be done before the issue occurs) is to increase the write throttle to a value, which is higher than the maximum projected write load. For example:

db.adminCommand({ setParameter: 1, wiredTigerConcurrentWriteTransactions: 4096 });

For more detail, here is a sequence of events which resulted in deadlocked threads:

Thread1 (already holds a ticket and waits on the local DB lock):

Thread 418 (Thread 0x7efc8ba6e700 (LWP 23482)):
#0  0x000000327fe0b7bb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000009cbe38 in mongo::CondVarLockGrantNotification::wait(unsigned int) ()
#2  0x00000000009d3133 in mongo::LockerImpl<false>::lockComplete(mongo::ResourceId, mongo::LockMode, unsigned int, bool) ()
#3  0x00000000009c55c7 in mongo::Lock::DBLock::DBLock(mongo::Locker*, mongo::StringData const&, mongo::LockMode) ()
#4  0x0000000000c9dc9b in ?? ()
#5  0x0000000000c9c477 in ?? ()
#6  0x0000000000c9c737 in mongo::repl::logOp(mongo::OperationContext*, char const*, char const*, mongo::BSONObj const&, mongo::BSONObj*, bool*, bool) ()
#7  0x00000000009bcd5f in mongo::WriteBatchExecutor::execOneInsert(mongo::WriteBatchExecutor::ExecInsertsState*, mongo::WriteErrorDetail**) ()
#8  0x00000000009bd9dd in mongo::WriteBatchExecutor::execInserts(mongo::BatchedCommandRequest const&, mongo::WriteConcernOptions const&, std::vector<mongo::WriteErrorDetail*, std::allocator<mongo::WriteErrorDetail*> >*) ()
#9  0x00000000009bf959 in mongo::WriteBatchExecutor::bulkExecute(mongo::BatchedCommandRequest const&, mongo::WriteConcernOptions const&, std::vector<mongo::BatchedUpsertDetail*, std::allocator<mongo::BatchedUpsertDetail*> >*, std::vector<mongo::WriteErr
orDetail*, std::allocator<mongo::WriteErrorDetail*> >*) ()
#10 0x00000000009c0185 in mongo::WriteBatchExecutor::executeBatch(mongo::BatchedCommandRequest const&, mongo::BatchedCommandResponse*) ()
#11 0x00000000009c2e6c in mongo::WriteCmd::run(mongo::OperationContext*, std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, mongo::BSONObj&, int, std::basic_string<char, std::char_traits<char>, std::allocator<char> >&, mongo:
:BSONObjBuilder&, bool) ()
#12 0x00000000009e5e81 in mongo::_execCommand(mongo::OperationContext*, mongo::Command*, std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, mongo::BSONObj&, int, std::basic_string<char, std::char_traits<char>, std::allocator<
char> >&, mongo::BSONObjBuilder&, bool) ()
#13 0x00000000009e6e9c in mongo::Command::execCommand(mongo::OperationContext*, mongo::Command*, int, char const*, mongo::BSONObj&, mongo::BSONObjBuilder&, bool) ()
#14 0x00000000009e7b6b in mongo::_runCommands(mongo::OperationContext*, char const*, mongo::BSONObj&, mongo::_BufBuilder<mongo::TrivialAllocator>&, mongo::BSONObjBuilder&, bool, int) ()
#15 0x0000000000bfebcb in mongo::runQuery(mongo::OperationContext*, mongo::Message&, mongo::QueryMessage&, mongo::NamespaceString const&, mongo::CurOp&, mongo::Message&) ()
#16 0x0000000000ad0752 in mongo::assembleResponse(mongo::OperationContext*, mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&) ()
#17 0x0000000000809935 in mongo::MyMessageHandler::process(mongo::Message&, mongo::AbstractMessagingPort*, mongo::LastError*) ()
#18 0x0000000000f93a19 in mongo::PortMessageServer::handleIncomingMsg(void*) ()
#19 0x000000327fe07851 in start_thread () from /lib64/libpthread.so.0

Thread2 (holds the local DB lock and waits on a ticket):

Thread 417 (Thread 0x7efc8b96d700 (LWP 23525)):
#0  0x000000327fe0d720 in sem_wait () from /lib64/libpthread.so.0
#1  0x0000000000f75b24 in mongo::TicketHolder::waitForTicket() ()
#2  0x0000000000def990 in mongo::WiredTigerRecoveryUnit::_getTicket(mongo::OperationContext*) ()
#3  0x00000000009bcbff in mongo::WriteBatchExecutor::execOneInsert(mongo::WriteBatchExecutor::ExecInsertsState*, mongo::WriteErrorDetail**) ()
#4  0x00000000009bd9dd in mongo::WriteBatchExecutor::execInserts(mongo::BatchedCommandRequest const&, mongo::WriteConcernOptions const&, std::vector<mongo::WriteErrorDetail*, std::allocator<mongo::WriteErrorDetail*> >*) ()
#5  0x00000000009bf959 in mongo::WriteBatchExecutor::bulkExecute(mongo::BatchedCommandRequest const&, mongo::WriteConcernOptions const&, std::vector<mongo::BatchedUpsertDetail*, std::allocator<mongo::BatchedUpsertDetail*> >*, std::vector<mongo::WriteErr
orDetail*, std::allocator<mongo::WriteErrorDetail*> >*) ()
#6  0x00000000009c0185 in mongo::WriteBatchExecutor::executeBatch(mongo::BatchedCommandRequest const&, mongo::BatchedCommandResponse*) ()
#7  0x00000000009c2e6c in mongo::WriteCmd::run(mongo::OperationContext*, std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, mongo::BSONObj&, int, std::basic_string<char, std::char_traits<char>, std::allocator<char> >&, mongo:
:BSONObjBuilder&, bool) ()
#8  0x00000000009e5e81 in mongo::_execCommand(mongo::OperationContext*, mongo::Command*, std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, mongo::BSONObj&, int, std::basic_string<char, std::char_traits<char>, std::allocator<
char> >&, mongo::BSONObjBuilder&, bool) ()
#9  0x00000000009e6e9c in mongo::Command::execCommand(mongo::OperationContext*, mongo::Command*, int, char const*, mongo::BSONObj&, mongo::BSONObjBuilder&, bool) ()
#10 0x00000000009e7b6b in mongo::_runCommands(mongo::OperationContext*, char const*, mongo::BSONObj&, mongo::_BufBuilder<mongo::TrivialAllocator>&, mongo::BSONObjBuilder&, bool, int) ()
#11 0x0000000000bfebcb in mongo::runQuery(mongo::OperationContext*, mongo::Message&, mongo::QueryMessage&, mongo::NamespaceString const&, mongo::CurOp&, mongo::Message&) ()
#12 0x0000000000ad0752 in mongo::assembleResponse(mongo::OperationContext*, mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&) ()
#13 0x0000000000809935 in mongo::MyMessageHandler::process(mongo::Message&, mongo::AbstractMessagingPort*, mongo::LastError*) ()
#14 0x0000000000f93a19 in mongo::PortMessageServer::handleIncomingMsg(void*) ()
#15 0x000000327fe07851 in start_thread () from /lib64/libpthread.so.0

Thread3 (blocked behind Thread1, because it acquires the database lock in S mode):

Thread 1383 (Thread 0x7f0d432ed700 (LWP 54124)):
#0  0x000000327fe0b7bb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000009cbe38 in mongo::CondVarLockGrantNotification::wait(unsigned int) ()
#2  0x00000000009d3133 in mongo::LockerImpl<false>::lockComplete(mongo::ResourceId, mongo::LockMode, unsigned int, bool) ()
#3  0x00000000009c55c7 in mongo::Lock::DBLock::DBLock(mongo::Locker*, mongo::StringData const&, mongo::LockMode) ()
#4  0x0000000000935681 in mongo::AutoGetDb::AutoGetDb(mongo::OperationContext*, mongo::StringData const&, mongo::LockMode) ()
#5  0x00000000009ea511 in mongo::DBStats::run(mongo::OperationContext*, std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, mongo::BSONObj&, int, std::basic_string<char, std::char_traits<char>, std::allocator<char> >&, mongo::BSONObjBuilder&, bool) ()
#6  0x00000000009e5e81 in mongo::_execCommand(mongo::OperationContext*, mongo::Command*, std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, mongo::BSONObj&, int, std::basic_string<char, std::char_traits<char>, std::allocator<char> >&, mongo::BSONObjBuilder&, bool) ()
#7  0x00000000009e6e9c in mongo::Command::execCommand(mongo::OperationContext*, mongo::Command*, int, char const*, mongo::BSONObj&, mongo::BSONObjBuilder&, bool) ()
#8  0x00000000009e7b6b in mongo::_runCommands(mongo::OperationContext*, char const*, mongo::BSONObj&, mongo::_BufBuilder<mongo::TrivialAllocator>&, mongo::BSONObjBuilder&, bool, int) ()
#9  0x0000000000bfebcb in mongo::runQuery(mongo::OperationContext*, mongo::Message&, mongo::QueryMessage&, mongo::NamespaceString const&, mongo::CurOp&, mongo::Message&) ()
#10 0x0000000000ad0752 in mongo::assembleResponse(mongo::OperationContext*, mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&) ()
#11 0x0000000000809935 in mongo::MyMessageHandler::process(mongo::Message&, mongo::AbstractMessagingPort*, mongo::LastError*) ()
#12 0x0000000000f93a19 in mongo::PortMessageServer::handleIncomingMsg(void*) ()
#13 0x000000327fe07851 in start_thread () from /lib64/libpthread.so.0



 Comments   
Comment by Jianghua Yang [ 04/Jan/17 ]

@Thomas Schubert , Thanks. I try some load testing on workloadc,the result shows 128 was right chosen。

Comment by Kelsey Schubert [ 03/Jan/17 ]

Hi yjhjstz,

128 was chosen as the default WT write throttle during load testing and is meant to serve as a conservative "backstop" to prevent the engine from being overwhelmed. By "conservative", I mean that it is unlikely to hurt users with beefy machines. In our testing, we continue to see that these values provide significant benefit for certain workloads.

Kind regards,
Thomas

Comment by Jianghua Yang [ 23/Dec/16 ]

why the default value for the WT write throttle is 128 ?

Comment by Ramon Fernandez Marina [ 24/Feb/16 ]

The fix for the v3.0 branch needs more investigation, so it won't make it into 3.0.10 – pushing it to a later release.

Comment by Githook User [ 02/Feb/16 ]

Author:

{u'username': u'GeertBosch', u'name': u'Geert Bosch', u'email': u'geert@mongodb.com'}

Message: SERVER-22011: Obtain tickets at outermost global lock in WT

(cherry picked from commit 2969c83e3dcd4ca26e81b27454938e1c2aa7fe53)
Branch: v3.2
https://github.com/mongodb/mongo/commit/9e55fe2085f8627ae7791b8a4b55e0c6114feac3

Comment by Githook User [ 01/Feb/16 ]

Author:

{u'username': u'GeertBosch', u'name': u'Geert Bosch', u'email': u'geert@mongodb.com'}

Message: SERVER-22011: Obtain tickets at outermost global lock in WT
Branch: master
https://github.com/mongodb/mongo/commit/2969c83e3dcd4ca26e81b27454938e1c2aa7fe53

Comment by Daniel Pasette (Inactive) [ 23/Dec/15 ]

Simple repro:

  1. mongod --replSet dan --setParameter wiredTigerConcurrentWriteTransactions=1
  2. loop of writes to a capped collection in test db
  3. loop of writes to a capped collection in local db
  4. use local; while(1) {printjson(db.stats());sleep(1);}
Generated at Thu Feb 08 03:59:08 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.