公司线上有个 tomcat 服务,里面合并部署了大概 8 个微服务,之所以没有像其他微服务那样单独部署,其目的是为了节约服务器资源,况且这 8 个服务是属于边缘服务,并发不高,就算宕机也不会影响核心业务。
因为并发不高,所以线上一共部署了 2 个 tomcat 进行负载均衡。
这个 tomcat 刚上生产线,运行挺平稳。大概过了大概 1 天后,运维同事反映 2 个 tomcat 节点均挂了。无法接受新的请求了。CPU 飙升到 100%。
接手这个问题后。首先大致看了下当时的 JVM 监控。
CPU 的确居高不下
FULL GC 从大概这个小时的 22 分开始,就开始频繁的进行 FULL GC,一分钟最高能进行 10 次 FULL GC
minor GC 每分钟竟然接近 60 次,相当于每秒钟都有 minor GC
从老年代的使用情况也反应了这一点
随机对线上应用分析了线程的 cpu 占用情况,用 top -H -p pid 命令
可以看到前面 4 条线程,都占用了大量的 CPU 资源。随即进行了 jstack,把线程栈信息拉下来,用前面 4 条线程的 ID 转换 16 进制后进行搜索。发现并没有找到相应的线程。所以判断为不是应用线程导致的。
第一个结论
通过对当时 JVM 的的监控情况,可以发现。这个小时的 22 分之前,系统 一直保持着一个比较稳定的运行状态,堆的使用率不高,但是 22 分之后,年轻代大量的 minor gc 后,老年代在几分钟之内被快速的填满。导致了 FULL GC 。同时 FULL GC 不停的发生,导致了大量的 STW,CPU 被 FULL GC 线程占据,出现 CPU 飙高,应用线程由于 STW 再加上 CPU 过高,大量线程被阻塞。同时新的请求又不停的进来,最终 tomcat 的线程池被占满,再也无法响应新的请求了。这个雪球终于还是滚大了。
分析完了案发现场。要解决的问题变成了:
是什么原因导致老年代被快速的填满?
拉了下当时的 JVM 参数
-Djava.awt.headless=true -Dfile.encoding=UTF-8 -server -Xms2048m -Xmx4096m -Xmn2048m -Xss512k -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:+DisableExx plicitGC -XX:MaxTenuringThreshold=5 -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCMSCompactAtFullCollection
-XX:+PrintGCDetails -Xloggc:/data/logs/gc.log
总共 4 个 G 的堆,年轻代单独给了 2 个 G,按照比率算,JVM 内存各个区的分配情况如下:
所以开始怀疑是 JVM 参数设置的有问题导致的老年代被快速的占满。
但是其实这参数已经是之前优化后的结果了,eden 区设置的挺大,大部分我们的方法产生的对象都是朝生夕死的对象,应该大部分都在年轻代会清理了。存活的对象才会进入 survivor 区。到达年龄或者触发了进入老年代的条件后才会进入老年代。基本上老年代里的对象大部分应该是一直存活的对象。比如 static 修饰的对象啊,一直被引用的 缓存啊,spring 容器中的 bean 等等。
我看了下垃圾回收进入老年代的触发条件后(关注公众号后回复“JVM”获取 JVM 内存分配和回收机制的资料),发现这个场景应该是属于大对象直接进老年代的这种,也就是说年轻代进行 minor GC 后,存活的对象足够大,不足以在 survivor 区域放下了,就直接进入老年代了。
但是一次 minor GC 应该超过 90%的对象都是无引用对象,只有少部分的对象才是存活的。而且这些个服务的并发一直不高,为什么一次 minor GC 后有那么大量的数据会存活呢。
随即看了下当时的 jmap -histo 命令产生的文件
发现 String 这个这个对象的示例竟然有 9000 多 w 个,占用堆超过 2G 。这肯定有问题。但是 tomcat 里有 8 个应用 ,不可能通过分析代码来定位到。还是要从 JVM 入手来反推。
第二次结论
程序并发不高,但是在几分钟之内,在 eden 区产生了大量的对象,并且这些对象无法被 minor GC 回收 ,由于太大,触发了大对象直接进老年代机制,老年代会迅速填满,导致 FULL GC,和后面 CPU 的飙升,从而导致 tomcat 的宕机。
基本判断是,JVM 参数应该没有问题,很可能问题出在应用本身不断产生无法被回收的对象上面。但是我暂时定位不到具体的代码位置。
第二天,又看了下当时的 JVM 监控,发现有这么一个监控数据当时漏看了
这是 FULL GC 之后,老年代的使用率。可以看到。FULL GC 后,老年代依然占据 80%多的空间。full gc 就根本清理不掉老年代的对象。这说明,老年代里的这些对象都是被程序引用着的。所以清理不掉。但是平稳的时候,老年代一直维持着大概 300M 的堆。从这个小时的 22 分开始,之后就狂飙到接近 2G 。这肯定不正常。更加印证了我前面一个观点。这是因为应用程序产生的无法回收的对象导致的。
但是当时我并没有 dump 下来 jvm 的堆。所以只能等再次重现问题。
终于,在晚上 9 点多,这个问题又重现了,熟悉的配方,熟悉的味道。
直接 jmap -dump,经过漫长的等待,产生了 4.2G 的一个堆快照文件 dump.hprof,经过压缩,得到一个 466M 的 tar.gz 文件
然后 download 到本地,解压。
运行堆分析工具 JProfile,装载这个 dump.hprof 文件。
然后查看堆当时的所有类占比大小的信息
发现导致堆溢出,就是这个 String 对象,和之前 Jmap 得出的结果一样,超过了 2 个 G,并且无法被回收
随即看大对象视图,发现这些个 String 对象都是被 java.util.ArrayList 引用着的,也就是有一个 ArrayList 里,引用了超过 2G 的对象
然后查看引用的关系图,往上溯源,源头终于显形:
这个 ArrayList 是被一个线程栈引用着,而这个线程栈信息里面,可以直接定位到相应的服务,相应的类。具体服务是 Media 这个微服务。
看来已经要逼近真相了!
第三次结论
本次大量频繁的 FULL GC 是因为应用程序产生了大量无法被回收的数据,最终进入老年代,最终把老年代撑满了导致的。具体的定位通过 JVM 的 dump 文件已经分析出,指向了 Media 这个服务的 ImageCombineUtils.getComputedLines 这个方法,是什么会产生尚不知道,需要具体分析代码。
得知了具体的代码位置, 直接进去看。经过小伙伴提醒,发现这个代码有一个问题。
这段代码为一个拆词方法,具体代码就不贴了,里面有一个循环,每一次循环会往一个 ArrayList 里加一个 String 对象,在循环的某一个阶段,会重置循环计数器 i,在普通的参数下并没有问题。但是某些特定的条件下。就会不停的重置循环计数器 i,导致一个死循环。
以下是模拟出来的结果,可以看到,才运行了一会,这个 ArrayList 就产生了 322w 个对象,且大部分 Stirng 对象都是空值。
至此,水落石出。
最终结论
因为 Media 这个微服务的程序在某一些特殊场景下的一段程序导致了死循环,产生了一个超大的 ArrayList 。导致了年轻代的快速被填满,然后触发了大对象直接进老年代的机制,直接往老年代里面放。老年代被放满之后。触发 FULL GC 。但是这些 ArrayList 被 GC ROOT 根引用着,无法回收。导致回收不掉。老年代依旧满的,随机马上又触发 FULL GC 。同时因为老年代无法被回收,导致 minor GC 也没法清理,不停的进行 minor GC 。大量 GC 导致 STW 和 CPU 飙升,导致应用线程卡顿,阻塞,直至最后整个服务无法接受请求。
觉得有用的话,请关注下我的公众号「元人部落」,作者坚持原创的内容技术分享,也有开源作品,欢迎关注
开源仓库为: https://gitee.com/bryan31
公众号一般周更,每次会分享一些实用的技术,陪你一起成长
关注后回复“资料”领取 50G 的视频资料,包括一套企业级微服务的视频教学
1
zhuawadao 2020-08-26 11:25:23 +08:00
多乎哉?不多矣。关之。
|
2
putaozhenhaochi 2020-08-26 11:47:27 +08:00 via Android 1
发推广区。谢谢
|
3
lewis89 2020-08-26 11:57:21 +08:00
写这种代码的直接打死吧,service 所有变量的引用 只在栈上,调用完了 自动弹出 自然就不会被 GCRoot 引用,而且微服务也通常不需要将 引用部署到类的成员变量上面,这样的话 服务本身就是存在状态的,而通常服务都是要被设计成无状态,可以随时被替换 被重启的。
|
4
bl 2020-08-26 11:59:40 +08:00
可以转载到 upupor.com 吗
|
6
yeqizhang 2020-08-26 12:13:45 +08:00 via Android
我记得我之前写的一个 bug 导致死循环,好像运维直接 jstack 直接定位了方法的……这么复杂的吗
|
7
li24361 2020-08-26 12:14:11 +08:00
看到 cpu 占满 就应该猜到死循环了,果然
还有一个可能就是 hashmap 多线程使用不当, 直接 dump 下来, 看下位置就 ok ata 上解决问题的,有一半都是因为这俩原因,已经快跟空指针排查一样慢慢开发都开始学会了 |
8
cheng6563 2020-08-26 12:20:56 +08:00 via Android
有产生 oom 异常吗? 一般都会设置 oom 时直接强停进程的。
|
11
wakzz 2020-08-26 14:49:29 +08:00
看到 JVM 的 CPU 占用率 100%,要么是 OOM 导致 Full GC,要么是 CPU 循环空载。
下一步就应该看 gc 日志,以及打印高 CPU 的线程名称来定位是 OOM 导致的 Full GC 还是空载问题。 定位出 OOM 后,先 jmap 把内存快照生成出来后,重启应用暂时恢复服务,再分析内存快照定位内存泄漏的代码; 如果是 CPU 空载,则要么 jstack 或者用红火图来定位 CPU 占用多的代码,来定位导致空载的代码。 |
12
haosamax 2020-08-26 16:20:31 +08:00
这个 list 在方法结束后不能回收吗
|
15
x66 2020-08-26 16:40:34 +08:00
写得不错,关注了!
|
16
bryan31 OP @haosamax 这个 list 是程序中是一个几千万次的循环,所以短时间内不会被 gc 回收,最终会进入老年代。在多线程情况下,会触发老年代大量的 full gc
|
18
bryan31 OP @haosamax CMS 其一,CMS 在小内存应用上的表现要优于 G1,而大内存应用上 G1 更有优势,大小内存的界限是 6GB 到 8GB,我司大多数项目堆都在 2~4G 。其二,目前我司用的还是 java8,java8 的 g1 个人认为可能还不成熟。
|
20
securityCoding 2020-08-26 17:27:03 +08:00
hprof+jstack 一般的问题都能定位到了
|
21
terry0314 2020-08-26 17:31:07 +08:00
好熟悉的报表,是 CAT 吗
|
23
vate32 2020-08-26 19:25:53 +08:00
作为一个刚毕业一年的小菜鸡,想了想不知道俺啥时候能达到这种水平
|
24
mazyi 2020-08-26 21:20:21 +08:00
JVM 归根结底还是堆栈信息,出了这种问题第一件事就是要运维搞下来。
|
25
rockyou12 2020-08-26 21:27:53 +08:00
上次也遇到个类似问题,不过是 sql 拼接有问题导致一条查出来就有 2 个 G,查几次就 oom 了。其实这种问题只要遇到过一次,知道要 heap dump 下来分析,还是不太难。
|
27
xomix 2020-08-27 10:05:32 +08:00
同样的问题在当年做 VB.NET 的时候遇到过,但是当时在开发组内测的时候就发现在一些功能执行后内存会虚增 8MB 不被回收,两个人利用 VS 的调试工具抽了大概 3 小时左右定位问题,没让这种 bug 跑出开发组。
上线前还是要在开发组内部做一下测试,防止这种恶行 bug 导致生产环境损失。 |
29
xixinimei 2020-09-29 02:19:56 +08:00
早先定位 hadoop mapreduce 程序时,也是先 dump 出文件,不过用的是 Eclipse Memory Analyzer 分析的
|