文档章节

进程无故消失的破案历程

PerfMa
 PerfMa
发布于 03/12 10:35
字数 1938
阅读 1.9W
收藏 29

本文来自 PerfMa社区 ;链接: https://club.perfma.com/article/62679

概述

前段时间公司有个系统的进程老是无故退出,在客户那边好好的,在家里服务器上老是出现,而且出现的时间也没啥规律,当然最终查出来还是有规律的,不过这个规律比较特别。大家看了后面的内容之后就明白了,真的很特殊!

初步分析 进程Crash?

当同事找到我的时候,我第一反应是是不是进程Crash了,如果是crash,那通常情况下会有crash的日志,检查了一遍,什么日志都没有留下,当然有时候Crash了,JVM也确实也不会留下Crash日志,不过这个特别罕见了,绝大部分是人为操作了。

被OS Kill?

既然不是Crash,那是不是系统存在内存泄露,被OS Kill了,不过很快通过dmesg也排除了,因为没有看到任何kill的迹象。

System.exit?

排除掉以上两个因素之后,接着马上就怀疑是否有什么代码执行过System.exit,于是重新编译了一把JDK,在System的exit方法处打印了些日志,于是坐等奇迹的发生。

令人兴奋的是,进程真的消失了,可是令人遗憾的是,我们埋点的日志并没有出现。这让我再次陷入沉思。

回归源码

从日志看确实是调用了ShutdownHook image.png

于是找到addShutdownHook源码的位置 image.png

再次翻了一下JDK的源码,除了正常退出,System.exit等之外还有哪些情况会调用这个Shutdown的Hook,于是将埋点埋到了Shutdown.runHooks方法里。 image.png

继续等待事情再次发生,果然没多久,当天下午又发生了,打印了如下日志 image.png

也就是说当时是收到了一个SIGHUP的信号,这个信号最终会让进程退出,JVM对这个信号确实是没有特殊处理的,因此没有我们看到的Crash日志。

那接下来就是要找到为什么会收到这个信号了,这个信号又是谁发出的。

找出信号源

SIGHUP这个信号,最主要发生的场景是Shell终端关闭一个Session的时候会对该Session关联的进程发送一个SIGHUP信号,这个信号默认是会退出进程的。为此我还特地下载了ITerm2(我和同事都是mac,用的iTerm2的终端)的源码,还真找到了几个发送SIGHUP信号的代码 image.png

看名字PTYTask就能猜到了,这应该是一个seesion任务,于是进到代码里看到主要是有两个方法有发送SIGHUP信号给子进程,分别是dealloc和stop,其中stop会通过sendSignal函数给子进程发送SIGHUP信号。 image.png 对于我这种比较喜欢自虐的人,一般会想怎么就确定这个就是我要找的代码,之前从没有写过Object-C的代码,想着是否有个类似java的jmap的工具可以让我看内存里的对象的情况,然而临时没找到,不过偶然发现mac自带的Activity工具就能看到一些迹象,于是在Activity里找到了iTerm2进程,然后对其内存数据进行了采样,看能否抓到类似PTYTask. dealloc或者stop的调用栈,可是比较难模拟,因为存在时间差,点击采样的时候,很快就结束了,我还没来得及关闭session。在看采样报告的时候偶然看到了/usr/bin/sample的命令,原来Activity是采用这个命令进行采样的,于是摸索了一把,真能搞起来,采样的时间可以自定义,间隔是1ms一次,这样可以让我有充足的时间来操作了,于是在采样开启之后,不断地开一个session,起一个进程,然后close,重复做了好几次,结束采样之后看采样的输出,还真的就抓到了PTYTask.stop的调用栈 image.png

这也就验证了我close session的时候确实会给对应的子进程发送SIGHUP的信号。

那到此为止我们可以确认的是

  • 进程退出是因为收到了信号SIGHUP
  • 而SIGHUP的发生是因为终端Session Close 那到底是不是这种情况呢?

重新复盘问题现场

