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

thread convoys from WiredTigerRecoveryUnit::registerChange

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.0.0-rc8
    • Component/s: Storage, WiredTiger
    • Labels:
      None

      This occurs with the WiredTiger btree with 10 user threads. I see frequent cases where most threads are stalled in pthread_mutex_timedlock which appears to be in g++/STL code. AFAIK, STL has something to cache allocations that the environment variable GLIBCXXX_FORCE_NEW=1 might disable.

      Can WiredTiger do something to reduce pressure on the STL allocator from the use of WiredTigerRecoverUnit::_changes which is:
      typedef OwnedPointerVector<Change> Changes;
      Changes _changes;

      I have yet to notice this problem in RocksDB, but maybe pressure on the allocator from other code triggers the problems for WiredTiger.

      The common thread stack with 3.0 rc8 is:

      __lll_timedlock_wait,pthread_mutex_timedlock,deallocate,deallocate,_M_deallocate,_M_emplace_back_aux<mongo::RecoveryUnit::Change*,push_back,push_back,mongo::WiredTigerRecoveryUnit::registerChange,mongo::WiredTigerRecordStore::_increaseDataSize,mongo::WiredTigerRecordStore::insertRecord,mongo::WiredTigerRecordStore::insertRecord,mongo::Collection::insertDocument,mongo::repl::(anonymous,mongo::repl::logOp,singleInsert,insertOne,mongo::WriteBatchExecutor::execOneInsert,mongo::WriteBatchExecutor::execInserts,mongo::WriteBatchExecutor::bulkExecute,mongo::WriteBatchExecutor::executeBatch,mongo::WriteCmd::run,mongo::_execCommand,mongo::Command::execCommand,mongo::_runCommands,runCommands,mongo::runQuery,receivedQuery,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone

      #0  0x00007f752d406d8c in __lll_timedlock_wait () from /foo/gcc-4.9-glibc-2.20/lib/libpthread.so.0
#1  0x00007f752d401abc in pthread_mutex_timedlock () from /foo/gcc-4.9-glibc-2.20/lib/libpthread.so.0
#2  0x0000000000f7265e in deallocate (this=0x7f752c585eee <__PRETTY_FUNCTION__.6239+5>, __p=<optimized out>) at /bar/third-party2/gcc/x/4.9.x/centos6-native/1317bc4/include/c++/4.9.x-google/ext/new_allocator.h:116
#3  deallocate (__a=..., __n=<optimized out>, __p=<optimized out>) at /bar/third-party2/gcc/x/4.9.x/centos6-native/1317bc4/include/c++/4.9.x-google/bits/alloc_traits.h:383
#4  _M_deallocate (this=0x7f752c585eee <__PRETTY_FUNCTION__.6239+5>, __n=<optimized out>, __p=<optimized out>) at /bar/third-party2/gcc/x/4.9.x/centos6-native/1317bc4/include/c++/4.9.x-google/bits/stl_vector.h:197
#5  _M_emplace_back_aux<mongo::RecoveryUnit::Change* const&> (this=0x7f752c585eee <__PRETTY_FUNCTION__.6239+5>) at /bar/third-party2/gcc/x/4.9.x/centos6-native/1317bc4/include/c++/4.9.x-google/bits/vector.tcc:475
#6  push_back (__x=<synthetic pointer>, this=0x7f752c585eee <__PRETTY_FUNCTION__.6239+5>) at /bar/third-party2/gcc/x/4.9.x/centos6-native/1317bc4/include/c++/4.9.x-google/bits/stl_vector.h:1049
#7  push_back (ptr=<optimized out>, this=0x7f752c585eee <__PRETTY_FUNCTION__.6239+5>) at src/mongo/base/owned_pointer_vector.h:85
#8  mongo::WiredTigerRecoveryUnit::registerChange (this=0x7f752c585e9e, change=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:176
#9  0x0000000000f6a1f2 in mongo::WiredTigerRecordStore::_increaseDataSize (this=0x7f752bbb5650, txn=<optimized out>, amount=2181) at src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp:987
#10 0x0000000000f6ff9e in mongo::WiredTigerRecordStore::insertRecord (this=0x7f752c3ec3b0, txn=0x7f73eba2b600, data=<optimized out>, len=0, enforceQuota=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp:587
#11 0x0000000000f694be in mongo::WiredTigerRecordStore::insertRecord (this=0x7f752bbb5600, txn=txn@entry=0x7f752c3ef6c0, doc=doc@entry=0x7f752c3ec4d0, enforceQuota=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp:617
#12 0x0000000000955c1e in mongo::Collection::insertDocument (this=0x7f752b82ea00, txn=txn@entry=0x7f752c3ef6c0, doc=doc@entry=0x7f752c3ec4d0, enforceQuota=enforceQuota@entry=false) at src/mongo/db/catalog/collection.cpp:180
#13 0x0000000000dbb9a5 in mongo::repl::(anonymous namespace)::_logOpOld (txn=0x7f752c3ef6c0, opstr=<optimized out>, ns=<optimized out>, logNS=<optimized out>, obj=..., o2=<optimized out>, bb=0x0, fromMigrate=false) at src/mongo/db/repl/oplog.cpp:336
#14 0x0000000000db8dc9 in mongo::repl::logOp (txn=0x7f752c3ef6c0, opstr=0x17965e9 "i", ns=0x7f751747e568 "iibench.purchases_index", obj=..., patt=0x0, b=0xc, b@entry=0x0, fromMigrate=false) at src/mongo/db/repl/oplog.cpp:380
#15 0x0000000000a6c7ce in singleInsert (result=0x7f752c3ec8c0, collection=<optimized out>, docToInsert=..., txn=0x7f752c3ef6c0) at src/mongo/db/commands/write_commands/batch_executor.cpp:1143
#16 insertOne (result=0x7f752c3ec8c0, state=0x7f752c3edea0) at src/mongo/db/commands/write_commands/batch_executor.cpp:1068
#17 mongo::WriteBatchExecutor::execOneInsert (this=this@entry=0x7f752c3ee360, state=state@entry=0x7f752c3edea0, error=error@entry=0x7f752c3ede80) at src/mongo/db/commands/write_commands/batch_executor.cpp:1109
#18 0x0000000000a6d682 in mongo::WriteBatchExecutor::execInserts (this=this@entry=0x7f752c3ee360, request=..., errors=errors@entry=0x7f752c3ee150) at src/mongo/db/commands/write_commands/batch_executor.cpp:882
#19 0x0000000000a6d784 in mongo::WriteBatchExecutor::bulkExecute (this=this@entry=0x7f752c3ee360, request=..., upsertedIds=upsertedIds@entry=0x7f752c3ee170, errors=errors@entry=0x7f752c3ee150) at src/mongo/db/commands/write_commands/batch_executor.cpp:764
#20 0x0000000000a6df75 in mongo::WriteBatchExecutor::executeBatch (this=this@entry=0x7f752c3ee360, request=..., response=response@entry=0x7f752c3ee3a0) at src/mongo/db/commands/write_commands/batch_executor.cpp:272
#21 0x0000000000a71b57 in mongo::WriteCmd::run (this=<optimized out>, txn=0x7f752c3ef6c0, dbName=..., cmdObj=..., options=<optimized out>, errMsg=..., result=..., fromRepl=false) at src/mongo/db/commands/write_commands/write_commands.cpp:147
#22 0x0000000000a956cc in mongo::_execCommand (txn=txn@entry=0x7f752c3ef6c0, c=c@entry=0x7f752bba0510, dbname=..., cmdObj=..., queryOptions=queryOptions@entry=0, errmsg=..., result=..., fromRepl=false) at src/mongo/db/dbcommands.cpp:1290
#23 0x0000000000a968ea in mongo::Command::execCommand (txn=txn@entry=0x7f752c3ef6c0, c=c@entry=0x7f752bba0510, queryOptions=queryOptions@entry=0, cmdns=cmdns@entry=0x7f7517426814 "iibench.$cmd", cmdObj=..., result=..., fromRepl=false) at src/mongo/db/dbcommands.cpp:1506
#24 0x0000000000a9787d in mongo::_runCommands (txn=0x7f752c3ef6c0, txn@entry=0x7c9e2b <free+379>, ns=0x7f7517426814 "iibench.$cmd", _cmdobj=..., b=..., anObjBuilder=..., fromRepl=fromRepl@entry=false, queryOptions=0) at src/mongo/db/dbcommands.cpp:1578
#25 0x0000000000cedb0a in runCommands (fromRepl=false, queryOptions=<optimized out>, anObjBuilder=..., b=..., curop=..., jsobj=..., ns=<optimized out>, txn=0x7c9e2b <free+379>) at src/mongo/db/query/find.cpp:137
#26 mongo::runQuery (txn=0x7c9e2b <free+379>, txn@entry=0x7f752c3ef6c0, m=..., q=..., nss=..., curop=..., result=..., fromDBDirectClient=false) at src/mongo/db/query/find.cpp:606
#27 0x0000000000bbd408 in receivedQuery (fromDBDirectClient=false, m=..., dbresponse=..., c=..., txn=0x7f752c3ef6c0) at src/mongo/db/instance.cpp:220
#28 mongo::assembleResponse (txn=txn@entry=0x7f752c3ef6c0, m=..., dbresponse=..., remote=..., fromDBDirectClient=fromDBDirectClient@entry=false) at src/mongo/db/instance.cpp:403
#29 0x000000000081add3 in mongo::MyMessageHandler::process (this=<optimized out>, m=..., port=0x7f7521570880, le=0x7f7517422060) at src/mongo/db/db.cpp:206
#30 0x000000000116e85e in mongo::PortMessageServer::handleIncomingMsg (arg=0x7f7521570880) at src/mongo/util/net/message_server_port.cpp:229
#31 0x00007f752d3fe7c9 in start_thread () from /foo/gcc-4.9-glibc-2.20/lib/libpthread.so.0
#32 0x00007f752c4fd8ad in clone () from /foo/gcc-4.9-glibc-2.20/lib/libc.so.6

            Assignee:
            Unassigned Unassigned
            Reporter:
            mdcallag Mark Callaghan
            Votes:
            0 Vote for this issue
            Watchers:
            10 Start watching this issue

              Created:
              Updated:
              Resolved: