2015年03月21日

Sigkill带来的挑战


SIGKILL信号,一次严峻挑战的线上问题排查

这个星期很大部分精力都放在了追踪线上程序频繁异常退出的原因,过程很曲折,被人挑战了,万幸的是,结果没有丢团队和自己的面子。很简单的,我们希望的总是当遇到问题时不回避,全力以赴的解决,不仅是为了更好的产品,还有更好的自己。

诡异问题


线上的问题是这样的,我们有三个程序,一个主程序称为PA,另一个称为PB,PB是为程序PA打辅助的,收集些简单的资源,代码逻辑很简单,最后一个程序称为PC,和他俩没什么多大关系。最近被告知PA和PB总是频繁重启,因此,开始查看这个问题。

将线上程序的现象总结归纳就是如下:

解决过程


最先的思路是查看程序的日志,发现PA和PB的日志表现十分正常,没有任何异常。由于对PA和PB的代码不怎么熟悉,因此怀疑可能是线上的环境突然触发了PA异常退出,我们尝试在代码里全局的搜索exit相关的代码,分析程序退出的动作,结果是退出前均会有日志记录。程序的退出也没有core文件,因此很棘手,查看了系统的messages和dmesg,翻了个底朝天,什么也没有。

开始转变思路,毫无头绪的情况下,只能使用大杀器,strace来跟踪程序的系统调用,希望能发现蛛丝马迹。

strace -fo /tmp/strace.out -p PID

结果给人带来了些希望,发现strace.out文件最后一行是SIGKILL信息,原来程序是被SIGKILL干掉的,对于SIGKILL,我们知道程序是毫无招架之力,直接挂掉,没有日志,没有core,这个结果很符合观察到的现象,我们分析SIGKILL信号的问题同时,再次对程序进行了strace跟踪,好确定不是偶然的。

分析SIGKILL信号产生的原因,最开始,将目光聚集在了系统负载上,以为程序的ulimit达到了上线,被内核无情的干掉。关于SIGKILL的产生场景,可以参考下面的文档:

因此我们查看进程的ulimit限制,发现各项设置均都很正常,网上对于此SIGKILL最常说的一个原因是OOM,如果是这样,内核就会干掉程序,留下印记在/var/log/messages里,我们再仔细分析了此情况,发现系统中无任何相关日志。对于系统中的dmesg日志和messages或syslog日志,可以参考下面的文章,知道什么样的信息会记录在其中:

对于OOM,可以再补充下,每个进程有一oom_scores和oom_adj两个文件,里面的内容以及OOM killer机制,可以参考下面的文档:

可以大致确定不是ulimit的问题,同时还观察到程序再次挂掉也是SIGKILL的原因。

随后对比PA和PB的日志,发现关键的现象了,两个程序总是同时挂掉,同时重启,因为PB是打辅助,代码简单,因此我们迅速扫了一眼PB的代码,发现这个程序基本上不可能这么诡异的自己挂掉而没有任何信息。因此,可以明确的认定程序挂掉的原因是外界的SIGKILL信号。

得出这个结论之后,我们需要更完整的验证,google一番,找到了强大的杀器,systemtap,可以先参考下面的文章:

在上面这篇文章中,介绍了通过systemtap来跟踪SIGKILL的方法,用完之后,方知强大。跟踪信号源,需要安装kernel-debuginfo, kernel-debuginfo-common 两个包,注意在安装时最好google到和内核版本一致的包,不然运行脚本时会出问题,难得再卸载重装。我们需要监控SIGKILL源,将上文中的监控代码再添加一个输出如下:

probe signal.send{
    if(sig_name == "SIGKILL")
        printf("%s was sent to %s (pid:%d) by %s (pid:%d) uid :%d\n", 
            sig_name, pid_name , sig_pid, execname(), pid(), uid()) 
}

注意:我们添加了pid()函数,这个函数返回了发出信号源的进程PID。好,万事俱备,只等程序再次异常退出了。在待到信号源之前,竟然程序很长一段时间都没问题,正是考验呀。第二天过来,发现程序已经重启了,急迫的查看上面脚本的结果,不负期望,结果如下:

SIGKILL was sent to PA (pid:1375) by sh (pid:1400) uid :500
SIGKILL was sent to PB (pid:1377) by sh (pid:1400) uid :500

结果充分的验证了PA和PB是被程序杀掉,而且是同一个程序,是脚本杀掉的,脚本还是以sh杀的,对于我们在命令行里,直接发出的kill -9一般都是bash发出的,尽管可能sh最终是软连接到bash上。因此,我们很确定了,程序PA和PB的退出不是程序本身的问题,而是被脚本干掉了。现在的问题来了,哪个脚本做了这个事,路径,参数等信息我们均没有,只有一个简单的名字和PID。

到这儿来之后,开始两条方向同时进行:

对于systemtap这个工具,也是首次接触,不是很熟悉,找到官方文档,链接在下:

除了上面这个链接之外,还有一个更详细的文档,一下子没找到链接,从上面的API来看,是没法得到我们要的结果,不知道systemtap其他的工具组合是否探测到更多信息。暂时搁置了这条思路。

现在已经知道发出SIGKILL进程的PID了,那么如何知道进程的信息了,对于运行的程序,直接ps一下,就OK,可是对于退出的程序,真是没办法,没有任何记录遗留在系统里,至少在我们知道的范围内,在/var/log目录下,翻遍了同样没有任何线索。只能对进程监控了,因此考虑可以写个脚本周期的ps,把系统的相关进程打印下来。

在写这个简单脚本之前,还是考虑了周期的长短,打印信息的量。在测试环境,发现执行一个kill需要10ms左右,因此我们考虑5ms的周期ps一次,对于ps的内容按time,sh等关键词过滤,减少程序的输出,那么一次ps的输出结果在100字节左右,在我们观察到的程序重启周期里,最后日志文件的大小还是可以接受的。脚本弄好之后,果断的运行起来:

#/bin/bash

while :
do
    ps -ef | grep xx | grep -v xxx | .... 
    usleep 5000
done

这个简单的脚本配合systemtap的监控脚本发生了强大的作用,PA和PB再次挂掉之后,我们通过systemtap脚本得到SIGKILL信号源程序的PID,在ps脚本中找到了进程的详细信息,看到结果之后,痛快的卧槽了下。这种感觉大家都理解的。

找到SIGKILL的真凶之后,我们痛快并谨慎的分析了真凶脚本,结果出来了。由于PC异常,导致PA和PB受到株连被人误杀了。

总结


这个过程的荣耀属于大哥,没有他的指引,很难如此顺利的定位问题。记得多隆大神说,他的成长之路就是,有了问题就解决问题。这不仅是一个态度问题,还是品质问题。这个排查问题的过程是我更关注的,接触了好多新的东西,OOM killer 机制,ulimit各种参数及后果,强大的systemtap内核调试工具,可以跟踪很多内核事件以及一次完整的经验,以后希望能够更快的定位问题,更有力的思维过程,最终写好自己的程序,为他们的运行负责。详细关键的日志真是不可缺少。

致谢兄弟们的支持!

前一篇: Blockingqueue的探索 后一篇: 异步dns解析