[SERVER-16428] WT session mutex is highly contented Created: 05/Dec/14  Updated: 18/Dec/14  Resolved: 17/Dec/14

Status: Closed
Project: Core Server
Component/s: Concurrency, Performance, Storage
Affects Version/s: 2.8.0-rc2
Fix Version/s: 2.8.0-rc3

Type: Bug Priority: Major - P3
Reporter: Davide Italiano Assignee: Kaloian Manassiev
Resolution: Done Votes: 0
Labels: 28qa
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File session.png    
Issue Links:
Related
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

As the title suggests. It's the hottest mutex in mongo-WT at the time of writing for some workloads (e.g. sysbench). I'm attaching some stacktraces to give better sense of the caller(s), together with percentages of time the lock is held.
Also, the VTune attached output shows up how the wait time on this lock is more than an order on magnitude than the second more contested lock.

Waiting Call Stack
1 of 22: 27.1% (1977.143s of 7292.660s)
 
mongod!lock+0x7 - mutex.hpp:59
mongod!lock+0 - locks.hpp:412
mongod!unique_lock+0 - locks.hpp:290
mongod!unlock_shared+0 - shared_mutex.hpp:108
mongod!~shared_lock+0 - locks.hpp:656
mongod!mongo::WiredTigerSessionCache::releaseSession+0x2c8 - wiredtiger_session_cache.cpp:187
mongod!mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit+0x34 - wiredtiger_recovery_unit.cpp:90
mongod!mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit+0x8 - wiredtiger_recovery_unit.cpp:93
mongod!~auto_ptr+0xe - auto_ptr.h:170
mongod!mongo::OperationContextImpl::~OperationContextImpl+0x2c - operation_context_impl.cpp:69
mongod!mongo::MyMessageHandler::process+0x5c2 - db.cpp:223
mongod!mongo::PortMessageServer::handleIncomingMsg+0x410 - message_server_port.cpp:234
libpthread-2.18.so!start_thread+0xc2 - [Unknown]:[Unknown]
libc-2.18.so!__clone+0x6c - [Unknown]:[Unknown]

Waiting Call Stack
2 of 22: 23.5% (1716.518s of 7292.660s)
 
mongod!lock+0x7 - mutex.hpp:59
mongod!lock+0 - locks.hpp:412
mongod!unique_lock+0xe - locks.hpp:290
mongod!lock_shared+0x18 - shared_mutex.hpp:60
mongod!lock+0 - locks.hpp:665
mongod!shared_lock+0 - locks.hpp:545
mongod!mongo::WiredTigerSessionCache::releaseSession+0x2a - wiredtiger_session_cache.cpp:181
mongod!mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit+0x34 - wiredtiger_recovery_unit.cpp:90
mongod!mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit+0x8 - wiredtiger_recovery_unit.cpp:93
mongod!~auto_ptr+0xe - auto_ptr.h:170
mongod!mongo::OperationContextImpl::~OperationContextImpl+0x2c - operation_context_impl.cpp:69
mongod!mongo::MyMessageHandler::process+0x5c2 - db.cpp:223
mongod!mongo::PortMessageServer::handleIncomingMsg+0x410 - message_server_port.cpp:234
libpthread-2.18.so!start_thread+0xc2 - [Unknown]:[Unknown]
libc-2.18.so!__clone+0x6c - [Unknown]:[Unknown]

Waiting Call Stack
3 of 22: 14.9% (1085.382s of 7292.660s)
 
mongod!lock+0x7 - mutex.hpp:59
mongod!lock+0 - locks.hpp:412
mongod!unique_lock+0 - locks.hpp:290
mongod!~shared_lock+0 - locks.hpp:656
mongod!mongo::WiredTigerSessionCache::getSession+0x327 - wiredtiger_session_cache.cpp:174
mongod!mongo::WiredTigerRecoveryUnit::getSession+0x38 - wiredtiger_recovery_unit.cpp:179
mongod!mongo::WiredTigerCursor::_init+0x1f - wiredtiger_recovery_unit.cpp:251
mongod!mongo::WiredTigerIndex::IndexCursor::IndexCursor+0x32 - wiredtiger_index.cpp:603
mongod!mongo::WiredTigerIndex::newCursor+0x39 - wiredtiger_index.cpp:397
mongod!mongo::BtreeBasedAccessMethod::findSingle+0x24 - btree_based_access_method.cpp:210
mongod!mongo::IDHackStage::work+0xeb - idhack.cpp:123
mongod!mongo::ProjectionStage::work+0x4d - projection.cpp:208
mongod!mongo::PlanExecutor::getNext+0x99 - plan_executor.cpp:288
mongod!mongo::runQuery+0xa93 - find.cpp:713
mongod!receivedQuery+0x1e4 - instance.cpp:221
mongod!mongo::assembleResponse+0x940 - instance.cpp:391
mongod!mongo::MyMessageHandler::process+0xdf - db.cpp:194
mongod!mongo::PortMessageServer::handleIncomingMsg+0x410 - message_server_port.cpp:234
libpthread-2.18.so!start_thread+0xc2 - [Unknown]:[Unknown]
libc-2.18.so!__clone+0x6c - [Unknown]:[Unknown]

