错误的使用 CompletionService 导致的内存泄漏

有开发人员发现他们的某些 server 上的业务时间偶尔变长, 再看 gc overhead 指标, 发现已经超过10%, 怀疑内存泄漏. 通过对 GC 日志的分析, heap dump的分析, 我们找到泄漏的根本原因.


  1. 首先看数据趋势, 可以看到业务时间从某个时间点之后变长, CPU 跟着增加, CPU 增加的原因就在于 GC 的耗时增加;
    perfSimple.png
  2. 看 verbose GC log 的具体日志, 我们可以看到 CMS GC 老年代的频率很高, 耗时也很多. 从34s 到52s 就要做3次老年代的 GC, 说明每次回收都无法获得足够多的空闲内存, 只能加快回收.

    2021-11-17T09:39:34.726-0700: 1459219.285: [CMS-concurrent-mark-start]
    2021-11-17T09:39:37.142-0700: 1459221.701: [CMS-concurrent-mark: 2.408/2.416 secs] [Times: user=2.90 sys=0.04, real=2.42 secs] 
    ...
    2021-11-17T09:39:37.434-0700: 1459221.993: [CMS-concurrent-sweep-start]
    2021-11-17T09:39:39.055-0700: 1459223.614: [CMS-concurrent-sweep: 1.616/1.621 secs] [Times: user=1.90 sys=0.00, real=1.62 secs] 
    2021-11-17T09:39:39.055-0700: 1459223.614: [CMS-concurrent-reset-start]
    2021-11-17T09:39:39.059-0700: 1459223.618: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    2021-11-17T09:39:41.063-0700: 1459225.622: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1348577K(1433600K)] 1792358K(2170880K), 0.1895637 secs] [Times: user=0.75 sys=0.00, real=0.19 secs] 
    ...
    2021-11-17T09:39:41.253-0700: 1459225.811: [CMS-concurrent-mark-start]
    2021-11-17T09:39:43.632-0700: 1459228.191: [CMS-concurrent-mark: 2.375/2.379 secs] [Times: user=2.84 sys=0.01, real=2.38 secs] 
    2021-11-17T09:39:43.632-0700: 1459228.191: [CMS-concurrent-preclean-start]
    ...
    2021-11-17T09:39:44.000-0700: 1459228.559: [CMS-concurrent-sweep-start]
    2021-11-17T09:39:45.590-0700: 1459230.149: [CMS-concurrent-sweep: 1.590/1.590 secs] [Times: user=1.81 sys=0.01, real=1.60 secs] 
    2021-11-17T09:39:45.590-0700: 1459230.149: [CMS-concurrent-reset-start]
    2021-11-17T09:39:45.594-0700: 1459230.153: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
    ...
    2021-11-17T09:39:52.122-0700: 1459236.681: [CMS-concurrent-mark-start]
  3. 捕获一个 heap dump, 从 heap dump 的 leak 分析可以看到 ClassLoader 保持的内存过多, 通常情况下 ClassLoader 只是引用类定义, 但是它可以通过 static 字段引用实例对象. 下面的 ClassLoader 使用了660M+ 内存, 具有很大的可疑. 如果我们不是很确定, 可以有2个办法来确定: 1) 重启服务器, 等服务器稳定运行在做一个 heap dump, 对比二者的这个 ClassLoader 使用的内存数量, 是不是差别比较大. 2) 增大 heap size, 让它一直运行, 直到再出现问题, 这时候这个 ClassLoader 使用的内存会更大.
    leak.png
  4. 从这个 ClassLoader 出发, 我们找到了对象的聚集地: ClassLoader -> BulkGet*Processer Class -> completionService -> CompletionQueue.
    accumulate.pngrefs.png
  5. 那么为什么这个 CompletionQueue 里这么多对象呢? 为什么不能回收?
    原来在代码 BulkGet*Processer 类里面, 定义了一个静态的 CompletionService, 当有 request 要处理的时候, 就把 Task submit 到这个 completionService 里面, 可是这个没有去拿结果. 可是 CompletionService 是要求把结果都要通过 poll 或 take 取出来, 然后才能从 completionQueue 结果集里面去除这个结果. 因为没有去拿这个结果, 结果导致它的 CompletionQueue 的结果越来越多, 最后把老年代占满.

标签: none

添加新评论