记一次JVM堆外内存泄露Bug的查找

发表于:2018-1-23 11:18

字体: | 上一篇 | 下一篇 | 我要投稿

 作者:无毁的湖光-Al    来源:开源中国

  前言
  JVM的堆外内存泄露的定位一直是个比较棘手的问题。此次的Bug查找从堆内内存的泄露反推出堆外内存,同时对物理内存的使用做了定量的分析,从而实锤了Bug的源头。笔者将此Bug分析的过程写成博客,以飨读者。
  由于物理内存定量分析部分用到了linux kernel虚拟内存管理的知识,读者如果有兴趣了解请看ulk3(《深入理解linux内核第三版》)
  内存泄露Bug现场
  一个线上稳定运行了三年的系统,从物理机迁移到docker环境后,运行了一段时间,突然被监控系统发出了某些实例不可用的报警。所幸有负载均衡,可以自动下掉节点,如下图所示: 
  登录到对应机器上后,发现由于内存占用太大,触发OOM,然后被linux系统本身给kill了。
  应急措施
  紧急在出问题的实例上再次启动应用,启动后,内存占用正常,一切Okay。
  奇怪现象
  当前设置的最大堆内存是1792M,如下所示:
  -Xmx1792m -Xms1792m -Xmn900m -XX:PermSi
  ze=256m -XX:MaxPermSize=256m -server -Xss512k
  查看操作系统层面的监控,发现内存占用情况如下图所示: 
  上图蓝色的线表示总的内存使用量,发现一直涨到了4G后,超出了系统限制。
  很明显,有堆外内存泄露了。
  查找线索
  gc日志
  一般出现内存泄露,笔者立马想到的就是查看当时的gc日志。
  本身应用所采用框架会定时打印出对应的gc日志,遂查看,发现gc日志一切正常。对应日志如下: 
  查看了当天的所有gc日志,发现内存始终会回落到170M左右,并无明显的增加。要知道JVM进程本身占用的内存可是接近4G(加上其它进程,例如日志进程就已经到4G了),进一步确认是堆外内存导致。
  排查代码
  打开线上服务对应对应代码,查了一圈,发现没有任何地方显式利用堆外内存,其没有依赖任何额外的native方法。关于网络IO的代码也是托管给Tomcat,很明显,作为一个全世界广泛流行的Web服务器,Tomcat不大可能有堆外内存泄露。
  进一步查找
  由于在代码层面没有发现堆外内存的痕迹,那就继续找些其它的信息,希望能发现蛛丝马迹。
  Dump出JVM的Heap堆
  由于线上出问题的Server已经被kill,还好有其它几台,登上去发现它们也 占用了很大的堆外内存,只是还没有到触发OOM的临界点而已。于是就赶紧用jmap dump了两台机器中应用JVM的堆情况,这两台留做现场保留不动,然后将其它机器迅速重启,以防同时被OOM导致服务不可用。
  使用如下命令dump:
  jmap -dump:format=b,file=heap.bin [pid]
  使用MAT分析Heap文件
  挑了一个heap文件进行分析,堆的使用情况如下图所示: 
  一共用了200多M,和之前gc文件打印出来的170M相差不大,远远没有到4G的程度。
  不得不说MAT是个非常好用的工具,它可以提示你可能内存泄露的点: 
  这个cachedBnsClient类有12452个实例,占用了整个堆的61.92%。
  查看了另一个heap文件,发现也是同样的情况。这个地方肯定有内存泄露,但是也占用了130多M,和4G相差甚远。
  查看对应的代码
  系统中大部分对于CachedBnsClient的调用,都是通过注解Autowired的,这部分实例数很少。
  唯一频繁产生此类实例的代码如下所示:
@Override
public void fun() {
BnsClient bnsClient = new CachedBnsClient();
// do something
return  ;
}
  此CachedBnsClient仅仅在方法体内使用,并没有逃逸到外面,再看此类本身
public class CachedBnsClient   {
private ConcurrentHashMap<String, List<String>> authCache = new ConcurrentHashMap<String, List<String>>();
private ConcurrentHashMap<String, List<URI>> validUriCache = new ConcurrentHashMap<String, List<URI>>();
private ConcurrentHashMap<String, List<URI>> uriCache = new ConcurrentHashMap<String, List<URI>>();
......
}
  没有任何static变量,同时也没有往任何全局变量注册自身。换言之,在类的成员(Member)中,是不可能出现内存泄露的。
  当时只粗略的过了一过成员变量,回过头来细想,还是漏了不少地方的。
  更多信息
  由于代码排查下来,感觉这块不应该出现内存泄露(但是事实确是如此的打脸)。这个类也没有显式用到堆外内存,而且只占了130M,和4G比起来微不足道,还是先去追查主要矛盾再说。
  使用jstack dump线程信息
  现场信息越多,越能找出蛛丝马迹。先用jstack把线程信息dump下来看下。 这一看,立马发现了不同,除了正常的IO线程以及框架本身的一些守护线程外,竟然还多出来了12563多个线程。
  "Thread-5" daemon prio=10 tid=0x00007fb79426e000 nid=0x7346 waiting on condition [0x00007fb7b5678000]
  java.lang.Thread.State: TIMED_WAITING (sleeping)
  at java.lang.Thread.sleep(Native Method)
  at com.xxxxx.CachedBnsClient$1.run(CachedBnsClient.java:62)
  而且这些正好是运行再CachedBnsClient的run方法上面!这些特定线程的数量正好是12452个,和cachedBnsClient数量一致!
  再次check对应代码
  原来刚才看CachedBnsClient代码的时候遗漏掉了一个关键的点!
public CachedBnsClient(BnsClient client) {
super();
this.backendClient = client;
new Thread() {
@Override
public void run() {
for (; ; ) {
refreshCache();
try {
Thread.sleep(60 * 1000);
} catch (InterruptedException e) {
logger.error("出错", e);
}
}
}
}
  这段代码是CachedBnsClient的构造函数,其在里面创建了一个无限循环的线程,每隔60s启动一次刷新一下里面的缓存!
  找到关键点
  在看到12452个等待在CachedBnsClient.run的业务的一瞬间笔者就意识到,肯定是这边的线程导致对外内存泄露了。下面就是根据线程大小计算其泄露内存量是不是确实能够引起OOM了。
  发现内存计算对不上
  由于我们这边设置的Xss是512K,即一个线程栈大小是512K,而由于线程共享其它MM单元(线程本地内存是是现在线程栈上的),所以实际线程堆外内存占用数量也是512K。进行如下计算:
  12563 * 512K = 6331M = 6.3G
  整个环境一共4G,加上JVM堆内存1.8G(1792M),已经明显的超过了4G。
  (6.3G + 1.8G)=8.1G > 4G
  如果按照此计算,应用应用早就被OOM了。
  怎么回事呢?
  为了解决这个问题,笔者又思考了好久。如下所示:

上文内容不用于商业目的,如涉及知识产权问题,请权利人联系博为峰小编(021-64471599-8017),我们将立即处理。
21/212>
《2023软件测试行业现状调查报告》独家发布~

关注51Testing

联系我们

快捷面板 站点地图 联系我们 广告服务 关于我们 站长统计 发展历程

法律顾问:上海兰迪律师事务所 项棋律师
版权所有 上海博为峰软件技术股份有限公司 Copyright©51testing.com 2003-2024
投诉及意见反馈:webmaster@51testing.com; 业务联系:service@51testing.com 021-64471599-8017

沪ICP备05003035号

沪公网安备 31010102002173号