OpenJ9的jps,jstack无响应问题

2022-09-14  本文已影响0人  nchuxyz

OpenJ9是IBM&Eclipse开源的一款jvm。与Oracle jvm(所谓“官方”)相比,memory footprint较小,启动速度快是它的主要优势。
我们在实施过程中,主要遇到了jps, jstack无响应问题,不影响程序运行,但影响程序问题排查。本文记录了解决该问题的过程。

问题现象

jvm运行约半个月后,使用依赖jvm attach api的工具(如jps, jstack等)attach到目标jvm上,很长一段时间无响应直至SocketTimeout,无法attach成功。
出现该情况后,使用kill -3 目标jvm,触发jvm coredump之后,再次使用jps, jstack等工具进行attach,可以attach成功,并能正确返回相应调试信息。

最终结论

根本原因是centos对/tmp目录的自动清理造成。
修改/usr/lib/tmpfiles.d/tmp.conf,设置

x /tmp/.com_ibm_tools_attach/*

可以彻底解决该问题。

排查过程

首先肯定去网上找有没有类似的场景类似的问题,最后找到一个比较相近的:
https://github.com/eclipse-openj9/openj9/issues/13010

github.com/eclipse-openj9/openj9/issues/13010
但是很不幸,这个场景是jvm停止之后残留的ipc文件导致,而我的场景中,jvm是一直正常运行着的,并未停止。所以,这个issue唯一有参考价值的地方,就是/tmp/.com_ibm_tools_attach这个目录,起码知道了这个目录是OpenJ9 jvm用于存放ipc文件的,是jps, jstack等工具依赖的关键目录。
这个时候我立马想到了/tmp目录的自动清理。运行半个月出问题,大概率是自动清理造成。于是立马查看了/tmp/.com_ibm_tools_attach这个目录之下的内容,很遗憾的发现,貌似所有进程的ipc文件都完好无损,压根就没有被清理的迹象。
其实此时离真相已经非常接近了,但对于一个从未接触过ipc的人来说,谁会发现inode中的玄机,谁会想到去查inode号呢?
所以当时,我错误地排除了文件被清理的这种可能,从OpenJ9源码入手,想找到一些线索。
OpenJ9中与attach api相关的实现有2部分,java部分和c++部分。
java部分实现主要集中在openj9.internal.tools.attach.target包的这几个类:AttachHandler, WaitLoop, Attachment, CommonDirectory, IPC
主要负责①ipc文件的管理以及②提供attach api服务,外部工具就是通过attach请求创建一个tcp连接进来,与jvm通信的。
c++部分主要通过ipc文件、共享内存、信号量等手段来实现进程间的ipc通信。
以jstack为例,具体流程如下:
目标jvm在启动后,会检查/tmp/.com_ibm_tools_attach(下文简称common directory)这个目录下的ipc文件,如果没有或者过期则会重新创建;
目标jvm在启动后,会创建1个Attach API wait loop的线程,用于监听外部的attach请求;
jstack内部开启一个ServerSocket,用于与目标jvm通信;
jstack向common directory/jvm进程号 这个目录写入replyInfo文件,文件内容为ServerSocket的端口号
jstack通过common directory下的信号量专用文件_notifier发送信号量。注意此操作不会向文件写入内容,不会改变_notifier文件的修改日期;
目标jvm收到信号量,读取replyInfo文件获取与jstack通信的端口号,通过该端口号连接jstack;
jstack与目标jvm通过端口连接后,删除replyInfo文件,后续两者就通过tcp通信。
这些过程会有很多日志,如果出现问题,可以通过:
OpenJ9 jvm参数-Dcom.ibm.tools.attach.logging=yes可以看到java部分的日志;
OpenJ9 jvm参数-Xtrace:maximal=j9prt,output=trace.out可以看到c++部分的日志。
好,说了这么多,回到之前的问题:ipc文件看上去没有被清理,为什么ipc无法正常工作?
起初我猜测信号量文件_notifier应该会有过期时间,因为问题半个月出现一次。但是从jvm的ipc相关代码中,并没有看到设置信号量过期时间为半个月的这种逻辑出现。
那问题就很诡异了,到底发生了什么,只有通过相关工具来跟踪信号量文件,才能找到真相,我这边使用的是ipcs工具。
ipcs -a
------ Semaphore Arrays --------
key        semid      owner      perms      nsems
0xd7549b54 4          root      600        152
0xd7549b55 5          root      600        152
0xd7549b56 6          root      600        152

ipcs输出的列中,我比较关心的是key和semid。semid不用过多解释,就是信号量的id,那这个key是如何生成的?
继续查看jvm代码,这个key是通过ftok()函数生成出来的,ftok会根据文件的inode号来生成,也就是说,这个key截取了_notifier文件的inode号一部分,如果文件名相同,inode号不对,是不能正常通信的。
到这里我似乎有些明白了,有没有可能出现_notifier文件被删除,但是后面又重新生成这种情况?
我把common directory整个删除,然后执行jstack,报错Error getting data from xxx...然后一看,common directory重新生成了,_notifier也重新生成了。因为重新生成的信号量文件与之前使用的信号量文件inode号不一致,所以两者的semid也肯定不一致,所以看上去文件还在,但是无法正常ipc通信,所以jstack调不通。
centos的自动清理功能是根据文件修改时间,上文说过,使用信号量文件通信,文件的修改时间是不会发生变化的,也就最终导致了_notifier文件被清理;被清理之后,我发现jstack调不通的时候,因为执行了jstack,jstack也是基于jvm运行,故_notifier文件被重新生成出来,造成了当初的错觉。
真相大白,不容易啊。

上一篇下一篇

猜你喜欢

热点阅读