个人程序跑了60多小时,就是为了让你看一眼JDK的BUG致使的内存泄漏。

https://mp.weixin.qq.com/s/ppZlpL5Ip7DHG1GG09uT6g

640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1在线客服java


荒腔走板



你们好,我是 why,欢迎来到我连续周更优质原创文章的第 56 篇。
老规矩,先来一个简短的荒腔走板,给冰冷的技术文注入一丝色彩。
上面图片中这个正在奔跑的少年,是正在参加校运会的我,那一年我 18 岁,高三。
参加的项目是 3000 米长跑,那个时候长跑一贯是你们都不喜欢的运动,可是我喜欢。
我是从小乡村出来的,小学、初中的时候操场就是用煤渣加泥土铺成的一圈仅 200 米的跑道。

在那个 200 米的跑道上,我从小学跑到初中,跑了不知道多少千米。

初中的时候参加了学校长跑队的集训。有一天集训完成以后,体育老师给咱们说:
大家必定要刻苦训练,未来要到城里面去读书。大家知道吗?城里面的跑道一圈是 400 米,仍是用塑胶铺成的跑道,跑上去不知道比这个煤渣舒服多少倍。我知道长跑很痛苦,可是若是你真的喜欢它,你就得享受这个痛苦的过程。不要放弃,特别是在最后冲刺阶段。由于,若是你不拼尽全力,等你到终点以后你老是会以为本身能再快一点,惋惜比赛已经结束了。
后来,我退出了集训队,可是老师的话我一直记得。

我也如愿进入了城里读高中,见到了传说中的“塑胶跑道”。还参加了开在塑胶跑道上的运动会。

前段时间我翻到这张照片的时候,我就想起了初中集训的一些点滴记忆,也想起了老师的话:享受痛苦,咬牙坚持,无愧结果。

这周,今年的高考也结束了。
其实这个道理放在高考,和高考以后的人生会面临的更多更复杂的挑战面前均可以。
人生嘛,无非就是:奔跑,跌倒,奔跑。
奔跑吧,骄傲的少年。前面有更多的机会和更难的挑战在等着你。
好了,说回文章。node


从一个BUG提及



前段时间翻到了一个 JDK 有点意思的 BUG,带你们一块儿瞅瞅。程序员


https://bugs.java.com/bugdatabase/view_bug.do?bug_id=8137185


640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1memory leak,内存泄漏。
是谁致使的内存泄漏呢?

ConcurrentLinkedQueue,这个队列。
这个 BUG 里面说,在 jetty 项目里面也爆出了这个 BUG:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1我看了一下,以为 jetty 的这个写的挺有意思的。

我按照 jetty 的这个讲吧,反正都是同一个 JDK BUG 致使的。地址以下:web


https://bugs.eclipse.org/bugs/show_bug.cgi?id=477817


640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1我用我八级半的蹩脚英语给你们翻译一下这个叫作 max 的同窗说了些什么。
他说:在 Java 项目里面,错误的使用 ConcurrentLinkedQueue(文章后面用缩写 CLQ 代替)会致使内存泄漏的问题。

在 jetty 的 QueuedThreadPool 这个线程池里面,使用了 CLQ 这个队列,它会致使内存缓慢增加,最终引起内存泄漏。
虽然 QueuedThreadPool 仅仅使用了这个队列的 add 方法和 remove 方法。但不幸的是,remove 方法不会把队列的大小变小,只会使队列里面被删除的 node 为空。所以,该列表将增加到无穷大。
而后他给了一个附件,附件里面是一段程序,能够演示这个问题。
咱们先不看他的程序,后面咱们统一演示这个问题。
先给你们看一下 jetty 的 QueuedThreadPool 线程池。
看哪一个版本的 jetty 呢?640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
能够看到这个 BUG 是在 2015 年 9 月 18 日被爆出来的。因此,咱们找一个这个日期以前的版本就行。

因而我找了一个 2015 年 9 月 3 日发布的  maven 版本:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
在这个版本里面的 QueuedThreadPool 是这样的:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1能够看到,它确实使用了 CLQ 队列。

而从这个对象全部被调用的地方来看,jetty 只使用了这个队列的 size、add、remove(obj) 方法:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1和前面 max 同窗描述的一致。

而后这个 max 同窗给了几张图片,来佐证他的论点:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1主要关注我框起来的地方,就是说他展现了一张图片。能够从这图片中看出内存泄漏的问题,而这个图片的来源是他们真实的项目。

这个项目已经运行了大约两天,每五分钟就会有一个 web 请求过来。
下面是他给出的图片:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1从他的这个图片中,我就只看出了 CLQ 的 node 不少。

