写点什么

解 Bug 之路 - 记一次 JVM 堆外内存泄露 Bug 的查找

发布于: 2020 年 09 月 15 日
解Bug之路-记一次JVM堆外内存泄露Bug的查找

解 Bug 之路-记一次 JVM 堆外内存泄露 Bug 的查找


前言


JVM 的堆外内存泄露的定位一直是个比较棘手的问题。此次的 Bug 查找从堆内内存的泄露反推出堆外内存,同时对物理内存的使用做了定量的分析,从而实锤了 Bug 的源头。笔者将此 Bug 分析的过程写成博客,以飨读者。

由于物理内存定量分析部分用到了 linux kernel 虚拟内存管理的知识,读者如果有兴趣了解请看 ulk3(《深入理解 linux 内核第三版》)


内存泄露 Bug 现场


一个线上稳定运行了三年的系统,从物理机迁移到 docker 环境后,运行了一段时间,突然被监控系统发出了某些实例不可用的报警。所幸有负载均衡,可以自动下掉节点,如下图所示:


gc_local


登录到对应机器上后,发现由于内存占用太大,触发 OOM,然后被 linux 系统本身给 kill 了。


应急措施


紧急在出问题的实例上再次启动应用,启动后,内存占用正常,一切 Okay。


奇怪现象


当前设置的最大堆内存是 1792M,如下所示:


-Xmx1792m -Xms1792m -Xmn900m -XX:PermSize=256m -XX:MaxPermSize=256m -server -Xss512k
复制代码


查看操作系统层面的监控,发现内存占用情况如下图所示:


gc_upper


上图蓝色的线表示总的内存使用量,发现一直涨到了 4G 后,超出了系统限制。

很明显,有堆外内存泄露了。


查找线索


gc 日志


一般出现内存泄露,笔者立马想到的就是查看当时的 gc 日志。

本身应用所采用框架会定时打印出对应的 gc 日志,遂查看,发现 gc 日志一切正常。对应日志如下:


gc_log


查看了当天的所有 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 文件进行分析,堆的使用情况如下图所示:


gc_heap_dump


一共用了 200 多 M,和之前 gc 文件打印出来的 170M 相差不大,远远没有到 4G 的程度。

不得不说 MAT 是个非常好用的工具,它可以提示你可能内存泄露的点:


gc_cached_bns_client


这个 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);                    }                }            }            ......        }.start();    }
复制代码


这段代码是 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 了。


怎么回事呢?


为了解决这个问题,笔者又思考了好久。如下所示:


Java 线程底层实现


JVM 的线程在 linux 上底层是调用 NPTL(Native Posix Thread Library)来创建的,一个 JVM 线程就对应 linux 的 lwp(轻量级进程,也是进程,只不过共享了 mm_struct,用来实现线程),一个 thread.start 就相当于 do_fork 了一把。

其中,我们在 JVM 启动时候设置了-Xss=512K(即线程栈大小),这 512K 中然后有 8K 是必须使用的,这 8K 是由进程的内核栈和 thread_info 公用的,放在两块连续的物理页框上。如下图所示:


gc_thread_task


众所周知,一个进程(包括 lwp)包括内核栈和用户栈,内核栈+thread_info 用了 8K,那么用户态的栈可用内存就是:


512K-8K=504K
复制代码


如下图所示:


gc_kernel_user


Linux 实际物理内存映射


事实上 linux 对物理内存的使用非常的抠门,一开始只是分配了虚拟内存的线性区,并没有分配实际的物理内存,只有推到最后使用的时候才分配具体的物理内存,即所谓的请求调页。如下图所示:


gc_do_page_fault


查看 smaps 进程内存使用信息


使用如下命令,查看


cat /proc/[pid]/smaps > smaps.txt
复制代码


实际物理内存使用信息,如下所示:


