kill命令正常执行,但进程迟迟没有退出。非必现场景,在批量回收资源时比较容易出现,平时开发测试时没有遇到。从场景上看出现的概率并不高,可能是在某种极端条件下才能触发,由于第一次收到报告后没有保留现场,先到官方JIRA平台上去搜相关的BUG,无果,又盲目的尝试了几个场景后只能先Hold住,等待下次出现。

很幸运,第二天BUG再次出现,僵尸进程?死循环?死锁?没有收到Kill信号?无数想法蹦出来,迅速登陆机器,查看现场,先从最简单的可能性开始开始排查。

top第一套组合拳,排除了僵尸进程可能性,并且TOP显示CPU使用率为0并不高;strace继续跟进查看,也没有发现有系统调用,最后在补一个pstack打印堆栈信息,全部线程都在wait。BUG的排查方向大致确定:线程间资源同步的问题(当然也不能排除是其他的可能性)。

详细分析pstack内容,从堆栈信息中看一个长相特别的(其他大部分的线程堆栈都是雷同的):

  1. 97 void ReplicationCoordinatorExternalStateImpl::shutdown() {
  2. 98 boost::lock_guard<boost::mutex> lk(_threadMutex);
  3. 99 if (_startedThreads) {
  4. 100 log() << "Stopping replication applier threads";
  5. 101 _syncSourceFeedback.shutdown();
  6. 102 _syncSourceFeedbackThread->join();
  7. 103 _applierThread->join();
  8. 104 BackgroundSync* bgsync = BackgroundSync::get();
  9. 106 _producerThread->join();
  10. 107 }
  11. 108 }

这么多的join,到底是哪个呢。上GDB,我们来看看Thread 46到底在等谁。先加载symbol-file,失败,加载后堆栈变得更乱了,换disassemble命令,显示汇编信息:

查看0x0000000000c8eeb7地址的上下文,通过前后指令的函数符号名确定了目前代码是在_applierThread->join(),这里可以思考下是否还有的其他方法获得代码行。

_applierThread 同样也是个线程,如果shutdown在等它,那它又在等谁呢,回头继续查pstack输出,找到相关的堆栈:

  1. Thread 34 (Thread 0x2b5f0a6d8700 (LWP 1355)):
  2. #1 0x0000000000c2687b in mongo::repl::BackgroundSync::waitUntilPaused() ()
  3. #2 0x0000000000cd192e in mongo::repl::SyncTail::tryPopAndWaitForMore(mongo::OperationContext*, mongo::repl::SyncTail::OpQueue*, mongo::repl::ReplicationCoordinator*) ()
  4. #3 0x0000000000cd2823 in mongo::repl::SyncTail::oplogApplication() ()
  5. #4 0x0000000000ccaaaf in mongo::repl::runSyncThread() ()
  6. #5 0x0000000000feb384 in ?? ()
  7. #6 0x0000003018007851 in start_thread () from /lib64/libpthread.so.0
  8. #7 0x000000300a4e767d in clone () from /lib64/libc.so.6

注意这里与shutdown的等待是不同的,shutdown是在等待线程退出,而这里是在等待某个条件变量,再次上GDB,查看Thread 34 & backtrace 1, info locals

  1. 469 void BackgroundSync::waitUntilPaused() {
  2. 470 boost::unique_lock<boost::mutex> lock(_mutex);
  3. 472 _pausedCondition.wait(lock);
  4. 473 }
  5. 474 }

_pause变量一直都是0,所以会hang在这里。继续查看代码,跟踪_pausedCondition的调用,有两个函数会去唤醒,一个是stop,另一个是shutdown,但shutdown的调用应该在线程退后调用,以便释放资源。

同时,再次回过来在pstack中查看BackgroundSync的堆栈信息,想看看到底卡在了哪里。结果找不到BackgroundSync线程,问题更清晰了,所有条件变量的唤醒,都是在该线程中完成的,如果BackgroundSync已经不存在了,一定会hang住。

再反复阅读代码,BackgroundSync在判断到inShutdown()时会自动结束生命周期,但结束后并没有更改_pause状态。

解决办法是线程最后退出前执行stop函数,修改_pause状态,(shutdown会提前释放资源),查看官方最最新代码,确认有同样的修改,反向追踪提交,找到相关,抱怨JIRA的搜索弱爆了。

  1. 1908 case kActionWinElection: {
  2. 1909 boost::unique_lock<boost::mutex> lk(_mutex);
  3. 1910 _electionId = OID::gen();
  4. 1911 _topCoord->processWinElection(_electionId, getNextGlobalOptime());
  5. 1912 _isWaitingForDrainToComplete = true;
  6. 1913 const PostMemberStateUpdateAction nextAction =
  7. 1914 _updateMemberStateFromTopologyCoordinator_inlock();
  8. 1915 invariant(nextAction != kActionWinElection);
  9. 1916 lk.unlock();
  10. 1917 _performPostMemberStateUpdateAction(nextAction);
  11. 1918 break;

也就是说刚刚赢得了选举后会产生_isWaitingForDrainToComplete == true状态,恰巧这个时间窗口内进程接受到退出信号。复现的办法就是在 的后面加上sleep,以此来延长时间窗口,当然也可以通过GDB BLOCK的方式来复现。