可是他说了,他这个项目请求量并不大,用的 jetty 框架也不该该建立这么多的 node 出来。
好了,咱们前面分析了 max 同窗说的这个问题,接下来就是大佬出场,来解惑了:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1咱们先不看回答,先看看回答问题的人是谁。 
Greg Wilkins,何许人也?
我找到了他的领英地址:编程


https://www.linkedin.com/in/gregwilkins/?originalSubdomain=au


640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
jetty 项目的领导者,短短的几个单词,就足以让你直呼牛逼。
高端的食材,每每只须要最简单的烹饪。高端的人才,每每只须要寥寥数语的介绍。
大佬的简历就是这么朴实无华,且枯燥。
并且,你看这个头像。哎,酸了酸了。果真再次印证了这句话:变秃了,也变强了,并不适用于外国的神仙。640?wx_fmt=jpeg&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1好了,咱们看一下这个 jetty 项目的领导者是怎么回答这个问题的:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
首先他用 stupefied 表示了很是的震惊!而后,用到了 Ouch 语气词。至关于咱们常说的:
640?wx_fmt=jpeg&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
他说:卧槽,我发现它不只致使内存泄漏,并且会随着时间的推移,致使队列愈来愈慢。太TM震惊了。
640?wx_fmt=jpeg&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1这个问题必定会对使用大量线程的服务器产生影响......但愿不是全部的服务器都会有影响。
但无论是否是全部的服务器都有这个问题,只要出现了这个问题,对于某些服务器来讲,它必定是一个很是严重的 BUG。

而后他说了一个 Great catch!我理解这是一个语气助词。就相似于:太牛逼了。
这个很差翻译,我贴一个例句,你们本身去体会一下吧:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1我也是没想到,在技术文里面还给你们教起了英文。

最后他说:我正在修复这个问题。
而后,在 7 分 37 秒以后, Greg 又回复了一次:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1能够看出,过了快 8 分钟,他还在持续震惊。我怀疑这 8 分钟里面他一直在摇头。

他说:我还在为这个 BUG 摇头,它怎么这么久都没被发现呢!对于 jetty 来讲修复起来很是的简单,使用 set 结构代替 queue 队列便可实现同样的效果。
那咱们看一下修复以后的 jetty 中的 QueuedThreadPool 是怎样的,这里我用的是 2015 年 10 月 6 日发布的一个包,也就是这个 BUG 爆出以后的最近的一个包:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1里面对应的代码是这样的:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1简单粗暴的用 CurrentHashSet 代替了 CLQ。
由于这个 BUG 在 JDK 中是已经修复了,出于好奇,我想看看 CLQ 还有没有机会从新站出来。
640?wx_fmt=jpeg&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
因而我看了一下今年发布的最新版本里面的代码:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1既不是用的 CurrentHashSet ,也没有给 CLQ 机会。
而是 JDK 8 的 ConcurrentHashMap 里面的 newKeySet 方法,C 位出道:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
这是一个小小的 jetty 线程池的演变过程。恭喜你,又学到了一个基本上不会用到的知识点。

回到 Greg 的回复中,此次的回复里面,他还给了一个修复的演示实例,下一小节我会针对这个实例进行解读。
在 23 分钟以后,他就提交代码修复完成了。
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1从第一次回复帖子,到定位问题,再到提交代码,用了 30 分钟的时间。
640?wx_fmt=gif&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
而后在凌晨 2 点 57 分(这个时间点,大佬都是不用睡觉的吗?仍是说刚修完福报,下班了), max 回复到:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1我不敢相信 CLQ 使用起来会有这样的问题,他们至少应该在 API 文档里面说明一下。
这里的他们,应该指的是 JDK 团队的成员,特指 Doug Lea,毕竟是他老爷子的做品。640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
为何没有在 API 文档里面说明呢?
由于他们本身也不知道有这个 BUG 啊。
Greg 连着回复了两条,而且直接指出了解决方案:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1问题的缘由是 remove 方法的源码里面,有上图中标号为 ① 的这样一行代码。
这行代码会去取消被移除的这个 node (其值已经被替换为 null)和 list 之间的连接,而后可让 GC 回收这个 node。
可是,当集合里面只有一个元素的时候, next != null 这个判断是不成立的。
因此就会出现这个须要移除的节点已经被置为 null 了,但却没有取消和队列之间的链接,致使 GC 线程不会回收这个节点。
他给出的解决方案也很简单,就是标号为②、③的地方。总之,只须要让代码执行 pred.casNext 方法就行。
总之一句话,致使内存泄漏的缘由是一个被置为 null 的 node,因为代码问题,致使该 node 节点,既不会被使用,也不会被 GC 回收掉。
若是你还没理解到这个 BUG 的缘由,说明你对 CLQ 这个队列的结构还不太清晰。
那么我建议你读一下《Java并发编程的艺术》这一本书,里面有一小节专门讲这个队列的,图文并茂,写的仍是很是清晰。640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1这个 BUG 在 jetty 里面的前因后果算是说清楚了。

