1. 告警
最近所负责的服务略频繁地收到4xx告警
![c4450bae4382ad66656888012a47c2bf.png](https://i-blog.csdnimg.cn/blog_migrate/a3cfc1713722d67232f53c4ad41c8915.jpeg)
2. 问题定位
1、查业务日志,没发现相关错误的日志
2、查nginx access log,发现返回的状态码都是499,从request_uri查了一遍发现不是集中在某一个请求上,说明应该不是某个接口的问题了,有可能进程层面问题了。
![264d141befaa99db4d0bc5647b1504f3.png](https://i-blog.csdnimg.cn/blog_migrate/74e9b20ddbf6be06ccdd2eb36fe91d31.jpeg)
通过对upstream_addr 分类,可以看到问题基本都是集中在 某一台这台机器上
3、网上资料了解到,499 是 nginx 扩展的 4xx 错误,代表客户端请求还未返回时,客户端主动断开连接。原因有几种,不过大部分原因都说到有可能服务器upstream处理过慢,导致用户提前关闭连接。那就先往这个方向排查,登录机器查看实际的access.log
![9d09fced53f16c760da01e0b2030466e.png](https://i-blog.csdnimg.cn/blog_migrate/215171eea46ec704321ada847b1fac12.jpeg)
发现upstream response都是10s以上。这就证明了上游服务器处理10秒还没有响应,因此nginx提前关闭链接,返回499
4、为什么进程响应如此慢,10秒太不正常了。考虑到那段时间就只有一台机器有问题,而且是进程层面的问题,首先想到的是GC,于是再次登录到机器上查看gc log。发现有Full GC,时间点和告警的时间也吻合。 惊呆的是,这次FullGC耗时长达19.07秒,由于我们的服务使用的是jdk8默认的ParallelGC,FullGC期间,整个应用Stop The World的。这是非常恐怖的一件事
![c5d85dbb7c0ecb0526c5d708ddfe80b1.png](https://i-blog.csdnimg.cn/blog_migrate/16330748bf394a02454709e2bf1d4604.jpeg)
由此看来,4xx告警的初步原因已经定位到,就是FullGC导致的。
3. FullGC原因排查
那么究竟为什么会发生FullGC呢?需要深入分析一下。
借助服务治理平台的JVM监控观察了几天。期间不同机器不同时间也发生了几次FullGC。从监控发现,基本每台机器隔两天就会发生一次FullGC,每次FullGC后年老代回收的垃圾不算多,使用比例还是挺高的。
![8c2e95c187ca4fb906cf3a1bc5669518.png](https://i-blog.csdnimg.cn/blog_migrate/8122112eacd0e585c278aae0e728e54f.jpeg)
为什么年老代空间占用这么多?
继续分析上面那条full gc log,
1、发生full gc时,年老代内存已经占用了99.98%了(1048397/1048576)。看起来因为年老代满了而触发的FullGC了。
2、full gc回收了年老代大约302M的垃圾,回收后年老代占用70.4%(738282/1048576)。这占用率还是比较高的。
4. 年老代对象分析
1、首先jmap简单打印一下所有对象的信息。发现有ClassPathList和ClassClassPath两个类的对象数量高达1000多万,并且这两个数量是一样的。仿佛嗅到了内存泄漏的味道。
![960251ca343ed7db95c5462123bd98b7.png](https://i-blog.csdnimg.cn/blog_migrate/eb764a7b0356c28724cf6cc74f10c6b2.jpeg)
2、只依靠对象统计信息,不足以定位问题,需要使用完整HeapDump,通过MAT进一步分析
jmap把完整堆heapDump下来
![e233d7154c980ac706057158abd58d04.png](https://i-blog.csdnimg.cn/blog_migrate/02147ced9ef535b1a7918d49e9ad6b35.jpeg)
隔一段时间后,继续jmap,这次只取存活对象的dump(实际效果是先执行一次FULL GC)
![852c6d79dba8a891380cede83e8dfd72.png](https://i-blog.csdnimg.cn/blog_migrate/1daf839fa14c96156643c9b79aa5934a.jpeg)
可以看到,经过Full GC后,ClassPathList对象没有被回收,数量反而继续增加。到这里,基本可以确定,ClassPathList是存在泄漏了。
5. 年老代ClassPathList分析
那么,ClassPathList究竟被谁引用着,导致回收不掉呢?
通过MAT的OQL过滤出老生代的ClassPathList对象,从对象的关联关系上继续深入分析。
首先需要知道老生代的地址区间,可以使用vjtools
通过vjmap的address命令,快速打印各代地址。
![5412505d31f34c40caf4f3cc698f133a.png](https://i-blog.csdnimg.cn/blog_migrate/a9f3dcabd86524c8eefd2857db2abdd4.jpeg)
可以得知,oldGen的下界是0x80000000,上界是0xc0000000(注意OQL中使用时要把数值前的那串0去掉)。
执行OQL只查询年老代中的ClassPathList对象:执行OQL只查询年老代中的ClassPathList对象:
![be5bbbecea05c0f0b2022bbcfc09e95d.png](https://i-blog.csdnimg.cn/blog_migrate/df45ca1161634fa2a35cd4f7efb35e1c.jpeg)
抽取其中一个对象分析,可以发现这个ClassPathList对象被一连串不同ClassPathList对象的next属性引用着。看起来是个链表的结构
![a0104ab0d1edd970cfb49c1d97998c99.png](https://i-blog.csdnimg.cn/blog_migrate/ba87adcc74b1af98a227deb0a63c56a7.jpeg)
再看看GCRoot,发现是被AppClassLoader也就是我们的应用类加载器引用着。除非这个加载器卸载了,否则ClassPathList对象是不会被GC掉了。
![6e76db86855c62c1538bdf8cb041f059.png](https://i-blog.csdnimg.cn/blog_migrate/ebecbf68c418242c6f8b63db88bd4c31.jpeg)
6. 项目中哪里使用了ClassPathList?
分析到这里,似乎离真相越来越近了。到底这个ClassPathList在项目中哪里使用到了?
通过前面的分析知道了ClassPathList的整体引用关系链:
AppClassLoader -> ClassPool类的defaultPool字段 -> ClassPoolTail类的source字段 -> ClassPathList类的pathList
6.1 ClassPathList源码
![d02ed6981e7046f17c1ea239ecea1a8c.png](https://i-blog.csdnimg.cn/blog_migrate/1b9f5565f267d8e9968f6485225f61e1.jpeg)
可以看到,ClassPathList有两个属性,一个是next,结合之前MAT的分析,ClassPathList的确就是一个链表的结构。随着时间的增长,ClassPathList不断新增,链表也随之变得越来越大,最后内存占用逐渐上升。
另一个path字段属于ClassPath类型,ClassPath是个接口,查看它的实现类,发现一个似曾相识的名称ClassClassPath,之前分析对象统计信息时,还有一个类的对象数量是和ClassPathList一样的,正是这个ClassClassPath。每新增一个ClassPathList,都会伴随着新增对应的ClassPath对象,这也解释了为什么两者数量是一致的了。
6.2 ClassClassPath源码
![9d3dfb175ab2e97573a8f94902f5306b.png](https://i-blog.csdnimg.cn/blog_migrate/759394f7998d62bcd9361484e42f1e4c.jpeg)
通过注释知道,这个ClassClassPath的作用大概就是,利用一个叫ClassPool的对象,可以调用其insertClassPath方法来新增一个ClassClassPath对象,insertClassPath方法内部通过头插法将ClassClassPath添加到ClassPathList链表,从而形成一个search-path,然后通过这个search-path能够获取到某一个Class类的信息。
![e9765c90f5a8826b93a8d4c81847db8a.png](https://i-blog.csdnimg.cn/blog_migrate/c9488913e880aca1b6c61f1d9e7298fd.jpeg)
于是尝试着搜了一下,看看项目中有没有调用到insertClassPath方法的地方。意外发现一个类,
![194590e454160cc5fa4bfbb4d863c0de.png](https://i-blog.csdnimg.cn/blog_migrate/c654cded205493f5f26ff5b8d4602296.jpeg)
这不就是我们项目用来打印方法入参、执行耗时、上报metrics的@AutoLog的实现类吗。
![6e6ab332d61b4bb65d6380e826f30fcd.png](https://i-blog.csdnimg.cn/blog_migrate/8a8ff13145b2ce680707d2aa725f9c91.jpeg)
可以看到getParams方法中调用了insertClassPath,注解@AutoLog的printParams默认为true,也就是每次调用都需要打印方法入参,每次打印前都要调用getParams先获取参数名称。因此每次都会insertClassPath,从而导致ClassPathList链表越来越大。
至此,内存泄漏的元凶已经找到。解决方法也就简单了。
因为目标只是想得到方法的参数名称,通过JoinPoint其实能直接获取到,因此可以改成JoinPoint获取的方式。
7. 压测
为了进行对比,分别在修改前后各进行一次压测。压测JVM参数大致与线上一致,为了尽快看到效果,只是调小了heap的大小。-Xms200m -Xmx200m
7.1 修改前
![2ba26066f964f0b2a4c88fe780e28056.png](https://i-blog.csdnimg.cn/blog_migrate/5087ea41b99411bd5c38bd1257f8c52c.jpeg)
ClassPathList数量不断增长
![135875f3cb98aec05feb4b1588fd67c2.png](https://i-blog.csdnimg.cn/blog_migrate/c6ff534558967316bb47e4184760fb45.jpeg)
年老代每次能回收的垃圾越来越少,每次回收过后的剩余空间也越来越小。最终整个年老代被撑满
![49ebcdabb9fc0e64420251b830c72e4a.png](https://i-blog.csdnimg.cn/blog_migrate/ac9d756b3c9611b50512531f0edccfb1.jpeg)
虽然还没触发OOM,但是CPU负载飙高,从基本都在处于频繁的FULLGC状态
7.2 修改后
![650ec95552396bf6fbf5ad59bef86318.png](https://i-blog.csdnimg.cn/blog_migrate/c7b2a35027ba120c69625aba0cb6b65f.jpeg)
ClassPathList已经被消灭掉了
![28dbfdfa0bf70b506bbcca5c100c834a.png](https://i-blog.csdnimg.cn/blog_migrate/0833d8e822d6cd22fe8660077fe7c30e.jpeg)
FullGC也趋于规律化了。每次回收的垃圾大致都相同
![2d5d6d7d6388fa3687950966ded8697f.png](https://i-blog.csdnimg.cn/blog_migrate/b6728ae29aaf0d1d3ca36f807f5abd34.jpeg)
8. 后记
- 很多时候只依靠简单的对象统计信息,不足以定位问题,需要使用完整HeapDump,通过MAT进一步分析。如果只需分析年老代对象,可以使用OQL过滤。可用如下方式可获得老生代地址:
第一种方式是在启动参数增加 -XX:+PrintHeapAtGC,每次GC都打印地址
第二种方式是使用vjmap的命令,在-old, -sur, -address 中,都会打印出该区间的地址
第三种方式,使用vjmap的address命令,快速打印各代地址,不会造成过长时间停顿。
详情参考:https://github.com/vipshop/vjtools/blob/master/vjmap/README.md
- 亲选服务使用JDK8, 默认的GC收集算法;-XX:+UseParallelOldGC。使用Parallel Scavenge(年轻代)+Parallel Old(老年代)的组合进行GC。这是一套注重吞吐量的收集器。吞吐量=程序运行时间/(程序运行时间+GC时间)。假设运行时间99秒、GC时间1秒。吞吐量=99%。但是对于有一定并发量的在线应用来说,GC时停顿1秒是挺大影响的。因此后续可根据情况调整使用CMS
附: 我们服务的JVM参数
-Xms2g -Xmx2g -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m -XX:NewRatio=1 -Xss512k -XX:SurvivorRatio=1 -XX:-UseAdaptiveSizePolicy -XX:+PrintPromotionFailure -XX:+PrintGCApplicationStoppedTime -Xloggc:/dev/shm/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=1m -XX:+PrintTenuringDistribution -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/weblog/java/-XX:ErrorFile=/data/weblog/java/hs_err_%p.log -XX:-OmitStackTraceInFastThrow
作者:zcliu
链接:https://www.jianshu.com/p/065c59606685