这个貌似不太可能,因为我们的shell脚本里执行java的时候都会带上&,这样进程就会后台运行,不会出现这种session的问题。看了下脚本,确实是带上了&的,自己也模拟了几遍,在一个shell里调用带有&的java命令,关闭终端java进程并不会退出。难道是因为同事的终端配置和我的不一样?后来要同事发了它的iTerm2里的seesion的配置给我看了下,和我的完全一样,这就挺奇怪了。

于是再回过来看看之前的几次进程消失时候的日志(我要同事有保留),看到那几个进程退出的时间点,分别是

  • 2019-01-14 20:42:52* 2019-01-15 18:34:00* 2019-01-18 00:57:58* 2019-01-18 17:34:30

这几个时间点完全没有规律看起来,不过我突然想起2019-01-18那天是周五,同事是在上海出差,而17:34:30那会应该是快下班了,或者那会正好从上海赶车回杭州,于是问了下那个点同事是不是准备回杭州了,同事说那会确实合上电脑准备赶车回杭州,于是我接着问其他几个时间是不是差不多也是合上电脑的时间,结果还真是那么巧,既然这样,那说明我们的判断方向是正确的了。

水落石出

后面突然发现同事修改过这个启动脚本,在脚本的最后加了行命令

java xxxx &cd $DIR_LOG && tail -f common-*.log

难道是这个命令搞的鬼?

突然想起一个问题来,父子进程的问题,假如说当我们在shell里加了&跑的话,当父进程跑完之后,会直接将其挂到init进程下面,也就是你通过ps -ef去看它的父进程会是1号进程,但是如果原来的父进程没有跑完,那其父进程仍然会是原来的进程,所以当我们执行这个脚本的时候,一直被执行tail等待日志输出,这样一来,如果我们将当前窗口关闭了,那就意味着父进程会退出,然后给子进程发送SIGHUP的信号,于是导致java进程退出,但是如果我们在tail日志过程中ctrl c了,那java进程会过继给init进程,因此此时当我们再关闭窗口的时候也不会给其发送SIGHUP的信号了。

经过验证果然如此,至此这个消失的进程终于得到了解释,嗯,好在不是我们代码的问题,值得欣慰,毕竟我们的代码是要在客户那边运行的,必须要保证好稳定性。

欢迎关注 PerfMa 社区,推荐阅读:

小心踩雷,一次Java内存泄漏排查

跟Kafka学技术系列之时间轮

© 著作权归作者所有

PerfMa
粉丝 17
博文 19
码字总数 38653
作品 0
杭州
私信 提问
加载中

评论(14)

