一、案件背景
近日,一个线上应用开始频繁报警:异常日志、接口rt超时、load高、tcp重传率高等等。现场监控如下:
从基础监控来看,cpu使用率不算特别异常,而load高说明等待cpu资源的线程队列长,配合rt上涨来看,推测是线程出现了堆积,而线程堆积一般有两种情况:
二、问题定位
线程耗时变长?
因为应用重度依赖缓存,一起排查问题的同学发现tair成功率也有下降,于是找tair同学开始排查。
另外从db监控来看也没有慢sql出现,近期也没有逻辑改动较大的发布,暂时从其他方向看看。
STW
可以看到问题期间GC次数和耗时明显上升,这里需要注意,因为GC监控里CMS(或G1)和Full GC都会归到Full GC里,所以登到机器上看看gc.log。
这里看到Metadata GC Threshold引起Full GC的字样较多,回收情况也很差(382626K->381836K)再通过jstat看下使用情况:
这里看到M区(metaspace)使用率是73.22%,而FGC平均每秒一次,GC前后O区(old gen)变化不大,可以确定是metaspace泄漏导致的Full GC。
值得注意:M区没到100%(73.22%),为什么会频繁触发fullGC呢?原因是classloader加过多时,会引起metaspace的碎片化问题。后面会进一步解释classloader过多原因。
到此,原因可以确定是FullGC伴随的大量STW引起了线程堆积。下面继续定位为什么metaspace会出现泄漏。
groovy动态类加载问题
对付GC问题,堆dump是最好的排查手段。话不多说,psp进行dump。针对metaspace(Perm gen)的泄漏问题,从看"类加载器视图"和"重复类定义"能很快定位泄漏对象,如下:
可以发现,类加载器中上千个GroovyClassLoader&innerLoader,另外类定义里的Comp_XXX也是应用里使用的groovy类,原来是踩到groovy重复加载会导致泄漏的坑。
但是令人疑惑的是,应用对编译出来的class都做了内存cache,命中就直接返回不再编译,为什么这里出现重复加载呢?
原来代码里通过guava cacheBuilder实现的内存cache,同时设置了缓存队列大小和弱引用
CacheBuilder.newBuilder().maximumSize(1000).softValues().build();
一开始怀疑是softReference会被回收,因为需要缓存的对象(官方模块)只有几十个,去掉softValues后跑一会,发现还是会复现问题,于是dump里查看缓存对象数量:
发现对象数量达到了1000,说明存在淘汰的对象,再次使用这些对象会重复编译,进而导致泄漏。
后续查看缓存对象,是一些不需要编译的三方模块,和同学确定是一次变更,把大量不需要编译的对象(三方模块)也缓存进来。修复方案分析如下:
三、后言
于此,问题原因已经水落石出,集群问题期间出现的表现,比如load高、rt高、cpu上涨、tair成功率下降通过gc引起的stw都可以合理解释。
但tcp重传率上涨的原因是什么呢?所有现象如果没有合理解释清楚,怕有问题遗漏,下面尝试分析下原因:
TCP重传率
TCP重传一种是为了保证数据可靠性的机制,其原理是在发送某一个数据以后就开启一个计时器,在一定时间内如果没有得到发送的数据报的ACK,那么就重新发送数据,直到发送成功为止。
- tcp抓包:sudo tcpdump -i eth0 -w ~/11131114249_fgc_tcpdump1.cap
- 通过oss上传11131114249_fgc_tcpdump1.cap,然后下载到本地
- 用wireshark对cap文件进行分析
这里需要解释8006端口是哪个进程的?是做什么的?为什么没有及时ACK?
相较BIO模式下的tomcat,NIO的nginx擅长做TCP建联,这大概也是在同机部署tomcat和nginx的一点益处。
小心“并发症”的扰乱
另外一点感想是,在多次排查线上问题时,比如出现各种“病症”:机器load飙高、GC变多、内存上涨、线程数开始堆积、RT升高、HSF大量超时、tair失败率上升、流量曲线集中等等。
一旦应用因为某个“病因”出现情况,就会出现很多“病症”,这些“病症”绝大部分都是“并发症”,是由“病因”引起的连锁反应,孰是因孰是果呢?
比如tair集群如果出现问题,导致读取失败,那么依赖缓存的应用肯定会出现rt变长,线程数开始堆积,进而导致内存上涨,FGC,load上涨等问题。