7fa69a6d1000-7fa69a74f000 rwxp 00000000 00:00 0 Size:                504 kBRss:                  92 kBPss:                  92 kBShared_Clean:          0 kBShared_Dirty:          0 kBPrivate_Clean:         0 kBPrivate_Dirty:        92 kBReferenced:           92 kBAnonymous:            92 kBAnonHugePages:         0 kBSwap:                  0 kBKernelPageSize:        4 kBMMUPageSize:           4 kB
7fa69a7d3000-7fa69a851000 rwxp 00000000 00:00 0 Size: 504 kBRss: 152 kBPss: 152 kBShared_Clean: 0 kBShared_Dirty: 0 kBPrivate_Clean: 0 kBPrivate_Dirty: 152 kBReferenced: 152 kBAnonymous: 152 kBAnonHugePages: 0 kBSwap: 0 kBKernelPageSize: 4 kBMMUPageSize: 4 kB
复制代码


搜索下 504KB,正好是 12563 个,对了 12563 个线程,其中 Rss 表示实际物理内存(含共享库)92KB,Pss 表示实际物理内存(按比例共享库)92KB(由于没有共享库,所以 Rss==Pss),以第一个 7fa69a6d1000-7fa69a74f000 线性区来看,其映射了 92KB 的空间,第二个映射了 152KB 的空间。如下图所示:


gc_mem


挑出符合条件(即 size 是 504K)的几十组看了下,基本都在 92K-152K 之间,再加上内核栈 8K


(92+152)/2+8K=130K,由于是估算,取整为128K,即反映此应用平均线程栈大小。
复制代码


注意,实际内存有波动的原因是由于环境不同,从而走了不同的分支,导致栈上的增长不同。


重新进行内存计算


JVM 一开始申请了


-Xmx1792m -Xms1792m
复制代码


即 1.8G 的堆内内存,这里是即时分配,一开始就用物理页框填充。

12563 个线程,每个线程栈平均大小 128K,即:


128K * 12563=1570M=1.5G的对外内存
复制代码


取个整数 128K,就能反映出平均水平。再拿这个 128K * 12563 =1570M = 1.5G,加上 JVM 的 1.8G,就已经达到了 3.3G,再加上 kernel 和日志传输进程等使用的内存数量,确实已经接近了 4G,这样内存就对应上了!(注:用于定量内存计算的环境是一台内存用量将近 4G,但还没 OOM 的机器)


为什么在物理机上没有应用 Down 机


笔者登录了原来物理机,应用还在跑,发现其同样有堆外内存泄露的现象,其物理内存使用已经达到了 5 个多 G!幸好物理机内存很大,而且此应用发布还比较频繁,所以没有被 OOM。

Dump 了物理机上应用的线程,


一共有28737个线程,其中28626个线程等待在CachedBnsClient上。
复制代码


同样用 smaps 查看进程实际内存信息,其平均大小依旧为


128K,因为是同一应用的原因
复制代码


继续进行物理内存计算


1.8+(28737 * 128k)/1024K =(3.6+1.8)=5.4G
复制代码


进一步验证了我们的推理。


这么多线程应用为什么没有卡顿


因为基本所有的线程都睡眠在


 Thread.sleep(60 * 1000);//一次睡眠60s
复制代码


上。所以仅仅占用了内存,实际占用的 CPU 时间很少。


总结


查找 Bug 的时候,现场信息越多越好,同时定位 Bug 必须要有实质性的证据。例如内存泄露就要用你推测出的模型进行定量分析。在定量和实际对不上的时候,深挖下去,你会发现不一样的风景!


公众号


关注笔者公众号,获取更多干货文章:




发布于: 2020 年 09 月 15 日阅读数: 87
用户头像

公众号: <<解Bug之路>> 2019.02.11 加入

无论多么艰苦的时刻,都不要忘记。辉煌的未来,在你的眼中闪耀!

评论

发布
暂无评论
解Bug之路-记一次JVM堆外内存泄露Bug的查找