1. 告警
最近所负责的服务略频繁地收到4xx告警
image.png
2. 问题定位
1、查业务日志，没发现相关错误的日志
2、查nginx access log，发现返回的状态码都是499，从request_uri查了一遍发现不是集中在某一个请求上，说明应该不是某个接口的问题了，有可能进程层面问题了。
image.png
通过对upstream_addr 分类，可以看到问题基本都是集中在 某一台这台机器上
3、网上资料了解到，499 是 nginx 扩展的 4xx 错误，代表客户端请求还未返回时，客户端主动断开连接。原因有几种，不过大部分原因都说到有可能服务器upstream处理过慢，导致用户提前关闭连接。那就先往这个方向排查，登录机器查看实际的access.log
image.png
发现upstream response都是10s以上。这就证明了上游服务器处理10秒还没有响应，因此nginx提前关闭链接，返回499
4、为什么进程响应如此慢，10秒太不正常了。考虑到那段时间就只有一台机器有问题，而且是进程层面的问题，首先想到的是GC，于是再次登录到机器上查看gc log。发现有Full GC，时间点和告警的时间也吻合。 惊呆的是，这次FullGC耗时长达19.07秒，由于我们的服务使用的是jdk8默认的ParallelGC，FullGC期间，整个应用Stop The World的。这是非常恐怖的一件事
image.png
由此看来，4xx告警的初步原因已经定位到，就是FullGC导致的。
3. FullGC原因排查
那么究竟为什么会发生FullGC呢？需要深入分析一下。
借助服务治理平台的JVM监控观察了几天。期间不同机器不同时间也发生了几次FullGC。从监控发现，基本每台机器隔两天就会发生一次FullGC，每次FullGC后年老代回收的垃圾不算多，使用比例还是挺高的。
image.png
为什么年老代空间占用这么多？
继续分析上面那条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多万，并且这两个数量是一样的。仿佛嗅到了内存泄漏的味道。
image.png
2、只依靠对象统计信息，不足以定位问题，需要使用完整HeapDump，通过MAT进一步分析
jmap把完整堆heapDump下来
image.png
隔一段时间后，继续jmap，这次只取存活对象的dump（实际效果是先执行一次FULL GC）
image.png
可以看到，经过Full GC后，ClassPathList对象没有被回收，数量反而继续增加。到这里，基本可以确定，ClassPathList是存在泄漏了。
5. 年老代ClassPathList分析
那么，ClassPathList究竟被谁引用着，导致回收不掉呢？
通过MAT的OQL过滤出老生代的ClassPathList对象，从对象的关联关系上继续深入分析。
首先需要知道老生代的地址区间，可以使用vjtools
通过vjmap的address命令，快速打印各代地址。
image.png
可以得知，oldGen的下界是0x80000000，上界是0xc0000000（注意OQL中使用时要把数值前的那串0去掉）。
执行OQL只查询年老代中的ClassPathList对象：执行OQL只查询年老代中的ClassPathList对象：
image.png
抽取其中一个对象分析，可以发现这个ClassPathList对象被一连串不同ClassPathList对象的next属性引用着。看起来是个链表的结构
image.png
再看看GCRoot，发现是被AppClassLoader也就是我们的应用类加载器引用着。除非这个加载器卸载了，否则ClassPathList对象是不会被GC掉了。
image.png
6. 项目中哪里使用了ClassPathList？
分析到这里，似乎离真相越来越近了。到底这个ClassPathList在项目中哪里使用到了？
通过前面的分析知道了ClassPathList的整体引用关系链：
AppClassLoader -> ClassPool类的defaultPool字段 -> ClassPoolTail类的source字段 -> ClassPathList类的pathList
6.1 ClassPathList源码
image.png
可以看到，ClassPathList有两个属性，一个是next，结合之前MAT的分析，ClassPathList的确就是一个链表的结构。随着时间的增长，ClassPathList不断新增，链表也随之变得越来越大，最后内存占用逐渐上升。
另一个path字段属于ClassPath类型，ClassPath是个接口，查看它的实现类，发现一个似曾相识的名称ClassClassPath，之前分析对象统计信息时，还有一个类的对象数量是和ClassPathList一样的，正是这个ClassClassPath。每新增一个ClassPathList，都会伴随着新增对应的ClassPath对象，这也解释了为什么两者数量是一致的了。
6.2 ClassClassPath源码
image.png
通过注释知道，这个ClassClassPath的作用大概就是，利用一个叫ClassPool的对象，可以调用其insertClassPath方法来新增一个ClassClassPath对象，insertClassPath方法内部通过头插法将ClassClassPath添加到ClassPathList链表，从而形成一个search-path，然后通过这个search-path能够获取到某一个Class类的信息。
image.png
于是尝试着搜了一下，看看项目中有没有调用到insertClassPath方法的地方。意外发现一个类，
image.png
这不就是我们项目用来打印方法入参、执行耗时、上报metrics的@AutoLog的实现类吗。
image.png
可以看到getParams方法中调用了insertClassPath，注解@AutoLog的printParams默认为true，也就是每次调用都需要打印方法入参，每次打印前都要调用getParams先获取参数名称。因此每次都会insertClassPath，从而导致ClassPathList链表越来越大。
至此，内存泄漏的元凶已经找到。解决方法也就简单了。
因为目标只是想得到方法的参数名称，通过JoinPoint其实能直接获取到，因此可以改成JoinPoint获取的方式。
7. 压测
为了进行对比，分别在修改前后各进行一次压测。压测JVM参数大致与线上一致，为了尽快看到效果，只是调小了heap的大小。-Xms200m -Xmx200m
7.1 修改前
image.png
ClassPathList数量不断增长
image.png
年老代每次能回收的垃圾越来越少，每次回收过后的剩余空间也越来越小。最终整个年老代被撑满
image.png
虽然还没触发OOM，但是CPU负载飙高，从基本都在处于频繁的FULLGC状态
7.2 修改后
image.png
ClassPathList已经被消灭掉了
image.png
FullGC也趋于规律化了。每次回收的垃圾大致都相同
image.png
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
网友评论