而后,咱们再回到 JDK BUG 的这个连接中去:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
他这里写的缘由就是我前面说的缘由,没有 unlink,因此不能被回收。
并且他说到:这个 BUG 在最新的JDK 七、8和9版本中都存在。
他说的最新是指截止这个 BUG 被提出来以前:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1服务器


Demo跑起来



这一小节里面,咱们跑一下 Greg 给的那个修复 Demo,亲手去摸一下这个 BUG 的样子。
数据结构


https://bugs.eclipse.org/bugs/attachment.cgi?id=256704


你能够打开上面那个连接,直接复制粘贴到你的 IDEA 里面去:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
注意第 13 行,由于 Greg 给的是修复 Demo,因此用的是 ConcurrentHashSet,因为咱们要演示这个bug,因此使用 CLQ。
这个 Demo 就是在死循环里面调用 queue 的 add(obj) 和 remove(obj) 方法。每循环 10000 次,就打印出时间间隔、队列大小、最大内存、剩余内存、总内存的值。

最终运行起来的效果是这样的(JDK 版本是 1.7.0_71):
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
能够看到每次打印 duration 这个时间间隔是愈来愈大,队列大小始终为 1。
后面三个内存相关的参数能够先不关心,下一小节咱们用图形化工具来看。
你知道上面这个程序,到我写文章写到这里的时候,我跑了多久了吗?
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=161 小时 32 分 53 秒。
最新一次循环 10000 次所须要的时间间隔是 575615ms,快接近 10 分钟:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
这就是 Greg 说的:不只仅是内存泄漏,并且愈来愈慢。640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
可是,一样的程序,我用 JDK 1.8.0_212 版本跑的时候状况倒是这样的:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
时间间隔很稳定,不会随着时间的推移而增长。

说明这个版本是修复了这个 BUG 的,我带你们看看源码:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
JDK 1.8.0_212 版本的源码里面,在 CLQ 的 remove(obj) 方法的 502 行末尾注释了一个 unlink。
官方的修复方法能够看这里:
并发


http://hg.openjdk.java.net/jdk8u/jdk8u-dev/jdk/rev/8efe549f3c87


改动比较多,可是原理仍是和以前分析的同样:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1我仅仅在两个 JDK 版本中跑过示例代码。

在 JDK 1.8.0_212 没有发现内存泄漏的问题,我看了对应的 remove(obj) 方法的源码确实是修复了。
在 JDK 1.7.0_71 中能够看到内存泄漏的问题。
unlink,一个简简单单的词,背后原来藏了这么多故事。640?wx_fmt=jpeg&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1app


jconsole、VisualVM、jmc



既然都说到内存泄漏了,那必须得介绍几个可视化的故障排除工具。

前面说了,这个程序跑了 61 个小时了,给你们看一下这个时间段里面堆内存的使用状况:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1能够看到整个堆内存的使用量是一个明显的、缓慢的上升趋势。
上面这个图就是来自 jconsole。
结合程序,经过图片咱们能够分析出,这种状况必定是内存泄漏了,这是一个很是经典的内存泄漏的走势。
接下来,咱们再看一下 jmc 的监控状况:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1上面展现的是已经使用的堆内存的大小,走势和 jconsole 的走势同样。

而后再看看 VisualVM 的图:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
VisualVM 的图,我不知道怎么看整个运行了 60 多小时的走势图,可是从上面的图也是能看出是有上升趋势的。

在 VisualVM 里面,咱们能够直接 Dump 堆,而后进行分析:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1能够清楚的看到, CLQ 的 Node 的大小占据了 94.2%。

可是,从咱们的程序来看,咱们根本就没有用到这么多 Node。咱们只是用了一个而已。
你说,这不是内存泄漏是什么。
内存泄漏最终会致使 OOM。

因此当发生 OOM 的时候,咱们须要分析是否是有内存泄漏。也就是看内存里面的对象到底应不该该存活,若是都应该存活那就不是内存泄漏,是内存不足了。须要检查一下 JVM 的参数配置(-Xmx/-Xms),根据机器内存状况,判断是否还能再调大一点。

同时,也须要检查一下代码,是否存在生命周期过程的对象,是否有数据结构使用不合理的地方,尽可能减小程序运行期的内存消耗。
咱们能够经过把堆内存设置的小一点,来模拟一下内存泄漏致使的 OOM。

仍是用以前的测试案例,可是咱们指定 -Xmx 为 20m,即最大可用的堆大小为 20m。

