历程无故消逝的破案历程

概述

前段时间公司有个系统的历程总是无故退出,在客户那里好好的,在家里服务器上总是泛起,而且泛起的时间也没啥纪律,固然最终查出来照样有纪律的,不外这个纪律对照稀奇。人人看了后面的内容之后就明了了,真的很特殊!

开端剖析 历程Crash?

当同事找到我的时刻,我第一反应是是不是历程Crash了,若是是crash,那通常情形下会有crash的日志,检查了一遍,什么日志都没有留下,固然有时刻Crash了,JVM也确实也不会留下Crash日志,不外这个稀奇罕见了,绝大部分是人为操作了。

被OS Kill?

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

System.exit?

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

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

回归源码

从日志看确实是挪用了ShutdownHook
历程无故消逝的破案历程

于是找到addShutdownHook源码的位置
历程无故消逝的破案历程

再次翻了一下JDK的源码,除了正常退出,System.exit等之外另有哪些情形会挪用这个Shutdown的Hook,于是将埋点埋到了Shutdown.runHooks方式里。
历程无故消逝的破案历程

继续守候事情再次发生,果真没多久,当天下昼又发生了,打印了如下日志
历程无故消逝的破案历程

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

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

前端Tips#6 – 在 async iterator 上使用 for-await-of 语法糖

找出信号源

SIGHUP这个信号,最主要发生的场景是Shell终端关闭一个Session的时刻会对该Session关联的历程发送一个SIGHUP信号,这个信号默认是会退出历程的。为此我还专程下载了ITerm2(我和同事都是mac,用的iTerm2的终端)的源码,还真找到了几个发送SIGHUP信号的代码
历程无故消逝的破案历程

看名字PTYTask就能猜到了,这应该是一个seesion义务,于是进到代码里看到主要是有两个方式有发送SIGHUP信号给子历程,分别是dealloc和stop,其中stop会通过sendSignal函数给子历程发送SIGHUP信号。
历程无故消逝的破案历程
对于我这种对照喜欢自虐的人,一样平常会想怎么就确定这个就是我要找的代码,之前从没有写过Object-C的代码,想着是否有个类似java的jmap的工具可以让我看内存里的工具的情形,然而暂且没找到,不外有时发现mac自带的Activity工具就能看到一些迹象,于是在Activity里找到了iTerm2历程,然后对其内存数据举行了采样,看能否抓到类似PTYTask. dealloc或者stop的挪用栈,可是对照难模拟,由于存在时间差,点击采样的时刻,很快就竣事了,我还没来得及关闭session。在看采样讲述的时刻有时看到了/usr/bin/sample的下令,原来Activity是接纳这个下令举行采样的,于是试探了一把,真能搞起来,采样的时间可以自定义,距离是1ms一次,这样可以让我有足够的时间来操作了,于是在采样开启之后,不断地开一个session,起一个历程,然后close,重复做了好几回,竣事采样之后看采样的输出,还真的就抓到了PTYTask.stop的挪用栈
历程无故消逝的破案历程

这也就验证了我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的信号了。

经由验证果真如此,至此这个消逝的历程终于获得了注释,嗯,幸亏不是我们代码的问题,值得欣慰,究竟我们的代码是要在客户那里运行的,必须要保证好稳定性。

 

原创文章,作者:28x29新闻网,如若转载,请注明出处:https://www.28x29.com/archives/642.html