1 现象
项目组有一个应用由多台机器组成一个集群向外提供服务,但是集群上线后大约两个星期发生了master机器宕机。
2 分析
2.1 使用jvisualvm连上新选举出来的master机器,观察堆栈的整体使用情况:
从图中可以看出堆内存的垃圾收集基本正常,但是线程数在持续增加
2.2 长期跟踪堆内存gc与线程数
每隔5分钟打印gc信息与控制器线程数到日志文件中,
$ ../jdk1.8.0_152/bin/jps
22673 controller-sidecar.jar
61202 Jstat
31045 Jps
18169 Main
17853 controller-launcher.jar
$ nohup ../jdk1.8.0_152/bin/jstat -gccause 18169 300000 > gcinfo.log &
$ cat printThread.sh
#!/bin/shwhile true
do
sleep 300
ps -Lp 18169 | wc
done
$ nohup ./printThread.sh > threads.log &
一天后查看日志内容:
日志中的前面几条gc信息:
$ more gcinfo.log
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT LGCC GCC
0.00 1.42 35.91 2.24 87.29 79.56 41 2.386 6 0.712 3.098 Allocation Failure No GC
1.14 0.00 43.07 2.28 87.29 79.56 50 2.519 6 0.712 3.231 Allocation Failure No GC
1.34 0.00 4.33 2.33 87.30 79.57 64 2.726 6 0.712 3.438 Allocation Failure No GC
0.00 1.50 20.00 2.36 87.30 79.57 73 2.861 6 0.712 3.573 Allocation Failure No GC
一天后最后几条日志信息:
$ tail gcinfo.log
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT LGCC GCC
0.76 0.00 99.97 81.87 86.65 79.09 14658 624.469 6 0.712 625.181 Allocation Failure No GC
0.00 0.68 34.50 81.95 86.65 79.09 14677 625.568 6 0.712 626.280 Allocation Failure No GC
0.00 0.94 13.89 82.17 86.65 79.09 14695 626.706 6 0.712 627.418 Allocation Failure No GC
从gc信息来看,并没有发现明显的内存泄露
开始监控时的线程数:
$ more threads.log
781 3905 27334
780 3900 27299
814 4070 28489
815 4075 28524
一天后的线程数:
$ tail threads.log
16274 81370 569589
16274 81370 569589
16274 81370 569589
16274 81370 569589
可见控制器的线程数在持续增加,有可能发生了线程资源泄露
查看用户的最大进程数:
$ ulimit -a
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 1032230
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 10240
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 10240
cpu time (seconds, -t) unlimited
max user processes (-u) 1032230
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited
2.3 分析具体发生了线程泄露的地方
打印控制器的堆栈快照
$ ../jdk1.8.0_152/bin/jstack -l jstack.tdump
查看堆栈内容发现有大量的线程池的线程栈,而且线程池的线程数都固定为11个线程,jstack.tdump部分内容如下:
"pool-1469-thread-11" #44160 prio=5 os_prio=0 tid=0x00007f2b1097c800 nid=0x8c38 waiting on condition [0x00007f2aeca4a000]
"pool-1469-thread-10" #44159 prio=5 os_prio=0 tid=0x00007f2b10a6c800 nid=0x8c37 waiting on condition [0x00007f2aed050000]
"pool-1469-thread-8" #44164 prio=5 os_prio=0 tid=0x00007f2b109a4000 nid=0x8c35 waiting on condition [0x00007f2aecb4b000]
"pool-1469-thread-4" #44167 prio=5 os_prio=0 tid=0x00007f2b10af0000 nid=0x8c34 waiting on condition [0x00007f2aee2e1000]
"pool-1469-thread-5" #44166 prio=5 os_prio=0 tid=0x00007f2b10acf800 nid=0x8c32 waiting on condition [0x00007f2aec646000]
"pool-1469-thread-7" #44165 prio=5 os_prio=0 tid=0x00007f2b10aa6000 nid=0x8c30 waiting on condition [0x00007f2aed252000]
"pool-1469-thread-9" #44163 prio=5 os_prio=0 tid=0x00007f2b10ab7000 nid=0x8c2f waiting on condition [0x00007f2aefdfc000]
"pool-1469-thread-3" #44162 prio=5 os_prio=0 tid=0x00007f2b10a47000 nid=0x8c2e waiting on condition [0x00007f2aeefee000]
"pool-1469-thread-1" #44161 prio=5 os_prio=0 tid=0x00007f2b10ac5000 nid=0x8c2a waiting on condition [0x00007f2af4ac9000]
"pool-1469-thread-6" #44158 prio=5 os_prio=0 tid=0x00007f2b109d0000 nid=0x8c24 waiting on condition [0x00007f2aed555000]
"pool-1469-thread-2" #44157 prio=5 os_prio=0 tid=0x00007f2b10ade000 nid=0x8c23 waiting on condition [0x00007f2af1e91000]
"pool-1468-thread-6" #44122 prio=5 os_prio=0 tid=0x00007f2b10abe800 nid=0x7943 waiting on condition [0x00007f2aed151000]
"pool-1468-thread-10" #44117 prio=5 os_prio=0 tid=0x00007f2b10a02000 nid=0x793d waiting on condition [0x00007f2af0174000]
"pool-1468-thread-8" #44120 prio=5 os_prio=0 tid=0x00007f2b10a7e000 nid=0x793c waiting on condition [0x00007f2af32a5000]
"pool-1468-thread-1" #44113 prio=5 os_prio=0 tid=0x00007f2b10a7b800 nid=0x793a waiting on condition [0x00007f2aedfde000]
"pool-1468-thread-7" #44121 prio=5 os_prio=0 tid=0x00007f2b10ac7800 nid=0x7938 waiting on condition [0x00007f2aee7e6000]
"pool-1468-thread-3" #44114 prio=5 os_prio=0 tid=0x00007f2b10a5e000 nid=0x7935 waiting on condition [0x00007f2aef0ef000]
"pool-1468-thread-9" #44119 prio=5 os_prio=0 tid=0x00007f2b10a25800 nid=0x792e waiting on condition [0x00007f2af4bca000]
"pool-1468-thread-4" #44115 prio=5 os_prio=0 tid=0x00007f2b10aa0800 nid=0x792c waiting on condition [0x00007f2af49c8000]
"pool-1468-thread-5" #44118 prio=5 os_prio=0 tid=0x00007f2b10ac1000 nid=0x792b waiting on condition [0x00007f2af0f82000]
"pool-1468-thread-11" #44116 prio=5 os_prio=0 tid=0x00007f2b10ac0000 nid=0x792a waiting on condition [0x00007f2aef7f6000]
"pool-1468-thread-2" #44112 prio=5 os_prio=0 tid=0x00007f2b10a82800 nid=0x7929 waiting on condition [0x00007f2af087b000]
对照项目代码,可以发现在DevDiscvry类中有一个call()函数,函数内容如下:
@Override
public CompletableFuture call() {
if (null == SegmentSet || SegmentSet.isEmpty()) {
LOG.warn("Devdiscvry: no netsegments.");
return null;
}
ExecutorService exec = Executors.newFixedThreadPool(deviceThread_num);
Iterator<String> it = SegmentSet.iterator();
List<CompletableFuture> futureresults = new ArrayList<>();
while (it.hasNext()) {
String tmp = it.next();
NetSgmtDiscvTask newTask = new NetSgmtDiscvTask(dataBroker, snmpService);
newTask.SetnetSegment(tmp);
CompletableFuture resultFuture = CompletableFuture.supplyAsync(() -> {
CompletableFuture result = new CompletableFuture();
try {
result = exec.submit(newTask).get();
} catch (Exception e) {
e.printStackTrace();
}
return result;
}).exceptionally(e -> {
LOG.error("Devdiscvry: NetSegment {} discover error!!!{}", tmp, e);
return null;
});
futureresults.add(resultFuture);
}
CompletableFuture combineFuture = CompletableFuture
.allOf(futureresults.toArray(new CompletableFuture[futureresults.size()]));
return combineFuture;
}
}
这个call()函数会被周期性的执行,这个函数中创建了一个线程池,并向他提交了一些任务,在函数退出前没有shutdown创建的线程池。ExecutorService exec = Executors.newFixedThreadPool()创建的ThreadPoolExecutor
对象与其他对象的不一样的地方在于,如果它创建了任务线程,这个线程又没有被close,即使它的引用已经超出了作用域范围,那么ThreadPoolExecutor对象也不会被gc回收,引起内存泄露和线程资源泄露
3 修改方法
3.1 线程池使用完后需要shutdown,释放线程池资源
3.1.1 在dcndiscvry模块的call()函数退出之前shutdown创建的线程池(这个方法最直接,改动量最小)
3.1.2 在call()函数外部创建线程池,在整个模块需要销毁时将线程池shutdown(最优)
3.2 建议项目中为创建的线程池取一个有意义的名字,方便分析堆栈时快速确定相应线程的具体位置,定位到具体代码