MongoDB · 捉蟲動態 · Kill Hang問題排查記錄 · 數據庫內核月報

AliCloudDB MongoDB在開發過程中遇到一個無法正常退出的BUG，由于是Release版本的編譯（-O3），debuginfo已經不能很好的展現出堆棧的情況。這時又該如何確定問題所在呢？本篇文章完整的記錄了整個排查過程。 ## 場景 kill命令正常執行，但進程遲遲沒有退出。非必現場景，在批量回收資源時比較容易出現，平時開發測試時沒有遇到。從場景上看出現的概率并不高，可能是在某種極端條件下才能觸發，由于第一次收到報告后沒有保留現場，先到官方JIRA平臺上去搜相關的BUG，無果，又盲目的嘗試了幾個場景后只能先Hold住，等待下次出現。 ## 排查 ### 確認BUG方向很幸運，第二天BUG再次出現，僵尸進程？死循環？死鎖？沒有收到Kill信號？無數想法蹦出來，迅速登陸機器，查看現場，先從最簡單的可能性開始開始排查。 `ps`?`top`第一套組合拳，排除了僵尸進程可能性，并且TOP顯示CPU使用率為0并不高；strace繼續跟進查看，也沒有發現有系統調用，最后在補一個pstack打印堆棧信息，全部線程都在wait。BUG的排查方向大致確定：線程間資源同步的問題（當然也不能排除是其他的可能性）。 ### 確認代碼范圍詳細分析pstack內容，從堆棧信息中看一個長相特別的（其他大部分的線程堆棧都是雷同的）： ~~~ Thread 46 (Thread 0x2b5f079be700 (LWP 613)): #0 0x000000301800b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000fec763 in boost::thread::join() () #2 0x0000000000c8eebc in mongo::repl::ReplicationCoordinatorExternalStateImpl::shutdown() () #3 0x0000000000c93fed in mongo::repl::ReplicationCoordinatorImpl::shutdown() () #4 0x0000000000ad2463 in mongo::exitCleanly(mongo::ExitCode) () #5 0x0000000000f9c176 in ?? () #6 0x0000000000feb384 in ?? () #7 0x0000003018007851 in start_thread () from /lib64/libpthread.so.0 #8 0x000000300a4e767d in clone () from /lib64/libc.so.6 ~~~ 從函數名上看起來是MongoDB退出的關鍵路徑，就從這里入手，人肉翻下源碼： ~~~ 97 void ReplicationCoordinatorExternalStateImpl::shutdown() { 98 boost::lock_guard<boost::mutex> lk(_threadMutex); 99 if (_startedThreads) { 100 log() << "Stopping replication applier threads"; 101 _syncSourceFeedback.shutdown(); 102 _syncSourceFeedbackThread->join(); 103 _applierThread->join(); 104 BackgroundSync* bgsync = BackgroundSync::get(); 105 bgsync->shutdown(); 106 _producerThread->join(); 107 } 108 } ~~~ 這么多的join，到底是哪個呢。上GDB，我們來看看Thread 46到底在等誰。先加載symbol-file，失敗，加載后堆棧變得更亂了，換`disassemble`命令，顯示匯編信息： ~~~ 0x0000000000c8ee6b <+75>: mov %rsp,%rdi 0x0000000000c8ee6e <+78>: callq 0xdc8670 <_ZN5mongo6logger16LogstreamBuilder10makeStreamEv> 0x0000000000c8ee73 <+83>: mov 0x20(%rsp),%rdi 0x0000000000c8ee78 <+88>: lea 0x86e299(%rip),%rsi # 0x14fd118 0x0000000000c8ee7f <+95>: mov $0x24,%edx 0x0000000000c8ee84 <+100>: callq 0x1456550 <_ZSt16__ostream_insertIcSt11char_traitsIcEERSt13basic_ostreamIT_T0_ES6_PKS3_l> 0x0000000000c8ee89 <+105>: mov %rsp,%rdi 0x0000000000c8ee8c <+108>: callq 0xdc88d0 <_ZN5mongo6logger16LogstreamBuilderD2Ev> 0x0000000000c8ee91 <+113>: lea 0x38(%rbp),%rdi 0x0000000000c8ee95 <+117>: callq 0xcce810 <_ZN5mongo4repl18SyncSourceFeedback8shutdownEv> 0x0000000000c8ee9a <+122>: mov 0xe8(%rbp),%rdi 0x0000000000c8eea1 <+129>: test %rdi,%rdi 0x0000000000c8eea4 <+132>: je 0xc8ef14 <_ZN5mongo4repl39ReplicationCoordinatorExternalStateImpl8shutdownEv+244> 0x0000000000c8eea6 <+134>: callq 0xfec600 <_ZN5boost6thread4joinEv> 0x0000000000c8eeab <+139>: mov 0xf0(%rbp),%rdi 0x0000000000c8eeb2 <+146>: test %rdi,%rdi 0x0000000000c8eeb5 <+149>: je 0xc8ef14 <_ZN5mongo4repl39ReplicationCoordinatorExternalStateImpl8shutdownEv+244> 0x0000000000c8eeb7 <+151>: callq 0xfec600 <_ZN5boost6thread4joinEv> => 0x0000000000c8eebc <+156>: callq 0xc284a0 <_ZN5mongo4repl14BackgroundSync3getEv> 0x0000000000c8eec1 <+161>: mov %rax,%rdi 0x0000000000c8eec4 <+164>: callq 0xc27f60 <_ZN5mongo4repl14BackgroundSync8shutdownEv> 0x0000000000c8eec9 <+169>: mov 0xf8(%rbp),%rdi 0x0000000000c8eed0 <+176>: test %rdi,%rdi 0x0000000000c8eed3 <+179>: je 0xc8ef14 <_ZN5mongo4repl39ReplicationCoordinatorExternalStateImpl8shutdownEv+244> 0x0000000000c8eed5 <+181>: callq 0xfec600 <_ZN5boost6thread4joinEv> 0x0000000000c8eeda <+186>: nopw 0x0(%rax,%rax,1) 0x0000000000c8eee0 <+192>: mov %rbx,%rdi 0x0000000000c8eee3 <+195>: callq 0x804a38 <pthread_mutex_unlock@plt> 0x0000000000c8eee8 <+200>: cmp $0x4,%eax 0x0000000000c8eeeb <+203>: je 0xc8eee0 <_ZN5mongo4repl39ReplicationCoordinatorExternalStateImpl8shutdownEv+192> 0x0000000000c8eeed <+205>: test %eax,%eax 0x0000000000c8eeef <+207>: jne 0xc8ef0f <_ZN5mongo4repl39ReplicationCoordinatorExternalStateImpl8shutdownEv+239> 0x0000000000c8eef1 <+209>: add $0x38,%rsp 0x0000000000c8eef5 <+213>: pop %rbx 0x0000000000c8eef6 <+214>: pop %rbp 0x0000000000c8eef7 <+215>: pop %r12 0x0000000000c8eef9 <+217>: pop %r13 0x0000000000c8eefb <+219>: retq ~~~ 查看`0x0000000000c8eeb7`地址的上下文，通過前后指令的函數符號名確定了目前代碼是在`_applierThread->join()`，這里可以思考下是否還有的其他方法獲得代碼行。 `_applierThread`?同樣也是個線程，如果shutdown在等它，那它又在等誰呢，回頭繼續查pstack輸出，找到相關的堆棧： ~~~ Thread 34 (Thread 0x2b5f0a6d8700 (LWP 1355)): #0 0x000000301800b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000c2687b in mongo::repl::BackgroundSync::waitUntilPaused() () #2 0x0000000000cd192e in mongo::repl::SyncTail::tryPopAndWaitForMore(mongo::OperationContext*, mongo::repl::SyncTail::OpQueue*, mongo::repl::ReplicationCoordinator*) () #3 0x0000000000cd2823 in mongo::repl::SyncTail::oplogApplication() () #4 0x0000000000ccaaaf in mongo::repl::runSyncThread() () #5 0x0000000000feb384 in ?? () #6 0x0000003018007851 in start_thread () from /lib64/libpthread.so.0 #7 0x000000300a4e767d in clone () from /lib64/libc.so.6 ~~~ 注意這里與shutdown的等待是不同的，shutdown是在等待線程退出，而這里是在等待某個條件變量，再次上GDB，查看Thread 34 & backtrace 1,?`info locals`： ~~~ _lastOpTimeFetched = {i = 4, secs = 1448986976}, _lastAppliedHash = 3485900536827542548, _lastFetchedHash = 3485900536827542548, _pause = false, _pausedCondition = {internal_mutex = { __data = {__lock = 0, __count = 0, __owner = 0, __nusers = 1, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0} }, __size = '\000' <repeats 12 times>, "\001", '\000' <repeats 26 times>, __align = 0 } ~~~ ### 找到代碼BUG 看看代碼怎么寫的吧： ~~~ 469 void BackgroundSync::waitUntilPaused() { 470 boost::unique_lock<boost::mutex> lock(_mutex); 471 while (!_pause) { 472 _pausedCondition.wait(lock); 473 } 474 } ~~~ `_pause`變量一直都是0，所以會hang在這里。繼續查看代碼，跟蹤`_pausedCondition`的調用，有兩個函數會去喚醒，一個是stop，另一個是shutdown，但shutdown的調用應該在線程退后調用，以便釋放資源。同時，再次回過來在pstack中查看`BackgroundSync`的堆棧信息，想看看到底卡在了哪里。結果找不到`BackgroundSync`線程，問題更清晰了，所有`_pausedCondition`條件變量的喚醒，都是在該線程中完成的，如果`BackgroundSync`已經不存在了，一定會hang住。再反復閱讀代碼，`BackgroundSync`在判斷到`inShutdown()`時會自動結束生命周期，但結束后并沒有更改`_pause`狀態。 ## FIX BUG 解決辦法是線程最后退出前執行stop函數，修改`_pause`狀態，（shutdown會提前釋放資源），查看官方最最新代碼，確認有同樣的修改，反向追蹤提交，找到相關[JIRA](https://jira.mongodb.org/browse/SERVER-19782)，抱怨JIRA的搜索弱爆了。 ## 復現和驗證為何該BUG出現的頻率會非常低呢，主要在判斷是否等待的條件上： ~~~ if (replCoord->isWaitingForApplierToDrain()) { 506 BackgroundSync::get()->waitUntilPaused(); 507 if (peek(&op)) { 508 // The producer generated a last batch of ops before pausing so return 509 // false so that we'll come back and apply them before signaling the drain 510 // is complete. 511 return false; 512 } 513 replCoord->signalDrainComplete(txn); 514 } ~~~ ~~~ 1908 case kActionWinElection: { 1909 boost::unique_lock<boost::mutex> lk(_mutex); 1910 _electionId = OID::gen(); 1911 _topCoord->processWinElection(_electionId, getNextGlobalOptime()); 1912 _isWaitingForDrainToComplete = true; 1913 const PostMemberStateUpdateAction nextAction = 1914 _updateMemberStateFromTopologyCoordinator_inlock(); 1915 invariant(nextAction != kActionWinElection); 1916 lk.unlock(); 1917 _performPostMemberStateUpdateAction(nextAction); 1918 break; 1919 } ~~~ 也就是說剛剛贏得了選舉后會產生`_isWaitingForDrainToComplete == true`狀態，恰巧這個時間窗口內進程接受到退出信號。復現的辦法就是在`kActionWinElection`的后面加上sleep，以此來延長時間窗口，當然也可以通過GDB BLOCK的方式來復現。