Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-16428

WT session mutex is highly contented

    XMLWordPrintable

    Details

    • Backwards Compatibility:
      Fully Compatible
    • Operating System:
      ALL

      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]

        Attachments

          Activity

            People

            Assignee:
            kaloian.manassiev Kaloian Manassiev
            Reporter:
            davide.italiano Davide Italiano
            Participants:
            Votes:
            0 Vote for this issue
            Watchers:
            9 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: