[转帖]一次艰难的内存泄露排查

一次,艰难,内存,泄露,排查 · 浏览次数 : 0

小编点评

**内容摘要：** 该文档介绍如何确定 CarnivalOneDayInfo 类是否出现内存泄露问题。 **主要内容：** * 首先，文档说明如何使用 jmap 命令分析类的内存使用情况。 * 然后，它解释了 CarnivalOneDayInfo 类中 "另外后面的优化方案是重构活动代码" 的含义。 * 接着，它说明了可以使用 equals 运算符代替 beanutils 中的 threadlocals 变量，避免内存泄露问题。 * 最后，它解释了在上线之前预估活动代码占用内存的必要性，以及如何获取动态内存占用信息。

正文

https://www.jianshu.com/p/d0dff28a4cce

 

一次艰难的内存泄露排查

  1. 现象

    • 2019.4.26 22:00左右，通过jstat -gcutil pid 5000 ,发现fgc次数很多而且频繁，此时老年代占比已经大约70%左右，且已经回收不了内存，我们这边设置的fgc阈值是老年代的70%。此时因为还有30%的老年空间，所以整体内存相对还算稳定，CPU也比较稳定，但是有很大的潜在的风险，就是内存一直上涨，不释放。

      [service@ZQ-SE-331-V05 ~]$ jstat -gcutil 1087 5000
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00  55.09  88.41  72.10  92.64  85.22   9223 1169.442   435  168.866 1338.307
 57.54   0.00  82.24  72.31  92.64  85.22   9224 1169.542   436  168.877 1338.418
  0.00  63.75   5.33  72.50  92.64  85.22   9225 1169.642   436  168.877 1338.519
  0.00  63.75  34.02  72.50  92.64  85.22   9225 1169.642   436  168.877 1338.519
  0.00  63.75  59.26  72.50  92.64  85.22   9225 1169.642   436  168.877 1338.519
  0.00  63.75  81.37  72.50  92.64  85.22   9225 1169.642   436  168.877 1338.519
 55.60   0.00  11.75  72.71  92.64  85.22   9226 1169.742   436  168.877 1338.619
 55.60   0.00  40.07  72.71  92.64  85.22   9226 1169.742   436  168.877 1338.619
 55.60   0.00  67.86  72.70  92.64  85.22   9226 1169.742   437  169.541 1339.284
  0.00  56.04   4.21  72.59  92.64  85.22   9227 1169.838   437  169.541 1339.379
  0.00  56.04  30.01  71.73  92.64  85.22   9227 1169.838   438  169.649 1339.487
  0.00  56.04  57.75  71.73  92.64  85.22   9227 1169.838   438  169.649 1339.487
  0.00  56.04  79.01  71.73  92.64  85.22   9227 1169.838   438  169.649 1339.487
 55.39   0.00   2.54  71.92  92.64  85.22   9228 1169.988   438  169.649 1339.638
 55.39   0.00  24.70  71.92  92.64  85.22   9228 1169.988   438  169.649 1339.638
 55.39   0.00  47.89  71.92  92.64  85.22   9228 1169.988   438  169.649 1339.638
 55.39   0.00  82.01  71.89  92.64  85.22   9228 1169.988   439  170.207 1340.196

    • 初步猜测是出现了内存泄露

    • 通过jmap -histo/-histo:live pid >> log 导出fgc前后的histo对比，发现了一个实例数很大的对象CarnivalOneDayInfo，达到了2kw级别，而且一直在增加

      num     #instances         #bytes  class name
----------------------------------------------
   1:      28906840     1387528320  java.util.HashMap
   2:      38675870     1237627840  java.util.HashMap$Node
   3:      18631826      745273040  xxx.CarnivalOneDayInfo
   
    num     #instances         #bytes  class name
----------------------------------------------
   1:      31092889     1492458672  java.util.HashMap
   2:      35749328     1143978496  java.util.HashMap$Node
   3:      20355334      814213360  xxx.CarnivalOneDayInfo

  2. 排查

    1. 直接看CarnivalOneDayInfo(嘉年华)相关代码，因为之前的测试大概知道这个问题，所以很快的定位到是在每分钟的MinuteJob中检查所有在线玩家的时间活动的时候，相关逻辑会克隆一个CarnivalOneDayInfo。所以初步定位是CarnivalOneDayInfo不断clone的问题

    2. 后端y同学看了一下相关逻辑，本地把相关clone逻辑注释后，再次本地观察histo，发现该对象实例不在增加，再次确认1的推论

    3. 但看了一下活动相关代码

      所有活动的检查都是clone了一份，为什么只有嘉年华活动泄露？

      看相关代码，发现clone出来的对象都是临时对象，应该会被fgc的，如何泄露呢？

    4. 所以直接开始操作第一步，准备查CarnivalOneDayInfo是被谁持有引用

      查这个问题的话，必须要把内存堆快照dump出来，然后利用工具检查，如mat

      但是线上玩家很多，而且堆内存很多，导出一次很花费时间，会stw

    5. 所以直接连开发服务器，查了一下，一样存在CarnivalOneDayInfo泄露的问题，所以直接利用

      jmap -dump:live,format=b,file=2388_heap.bin 2388，导出开发服务器java进程的堆内存快照

      直接利用mat打开

    6. 对mat使用有经验的话，操作步骤是直接

      选择dominator_tree

      搜索CarnivalOneDayInfo

      List Objects

      选择With incoming references，谁持有了它的引用

    7. 直接发现是被

      queue-executor-handler-5

      java.lang.ThreadLocal$ThreadLocalMap @ 0x8104eec0

      java.lang.ThreadLocalThreadLocalMapEntry[64] @ 0x866710f0

      java.lang.ThreadLocalThreadLocalMapEntry @ 0x86671608

      java.util.IdentityHashMap @ 0x86671628

      java.lang.Object[]，通过查看这个属性，可以看到其大量持有了CarnivalOneDayInfo和HashSet

    8. 从上面可以很确定的是，CarnivalOneDayInfo是直接被逻辑线程的threadlocal持有

  3. 艰难的分析之路

    1. 逻辑线程的threadlocal怎么会持有CarnivalOneDayInfo，从代码和想法上感觉不可思议

    2. 我这边的第一步是直接在ide中查所有ThreadLocal的引用，发现

      logback

      protobuf

      业务自己的threadlocal

      BeanUtils的threadlocal

    3. 排查后，简单测试了一下，和查了一下相关代码，发现没有什么思路和投诉。觉得beanutils和logback有点问题，但是感觉和CarnivalOneDayInfo关系也不大

    4. 于是下面我的重点在于想从mat入手，看看能不能从中找出threadlocal的名字，但最终是被证明是徒劳的，只有引用地址

    5. 不过我们z同学从是debug的排查思路出发的

      在ThreadLocal的set和setInitialValue打断点

      然后跑游戏，重点断点在MinuteJob，向逻辑线程投递消息检查活动状态这块

      每次调用checkTimeActivity，都去观察每个ThreadLocalThreadLocalMapEntry

      然后重点观察是否出现IdentityHashMap，因为上面mat分析到了是这个map

      终于定位到堆栈

    6. 堆栈

      MinuJob -> 遍历在线所有玩家，向逻辑线程投递消息 -> ActivityManager#checkTimeActivity

      遍历所有个人活动 -> CarnivalActivityInfo#checkActivityState

      CarnivalActivityInfo diff = playerInfo.clone() // 在这里clone了一份

      checkIsSameState -> activityBaseInfo.getCarnivalDaysMap().equals(carnivalDaysMap) // 调用equals比较

      去依次比较CarnivalDaysMap中每一个CarnivalOneDayInfo

      调用CarnivalOneDayInfo -> BaseCarnivalOneDayInfo # equals

      BeanUtils.isDirty

    7. 具体代码

      private static Set<String> getDirtyNamesByBean(AugmentedBean augmentedBean) {
        IdentityHashMap<AugmentedBean, Set<String>> dirtyNamesMap = dirtyNames.get();
        if (dirtyNamesMap == null) {
            dirtyNamesMap = new IdentityHashMap<>();
            dirtyNames.set(dirtyNamesMap);
        }
        return dirtyNamesMap.computeIfAbsent(augmentedBean, k -> Sets.newHashSet());
    }

    public static boolean isDirty(AugmentedBean augmentedBean) {
        return getDirtyNamesByBean(augmentedBean).size() > 0;
    }

    8. 从上面可以非常容易的看到

      • 是这里创建了一个IdentityHashMap，然后set到了threadlocal中
      • 和之前的分析如出一辙

    9. 至此完全定位问题是，是BeanUtils的锅

  4. 复盘和总结

    1. 其实在3的时候，非常怀疑过beanutils的问题，但是没有太仔细注意，现在一看，和上面的分析一模一样
    2. 分析内存泄露，思路
      • 对比fgc前后的histo，确认那些对象实例数一直在增加，而且明显偏大
      • 分析代码，如果直接定位问题，最好
      • 如果不能直接定位，需要确认是谁持有该对象引用，那么需要dump堆内存快照
      • 但是不能在线上dump，需要在开发服务器复现（内存泄露通常比较容易复现），然后在开发服务器dump
      • dump出来后，利用mat工具分析泄露，List Objects With incoming references，找到引用
      • 下一步是需要确认为什么这里会引用，可以分析代码，解决问题，最好
      • 如果不能，那么可以使用debug的方式，在上一步引用相关对象的代码出加断点，确认线程堆栈
    3. 也解释了为什么只有嘉年华活动有泄露，因为只有它调用了beanutils生成的basexx的equals方法，其他都没有调用
    4. beanutils是当初clone对象的一个解决方案，用来回滚和diff，增量更新，后来该方案废弃，因为会随着对象的复杂度提高而导致clone成本高，但是遗留了一大部分生成的代码，而这次的bug也是因为调用了废弃的生成代码的方法。所以下一个版本一定将所有生成的废弃代码清理一遍

  5. 后续解决办法

    • 发现了beanutils的这个问题后，那么很容易解决泄露问题了。我写了一个beanshell脚本，向逻辑线程投递了消息，调用 BeanUtils.clean，清理所有threadlocals

      import x.BeanUtils;
import y.HandlerModule;

for (int i = 1; i <= 16; i++) {
    HandlerModule.instance.addQueueTask(i, new Runnable() {
        public void run() {
            BeanUtils.clean();
        }
    });
}

    • 在用jstat看了一下，CarnivalOneDayInfo经过fgc后，从kw到了百万，老年代占用也从70到了30

      $ jstat -gcutil 1087 5000

74.73   0.00  16.02  72.48  92.61  85.04  10156 1313.117   575  271.355 1584.472
 74.73   0.00  34.71  72.48  92.61  85.04  10156 1313.117   575  271.355 1584.472
 74.73   0.00  54.42  72.48  92.61  85.04  10156 1313.117   575  271.355 1584.472
 74.73   0.00  73.29  72.48  92.61  85.04  10156 1313.117   575  271.355 1584.472
 74.73   0.00  89.41  72.48  92.61  85.04  10156 1313.117   575  271.355 1584.472
  0.00  71.54   9.25  72.74  92.64  85.06  10157 1313.303   576  272.188 1585.492
  0.00  71.54  28.30  72.73  92.64  85.06  10157 1313.303   577  272.188 1585.492
  0.00  71.54  55.85  72.73  92.64  85.06  10157 1313.303   577  272.463 1585.766
  0.00  71.54  78.05  72.73  92.64  85.06  10157 1313.303   577  272.463 1585.766
 69.21   0.00   1.70  70.98  92.64  85.06  10158 1313.438   578  273.320 1586.758
 69.21   0.00  19.97  63.09  92.64  85.06  10158 1313.438   578  273.320 1586.758
 69.21   0.00  39.82  53.33  92.64  85.06  10158 1313.438   578  273.320 1586.758
 69.21   0.00  59.75  41.61  92.64  85.06  10158 1313.438   578  273.320 1586.758
 69.21   0.00  75.12  31.79  92.64  85.06  10158 1313.438   578  273.320 1586.758
 69.21   0.00  94.13  31.79  92.64  85.06  10158 1313.438   578  273.320 1586.758
  0.00  86.02  15.60  32.07  92.64  85.06  10159 1313.761   578  273.320 1587.081
  0.00  86.02  94.86  32.07  92.64  85.06  10159 1313.761   578  273.320 1587.081
  
  [service@ZQ-SE-331-V05 config]$  jmap -histo 1087 | grep CarnivalOneDayInfo
  10:       1408627       56345080  xxx.CarnivalOneDayInfo

    • 另外后面的优化方案是重构活动代码，另外即使用equals，也不用之前beanutils生成的类的equals比较，避免beanutils threadlocals的泄露问题

  6. 关于内存问题，在正式上线之前，一定要可根据同时在线人数，dau等准确预估整体占用内存，如一个player的实际的占用内存，全局静态数据如排行榜的实际占用内存等。可以通过代码和工具获取。这样能快速确认是否是出现了内存泄露还是真的比较占内存。

一次 艰难 内存 泄露 排查

与[转帖]一次艰难的内存泄露排查相似的内容：

[转帖]一次艰难的内存泄露排查

https://www.jianshu.com/p/d0dff28a4cce 一次艰难的内存泄露排查 现象 2019.4.26 22:00左右，通过jstat -gcutil pid 5000 ,发现fgc次数很多而且频繁，此时老年代占比已经大约70%左右，且已经回收不了内存，我们这边设置的fgc阈

一次 艰难 内存 泄露
0
[转帖]密集计算场景下的 JNI 实战

https://www.jianshu.com/p/ab8fd26014c1 作者：vivo 互联网服务器团队- Wei Qianzi、Li Haoxuan 在 Java 发展历程中，JNI 一直都是一个不可或缺的角色，但是在实际的项目开发中，JNI 这项技术应用的很少。在笔者经过艰难的踩坑之后，终

密集 计算 场景 jni
0
[转帖]一次春节大促性能压测不达标的瓶颈推演

https://plantegg.github.io/2020/11/23/%E4%B8%80%E6%AC%A1%E6%98%A5%E8%8A%82%E5%A4%A7%E4%BF%83%E6%80%A7%E8%83%BD%E5%8E%8B%E6%B5%8B%E4%B8%8D%E8%BE%BE%E6%

一次 春节 性能 标的
0
[转帖]一次SpringBoot版本升级，引发的血案

https://z.itpub.net/article/detail/B6495288E725529E58105397659A08EB 前言 近项目组升级了SpringBoot版本，由之前的2.0.4升级到新版本2.7.5，却引出了一个大Bug。 到底是怎么回事呢？ 1.案发现场 有一天，项目组的同

一次 springboot 版本升级 引发
0
[转帖]一次 Scan 竟耗时上百秒？Redis Scan 原理解析与踩坑

来自：指月 https://www.lixueduan.com原文：https://www.lixueduan.com/post/redis/redis-scan/主要分析了 Redis Scan 命令基本使用和具体实现，包括Count 参数与 Scan 总耗时的关系，以及核心的逆二进制迭代算法分析

一次 scan 耗时 上百
0
[转帖]一次海光物理机资源竞争压测的记录

一次海光物理机资源竞争压测的记录 https://plantegg.github.io/2021/03/07/%E4%B8%80%E6%AC%A1%E6%B5%B7%E5%85%89%E7%89%A9%E7%90%86%E6%9C%BA%E8%B5%84%E6%BA%90%E7%AB%9E%E4%B

一次 海光 物理 资源
0
[转帖]一次海光物理机资源竞争压测的记录

一次海光物理机资源竞争压测的记录 https://plantegg.github.io/2021/03/07/%E4%B8%80%E6%AC%A1%E6%B5%B7%E5%85%89%E7%89%A9%E7%90%86%E6%9C%BA%E8%B5%84%E6%BA%90%E7%AB%9E%E4%B

一次 海光 物理 资源
0
[转帖] 一次SSL握手异常，我发现JDK还有发行版区别

https://www.cnblogs.com/codelogs/p/16633704.html 简介# 最近，我们一个多机房部署的服务，调用方反馈有问题，在调用新加坡机房时正常，而调用印度机房则报SSL握手异常。 排查花了一些时间，同时也积累了一些经验，故记录一下，读完本文，你将了解到如下内容：

一次 ssl 握手 异常
0
[转帖]一次fork引发的惨案！

https://www.cnblogs.com/xuanyuan/p/15502289.html “你还有什么要说的吗？没有的话我就要动手了”，kill程序最后问道。 这一次，我没有再回答。 只见kill老哥手起刀落，我短暂的一生就这样结束了··· 我是一个网络程序，一直以来都运行在Windows系

一次 fork 引发 惨案
0
[转帖]一次操作系统报错OutOfMemory Error的处理记录

在启动公司内嵌的tomcat容器时出现报错, 如下: # There is insufficient memory for the Java Runtime Environment to continue.# Native memory allocation (malloc) failed to a

一次 操作系统 报错 outofmemory
0
# 热门排行
微软 New Bing AI 申请与使用保姆级教程（免魔法） ChatGPT API使用介绍 ChatGPT开发实战 一篇带你了解如何使用纯前端类Excel表格构建现金流量表 手把手教你玩转 Excel 数据透视表 为什么 C# 可能是最好的第一编程语言 .NET 入门到高级路线 提高工作效率的神器：基于前端表格实现Chrome Excel扩展插件 React + Springboot + Quartz，从0实现Excel报表自动化 用Echarts实现前端表格引用从属关系可视化
© PmDaddy. 2023 PmDaddy教程网 All rights reserved.