@HUST-SuWB
2018-04-22T06:43:30.000000Z
字数 1658
阅读 384
蘑菇街
某天早上一到公司就接到一个上游系统同事的反馈,说依赖的我的一个接口开始时不时的超时,让我赶紧处理下。
既然是线上异常,肯定不敢怠慢,赶紧打开监控确认了下,发现这个接口确实在近期有一个rt的飙升,几乎涨了十几倍(由原本的3-5ms暴涨到了50ms)。
确认了下代码,这个接口没有任何多余的逻辑,只是读了2次缓存,然后根据读取的缓存进行return,所以首先怀疑是不是缓存异常了,去查了一下我这个系统缓存的性能监控,读取非常稳定,基本上1ms就够了,那么问题也不在缓存这里。
接下来开始查看服务器监控,发现接口开始超时的时间点伴随着服务器负载的飙升和内存占用的飙升,看来问题就在这里了。那么是什么引起的服务器负载飙升呢?我逐一排查了服务接口,找到了一个接口在某个时间点的QPS有飙升,而且这个飙升的时间点与服务器负载飙升的时间点是吻合的,那么有理由怀疑是由于这个接口的QPS飙升导致了服务器异常。
这个时候,我还把服务器的JVM内存快照dump下来分析了一把,发现有大量的线程对象占用了大量的内存,同时还发现full gc的次数也飙升,而且时间点也是吻合的。那么答案已经呼之欲出了,多半是代码里有漏洞导致了内存中大量的对象无法回收,才引起了后边一系列的问题。
好,现在开始分析这个QPS飙升的接口,很快就定位了问题,在这个接口里由于外部接口调用比较多,为了保证rt尽量小,所以使用了future并行模式,而并行的线程池是每次进入这个接口都会new一个新的,看来就是这里的线程池一直没有被回收了。
本地写了段单测代码,贴一下
@Test
public void threadTest() {
ExecutorService executorService = Executors.newSingleThreadExecutor();
CompletionService<Integer> completionService = new ExecutorCompletionService<>(executorService);
final long start = System.currentTimeMillis();
for(int i=0; i< COUNT; i++) {
completionService.submit(() -> {
//TODO 在这里调用待调试的业务接口
return 1;
});
}
try {
int count = 0;
for(int i=0; i<COUNT; i++) {
if(completionService.take().get() != null) {
System.out.println("当前已处理完成的请求个数为 " + i);
count++;
}
}
if(count > 0) {
long end = System.currentTimeMillis();
System.out.println("总耗时为 " + (end-start)/1000 + " s");
}
} catch (Exception e) {
System.out.println(e);
}
}
然后通过jstat -gcutil捕捉程序运行期间的gc,可以发现以下几个现象:
对于每次new一个新的线程池的方式,每次young gc的时候会导致老年代内存大增,也就意味着新生代很多活跃对象无法回收,被转移到了老年代;然后进行开始频繁的full gc,每次full gc都会导致一定时间的stop-the-world;后边内存就直接爆掉了,程序异常退出,在测试的时候爆内存还只执行了大概600次请求;
如果调整线程池的使用姿势,把线程池改为全局的静态变量,则程序可以正常运行结束;
如果不改为全局静态变量,但是每次在方法体退出前手动shutdown,那么会有频繁的young gc,但是young
gc的效果非常显著,并且程序一样可以正常运行结束;
线程池对象是无法被自动回收的,除非new完以后手动注销,所以最好是通过定义全局的静态变量来使用,不要每次都new一个新的对象。