这个星期很大部分精力都放在了追踪线上程序频繁异常退出的原因,过程很曲折,被人挑战了,万幸的是,结果没有丢团队和自己的面子。很简单的,我们希望的总是当遇到问题时不回避,全力以赴的解决,不仅是为了更好的产品,还有更好的自己。
线上的问题是这样的,我们有三个程序,一个主程序称为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内核调试工具,可以跟踪很多内核事件以及一次完整的经验,以后希望能够更快的定位问题,更有力的思维过程
,最终写好自己的程序,为他们的运行负责。详细关键的日志真是不可缺少。
致谢兄弟们的支持!