而后把代码跑起来,同时经过 VisualVM 、jconsole、jmc 这三个工具监控起来,为了咱们有足够的时候准备好检测工具,我在第 8 行加入休眠代码,其余的代码和以前的同样:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
加入 -Xmx20m 参数:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
运行起来以后,咱们同时经过工具来查看内存变化,下面三个图从上到下的工具分别是 VisualVM、jconsole、jmc:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
从图片的走势来看,和咱们以前分析的是同样的,内存一直在增加。
程序运行 19 分 06 秒后,发生 OOM 异常:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
那正常的走势图应该是怎么样的呢?
咱们在 JDK 1.8.0_121 版本中(已经修复了 remove 方法),用相同的 JVM 参数(-Xmx20m)再跑一下:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1
首先从上面的日志中能够看出,时间间隔并无递增,程序运行的很是的快。
而后用 VisualVM 检测内存,一样跑 19 分钟后截图以下:640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1能够看到堆内存的使用量并无随着时间的推移而愈来愈高。可是仍是有很是频繁的 GC 操做。

这个不难理解,由于 CLQ 的数据结构用的是链表。而链表又是由不一样的 node 节点组成。
因为调用 remove 方法后,node 节点具有被回收的条件,因此频繁的调用 remove 方法对节点进行删除,会触发 JVM 的 min GC。

这种 JDK BUG 致使的内存泄漏其实挺让人崩溃的。首先你第一次感知到它是由于程序发生了 OOM。
也许你会先无脑的加大堆内存空间,刚好你的程序运行了一周以后又要上线了,因此涉及到重启应用。
而后很长一段时间内没有发生 OOM 了。你就想这个问题可能解决了。
可是它仍是在继续发生着,极可能因为节假日先后不能上线,好比国庆七天,加上先后几天,大概有半个月的样子应用没有上线,因此没有重启,程序愈来愈慢,最终致使第二次 OOM 的出现。
这个时候,你以为可能不是内存溢出这么简单了。
会不会是内存泄漏了?
而后你再次重启。此次重启以后,你开始时不时的 Dump 一下内存,拿出来分析分析。

忽然发现,这个 node 怎么这么多呢?
最终,找到这个问题的缘由。
原来是 JDK 的 BUG。

你就会发出和 Greg 同样的感叹:卧槽,震惊,这么牛皮!?640?wx_fmt=jpeg&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1我这个运行了 60 多小时的程序到如今堆内存使用了 233m,可是我整个堆的大小是接近 2G。
经过 jmc 同时展现堆的总体大小和已经使用的堆大小你能够发现,距离内存泄漏能够说是道阻且长了:
640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1我粗略的算了一下,这个程序大概还得运行 475 个小时左右,也就是 19 天以后才会出现因为内存泄漏,致使的 OOM。

我会尽可能跑下去,可是听到我电脑嗡嗡嗡的风扇声,我不知道它还能不能顶得住。
640?wx_fmt=jpeg&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1若是它顶住了,我在后面的文章里面通知你们。

好了,图形化工具这一小节就到这里了。

咱们只是展现了它们很是小的一个功能,合理的使用它们经常能达到事半功倍的做用。

若是你不太了解它们的功能,建议你看看《深刻理解JVM虚拟机(第3版)》,里面有一章节专门讲这几个工具的。640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1框架


最后说一句(求关注)


640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1这是我昨天晚上写文章的时候拍的 ,女友说一眼望去感受我是一个盯盘的人,在看股票走势图,这只股票太牛逼了。
要是股市的整体走势也像内存泄露那么单纯而直接就行了。
只要在 OOM 以前落袋为安就行。惋惜有的人就是在 OOM 的前一刻满仓杀入,真是个悲伤的故事。
文中提到的两本书,都是很是优秀的值得学习的书籍。做为一个 Java 程序员,若是你尚未拥有这两本书,我强烈建议你买来看看。

另外,我最近的阅读量降低的很是厉害,正反馈持续减弱。
因此安排个“一键三连”(转发、在看、点赞)吧,周更很累的,不要白嫖我,须要一点正反馈。image.png才疏学浅,不免会有纰漏,若是你发现了错误的地方,因为本号没有留言功能,还请你在后台留言指出来,我对其加以修改。
感谢您的阅读,我坚持原创,十分欢迎并感谢您的关注。


640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1


我是 why,一个被代码耽误的文学创做者,不是大佬,可是喜欢分享,是一个又暖又有料的四川好男人。


还有,重要的事情说三遍:


欢迎关注我呀。欢迎关注我呀。欢迎关注我呀。640?wx_fmt=png&tp=webp&wxfrom=5&wx_lazy=1&wx_co=1

相关文章
相关标签/搜索