美文网首页
记一次线程池资源泄露问题分析

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

作者: 生饼 | 来源:发表于2018-06-10 17:22 被阅读0次

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

    相关文章

      网友评论

          本文标题:记一次线程池资源泄露问题分析

          本文链接:https://www.haomeiwen.com/subject/wmzfeftx.html