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

Collection creation during final phase of checkpoint holds database lock for extended time

XMLWordPrintableJSON

    • Fully Compatible
    • ALL

      Here's an example:

      • At B we see an operation acquring the db lock (acquireCount)
      • Apparently that operation blocks because we see many threads queuing up behind it (timeAcquiringMicros), resulting in a complete stall in this case (single db)
      • This has occurred during the final phase of a checkpoint (range of IDs pinned), and ends at the end of the checkpoint
      • In the same app (not shown above) we see other create collections during a checkpoint, but not during the final phase, that do not cause a similar stall, so this appears to be specific to the final phase of a checkpoint.

      Stack traces collected during the stall show that the blocked operation is a create collection (this was not evident from the stats and required stack traces because this was an implicit create and we don't have a counter for that), and that it is blocked in __wt_session_create:

      00000063`18cac488 00007ffc`4b93dd39 ntdll!ZwWaitForSingleObject+0xa
00000063`18cac490 00007ffc`4b93b704 ntdll!RtlLockHeap+0x169
00000063`18cac560 00007ff7`ef7e827d ntdll!RtlEnterCriticalSection+0xe4
00000063`18cac5a0 00007ff7`ef7e4bbc mongod!__wt_session_create+0x8d
00000063`18cac5d0 00007ff7`ef18c88b mongod!__session_create+0x19c
00000063`18cac630 00007ff7`ef11dae1 mongod!mongo::WiredTigerKVEngine::createRecordStore+0x26b
00000063`18cac860 00007ff7`eed76f75 mongod!mongo::KVDatabaseCatalogEntry::createCollection+0x321
00000063`18cacb00 00007ff7`eee03b13 mongod!mongo::Database::createCollection+0x4b5
00000063`18cacdb0 00007ff7`eee06a1f mongod!mongo::WriteBatchExecutor::ExecInsertsState::_lockAndCheckImpl+0x563
00000063`18cad130 00007ff7`eee06714 mongod!mongo::insertOne+0x14f
00000063`18cad2c0 00007ff7`eee05316 mongod!mongo::WriteBatchExecutor::insertMany+0x164
00000063`18cad390 00007ff7`eee04654 mongod!mongo::WriteBatchExecutor::execInserts+0x1b6
00000063`18cad510 00007ff7`eee05bba mongod!mongo::WriteBatchExecutor::bulkExecute+0xd4
00000063`18cad610 00007ff7`eee0b6d1 mongod!mongo::WriteBatchExecutor::executeBatch+0x3ca
00000063`18cad960 00007ff7`eee2394e mongod!mongo::WriteCmd::run+0x1a1
00000063`18cadb90 00007ff7`eee1ee0e mongod!mongo::Command::run+0x74e
00000063`18cadf70 00007ff7`eed9a717 mongod!mongo::Command::execCommand+0x8ae
00000063`18cae3d0 00007ff7`eeeeb897 mongod!mongo::runCommands+0x297
00000063`18cae6a0 00007ff7`eeee776c mongod!mongo::receivedCommand+0x207
00000063`18caea60 00007ff7`ef81221e mongod!mongo::assembleResponse+0x90c
00000063`18caf160 00007ff7`ef2e57f7 mongod!mongo::MyMessageHandler::process+0xce
00000063`18caf380 00007ff7`ef016bdd mongod!mongo::PortMessageServer::handleIncomingMsg+0x4a7

      Stack traces also confirm multiple threads queued up behind db lock:

      00000063`18bacde8 00007ffc`48b21118 ntdll!ZwWaitForSingleObject+0xa
00000063`18bacdf0 00007ffc`2748744f KERNELBASE!WaitForSingleObjectEx+0x98
00000063`18bace90 00007ffc`2748515b msvcr120!CRT_RTC_INITW+0x3af
00000063`18baced0 00007ffc`2cfac8c6 msvcr120!Concurrency::details::_Condition_variable::wait_for+0x1ab
00000063`18bacf90 00007ff7`eee1673f msvcp120!Call_onceEx+0xe2
00000063`18bad000 00007ff7`eee1504b mongod!mongo::CondVarLockGrantNotification::wait+0xef
00000063`18bad0a0 00007ff7`eee144e7 mongod!mongo::LockerImpl<0>::lockComplete+0x8b
00000063`18bad250 00007ff7`eee0c725 mongod!mongo::LockerImpl<0>::lock+0x57
00000063`18bad290 00007ff7`eee02cec mongod!mongo::Lock::DBLock::DBLock+0x155
00000063`18bad300 00007ff7`eee036ea mongod!std::make_unique<mongo::Lock::DBLock,mongo::Locker * __ptr64,mongo::StringData,enum mongo::LockMode>+0x5c
00000063`18bad360 00007ff7`eee06a1f mongod!mongo::WriteBatchExecutor::ExecInsertsState::_lockAndCheckImpl+0x13a
00000063`18bad6e0 00007ff7`eee06714 mongod!mongo::insertOne+0x14f
00000063`18bad870 00007ff7`eee05316 mongod!mongo::WriteBatchExecutor::insertMany+0x164
00000063`18bad940 00007ff7`eee04654 mongod!mongo::WriteBatchExecutor::execInserts+0x1b6
00000063`18badac0 00007ff7`eee05bba mongod!mongo::WriteBatchExecutor::bulkExecute+0xd4
00000063`18badbc0 00007ff7`eee0b6d1 mongod!mongo::WriteBatchExecutor::executeBatch+0x3ca
00000063`18badf10 00007ff7`eee2394e mongod!mongo::WriteCmd::run+0x1a1
00000063`18bae140 00007ff7`eee1ee0e mongod!mongo::Command::run+0x74e
00000063`18bae520 00007ff7`eed9a717 mongod!mongo::Command::execCommand+0x8ae
00000063`18bae980 00007ff7`eeeeb897 mongod!mongo::runCommands+0x297
00000063`18baec50 00007ff7`eeee776c mongod!mongo::receivedCommand+0x207
00000063`18baf010 00007ff7`ef81221e mongod!mongo::assembleResponse+0x90c
00000063`18baf710 00007ff7`ef2e57f7 mongod!mongo::MyMessageHandler::process+0xce
00000063`18baf930 00007ff7`ef016bdd mongod!mongo::PortMessageServer::handleIncomingMsg+0x4a7

        1. create-stall.png
          create-stall.png
          165 kB

            Assignee:
            michael.cahill@mongodb.com Michael Cahill (Inactive)
            Reporter:
            bruce.lucas@mongodb.com Bruce Lucas (Inactive)
            Votes:
            2 Vote for this issue
            Watchers:
            18 Start watching this issue

              Created:
              Updated:
              Resolved: