Launching soon: The world's first vendor agnostic bug scrubLearn more & join waitlist
OPERATIONAL DEFECT DATABASE
...
...
The docs state that ensureIndex(.., {"background":false} ) don't block all operations on a database but that is not the case for WiredTiger.With a long-running background index creation in progress on "purchases_index" the following commands have been blocked for me: show collections -> for the database that contains purchases_index db.purchases_index.getIndexes() db.pi.insert( {"foo":1} ) --> "pi" did not exist prior to this insert
mdcallag commented on Thu, 22 Jan 2015 13:40:52 +0000: Ran index builds that took a few hours with "show collections" and "db.purchases_index.getIndexes()" running in a loop. Was unable to reproduce the hang. milkie commented on Thu, 22 Jan 2015 13:32:03 +0000: In Kal's commit 8f83ff2335ea0e2dd0dc2fc79b6509c4f8f2d4fc, traditional lock yielding was activated for all document-level-locking storage engines. It's part of rc5, so you might see better behavior versus rc4. ramon.fernandez commented on Thu, 22 Jan 2015 04:02:55 +0000: Thanks mdcallag, that's what I was looking for. mdcallag commented on Thu, 22 Jan 2015 03:57:51 +0000: Here is mongo.conf. The log is huge especially from the too frequent background index build status messages. processManagement: fork: true systemLog: destination: file path: /data/mysql/mongo.280rc4/log logAppend: true storage: syncPeriodSecs: 60 dbPath: /data/mysql/mongo.280rc4/data journal: enabled: true mmapv1: journal: commitIntervalMs: 100 storage.wiredTiger.collectionConfig.blockCompressor: snappy storage.wiredTiger.engineConfig.journalCompressor: snappy operationProfiling.slowOpThresholdMs: 2000 This is the log from server start. 2015-01-21T16:14:32.142-0800 I CONTROL [initandlisten] MongoDB starting : pid=22092 port=27017 dbpath=/data/mysql/mongo.280rc4/data 64-bit host=X 2015-01-21T16:14:32.142-0800 I CONTROL [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended. 2015-01-21T16:14:32.142-0800 I CONTROL [initandlisten] 2015-01-21T16:14:32.143-0800 I CONTROL [initandlisten] db version v2.8.0-rc5 2015-01-21T16:14:32.143-0800 I CONTROL [initandlisten] git version: nogitversion 2015-01-21T16:14:32.143-0800 I CONTROL [initandlisten] build info: Linux dev1434.prn1.facebook.com 3.2.51-103_fbk20_00350_gbc67779 #103 SMP Mon Dec 2 10:44:28 PST 2013 x86_64 BOOST_LIB_VERSION=1_49 2015-01-21T16:14:32.143-0800 I CONTROL [initandlisten] allocator: system 2015-01-21T16:14:32.143-0800 I CONTROL [initandlisten] options: { config: "/data/mysql/mongo.280rc4/mongo.conf", operationProfiling: { slowOpThresholdMs: 2000 }, processManagement: { fork: true }, storage: { dbPath: "/data/mysql/mongo.280rc4/data", engine: "wiredTiger", journal: { enabled: true }, mmapv1: { journal: { commitIntervalMs: 100 } }, syncPeriodSecs: 60.0, wiredTiger: { collectionConfig: { blockCompressor: "snappy" }, engineConfig: { cacheSizeGB: 4, journalCompressor: "snappy" } } }, systemLog: { destination: "file", logAppend: true, path: "/data/mysql/mongo.280rc4/log" } } 2015-01-21T16:14:32.143-0800 W STORAGE [initandlisten] Detected configuration for non-active storage engine mmapv1 when current storage engine is wiredTiger 2015-01-21T16:14:32.144-0800 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=4G,session_max=20000,eviction=(threads_max=4),statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), 2015-01-21T16:14:32.168-0800 I NETWORK [initandlisten] waiting for connections on port 27017 2015-01-21T17:11:35.914-0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:45914 #1 (1 connection now open) 2015-01-21T17:11:42.677-0800 I NETWORK [conn1] end connection 127.0.0.1:45914 (0 connections now open) 2015-01-21T17:15:45.495-0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:48359 #2 (1 connection now open) 2015-01-21T17:15:45.497-0800 I COMMAND [conn2] CMD: dropIndexes iibench.purchases_index 2015-01-21T17:15:47.107-0800 I COMMAND [conn2] CMD: dropIndexes iibench.purchases_index 2015-01-21T17:15:48.333-0800 I COMMAND [conn2] CMD: dropIndexes iibench.purchases_index 2015-01-21T17:15:49.463-0800 I NETWORK [conn2] end connection 127.0.0.1:48359 (0 connections now open) 2015-01-21T17:16:03.357-0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:48569 #3 (1 connection now open) 2015-01-21T17:16:20.194-0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:48767 #4 (2 connections now open) 2015-01-21T17:16:20.199-0800 I INDEX [conn4] build index on: iibench.purchases_index properties: { v: 1, key: { price: 1.0, dateandtime: 1.0, customerid: 1.0 }, name: "price_1_dateandtime_1_customerid_1", ns: "iibench.purchases_index", background: true } 2015-01-21T17:16:23.001-0800 I - [conn4] Index Build (background): 99000/100000000 0% 2015-01-21T17:16:26.002-0800 I - [conn4] Index Build (background): 202700/100000000 0% ramon.fernandez commented on Thu, 22 Jan 2015 03:52:22 +0000: mdcallag, can you post the full logs or the options you started mongod with in the WiredTiger case? Are you also using direct_io=[data] like in other tickets? Also, is this a stand-alone server or a replicaset? Thanks, Ramón. mdcallag commented on Thu, 22 Jan 2015 02:42:43 +0000: But looking at output I pasted from db.currentOp() shows that background:true was used. Still trying to reproduce this. I had stacks for more threads from the first (and only) time I hit the problem. At a high level there are several background threads blocked trying to get a lock in IS mode and the listCollections thread is blocked trying to get it in S mode. 1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait,timed_wait::lockComplete,mongo::Lock::DBLock::DBLock,mongo::TTLMonitor::getTTLIndexesForDB,mongo::TTLMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone 1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait,timed_wait::lockComplete,mongo::Lock::DBLock::DBLock,mongo::AutoGetDb::AutoGetDb,mongo::CmdListCollections::run,mongo::_execCommand,mongo::Command::execCommand,mongo::_runCommands,runCommands,mongo::runQuery,receivedQuery,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone 1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait,timed_wait::lockComplete,mongo::Lock::DBLock::DBLock,mongo::AutoGetDb::AutoGetDb,mongo::AutoGetCollectionForRead::AutoGetCollectionForRead,mongo::GlobalCursorIdCache::timeoutCursors,mongo::CursorManager::timeoutCursorsGlobal,mongo::ClientCursorMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone 1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait,timed_wait,,mongo::RangeDeleter::doWork,boost::(anonymous,start_thread,clone 1 pthread_cond_timedwait@@GLIBC_2.3.2,boost::condition_variable_any::timed_wait,timed_wait,,timed_wait,,mongo::(anonymous,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone 1 mongo::BSONObj::woCompare,mongo::BtreeExternalSortComparison::operator(),operator(),std::__move_merge<std::pair<mongo::BSONObj,,__merge_sort_loop<std::pair<mongo::BSONObj,,std::__merge_sort_with_buffer<std::_Deque_iterator<std::pair<mongo::BSONObj,,std::__stable_sort_adaptive<std::_Deque_iterator<std::pair<mongo::BSONObj,,stable_sort<std::_Deque_iterator<std::pair<mongo::BSONObj,,mongo::sorter::NoLimitSorter<mongo::BSONObj,,mongo::sorter::NoLimitSorter<mongo::BSONObj,,mongo::sorter::NoLimitSorter<mongo::BSONObj,,mongo::BtreeBasedBulkAccessMethod::insert,mongo::MultiIndexBlock::insert,mongo::MultiIndexBlock::insertAllDocumentsInCollection,mongo::CmdCreateIndex::run,mongo::_execCommand,mongo::Command::execCommand,mongo::_runCommands,runCommands,mongo::runQuery,receivedQuery,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone With much more detail in... Thread 7 (Thread 0x7f91afbff700 (LWP 9408)): #0 0x00007f91bc6837ae in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #1 0x0000000000c44956 in timed_wait > (wait_until=..., m=..., this=0x7f91bb871e10) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:161 #2 timed_wait, boost::date_time::subsecond_duration > (wait_duration=..., m=..., this=0x7f91bb871e10) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:183 #3 mongo::RangeDeleter::doWork (this=0x7f91bb871d80) at src/mongo/db/range_deleter.cpp:458 #4 0x0000000000feb354 in boost::(anonymous namespace)::thread_proxy (param=) at src/third_party/boost/libs/thread/src/pthread/thread.cpp:121 #5 0x00007f91bc67efa8 in start_thread () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #6 0x00007f91bc3a15ad in clone () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libc.so.6 Thread 6 (Thread 0x7f91af3fe700 (LWP 9409)): #0 0x00007f91bc6837ae in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #1 0x0000000000a0ff1e in timed_wait (wait_until=..., m=..., this=0x7f91acc171d0) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:74 #2 timed_wait > (wait_duration=..., m=..., this=0x7f91acc171d0) at src/third_party/boost/boost/thread/pthread/condition_variable_fwd.hpp:72 #3 mongo::CondVarLockGrantNotification::wait (this=this@entry=0x7f91acc171a0, timeoutMs=) at src/mongo/db/concurrency/lock_state.cpp:254 #4 0x0000000000a17613 in mongo::LockerImpl::lockComplete (this=0x7f91acc16c00, resId=..., mode=mongo::MODE_IS, timeoutMs=4294967295, checkDeadlock=false) at src/mongo/db/concurrency/lock_state.cpp:688 #5 0x0000000000a07fe1 in mongo::Lock::DBLock::DBLock (this=0x7f91af3fd730, lockState=0x7f91acc16c00, db=..., mode=) at src/mongo/db/concurrency/d_concurrency.cpp:150 #6 0x0000000000dd5a12 in mongo::TTLMonitor::getTTLIndexesForDB (this=this@entry=0x7f91bbbb8d00, txn=txn@entry=0x7f91af3fd810, dbName=..., indexes=indexes@entry=0x7f91af3fd7f0) at src/mongo/db/ttl.cpp:142 #7 0x0000000000dd6e82 in mongo::TTLMonitor::run (this=0x7f91bbbb8d00) at src/mongo/db/ttl.cpp:115 #8 0x0000000000f32880 in mongo::BackgroundJob::jobBody (this=0x7f91bbbb8d00) at src/mongo/util/background.cpp:163 #9 0x0000000000feb354 in boost::(anonymous namespace)::thread_proxy (param=) at src/third_party/boost/libs/thread/src/pthread/thread.cpp:121 #10 0x00007f91bc67efa8 in start_thread () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #11 0x00007f91bc3a15ad in clone () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libc.so.6 Thread 5 (Thread 0x7f91ae3ff700 (LWP 9410)): #0 0x00007f91bc6837ae in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #1 0x0000000000a0ff1e in timed_wait (wait_until=..., m=..., this=0x7f91ac8171d0) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:74 #2 timed_wait > (wait_duration=..., m=..., this=0x7f91ac8171d0) at src/third_party/boost/boost/thread/pthread/condition_variable_fwd.hpp:72 #3 mongo::CondVarLockGrantNotification::wait (this=this@entry=0x7f91ac8171a0, timeoutMs=) at src/mongo/db/concurrency/lock_state.cpp:254 #4 0x0000000000a17613 in mongo::LockerImpl::lockComplete (this=0x7f91ac816c00, resId=..., mode=mongo::MODE_IS, timeoutMs=4294967295, checkDeadlock=false) at src/mongo/db/concurrency/lock_state.cpp:688 #5 0x0000000000a07fe1 in mongo::Lock::DBLock::DBLock (this=0x7f91ae3fe7a8, lockState=0x7f91ac816c00, db=..., mode=) at src/mongo/db/concurrency/d_concurrency.cpp:150 #6 0x00000000009803b0 in mongo::AutoGetDb::AutoGetDb (this=0x7f91ae3fe7a8, txn=0x7f91ae3fe850, ns=..., mode=mongo::MODE_IS) at src/mongo/db/client.cpp:209 #7 0x0000000000980540 in mongo::AutoGetCollectionForRead::AutoGetCollectionForRead (this=0x7f91ae3fe790, txn=0x7f91ae3fe850, ns=...) at src/mongo/db/client.cpp:237 #8 0x0000000000969dbc in mongo::GlobalCursorIdCache::timeoutCursors (this=0x7f91bbba7200, txn=txn@entry=0x7f91ae3fe850, millisSinceLastCall=4000) at src/mongo/db/catalog/cursor_manager.cpp:265 #9 0x0000000000969e7c in mongo::CursorManager::timeoutCursorsGlobal (txn=txn@entry=0x7f91ae3fe850, millisSinceLastCall=) at src/mongo/db/catalog/cursor_manager.cpp:289 #10 0x0000000000983235 in mongo::ClientCursorMonitor::run (this=) at src/mongo/db/clientcursor.cpp:290 #11 0x0000000000f32880 in mongo::BackgroundJob::jobBody (this=0x1caeb00 ) at src/mongo/util/background.cpp:163 #12 0x0000000000feb354 in boost::(anonymous namespace)::thread_proxy (param=) at src/third_party/boost/libs/thread/src/pthread/thread.cpp:121 #13 0x00007f91bc67efa8 in start_thread () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #14 0x00007f91bc3a15ad in clone () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libc.so.6 Thread 4 (Thread 0x7f91adbfe700 (LWP 9411)): #0 0x00007f91bc6837ae in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #1 0x0000000000f35736 in boost::condition_variable_any::timed_wait > (this=this@entry=0x7f91bb986048, m=..., wait_until=...) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:161 #2 0x0000000000f333f6 in timed_wait, std::function > (pred=..., wait_until=..., m=..., this=0x7f91bb986048) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:191 #3 timed_wait, std::function > (pred=..., wait_until=..., m=..., this=0x7f91bb986048) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:200 #4 mongo::(anonymous namespace)::PeriodicTaskRunner::run (this=0x7f91bb986020) at src/mongo/util/background.cpp:338 #5 0x0000000000f32880 in mongo::BackgroundJob::jobBody (this=0x7f91bb986020) at src/mongo/util/background.cpp:163 #6 0x0000000000feb354 in boost::(anonymous namespace)::thread_proxy (param=) at src/third_party/boost/libs/thread/src/pthread/thread.cpp:121 #7 0x00007f91bc67efa8 in start_thread () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #8 0x00007f91bc3a15ad in clone () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libc.so.6 Thread 3 (Thread 0x7f91bc19c700 (LWP 32318)): #0 mongo::BSONObj::woCompare (this=this@entry=0x7f82c1400490, r=..., o=..., considerFieldName=considerFieldName@entry=false) at src/mongo/bson/bsonobj.cpp:125 #1 0x0000000000ad6d70 in mongo::BtreeExternalSortComparison::operator() (this=, l=..., r=...) at src/mongo/db/index/btree_based_bulk_access_method.cpp:68 #2 0x0000000000addfc7 in operator() (rhs=..., lhs=..., this=) at src/mongo/db/sorter/sorter.cpp:436 #3 std::__move_merge*, std::pair*, std::_Deque_iterator, std::pair&, std::pair*>, mongo::sorter::NoLimitSorter::STLComparator> (__first1=0x7f82c13eb9e8, __last1=__last1@entry=0x7f82c13f5000, __first2=0x7f82c1400490, __first2@entry=0x7f82c13f5000, __last2=__last2@entry=0x7f82c140a000, __result=..., __comp=__comp@entry=...) at /mnt/gvfs/third-party2/gcc/1ec615e23800f0815d474478ba476a0adc3fe788/4.8.1/centos6-native/cc6c9dc/include/c++/4.8.1/bits/stl_algo.h:3305 #4 0x0000000000ade59c in __merge_sort_loop*, std::_Deque_iterator, std::pair&, std::pair*>, long, mongo::sorter::NoLimitSorter::STLComparator> (__comp=..., __step_size=3584, __result=..., __last=0x7f82c26aaab8, __first=) at /mnt/gvfs/third-party2/gcc/1ec615e23800f0815d474478ba476a0adc3fe788/4.8.1/centos6-native/cc6c9dc/include/c++/4.8.1/bits/stl_algo.h:3357 #5 std::__merge_sort_with_buffer, std::pair&, std::pair*>, std::pair*, mongo::sorter::NoLimitSorter::STLComparator> (__first=..., __last=..., __buffer=__buffer@entry=0x7f82c0c00000, __comp=__comp@entry=...) at /mnt/gvfs/third-party2/gcc/1ec615e23800f0815d474478ba476a0adc3fe788/4.8.1/centos6-native/cc6c9dc/include/c++/4.8.1/bits/stl_algo.h:3444 #6 0x0000000000adf9d1 in std::__stable_sort_adaptive, std::pair&, std::pair*>, std::pair*, long, mongo::sorter::NoLimitSorter::STLComparator> (__first=..., __last=..., __buffer=0x7f82c0c00000, __buffer_size=2330169, __comp=__comp@entry=...) at /mnt/gvfs/third-party2/gcc/1ec615e23800f0815d474478ba476a0adc3fe788/4.8.1/centos6-native/cc6c9dc/include/c++/4.8.1/bits/stl_algo.h:3496 #7 0x0000000000adfd0d in stable_sort, std::pair&, std::pair*>, mongo::sorter::NoLimitSorter::STLComparator> (__comp=..., __last=..., __first=...) at /mnt/gvfs/third-party2/gcc/1ec615e23800f0815d474478ba476a0adc3fe788/4.8.1/centos6-native/cc6c9dc/include/c++/4.8.1/bits/stl_algo.h:5726 #8 mongo::sorter::NoLimitSorter::sort (this=this@entry=0x7f91abcc8f40) at src/mongo/db/sorter/sorter.cpp:444 #9 0x0000000000adfdd0 in mongo::sorter::NoLimitSorter::spill (this=this@entry=0x7f91abcc8f40) at src/mongo/db/sorter/sorter.cpp:467 #10 0x0000000000ae0067 in mongo::sorter::NoLimitSorter::add (this=0x7f91abcc8f40, key=..., val=...) at src/mongo/db/sorter/sorter.cpp:413 #11 0x0000000000ad5715 in mongo::BtreeBasedBulkAccessMethod::insert (this=0x7f8d89cdbd40, txn=, obj=..., loc=..., options=..., numInserted=0x7f91bc199fe0) at src/mongo/db/index/btree_based_bulk_access_method.cpp:108 #12 0x000000000097b505 in mongo::MultiIndexBlock::insert (this=this@entry=0x7f91bc19a2e0, doc=..., loc=...) at src/mongo/db/catalog/index_create.cpp:286 #13 0x000000000097c56c in mongo::MultiIndexBlock::insertAllDocumentsInCollection (this=this@entry=0x7f91bc19a2e0, dupsOut=dupsOut@entry=0x0) at src/mongo/db/catalog/index_create.cpp:239 #14 0x00000000009a3f3b in mongo::CmdCreateIndex::run (this=, txn=0x7f91bc19b680, dbname=..., cmdObj=..., options=, errmsg=..., result=..., fromRepl=false) at src/mongo/db/commands/create_indexes.cpp:198 #15 0x0000000000a23964 in mongo::_execCommand (txn=txn@entry=0x7f91bc19b680, c=c@entry=0x1caf6a0 , dbname=..., cmdObj=..., queryOptions=queryOptions@entry=0, errmsg=..., result=..., fromRepl=fromRepl@entry=false) at src/mongo/db/dbcommands.cpp:1252 #16 0x0000000000a248a3 in mongo::Command::execCommand (txn=txn@entry=0x7f91bc19b680, c=c@entry=0x1caf6a0 , queryOptions=queryOptions@entry=0, cmdns=cmdns@entry=0x7f91abc6e414 "iibench.$cmd", cmdObj=..., result=..., fromRepl=fromRepl@entry=false) at src/mongo/db/dbcommands.cpp:1468 #17 0x0000000000a2535b in mongo::_runCommands (txn=txn@entry=0x7f91bc19b680, ns=0x7f91abc6e414 "iibench.$cmd", _cmdobj=..., b=..., anObjBuilder=..., fromRepl=fromRepl@entry=false, queryOptions=0) at src/mongo/db/dbcommands.cpp:1543 #18 0x0000000000bee415 in runCommands (fromRepl=false, queryOptions=, anObjBuilder=..., b=..., curop=..., jsobj=..., ns=, txn=0x7f91bc19b680) at src/mongo/db/query/find.cpp:135 #19 mongo::runQuery (txn=txn@entry=0x7f91bc19b680, m=..., q=..., nss=..., curop=..., result=..., fromDBDirectClient=fromDBDirectClient@entry=false) at src/mongo/db/query/find.cpp:567 #20 0x0000000000b0320a in receivedQuery (fromDBDirectClient=false, m=..., dbresponse=..., c=..., txn=0x7f91bc19b680) at src/mongo/db/instance.cpp:217 #21 mongo::assembleResponse (txn=txn@entry=0x7f91bc19b680, m=..., dbresponse=..., remote=..., fromDBDirectClient=fromDBDirectClient@entry=false) at src/mongo/db/instance.cpp:400 #22 0x0000000000857880 in mongo::MyMessageHandler::process (this=, m=..., port=0x7f91b4fe9600, le=0x7f91abc22060) at src/mongo/db/db.cpp:197 #23 0x0000000000f5e8c1 in mongo::PortMessageServer::handleIncomingMsg (arg=0x7f91b4fe9600) at src/mongo/util/net/message_server_port.cpp:225 #24 0x00007f91bc67efa8 in start_thread () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #25 0x00007f91bc3a15ad in clone () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libc.so.6 Thread 2 (Thread 0x7f91bdb1e700 (LWP 15103)): #0 0x00007f91bc6837ae in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #1 0x0000000000a0ff1e in timed_wait (wait_until=..., m=..., this=0x7f85544091d0) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:74 #2 timed_wait > (wait_duration=..., m=..., this=0x7f85544091d0) at src/third_party/boost/boost/thread/pthread/condition_variable_fwd.hpp:72 #3 mongo::CondVarLockGrantNotification::wait (this=this@entry=0x7f85544091a0, timeoutMs=) at src/mongo/db/concurrency/lock_state.cpp:254 #4 0x0000000000a17613 in mongo::LockerImpl::lockComplete (this=0x7f8554408c00, resId=..., mode=mongo::MODE_S, timeoutMs=4294967295, checkDeadlock=false) at src/mongo/db/concurrency/lock_state.cpp:688 #5 0x0000000000a07fe1 in mongo::Lock::DBLock::DBLock (this=0x7f91bdb1c340, lockState=0x7f8554408c00, db=..., mode=) at src/mongo/db/concurrency/d_concurrency.cpp:150 #6 0x00000000009803b0 in mongo::AutoGetDb::AutoGetDb (this=0x7f91bdb1c340, txn=0x7f91bdb1d680, ns=..., mode=mongo::MODE_S) at src/mongo/db/client.cpp:209 #7 0x00000000009bb0d0 in mongo::CmdListCollections::run (this=0x1caffa0 , txn=0x7f91bdb1d680, dbname=..., jsobj=..., errmsg=..., result=...) at src/mongo/db/commands/list_collections.cpp:104 #8 0x0000000000a23964 in mongo::_execCommand (txn=txn@entry=0x7f91bdb1d680, c=c@entry=0x1caffa0 , dbname=..., cmdObj=..., queryOptions=queryOptions@entry=0, errmsg=..., result=..., fromRepl=fromRepl@entry=false) at src/mongo/db/dbcommands.cpp:1252 #9 0x0000000000a248a3 in mongo::Command::execCommand (txn=txn@entry=0x7f91bdb1d680, c=c@entry=0x1caffa0 , queryOptions=queryOptions@entry=0, cmdns=cmdns@entry=0x7f81432a4814 "iibench.$cmd", cmdObj=..., result=..., fromRepl=fromRepl@entry=false) at src/mongo/db/dbcommands.cpp:1468 #10 0x0000000000a2535b in mongo::_runCommands (txn=txn@entry=0x7f91bdb1d680, ns=0x7f81432a4814 "iibench.$cmd", _cmdobj=..., b=..., anObjBuilder=..., fromRepl=fromRepl@entry=false, queryOptions=0) at src/mongo/db/dbcommands.cpp:1543 #11 0x0000000000bee415 in runCommands (fromRepl=false, queryOptions=, anObjBuilder=..., b=..., curop=..., jsobj=..., ns=, txn=0x7f91bdb1d680) at src/mongo/db/query/find.cpp:135 #12 mongo::runQuery (txn=txn@entry=0x7f91bdb1d680, m=..., q=..., nss=..., curop=..., result=..., fromDBDirectClient=fromDBDirectClient@entry=false) at src/mongo/db/query/find.cpp:567 #13 0x0000000000b0320a in receivedQuery (fromDBDirectClient=false, m=..., dbresponse=..., c=..., txn=0x7f91bdb1d680) at src/mongo/db/instance.cpp:217 #14 mongo::assembleResponse (txn=txn@entry=0x7f91bdb1d680, m=..., dbresponse=..., remote=..., fromDBDirectClient=fromDBDirectClient@entry=false) at src/mongo/db/instance.cpp:400 #15 0x0000000000857880 in mongo::MyMessageHandler::process (this=, m=..., port=0x7f91b4c422e0, le=0x7f90d9b95060) at src/mongo/db/db.cpp:197 #16 0x0000000000f5e8c1 in mongo::PortMessageServer::handleIncomingMsg (arg=0x7f91b4c422e0) at src/mongo/util/net/message_server_port.cpp:225 #17 0x00007f91bc67efa8 in start_thread () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #18 0x00007f91bc3a15ad in clone () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libc.so.6 Thread 1 (Thread 0x7f91bdb20cc0 (LWP 9402)): #0 0x00007f91bc398233 in select () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libc.so.6 #1 0x0000000000f57fb2 in mongo::Listener::initAndListen (this=0x7f91b4c56508) at src/mongo/util/net/listen.cpp:264 #2 0x0000000000852ff3 in _initAndListen (listenPort=) at src/mongo/db/db.cpp:621 #3 mongo::initAndListen (listenPort=) at src/mongo/db/db.cpp:626 #4 0x00000000008568a4 in mongoDbMain (envp=, argv=0x7fff4c0491c8, argc=) at src/mongo/db/db.cpp:872 #5 main (argc=7, argv=0x7fff4c0491c8, envp=) at src/mongo/db/db.cpp:675 Detaching from program: /data/mysql/mongo.280rc4/bin/mongod.rc5.jem.dbg, process 9402 ramon.fernandez commented on Thu, 22 Jan 2015 02:13:55 +0000: Hi mdcallag, thanks for letting us know. I wasn't able to reproduce on master either using a synthetic, insert-only workload. Want to give this another try tomorrow morning to be on the safe side though. mdcallag commented on Thu, 22 Jan 2015 01:19:21 +0000: And now I can't reproduce this which makes me think my original test was using background:false mdcallag commented on Wed, 21 Jan 2015 22:49:25 +0000: Thread stacks from another hang: Thread 4 (Thread 0x7f06bf5fa700 (LWP 6585)): #0 0x00007f06be15f7ae in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #1 0x000000000137668f in __wt_cond_wait (session=session@entry=0x7f06b440a000, cond=0x7f06bd7a74a0, usecs=usecs@entry=100000) at src/third_party/wiredtiger/src/os_posix/os_mtx_cond.c:77 #2 0x00000000013a183e in __wt_cache_full_check (session=0x7f06b440a000) at src/third_party/wiredtiger/src/include/cache.i:166 #3 __session_begin_transaction (wt_session=0x7f06b440a000, config=) at src/third_party/wiredtiger/src/session/session_api.c:743 #4 0x0000000000db62f8 in mongo::WiredTigerRecoveryUnit::_txnOpen (this=this@entry=0x7f0563e8de60) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:219 #5 0x0000000000db6440 in mongo::WiredTigerRecoveryUnit::getSession (this=0x7f0563e8de60) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:183 #6 0x0000000000db6480 in mongo::WiredTigerCursor::_init (this=0x7f06bf5f7d70, uri=..., id=25, ru=) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:251 #7 0x0000000000da89e0 in mongo::WiredTigerIndex::insert (this=0x7f05cedeb060, txn=, key=..., loc=..., dupsAllowed=) at src/mongo/db/storage/wiredtiger/wiredtiger_index.cpp:362 #8 0x0000000000ad038b in mongo::BtreeBasedAccessMethod::insert (this=0x7f0561eb3ee0, txn=0x7f06bf5f9660, obj=..., loc=..., options=..., numInserted=0x7f06bf5f7f20) at src/mongo/db/index/btree_based_access_method.cpp:86 #9 0x0000000000979285 in mongo::MultiIndexBlock::insert (this=this@entry=0x7f06bf5f8220, doc=..., loc=...) at src/mongo/db/catalog/index_create.cpp:281 #10 0x000000000097a2c7 in mongo::MultiIndexBlock::insertAllDocumentsInCollection (this=this@entry=0x7f06bf5f8220, dupsOut=dupsOut@entry=0x0) at src/mongo/db/catalog/index_create.cpp:234 #11 0x00000000009a1bfe in mongo::CmdCreateIndex::run (this=, txn=0x7f06bf5f9660, dbname=..., cmdObj=..., options=, errmsg=..., result=..., fromRepl=false) at src/mongo/db/commands/create_indexes.cpp:198 #12 0x0000000000a1d3e4 in mongo::_execCommand (txn=txn@entry=0x7f06bf5f9660, c=c@entry=0x1c92a00 , dbname=..., cmdObj=..., queryOptions=queryOptions@entry=0, errmsg=..., result=..., fromRepl=fromRepl@entry=false) at src/mongo/db/dbcommands.cpp:125 2 #13 0x0000000000a1e323 in mongo::Command::execCommand (txn=txn@entry=0x7f06bf5f9660, c=c@entry=0x1c92a00 , queryOptions=queryOptions@entry=0, cmdns=cmdns@entry=0x7f0573322414 "iibench.$cmd", cmdObj=..., result=..., fromRepl=fromRepl@entry=false) a t src/mongo/db/dbcommands.cpp:1468 #14 0x0000000000a1eddb in mongo::_runCommands (txn=txn@entry=0x7f06bf5f9660, ns=0x7f0573322414 "iibench.$cmd", _cmdobj=..., b=..., anObjBuilder=..., fromRepl=fromRepl@entry=false, queryOptions=0) at src/mongo/db/dbcommands.cpp:1543 #15 0x0000000000be9b8a in runCommands (fromRepl=false, queryOptions=, anObjBuilder=..., b=..., curop=..., jsobj=..., ns=, txn=0x7f06bf5f9660) at src/mongo/db/query/find.cpp:131 #16 mongo::runQuery (txn=txn@entry=0x7f06bf5f9660, m=..., q=..., curop=..., result=..., fromDBDirectClient=fromDBDirectClient@entry=false) at src/mongo/db/query/find.cpp:565 #17 0x0000000000afe8d5 in receivedQuery (fromDBDirectClient=false, m=..., dbresponse=..., c=..., txn=0x7f06bf5f9660) at src/mongo/db/instance.cpp:224 #18 mongo::assembleResponse (txn=txn@entry=0x7f06bf5f9660, m=..., dbresponse=..., remote=..., fromDBDirectClient=fromDBDirectClient@entry=false) at src/mongo/db/instance.cpp:394 #19 0x00000000008562a0 in mongo::MyMessageHandler::process (this=, m=..., port=0x7f06b6442d80, le=0x7f057db5a650) at src/mongo/db/db.cpp:195 #20 0x0000000000f4b7e1 in mongo::PortMessageServer::handleIncomingMsg (arg=0x7f06bd46a550) at src/mongo/util/net/message_server_port.cpp:234 #21 0x00007f06be15afa8 in start_thread () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #22 0x00007f06bde7d5ad in clone () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libc.so.6 Thread 3 (Thread 0x7f06bdd79700 (LWP 36558)): #0 0x00007f06be15f7ae in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #1 0x0000000000a0da6e in timed_wait (wait_until=..., m=..., this=0x7f0531026bd0) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:74 #2 timed_wait > (wait_duration=..., m=..., this=0x7f0531026bd0) at src/third_party/boost/boost/thread/pthread/condition_variable_fwd.hpp:72 #3 mongo::CondVarLockGrantNotification::wait (this=this@entry=0x7f0531026ba0, timeoutMs=) at src/mongo/db/concurrency/lock_state.cpp:189 #4 0x0000000000a14fd2 in mongo::LockerImpl::lockComplete (this=0x7f0531026600, resId=..., timeoutMs=4294967295, checkDeadlock=false) at src/mongo/db/concurrency/lock_state.cpp:607 #5 0x0000000000a05bb1 in mongo::Lock::DBLock::DBLock (this=0x7f06bdd77280, lockState=0x7f0531026600, db=..., mode=) at src/mongo/db/concurrency/d_concurrency.cpp:147 #6 0x000000000097e1d0 in mongo::AutoGetDb::AutoGetDb (this=0x7f06bdd77280, txn=0x7f06bdd78660, ns=..., mode=mongo::MODE_S) at src/mongo/db/client.cpp:209 #7 0x00000000009b9154 in mongo::CmdListCollections::run (this=0x1c93300 , txn=0x7f06bdd78660, dbname=..., jsobj=..., errmsg=..., result=...) at src/mongo/db/commands/list_collections.cpp:77 #8 0x0000000000a1d3e4 in mongo::_execCommand (txn=txn@entry=0x7f06bdd78660, c=c@entry=0x1c93300 , dbname=..., cmdObj=..., queryOptions=queryOptions@entry=0, errmsg=..., result=..., fromRepl=fromRepl@entry=false) at src/mongo/db/dbcommands.cpp:1252 #9 0x0000000000a1e323 in mongo::Command::execCommand (txn=txn@entry=0x7f06bdd78660, c=c@entry=0x1c93300 , queryOptions=queryOptions@entry=0, cmdns=cmdns@entry=0x7f053105f414 "iibench.$cmd", cmdObj=..., result=..., fromRepl=fromRepl@entry=false) at src/mongo/db/dbcommands.cpp:1468 #10 0x0000000000a1eddb in mongo::_runCommands (txn=txn@entry=0x7f06bdd78660, ns=0x7f053105f414 "iibench.$cmd", _cmdobj=..., b=..., anObjBuilder=..., fromRepl=fromRepl@entry=false, queryOptions=0) at src/mongo/db/dbcommands.cpp:1543 #11 0x0000000000be9b8a in runCommands (fromRepl=false, queryOptions=, anObjBuilder=..., b=..., curop=..., jsobj=..., ns=, txn=0x7f06bdd78660) at src/mongo/db/query/find.cpp:131 #12 mongo::runQuery (txn=txn@entry=0x7f06bdd78660, m=..., q=..., curop=..., result=..., fromDBDirectClient=fromDBDirectClient@entry=false) at src/mongo/db/query/find.cpp:565 #13 0x0000000000afe8d5 in receivedQuery (fromDBDirectClient=false, m=..., dbresponse=..., c=..., txn=0x7f06bdd78660) at src/mongo/db/instance.cpp:224 #14 mongo::assembleResponse (txn=txn@entry=0x7f06bdd78660, m=..., dbresponse=..., remote=..., fromDBDirectClient=fromDBDirectClient@entry=false) at src/mongo/db/instance.cpp:394 #15 0x00000000008562a0 in mongo::MyMessageHandler::process (this=, m=..., port=0x7f06b6442380, le=0x7f0531022060) at src/mongo/db/db.cpp:195 #16 0x0000000000f4b7e1 in mongo::PortMessageServer::handleIncomingMsg (arg=0x7f06bd46a760) at src/mongo/util/net/message_server_port.cpp:234 #17 0x00007f06be15afa8 in start_thread () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #18 0x00007f06bde7d5ad in clone () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libc.so.6 Thread 2 (Thread 0x7f06b6a1c700 (LWP 38547)): #0 0x00007f06be15f7ae in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #1 0x0000000000a0da6e in timed_wait (wait_until=..., m=..., this=0x7f0533027bd0) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:74 #2 timed_wait > (wait_duration=..., m=..., this=0x7f0533027bd0) at src/third_party/boost/boost/thread/pthread/condition_variable_fwd.hpp:72 #3 mongo::CondVarLockGrantNotification::wait (this=this@entry=0x7f0533027ba0, timeoutMs=) at src/mongo/db/concurrency/lock_state.cpp:189 #4 0x0000000000a14fd2 in mongo::LockerImpl::lockComplete (this=0x7f0533027600, resId=..., timeoutMs=4294967295, checkDeadlock=false) at src/mongo/db/concurrency/lock_state.cpp:607 #5 0x0000000000a05bb1 in mongo::Lock::DBLock::DBLock (this=0x7f0533024190, lockState=0x7f0533027600, db=..., mode=) at src/mongo/db/concurrency/d_concurrency.cpp:147 #6 0x00000000009fb652 in mongo::WriteBatchExecutor::ExecInsertsState::_lockAndCheckImpl (this=this@entry=0x7f06b6a19df0, result=result@entry=0x7f06b6a187f0, intentLock=intentLock@entry=false) at src/mongo/db/commands/write_commands/batch_executor.cpp:971 #7 0x00000000009fb944 in mongo::WriteBatchExecutor::ExecInsertsState::_lockAndCheckImpl (this=this@entry=0x7f06b6a19df0, result=result@entry=0x7f06b6a187f0, intentLock=, intentLock@entry=true) at src/mongo/db/commands/write_commands/batch_executor.cpp:1003 #8 0x00000000009fcc50 in lockAndCheck (result=0x7f06b6a187f0, this=0x7f06b6a19df0) at src/mongo/db/commands/write_commands/batch_executor.cpp:1026 #9 insertOne (result=0x7f06b6a187f0, state=0x7f06b6a19df0) at src/mongo/db/commands/write_commands/batch_executor.cpp:1054 #10 mongo::WriteBatchExecutor::execOneInsert (this=this@entry=0x7f06b6a1a2b0, state=state@entry=0x7f06b6a19df0, error=error@entry=0x7f06b6a19dd0) at src/mongo/db/commands/write_commands/batch_executor.cpp:1083 #11 0x00000000009fd828 in mongo::WriteBatchExecutor::execInserts (this=this@entry=0x7f06b6a1a2b0, request=..., errors=errors@entry=0x7f06b6a1a0c0) at src/mongo/db/commands/write_commands/batch_executor.cpp:874 #12 0x00000000009fef74 in mongo::WriteBatchExecutor::bulkExecute (this=this@entry=0x7f06b6a1a2b0, request=..., upsertedIds=upsertedIds@entry=0x7f06b6a1a0e0, errors=errors@entry=0x7f06b6a1a0c0) at src/mongo/db/commands/write_commands/batch_executor.cpp:757 #13 0x00000000009ff675 in mongo::WriteBatchExecutor::executeBatch (this=this@entry=0x7f06b6a1a2b0, request=..., response=response@entry=0x7f06b6a1a2f0) at src/mongo/db/commands/write_commands/batch_executor.cpp:266 #14 0x0000000000a0164d in mongo::WriteCmd::run (this=, txn=0x7f06b6a1b660, dbName=..., cmdObj=..., options=, errMsg=..., result=..., fromRepl=false) at src/mongo/db/commands/write_commands/write_commands.cpp:144 #15 0x0000000000a1d3e4 in mongo::_execCommand (txn=txn@entry=0x7f06b6a1b660, c=c@entry=0x7f06bd7a75f0, dbname=..., cmdObj=..., queryOptions=queryOptions@entry=0, errmsg=..., result=..., fromRepl=fromRepl@entry=false) at src/mongo/db/dbcommands.cpp:1252 #16 0x0000000000a1e323 in mongo::Command::execCommand (txn=txn@entry=0x7f06b6a1b660, c=c@entry=0x7f06bd7a75f0, queryOptions=queryOptions@entry=0, cmdns=cmdns@entry=0x7f0533071414 "iibench.$cmd", cmdObj=..., result=..., fromRepl=fromRepl@entry=false) at src/mongo/db/dbcommands.cpp:1468 #17 0x0000000000a1eddb in mongo::_runCommands (txn=txn@entry=0x7f06b6a1b660, ns=0x7f0533071414 "iibench.$cmd", _cmdobj=..., b=..., anObjBuilder=..., fromRepl=fromRepl@entry=false, queryOptions=0) at src/mongo/db/dbcommands.cpp:1543 #18 0x0000000000be9b8a in runCommands (fromRepl=false, queryOptions=, anObjBuilder=..., b=..., curop=..., jsobj=..., ns=, txn=0x7f06b6a1b660) at src/mongo/db/query/find.cpp:131 #19 mongo::runQuery (txn=txn@entry=0x7f06b6a1b660, m=..., q=..., curop=..., result=..., fromDBDirectClient=fromDBDirectClient@entry=false) at src/mongo/db/query/find.cpp:565 #20 0x0000000000afe8d5 in receivedQuery (fromDBDirectClient=false, m=..., dbresponse=..., c=..., txn=0x7f06b6a1b660) at src/mongo/db/instance.cpp:224 #21 mongo::assembleResponse (txn=txn@entry=0x7f06b6a1b660, m=..., dbresponse=..., remote=..., fromDBDirectClient=fromDBDirectClient@entry=false) at src/mongo/db/instance.cpp:394 #22 0x00000000008562a0 in mongo::MyMessageHandler::process (this=, m=..., port=0x7f06b6442dd0, le=0x7f0533023060) at src/mongo/db/db.cpp:195 #23 0x0000000000f4b7e1 in mongo::PortMessageServer::handleIncomingMsg (arg=0x7f06bd46a7e0) at src/mongo/util/net/message_server_port.cpp:234 #24 0x00007f06be15afa8 in start_thread () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0 #25 0x00007f06bde7d5ad in clone () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libc.so.6 mdcallag commented on Wed, 21 Jan 2015 22:47:09 +0000: Output from "db.currentOp()" { "desc" : "conn22", "threadId" : "0x7f05cfba61c0", "connectionId" : 22, "opid" : 127, "active" : true, "secs_running" : 2068, "microsecs_running" : NumberLong(2068470297), "op" : "query", "ns" : "iibench.$cmd", "query" : { "createIndexes" : "purchases_index", "indexes" : [ { "key" : { "price" : 1, "dateandtime" : 1, "customerid" : 1 }, "name" : "price_1_dateandtime_1_customerid_1", "background" : true } ] }, "client" : "127.0.0.1:58927", "msg" : "Index Build (background) Index Build (background): 69799031/87019600 80%", "progress" : { "done" : 69799032, "total" : 87019600 }, "locks" : { "Global" : "w", "Database" : "w", "Collection" : "w" }, "waitingForLock" : false, "lockStats" : { } }, { "desc" : "conn23", "threadId" : "0x7f053101a1c0", "connectionId" : 23, "opid" : 133, "active" : true, "secs_running" : 150, "microsecs_running" : NumberLong(150361708), "op" : "query", "ns" : "iibench.$cmd", "query" : { "listCollections" : 1, "cursor" : { } }, "client" : "127.0.0.1:30444", "killPending" : true, "locks" : { "Global" : "r", "Database" : "R" }, "waitingForLock" : true, "lockStats" : { } } ] }
1) Create a large collection (I used iibench-mongodb) 2) drop all secondary indexes it uses 3) Run: db.purchases_index.ensureIndex( {"price":1, "customerid":1} , {"background":true} ) 4) in another shell run the commands "show collections" and "db.purchases_index.getIndexes() The problem does not reproduce with mmapv1. The problem was produced with the WT btree