有次遇到了某一台新搭建的服务器偶发性发生java挂掉的情况,查看日志没有看到相关有用信息,有些时候进程还存在,但是服务不可用。有些时候进程不存在,就像是被执行kill -9一样。查看服务停止时相关操作,发现某核心应用正好处在该时间区间。因此怀疑是因为进程OOM导致java挂掉了。
/var/log/messages 日志是核心系统日志文件。它包含了系统启动时的引导消息,以及系统运行时的其他状态消息。IO 错误、网络错误和其他系统错误都会记录到这个文件中。
关于进程OOM被kill的信息会记录在当中,需要注意,/var/log/messages达到一定大小会自动切换新的文件,重命名为messages-当时日期,查找的时候,需要找到对应时间段的文件。

当时发生时间为0704,所以需要查看的是0705的日志文件。

看到在0704 的17:15发生了oom-kill的动作,跟java故障时间非常接近。但是这一段我看不出是kill的java,也是有相关信息,但是看不出来。
现在就有以下两个问题:
12. 如果真的是oom-kill掉的java,那为什么是killjava,其他的java进程都没有kill?
13. 如果不是oom的问题,那又是什么问题?
首先,把看起来比较容易的,有点眉目的先梳理一下。
OOM为什么只kill java?
有同事处理该事情上,加大了java的内存和OS的内存,避免了java挂掉的情况发生。但是java已经达到了4G的堆栈内存设置,应该不会超过才对。反而可能是设置过大。那设置多少才是合理的呢?我们来查看GC log。

这就是gc log的格式和内容。咋一看,就像是一张密码表。
Gc=Garbage Collection
求助一下网友们:
- 0.756: [Full GC (System) 0.756: [CMS: 0K->1696K(204800K), 0.0347096 secs] 11488K->1696K(252608K), [CMS Perm : 10328K->10320K(131072K)], 0.0347949 secs] [Times: user=0.06 sys=0.00, real=0.05 secs]
- 1.728: [GC 1.728: [ParNew: 38272K->2323K(47808K), 0.0092276 secs] 39968K->4019K(252608K), 0.0093169 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
- 2.642: [GC 2.643: [ParNew: 40595K->3685K(47808K), 0.0075343 secs] 42291K->5381K(252608K), 0.0075972 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
- 4.349: [GC 4.349: [ParNew: 41957K->5024K(47808K), 0.0106558 secs] 43653K->6720K(252608K), 0.0107390 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
- 5.617: [GC 5.617: [ParNew: 43296K->7006K(47808K), 0.0136826 secs] 44992K->8702K(252608K), 0.0137904 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
- 7.429: [GC 7.429: [ParNew: 45278K->6723K(47808K), 0.0251993 secs] 46974K->10551K(252608K), 0.0252421 secs]
5.617(时间戳): [GC(Young GC) 5.617(时间戳): [ParNew(使用ParNew作为年轻代的垃圾回收期): 43296K(年轻代垃圾回收前的大小)->7006K(年轻代垃圾回收以后的大小)(47808K)(年轻代的总大小), 0.0136826 secs(回收时间)] 44992K(堆区垃圾回收前的大小)->8702K(堆区垃圾回收后的大小)(252608K)(堆区总大小), 0.0137904 secs(回收时间)] [Times: user=0.03(Young GC用户耗时) sys=0.00(Young GC系统耗时), real=0.02 secs(Young GC实际耗时)]
新老一代就不关注了,看到“回收前”、“回收后”、“堆区”,好吧,那我们关注的应该是这几个数值,对比这个例子分析,我们关注回收后“堆区大小”,即为进程运行所需要的内存大致大小。看到截图的信息为:744080K=727M,也就是说,实际使用的堆内存大小大概为727M。
1125376K=1099M,这个数值是java虚拟机向os申请的内存使用量。
所以设置为1.5G,为实际堆2倍。
关于新一代、老一代,新一代就是小鲜肉内存,刚申请占用的,没有或者经过少了gc机制的洗礼。老一代就是老油条内存,gc多次洗礼都洗不掉的。就被放到老一代。老一代是堆内存占用的中坚力量。、
看完GC log,我们知道应该设置为Xmx=1.5G了。
那这个1.5G跟原来的4G,有啥区别呢,设置成1.5G就不会被oom kill掉么?
对于这个,linux有自己的一套算法,对于OS OOM应该kill哪个进程,会对进程的使用时间,内存的占用大小进行权重分析。在/proc/pid/oom_score能够查看到对应进程得分,oom killer会根据这个得分kill掉得分高的进程。因为事故服务器的xmx已经被降低为1.5G,所以看不到4G的状态值。

这个是在本地虚拟机4G的得分:108

这个使用时长还是算有点长吧。
再看一下服务器上的1.5G得分:26

这个得分,比编译的java进程要低很多,所以这个这保证java不会被kill。
后续:
降低了内存参数之后,第二天还是发生了OOM 被kill的情况,刚好在服务器上进行ps操作,查询得到pid信息,对照/var/log/message:
/var/log/message:
日志显示得分为:107,pid为21998

进程PID:21998

监控内心信息:kill之前,只有300M可用内存。

查询到重启后的pid信息:24026
执行 echo -500 > /proc/24026/oom_score_adj
对得分进行减分操作,避免再次被kill。
查看24026得分为:0

oom_score_adj文件取值在-1000到1000,在得分之后,会对该文件数值进行+操作。
/proc/$pid/oom_adj是为了兼容Linux 2.6.36(出现了oom_score_adj)之前老版本的文件,该文件的数值为-17到15,经过算法换算,并不是简单的+操作。
参考资料:
Gc log分析:https://blog.csdn.net/huangzhaoyang2009/article/details/11860757
Linux oom机制:https://www.chenyudong.com/archives/linux-oom-killer.html
Q.E.D.