性能文章>进程无故消失的破案历程>

进程无故消失的破案历程原创

3年前
12902617

概述

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

初步分析 进程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的信号了。

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

点赞收藏
你假笨

通过创新的技术肯定可以让这个世界变得更美好,让我们为技术而狂吧

请先登录,查看6条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

【全网首发】一次想不到的 Bootstrap 类加载器带来的 Native 内存泄露分析

【全网首发】一次想不到的 Bootstrap 类加载器带来的 Native 内存泄露分析

记一次线上RPC超时故障排查及后续GC调优思路

记一次线上RPC超时故障排查及后续GC调优思路

解读JVM级别本地缓存Caffeine青出于蓝的要诀 —— 缘何会更强、如何去上手

解读JVM级别本地缓存Caffeine青出于蓝的要诀 —— 缘何会更强、如何去上手

【全网首发】一次疑似 JVM Native 内存泄露的问题分析

【全网首发】一次疑似 JVM Native 内存泄露的问题分析

解读JVM级别本地缓存Caffeine青出于蓝的要诀2 —— 弄清楚Caffeine的同步、异步回源方式

解读JVM级别本地缓存Caffeine青出于蓝的要诀2 —— 弄清楚Caffeine的同步、异步回源方式

【全网首发】从源码角度分析一次诡异的类被加载问题

【全网首发】从源码角度分析一次诡异的类被加载问题

17
6