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

前言

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

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

内存泄露Bug现场

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

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

应急措施

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

奇怪现象

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

-Xmx1792m -Xms1792m -Xmn900m -XX:PermSize=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); } } } }

这段代码是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 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 kB7fa69a7d3000-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的空间。如下图所示:

挑出符合条件(即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时间很少。

总结

在这里给大家提供一个交流,讨论的平台,java架构师群671017482

具有1-5工作经验的,面对目前流行的技术不知从何下手,需要突破技术瓶颈的可以加群。

在公司待久了,过得很安逸,但跳槽时面试碰壁。需要在短时间内进修、跳槽拿高薪的可以加群。

如果没有工作经验,但基础非常扎实,对java工作机制,常用设计思想,常用java开发框架掌握熟练的可以加群。

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

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 204,921评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 87,635评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,393评论 0 338
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,836评论 1 277
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,833评论 5 368
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,685评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,043评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,694评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 42,671评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,670评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,779评论 1 332
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,424评论 4 321
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,027评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,984评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,214评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,108评论 2 351
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,517评论 2 343

推荐阅读更多精彩内容

  • JVM内存模型Java虚拟机(Java Virtual Machine=JVM)的内存空间分为五个部分,分别是: ...
    光剑书架上的书阅读 2,483评论 2 26
  • 这篇文章是我之前翻阅了不少的书籍以及从网络上收集的一些资料的整理,因此不免有一些不准确的地方,同时不同JDK版本的...
    高广超阅读 15,538评论 3 83
  • 内存溢出和内存泄漏的区别 内存溢出:out of memory,是指程序在申请内存时,没有足够的内存空间供其使用,...
    Aimerwhy阅读 730评论 0 1
  • 好吧,我也是markdown语法的新手,有些标记还真的是没有记住,而且对于文字的排版,相当于一无所知吧。虽然我是一...
    今夜相思又几许阅读 32,061评论 1 19
  • 小时候躲在厨房门后看妈妈做饭,伴着饭香看她忙碌的背影,突然觉得眼前的这个人好像在发光。我特别喜欢看一些美食电影,他...
    明媚XYZ阅读 1,083评论 1 3