Waiting Call Stack
4 of 22: 13.1% (955.371s of 7292.660s)
 
mongod!lock+0x7 - mutex.hpp:59
mongod!lock+0 - locks.hpp:412
mongod!unique_lock+0xe - locks.hpp:290
mongod!lock_shared+0x23 - shared_mutex.hpp:60
mongod!lock+0 - locks.hpp:665
mongod!shared_lock+0 - locks.hpp:545
mongod!mongo::WiredTigerSessionCache::getSession+0x7 - wiredtiger_session_cache.cpp:157
mongod!mongo::WiredTigerRecoveryUnit::getSession+0x38 - wiredtiger_recovery_unit.cpp:179
mongod!mongo::WiredTigerCursor::_init+0x1f - wiredtiger_recovery_unit.cpp:251
mongod!mongo::WiredTigerIndex::IndexCursor::IndexCursor+0x32 - wiredtiger_index.cpp:603
mongod!mongo::WiredTigerIndex::newCursor+0x39 - wiredtiger_index.cpp:397
mongod!mongo::BtreeBasedAccessMethod::findSingle+0x24 - btree_based_access_method.cpp:210
mongod!mongo::IDHackStage::work+0xeb - idhack.cpp:123
mongod!mongo::ProjectionStage::work+0x4d - projection.cpp:208
mongod!mongo::PlanExecutor::getNext+0x99 - plan_executor.cpp:288
mongod!mongo::runQuery+0xa93 - find.cpp:713
mongod!receivedQuery+0x1e4 - instance.cpp:221
mongod!mongo::assembleResponse+0x940 - instance.cpp:391
mongod!mongo::MyMessageHandler::process+0xdf - db.cpp:194
mongod!mongo::PortMessageServer::handleIncomingMsg+0x410 - message_server_port.cpp:234
libpthread-2.18.so!start_thread+0xc2 - [Unknown]:[Unknown]
libc-2.18.so!__clone+0x6c - [Unknown]:[Unknown]

Waiting Call Stack
5 of 22: 2.7% (194.191s of 7292.660s)
 
mongod!lock+0x7 - mutex.hpp:59
mongod!lock+0 - locks.hpp:412
mongod!unique_lock+0 - locks.hpp:290
mongod!~shared_lock+0 - locks.hpp:656
mongod!mongo::WiredTigerSessionCache::getSession+0x327 - wiredtiger_session_cache.cpp:174
mongod!mongo::WiredTigerRecoveryUnit::getSession+0x38 - wiredtiger_recovery_unit.cpp:179
mongod!mongo::WiredTigerCursor::_init+0x1f - wiredtiger_recovery_unit.cpp:251
mongod!mongo::WiredTigerIndex::IndexCursor::IndexCursor+0x32 - wiredtiger_index.cpp:603
mongod!mongo::WiredTigerIndex::newCursor+0x39 - wiredtiger_index.cpp:397
mongod!mongo::BtreeBasedAccessMethod::findSingle+0x24 - btree_based_access_method.cpp:210
mongod!mongo::IDHackStage::work+0xeb - idhack.cpp:123
mongod!mongo::UpdateStage::work+0x7b - update.cpp:706
mongod!mongo::PlanExecutor::getNext+0x99 - plan_executor.cpp:288
mongod!mongo::PlanExecutor::executePlan+0x3c - plan_executor.cpp:400
mongod!mongo::UpdateExecutor::execute+0x131 - update_executor.cpp:237
mongod!multiUpdate+0x411 - batch_executor.cpp:1277
mongod!mongo::WriteBatchExecutor::execUpdate+0x79 - batch_executor.cpp:891
mongod!mongo::WriteBatchExecutor::bulkExecute+0x1f1 - batch_executor.cpp:761
mongod!mongo::WriteBatchExecutor::executeBatch+0x394 - batch_executor.cpp:262
mongod!mongo::WriteCmd::run+0x172 - write_commands.cpp:144
mongod!mongo::_execCommand+0x33 - dbcommands.cpp:1231
mongod!mongo::Command::execCommand+0xc24 - dbcommands.cpp:1445
mongod!mongo::_runCommands+0x289 - dbcommands.cpp:1520
mongod!runCommands+0x32 - find.cpp:131
mongod!mongo::runQuery+0x4a - find.cpp:527
mongod!receivedQuery+0x1e4 - instance.cpp:221
mongod!mongo::assembleResponse+0x940 - instance.cpp:391
mongod!mongo::MyMessageHandler::process+0xdf - db.cpp:194
mongod!mongo::PortMessageServer::handleIncomingMsg+0x410 - message_server_port.cpp:234
libpthread-2.18.so!start_thread+0xc2 - [Unknown]:[Unknown]
libc-2.18.so!__clone+0x6c - [Unknown]:[Unknown]



 Comments   
Comment by Githook User [ 17/Dec/14 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-16428 Partition the WT session cache
Branch: master
https://github.com/mongodb/mongo/commit/26d1d8d654693540f690a70077e0f0141e1e4cce

Comment by Githook User [ 11/Dec/14 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-16428 Recovery units should not know about OpCtx
Branch: master
https://github.com/mongodb/mongo/commit/0279923636be460e3027152d83ed1c790cd536fc

Generated at Thu Feb 08 03:41:01 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.