凯发娱发k8

解bug之路-凯发娱发k8

2023-08-17,,

前言

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> authcache = new concurrenthashmap>();
private concurrenthashmap> validuricache = new concurrenthashmap>();
private concurrenthashmap> uricache = new concurrenthashmap>();
......
}

没有任何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公用的,放在两块连续的物理页框上。如下图所示:

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

512k-8k=504k

如下图所示:

linux实际物理内存映射

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

查看smaps进程内存使用信息

使用如下命令,查看

cat /proc/[pid]/smaps > smaps.txt

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

7fa69a6d1000-7fa69a74f000 rwxp 00000000 00:00 0
size: 504 kb
rss: 92 kb
pss: 92 kb
shared_clean: 0 kb
shared_dirty: 0 kb
private_clean: 0 kb
private_dirty: 92 kb
referenced: 92 kb
anonymous: 92 kb
anonhugepages: 0 kb
swap: 0 kb
kernelpagesize: 4 kb
mmupagesize: 4 kb 7fa69a7d3000-7fa69a851000 rwxp 00000000 00:00 0
size: 504 kb
rss: 152 kb
pss: 152 kb
shared_clean: 0 kb
shared_dirty: 0 kb
private_clean: 0 kb
private_dirty: 152 kb
referenced: 152 kb
anonymous: 152 kb
anonhugepages: 0 kb
swap: 0 kb
kernelpagesize: 4 kb
mmupagesize: 4 kb

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

挑出符合条件(即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必须要有实质性的证据。例如内存泄露就要用你推测出的模型进行定量分析。在定量和实际对不上的时候,深挖下去,你会发现不一样的风景!

公众号

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

https://my.oschina.net/alchemystar/blog/1603817

解bug之路-记一次jvm堆外内存泄露bug的查找的相关教程结束。

网站地图