记一次线程池资源泄露问题分析

1 现象

项目组有一个应用由多台机器组成一个集群向外提供服务,但是集群上线后大约两个星期发生了master机器宕机。

2 分析

2.1 使用jvisualvm连上新选举出来的master机器,观察堆栈的整体使用情况:

2.png

从图中可以看出堆内存的垃圾收集基本正常,但是线程数在持续增加

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/sh

while 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 建议项目中为创建的线程池取一个有意义的名字,方便分析堆栈时快速确定相应线程的具体位置,定位到具体代码

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 203,324评论 5 476
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,303评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,192评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,555评论 1 273
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,569评论 5 365
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,566评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,927评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,583评论 0 257
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,827评论 1 297
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,590评论 2 320
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,669评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,365评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,941评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,928评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,159评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,880评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,399评论 2 342

推荐阅读更多精彩内容