[SERVER-16980] background ensureIndex blocks too many operations with WiredTiger Created: 21/Jan/15  Updated: 22/Jan/15  Resolved: 22/Jan/15

Status: Closed
Project: Core Server
Component/s: Storage, WiredTiger
Affects Version/s: 2.8.0-rc4
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Mark Callaghan Assignee: Ramon Fernandez Marina
Resolution: Duplicate Votes: 0
Labels: wiredtiger
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-16431 Get rid of the ParallelBatchWriter mu... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

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

Participants:

 Description   

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



 Comments   
Comment by Ramon Fernandez Marina [ 22/Jan/15 ]

mdcallag, I went back to rc4 and I do see the temporary hangs in some operations, most notably show collections. Therefore I'm going to mark this ticket as "fixed" in rc5 – thanks for your report!

Comment by Ramon Fernandez Marina [ 22/Jan/15 ]

Nevermind – it was pointed out to me I have a typo in my index build command, which turns it into a foreground index build and hence blocks other operations. I'm not able to reproduce hangs in either rc5 or master right now, so I'm going to resolve this ticket. Apologies for the pilot error, and thanks for your all your help mdcallag.

Comment by Mark Callaghan [ 22/Jan/15 ]

Thanks for reproducing this.

Now I easily get the hang in rc4 for this, but my longer running test did not get it for rc5

db.purchases_index.ensureIndex({"price":1, "customerid":1}, {"background":true});

And these are all of the ensureIndex commands

db.purchases_index.ensureIndex({"price":1, "customerid":1}, {"background":true});
db.purchases_index.ensureIndex({"cashregisterid" : 1, "price" : 1, "customerid" : 1}, {"background":true});
db.purchases_index.ensureIndex({"price" : 1, "dateandtime" : 1, "customerid" : 1}, {"background":true});