h
heike07
哈哈 还好不是技术问题(甩甩甩~)
Jackie-Liu
Jackie-Liu
加 nohup
骨二
骨二
所以为嘛要手动运行java命令呢?
M
MorningX
厉害
SamZhou
SamZhou
为啥不用screen?
银杏林守望者
楼主有心,点赞。
不过我怀疑楼主后面分析的有问题。
“假如说当我们在shell里加了&跑的话,当父进程跑完之后,会直接将其挂到init进程下面。”
这个有前提条件,必须在shell里面显式执行exit才会这样(setsid)。
假如直接杀掉shell是不会保留后台进程的。而你说了“差不多也是合上电脑的时间”,这时候相当于直接杀掉shell,传递到服务器以后由于父进程关闭又不会setsid,会杀掉所有的后台进程(java和tail),而不是和tail有关。
PerfMa
PerfMa 博主
感谢支持,欢迎一起探讨,https://club.perfma.com/article/62679
酷酷的就
酷酷的就
不加nohup,只加&,这个进程还是和客户session关联的 可以做前后台切换,所以标准写法就是前加nohup后加&是一个完整命令,待完成后再执行tail
无毁的湖光-Al
无毁的湖光-Al
哈哈 去年我也遇到这问题 手贱在最后加了tail 莫名其妙连接变成timewait主动关闭状态了 看到timewait才想到可能是进程被发信号从而主动关连接了:)然后才破案
PerfMa
PerfMa 博主
深有同感!欢迎到我们社区一起探讨(https://club.perfma.com)
lorabitn
lorabitn
详情链接:https://www.jianshu.com/p/491e3723bfdf
lorabitn
lorabitn
好文,排查过程有理有据
我们是菜鸟物流技术部,目前极度缺人,诚挚邀请加入我们
记一次奇怪的mysql从库故障处理

一天下午,同事说有一台从数据库出现问题,查明原因是在同步过程中,从库在执行relay log时出现问题,导致大量relay log积压沾满磁盘空间,然后导致mysql整个宕掉。 同事一登录就删除了大量的...

wwwgood2012
2018/09/11
0
0
python进程无故消失的问题

该进程主要用于监控用另一个进程,定时杀掉重启。大多数时间该程序都是正常的,但是隔几个月就会发生该进程消失的问题,通过日志诊断,发现消失的时候'循环3'已输出,说明正在执行time.slee...

g3825734
2015/05/20
491
2
centos下后台程序无故消失

centos-6.2下,后台程序无故消失(未手动kill),也未产生core-dump文件,并且已开启生成core-dump文件。也不知是否是被系统kill了,但是/var/log/messages日志为空,谁能提供点建议?谢谢...

强哥哥最牛逼
2016/04/01
196
0
内测建议

1 调整中间筹码 done 2 续庄改为继续 done 3 等待时间设计更加灵活 4 必须要20 50这几种 done 5 创建房间选择不准的bug done 6 连庄后是否必须10分还是必须800/10 7 总下注有时候无故消失...

enenming
2017/08/04
0
0
一个简单的物流下单小程序定制开发,一周时间完成

以下链接是具体需求 https://docs.qq.com/doc/BKmLBH47TNS12DUllg3d1YUn1WIUXs1TTZNX4 请尽量先通过站内IM联系,消息每天都会查看,QQ太杂乱有时候对应不上人(实在要加请注明站内用户名) ...

张金达
2018/08/01
0
0

没有更多内容

加载失败,请刷新页面

加载更多

大刘海终于收窄?iPhone 12系列设计细节曝光:三摄+雷达更占空间

苹果第一次给屏幕加上刘海,是在2017年的iPhone X。此后,尽管安卓阵营已经先后发展出了水滴屏、升降屏、打孔屏等形态各异的更高屏占比的设计方案,苹果一直将宽大的刘海保留在其后iPhone XS...

osc_p0v6j6lt
15分钟前
24
0
爆单也没能救它 瑞幸咖啡股价一度下跌20%再创新低

瑞幸咖啡(NASDAQ:LK)股价周一继续下挫,跌破上周四曝光营收造假的低点4.90美元,一度报4.27美元,下跌超20%,市值不足11亿美元。这一价格也创造了瑞幸上市后的历史最低。 据报道,高盛称,瑞...

osc_6kj0kt57
16分钟前
16
0
疫情蔓延放缓 早盘美股道指大涨逾千点

北京时间6日晚,美股周一早盘继续上扬,道指大涨逾千点。投资者对全球疫情蔓延局势的判断有所改善,风险情绪随之受到提振。美国总统特朗普称迹象显示美国疫情已开始趋于稳定,并表示他仍在考...

osc_jo2m8l1r
17分钟前
24
0
4.3万元!赛博朋克2077定制版NIVIDIA显卡成功卖出

虽然《赛博朋克2077》游戏跳票了,但是2月份NVIDIA依然推出了一款赛博朋克限量版显卡——GeForce RTX 2080 Ti“ Cyberpunk 2077 Edition”,全球限量200块,官方售价1100美元。 访问购买页面...

osc_9mctux05
18分钟前
26
0
高盛:瑞幸咖啡股东发生违约 7635万股ADS强制出售

据国外媒体报道,高盛今日发布报告称,在瑞幸咖啡股东Haode Investment公司(借款人)发生违约之后,根据一项5.18亿美元的保证金贷款安排,贷款人组成的银团已指示作为担保受托人的瑞士信贷新...

osc_t6qz550e
20分钟前
19
0

没有更多内容

加载失败,请刷新页面

加载更多

返回顶部
顶部