Thread stacks from an rc4 hang

      1 select,mongo::Listener::initAndListen,_initAndListen,mongo::initAndListen,mongoDbMain,main
      1 __rec_row_leaf,__wt_reconcile,__evict_review,__wt_evict,__wt_evict_page,__wt_evict_lru_page,__evict_lru_pages,__evict_server_work,__evict_pass,__evict_server,start_thread,clone
      1 pthread_cond_wait@@GLIBC_2.3.2,wait<boost::unique_lock<boost::timed_mutex>,mongo::DeadlineMonitor<mongo::V8Scope>::deadlineMonitorThread,boost::(anonymous,start_thread,clone
      1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__sweep_server,start_thread,clone
      1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__log_server,start_thread,clone
      1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__ckpt_server,start_thread,clone
      1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait,timed_wait<boost::date_time::subsecond_duration<boost::posix_time::time_duration,,mongo::CondVarLockGrantNotification::wait,mongo::LockerImpl<false>::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<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::RangeDeleter::doWork,boost::(anonymous,start_thread,clone
      1 pthread_cond_timedwait@@GLIBC_2.3.2,boost::condition_variable_any::timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::(anonymous,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
      1 nanosleep,mongo::sleepsecs,mongo::TTLMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
      1 nanosleep,mongo::sleepsecs,mongo::ClientCursorMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
      1 mongo::IndexEntryComparison::compare,Compare,mongo::(anonymous,__wt_compare,__wt_row_search,__cursor_row_search,__wt_btcur_insert,__curfile_insert,mongo::WiredTigerIndexStandard::_insert,mongo::WiredTigerIndex::insert,mongo::BtreeBasedAccessMethod::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

And db.currentOp output from an rc4 hang

{
        "inprog" : [
                {
                        "desc" : "conn11",
                        "threadId" : "0x7f471c6371c0",
                        "connectionId" : 11,
                        "opid" : 21000592,
                        "active" : true,
                        "secs_running" : 24,
                        "microsecs_running" : NumberLong(24965946),
                        "op" : "query",
                        "ns" : "iibench.$cmd",
                        "query" : {
                                "createIndexes" : "purchases_index",
                                "indexes" : [
                                        {
                                                "key" : {
                                                        "price" : 1,
                                                        "customerid" : 1
                                                },
                                                "name" : "price_1_customerid_1",
                                                "background" : true
                                        }
                                ]
                        },
                        "client" : "127.0.0.1:23499",
                        "msg" : "Index Build (background) Index Build (background): 1047370/10000000 10%",
                        "progress" : {
                                "done" : 1047371,
                                "total" : 10000000
                        },
                        "locks" : {
                                "Global" : "w",
                                "Database" : "w",
                                "Collection" : "w"
                        },
                        "waitingForLock" : false,
                        "lockStats" : {
                                
                        }
                },
                {
                        "desc" : "conn3",
                        "threadId" : "0x7f47dcc1a1c0",
                        "connectionId" : 3,
                        "opid" : 21000593,
                        "active" : true,
                        "secs_running" : 22,
                        "microsecs_running" : NumberLong(22056485),
                        "op" : "query",
                        "ns" : "iibench.$cmd",
                        "query" : {
                                "listCollections" : 1,
                                "cursor" : {
                                        
                                }
                        },
                        "client" : "127.0.0.1:19927",
                        "locks" : {
                                "Global" : "r",
                                "Database" : "R"
                        },
                        "waitingForLock" : true,
                        "lockStats" : {
                                
                        }
                }
        ]
}

Comment by Ramon Fernandez Marina [ 22/Jan/15 ]

mdcallag, what index where you building? I tried:

db.purchases_index.ensureIndex({dateandtime: 1, customerid: 1, price: 1}, {background:true})

and operations like show collections or db.purchases_index.getIndexes() would complete immediately. But when I try:

db.purchases_index.ensureIndex({productid:1, price:1}, {backtround:true})

the operations listed above, along with db.purchases_index.insert({foo:1}) hang. Here's the output of db.currentOp():

MongoDB shell version: 2.8.0-rc6-pre-
connecting to: test
{
        "inprog" : [
                {
                        "desc" : "conn29",
                        "threadId" : "0x13316c820",
                        "connectionId" : 29,
                        "opid" : 111863625,
                        "active" : true,
                        "secs_running" : 10,
                        "microsecs_running" : NumberLong(10965280),
                        "op" : "query",
                        "ns" : "iibench2.$cmd",
                        "query" : {
                                "listIndexes" : "purchases_index"
                        },
                        "client" : "127.0.0.1:50927",
                        "numYields" : 0,
                        "locks" : {
                                "Global" : "r",
                                "Database" : "r"
                        },
                        "waitingForLock" : true,
                        "lockStats" : {
                                "Global" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(1),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "MMAPV1Journal" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Database" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(1),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(1),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(115516275),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Collection" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Metadata" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "oplog" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                }
                        }
                },
                {
                        "desc" : "conn27",
                        "threadId" : "0x13316d040",
                        "connectionId" : 27,
                        "opid" : 111863610,
                        "active" : true,
                        "secs_running" : 286,
                        "microsecs_running" : NumberLong(286416042),
                        "op" : "query",
                        "ns" : "iibench2.$cmd",
                        "query" : {
                                "listCollections" : 1
                        },
                        "client" : "127.0.0.1:50668",
                        "numYields" : 0,
                        "locks" : {
                                "Global" : "r",
                                "Database" : "R"
                        },
                        "waitingForLock" : true,
                        "lockStats" : {
                                "Global" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(1),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "MMAPV1Journal" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Database" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(1),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(1),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong("81949279334"),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Collection" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Metadata" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "oplog" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                }
                        }
                },
                {
                        "desc" : "conn18",
                        "threadId" : "0x1deca6be0",
                        "connectionId" : 18,
                        "opid" : 111863613,
                        "active" : true,
                        "secs_running" : 236,
                        "microsecs_running" : NumberLong(236683745),
                        "op" : "insert",
                        "ns" : "iibench2.puchases_index",
                        "insert" : {
                                "_id" : ObjectId("54c106d1ef312bda7f783775"),
                                "foo" : 1
                        },
                        "client" : "127.0.0.1:50045",
                        "numYields" : 0,
                        "locks" : {
                                "Global" : "w",
                                "Database" : "w"
                        },
                        "waitingForLock" : true,
                        "lockStats" : {
                                "Global" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(4),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "MMAPV1Journal" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Database" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(3),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(1)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(2),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(1)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong("139156501043"),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(11817)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Collection" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(2),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(1)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Metadata" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "oplog" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                }
                        }
                },
                {
                        "desc" : "conn13",
                        "threadId" : "0xb91fbee0",
                        "connectionId" : 13,
                        "opid" : 111863603,
                        "active" : true,
                        "secs_running" : 296,
                        "microsecs_running" : NumberLong(296788833),
                        "op" : "query",
                        "ns" : "iibench2.$cmd",
                        "query" : {
                                "createIndexes" : "purchases_index",
                                "indexes" : [
                                        {
                                                "key" : {
                                                        "productid" : 1,
                                                        "price" : 1
                                                },
                                                "name" : "productid_1_price_1",
                                                "backtround" : true
                                        }
                                ]
                        },
                        "client" : "127.0.0.1:44017",
                        "msg" : "Index Build Index Build: 53049457/55902311 94%",
                        "progress" : {
                                "done" : 53049457,
                                "total" : 55902311
                        },
                        "numYields" : 0,
                        "locks" : {
                                "Global" : "w",
                                "Database" : "W",
                                "Collection" : "w"
                        },
                        "waitingForLock" : false,
                        "lockStats" : {
                                "Global" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(11),
                                                "w" : NumberLong(7),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "MMAPV1Journal" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Database" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(8),
                                                "w" : NumberLong(1),
                                                "R" : NumberLong(3),
                                                "W" : NumberLong(6)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(2),
                                                "W" : NumberLong(3)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(22225),
                                                "W" : NumberLong(4211)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Collection" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(4),
                                                "w" : NumberLong(3),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "Metadata" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                },
                                "oplog" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "acquireWaitCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "timeAcquiringMicros" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        },
                                        "deadlockCount" : {
                                                "r" : NumberLong(0),
                                                "w" : NumberLong(0),
                                                "R" : NumberLong(0),
                                                "W" : NumberLong(0)
                                        }
                                }
                        }
                }
        ]
}

And this is my startup log (I forgot to remove the direct_io config string after all):

2015-01-21T22:48:51.920-0500 I CONTROL  [initandlisten] MongoDB starting : pid=29650 port=27017 dbpath=/home/rf/tmp/SERVER-169
80/db 64-bit host=tab
2015-01-21T22:48:51.920-0500 I CONTROL  [initandlisten]
2015-01-21T22:48:51.921-0500 I CONTROL  [initandlisten] db version v2.8.0-rc6-pre-
2015-01-21T22:48:51.921-0500 I CONTROL  [initandlisten] git version: fc0d56be2cc3ba75fecd7d9047942cf686815dfe
2015-01-21T22:48:51.921-0500 I CONTROL  [initandlisten] build info: Linux tab 3.13.0-36-generic #63-Ubuntu SMP Wed Sep 3 21:30
:07 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49
2015-01-21T22:48:51.921-0500 I CONTROL  [initandlisten] allocator: tcmalloc
2015-01-21T22:48:51.921-0500 I CONTROL  [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "/hom
e/rf/tmp/SERVER-16980/db", engine: "wiredTiger", wiredTiger: { engineConfig: { cacheSizeGB: 8, configString: "direct_io=[data]
" } } }, systemLog: { destination: "file", logAppend: true, path: "/home/rf/tmp/SERVER-16980/mongod.log" } }
2015-01-21T22:48:51.921-0500 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=8G,session_max=20000,evictio
n=(threads_max=4),statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),checkpoint=(wait=60,log_siz
e=2GB),statistics_log=(wait=0),direct_io=[data]
2015-01-21T22:48:51.996-0500 I NETWORK  [initandlisten] waiting for connections on port 27017

Comment by Mark Callaghan [ 22/Jan/15 ]

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.

Comment by Eric Milkie [ 22/Jan/15 ]

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.

Comment by Ramon Fernandez Marina [ 22/Jan/15 ]

Thanks mdcallag, that's what I was looking for.

Comment by Mark Callaghan [ 22/Jan/15 ]

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%

Comment by Ramon Fernandez Marina [ 22/Jan/15 ]

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.

Comment by Mark Callaghan [ 22/Jan/15 ]

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<boost::date_time::subsecond_duration<boost::posix_time::time_duration,,mongo::CondVarLockGrantNotification::wait,mongo::LockerImpl<false>::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<boost::date_time::subsecond_duration<boost::posix_time::time_duration,,mongo::CondVarLockGrantNotification::wait,mongo::LockerImpl<false>::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<boost::date_time::subsecond_duration<boost::posix_time::time_duration,,mongo::CondVarLockGrantNotification::wait,mongo::LockerImpl<false>::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<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::RangeDeleter::doWork,boost::(anonymous,start_thread,clone
      1 pthread_cond_timedwait@@GLIBC_2.3.2,boost::condition_variable_any::timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,timed_wait<boost::unique_lock<boost::timed_mutex>,,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<boost::unique_lock<boost::timed_mutex> > (wait_until=..., m=..., this=0x7f91bb871e10) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:161
#2  timed_wait<boost::unique_lock<boost::timed_mutex>, boost::date_time::subsecond_duration<boost::posix_time::time_duration, 1000l> > (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=<optimized out>) 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<boost::date_time::subsecond_duration<boost::posix_time::time_duration, 1000l> > (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=<optimized out>) at src/mongo/db/concurrency/lock_state.cpp:254
#4  0x0000000000a17613 in mongo::LockerImpl<false>::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=<optimized out>) 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=<optimized out>) 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<boost::date_time::subsecond_duration<boost::posix_time::time_duration, 1000l> > (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=<optimized out>) at src/mongo/db/concurrency/lock_state.cpp:254
#4  0x0000000000a17613 in mongo::LockerImpl<false>::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=<optimized out>) 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=<optimized out>) at src/mongo/db/catalog/cursor_manager.cpp:289
#10 0x0000000000983235 in mongo::ClientCursorMonitor::run (this=<optimized out>) at src/mongo/db/clientcursor.cpp:290
#11 0x0000000000f32880 in mongo::BackgroundJob::jobBody (this=0x1caeb00 <mongo::(anonymous namespace)::clientCursorMonitor>) at src/mongo/util/background.cpp:163
#12 0x0000000000feb354 in boost::(anonymous namespace)::thread_proxy (param=<optimized out>) 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<boost::unique_lock<boost::timed_mutex> > (this=this@entry=0x7f91bb986048, m=..., wait_until=...) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:161
#2  0x0000000000f333f6 in timed_wait<boost::unique_lock<boost::timed_mutex>, std::function<bool()> > (pred=..., wait_until=..., m=..., this=0x7f91bb986048) at src/third_party/boost/boost/thread/pthread/condition_variable.hpp:191
#3  timed_wait<boost::unique_lock<boost::timed_mutex>, std::function<bool()> > (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=<optimized out>) 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=<optimized out>, l=..., r=...) at src/mongo/db/index/btree_based_bulk_access_method.cpp:68
#2  0x0000000000addfc7 in operator() (rhs=..., lhs=..., this=<synthetic pointer>) at src/mongo/db/sorter/sorter.cpp:436
#3  std::__move_merge<std::pair<mongo::BSONObj, mongo::RecordId>*, std::pair<mongo::BSONObj, mongo::RecordId>*, std::_Deque_iterator<std::pair<mongo::BSONObj, mongo::RecordId>, std::pair<mongo::BSONObj, mongo::RecordId>&, std::pair<mongo::BSONObj, mongo::RecordId>*>, mongo::sorter::NoLimitSorter<mongo::BSONObj, mongo::RecordId, mongo::BtreeExternalSortComparison>::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::pair<mongo::BSONObj, mongo::RecordId>*, std::_Deque_iterator<std::pair<mongo::BSONObj, mongo::RecordId>, std::pair<mongo::BSONObj, mongo::RecordId>&, std::pair<mongo::BSONObj, mongo::RecordId>*>, long, mongo::sorter::NoLimitSorter<mongo::BSONObj, mongo::RecordId, mongo::BtreeExternalSortComparison>::STLComparator> (__comp=..., __step_size=3584, __result=..., __last=0x7f82c26aaab8, __first=<optimized out>) 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::_Deque_iterator<std::pair<mongo::BSONObj, mongo::RecordId>, std::pair<mongo::BSONObj, mongo::RecordId>&, std::pair<mongo::BSONObj, mongo::RecordId>*>, std::pair<mongo::BSONObj, mongo::RecordId>*, mongo::sorter::NoLimitSorter<mongo::BSONObj, mongo::RecordId, mongo::BtreeExternalSortComparison>::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::_Deque_iterator<std::pair<mongo::BSONObj, mongo::RecordId>, std::pair<mongo::BSONObj, mongo::RecordId>&, std::pair<mongo::BSONObj, mongo::RecordId>*>, std::pair<mongo::BSONObj, mongo::RecordId>*, long, mongo::sorter::NoLimitSorter<mongo::BSONObj, mongo::RecordId, mongo::BtreeExternalSortComparison>::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::_Deque_iterator<std::pair<mongo::BSONObj, mongo::RecordId>, std::pair<mongo::BSONObj, mongo::RecordId>&, std::pair<mongo::BSONObj, mongo::RecordId>*>, mongo::sorter::NoLimitSorter<mongo::BSONObj, mongo::RecordId, mongo::BtreeExternalSortComparison>::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<mongo::BSONObj, mongo::RecordId, mongo::BtreeExternalSortComparison>::sort (this=this@entry=0x7f91abcc8f40) at src/mongo/db/sorter/sorter.cpp:444
#9  0x0000000000adfdd0 in mongo::sorter::NoLimitSorter<mongo::BSONObj, mongo::RecordId, mongo::BtreeExternalSortComparison>::spill (this=this@entry=0x7f91abcc8f40) at src/mongo/db/sorter/sorter.cpp:467
#10 0x0000000000ae0067 in mongo::sorter::NoLimitSorter<mongo::BSONObj, mongo::RecordId, mongo::BtreeExternalSortComparison>::add (this=0x7f91abcc8f40, key=..., val=...) at src/mongo/db/sorter/sorter.cpp:413
#11 0x0000000000ad5715 in mongo::BtreeBasedBulkAccessMethod::insert (this=0x7f8d89cdbd40, txn=<optimized out>, 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=<optimized out>, txn=0x7f91bc19b680, dbname=..., cmdObj=..., options=<optimized out>, 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 <mongo::cmdCreateIndex>, 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 <mongo::cmdCreateIndex>, 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=<optimized out>, anObjBuilder=..., b=..., curop=..., jsobj=..., ns=<optimized out>, 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=<optimized out>, 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<boost::date_time::subsecond_duration<boost::posix_time::time_duration, 1000l> > (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=<optimized out>) at src/mongo/db/concurrency/lock_state.cpp:254
#4  0x0000000000a17613 in mongo::LockerImpl<false>::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=<optimized out>) 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 <mongo::cmdListCollections>, 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 <mongo::cmdListCollections>, 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 <mongo::cmdListCollections>, 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=<optimized out>, anObjBuilder=..., b=..., curop=..., jsobj=..., ns=<optimized out>, 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=<optimized out>, 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=<optimized out>) at src/mongo/db/db.cpp:621
#3  mongo::initAndListen (listenPort=<optimized out>) at src/mongo/db/db.cpp:626
#4  0x00000000008568a4 in mongoDbMain (envp=<optimized out>, argv=0x7fff4c0491c8, argc=<optimized out>) at src/mongo/db/db.cpp:872
#5  main (argc=7, argv=0x7fff4c0491c8, envp=<optimized out>) at src/mongo/db/db.cpp:675
Detaching from program: /data/mysql/mongo.280rc4/bin/mongod.rc5.jem.dbg, process 9402

Comment by Ramon Fernandez Marina [ 22/Jan/15 ]

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.

Comment by Mark Callaghan [ 22/Jan/15 ]

And now I can't reproduce this which makes me think my original test was using background:false

Comment by Mark Callaghan [ 21/Jan/15 ]

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=<optimized out>) 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=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:251
#7  0x0000000000da89e0 in mongo::WiredTigerIndex::insert (this=0x7f05cedeb060, txn=<optimized out>, key=..., loc=..., dupsAllowed=<optimized out>) 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=<optimized out>, txn=0x7f06bf5f9660, dbname=..., cmdObj=..., options=<optimized out>, 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 <mongo::cmdCreateIndex>, 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 <mongo::cmdCreateIndex>, 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=<optimized out>, anObjBuilder=..., b=..., curop=..., jsobj=..., ns=<optimized out>, 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=<optimized out>, 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<boost::date_time::subsecond_duration<boost::posix_time::time_duration, 1000l> > (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=<optimized out>) at src/mongo/db/concurrency/lock_state.cpp:189
#4  0x0000000000a14fd2 in mongo::LockerImpl<false>::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=<optimized out>) 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 <mongo::cmdListCollections>, 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 <mongo::cmdListCollections>, 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 <mongo::cmdListCollections>, 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=<optimized out>, anObjBuilder=..., b=..., curop=..., jsobj=..., ns=<optimized out>, 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=<optimized out>, 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<boost::date_time::subsecond_duration<boost::posix_time::time_duration, 1000l> > (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=<optimized out>) at src/mongo/db/concurrency/lock_state.cpp:189
#4  0x0000000000a14fd2 in mongo::LockerImpl<false>::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=<optimized out>) 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=<optimized out>, 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=<optimized out>, txn=0x7f06b6a1b660, dbName=..., cmdObj=..., options=<optimized out>, 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=<optimized out>, anObjBuilder=..., b=..., curop=..., jsobj=..., ns=<optimized out>, 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=<optimized out>, 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

Comment by Mark Callaghan [ 21/Jan/15 ]

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" : {
 
                        }
                }
        ]
}

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