Hugegraph-loader的性能问题分析

2019-05-03

图

问题描述:

在一次生产测试中, 发现Hugegraph-Loader 在0.8版与我改动的版本之间存在的导入性能数倍的差异, 并且改动后的新版占用内存会持续提升, 并且频繁触发GC. 推测可能存在某些问题, 需要定位分析一下.

0x00. 大体思路

**测试环境: ** 1Server(0.9.1) + 2Loader (0.8 + 0.8.1)

确认性能上的具体差距 (排除功能变化)
- 第一次测试先使用无List/Set, 无Date的schema
- 第二次测试, 先清空数据, 再设置有List/Set 和Date的schema
确认GC次数差别, 次数多导堆
确认内存占用上差别, 需要使用数据量大的数据源导入
确认时间有明显差别, 加上**火焰图**记录, 时间设置长一些
最后才考虑导出堆内存 ,分析是否有内存泄露

0x01. 测试

这里新版Loader是自己修改后的, 旧版是官方的版本.

newLoader- 内存使用2.8G
oldLoader - 内存使用1.4G

内存使用率在千万级数据源正常(导入时间10分钟左右), 大约20%左右. 但是随时间增长会提升到40%,. 大数据源待观察, 以下是千万数量数据源jstatus gcutil 的反映情况:

#10G最大堆, gcutil从开始监控到结束最后结果. 2千万数据量
S0     S1     E      O      M     CCS      YGC     YGCT    FGC    FGCT     GCT
0.00  93.07  86.04  57.67  97.57  93.76    111      83      2    0.885   84.050

#4G最大堆,ygc次数明显增多, 同上2千万数据
S0     S1     E      O      M      CCS      YGC     YGCT    FGC    FGCT     GCT
98.56   0.00  75.40  59.86  97.39  93.59    270      82      3    2.132   84.261

#4G最大堆,2亿数据量
S0     S1     E      O      M      CCS     YGC     YGCT    FGC    FGCT     GCT
99.68  70.21 100.00  97.88  96.81  92.77   1825     786     7   11.018  797.547

在使用2亿数据量导入的时候, 内存使用不断缓慢增加, 达到了3G+, 并且通过jmap查看实时对象存活情况发现, 有些不太对劲…

num     #instances         #bytes  class name
----------------------------------------------
   1:      81987549     8797823536  [B
   2:      62179076     2672011072  [C
   3:      47629915     1143117960  java.lang.String  #4000万个String
   4:      23824434      998222744  [Ljava.lang.Object;
   5:      15745811      755798928  java.nio.HeapByteBuffer
   6:       6371299      557893136  [Ljava.util.HashMap$Node;  #600万个HashMap
   7:        427359      547525312  [I
   8:      32944351      527109616  java.lang.Integer
   9:      11009541      440381640  java.util.LinkedHashMap$Entry #1100万个LinkedHashMap
  10:      12652240      404871680  java.util.HashMap$Node
  11:      12590798      402905536  java.util.ArrayList$Itr
  12:      23495583      375929328  com.baidu.hugegraph.backend.id.IdGenerator$StringId
  13:      14243123      341834952  java.util.ArrayList
  14:      14094000      338256000  com.baidu.hugegraph.backend.cache.CachedSchemaTransaction$$Lambda$145/590414408
  15:       7868106      314724240  java.util.HashMap$KeyIterator

那就开始分析具体是谁导致了这么多引用无法释放了, 然后推断是内存泄漏, 进而去看内存dump了么? 不一定, 先按逻辑排除, 看看火焰图对比(取了800s) , 别过早下一个不确定的结论, 可能会导致你的问题分析之路走向完全错误的方向….

这是release0.8版: (点此查看大图, 且可以操作)

这是我改动后的新版本: (点此查看大图, 且可以操作)

上一次文章里介绍过火焰图, 这里大家也可以以我的这次问题为例, 自己去访问火焰图看看 (可以点击/高亮搜索), 它并非是一个纯静态的图片哦, 看看就从这两张图能不能看出什么端倪, 如果熟悉了火焰图, 其实就这两张图你就能很快定位问题了.

0x02. 分析

火焰图关键从分层的地方开始看, 可以明显看到, 原本官方的火焰图的loadeVertex 这里是没有分叉的, 但是我修改之后却多出了一个非常高的火焰…. 并占据了大量时间, 无中生有显然是不正常的, 那就可以结合图中对应方法, 结合代码看看, 这里为什么突然分叉了, 并且有如此之高的火焰呢? (一般说明生成了大量的对象)

这是对应的官方的旧版代码:

public final class HugeClientWrapper {

    private static volatile HugeClient instance;

    public static HugeClient get(LoadOptions options) {
        if (instance == null) {
            synchronized(HugeClientWrapper.class) {
                if (instance == null) {
                    instance = newHugeClient(options);
                }
            }
        }
        return instance;
    }

    private HugeClientWrapper() {}

    private static HugeClient newHugeClient(LoadOptions options) {
        String address = options.host + ":" + options.port;
            return new HugeClient(address, options...);
        }
    }
}

这是我修改后的代码:

public final enum HugeClientWrapper {
    INSTANCE;
    
   private static HugeClient newHugeClient(LoadOptions options) {
      String address = options.host + ":" + options.port;
      return new HugeClient(address, options...);
   }
}

先说下我为什么要改这部分代码, 因为很早的时候在effective java 上看到说过枚举是实现单例的最佳模式, 然后那天偶然又看到了这篇文章, 强烈建议用枚举替代其他版本的单例实现….加上我看枚举实现太简洁了, 就很开心的大笔一挥, 给它优化为一行INSTANCE 了, 然后试了下, 运行也没有明显问题, 很是开心了一会…

那再结合火焰图, 我修改后出现了大量的HugeClient对象调用, 要知道这可是单例, 而且从逻辑上也很好理解Client 对象显然只应该在初始化的时候生成一个, 并全局复用, 那怎么会在火焰图上有这么多次调用呢? 关键在于大家仔细看看, 官方的双重锁单例并非实例化的当前类, 而是实例化了 instance = newHugeClient(options);也就是说, 通过这个Wrapper类来中转保持HugeClient 的唯一..

而如果照我那样修改, 等于每次调用的时候是Xxx xx = HugeClientWrapper.INSTANCE.newHugeClient(options) , 那等于说是每次都重新初始化了一个HugeClient对象, 而且你跟进去可以看到这个对象的初始化工作就非常多, 又生成了许多的小对象… 那问题就很清晰了, 本来只有初始化调用一次, 全局复用的Client对象, 被我改成了每次插入都会重新生成的方式, 自然就会产生一系列的小对象, 小对象一多, GC次数自然也就不断上升, 内存占用也会高出许多了…

真相大白 ! 如果这里要用枚举实现单例, 那就应该修改HugeClient模块里的HugeClient 类为枚举, 而不是修改Wrapper, 不过这个就麻烦多了…

0x03. 反思

这个问题虽然最后找到发现是个低级错误, 可以说对着代码看 ,都是送分题的, 但是仔细想想, 中间找到它的过程并不顺畅, 主要有这几个问题:

1. 错误的内存泄露推断

我从JVM情况和GC次数/内存占用的持续升高, 感觉这像是内存泄露, 然后花大量时间去看jmap的状态和导出的巨大的堆文件….耗费了大量时间, 只是得出了许多小对象的结论, 但是不知道为何多出了如此多的小对象, 然后硬扣给了SafeDateFormat和List/Set的功能, 觉得是他们哪里代码没写好, 从而导致生成了许多小对象(String/Collection), 导致完全偏离了轨道…

其实有几个可以明显避免的排查手段:

内存泄露虽然不好确定, 但是可以很简单的反推不是内存泄露, 比如JVM的老年代快满了的时候, 手动利用jmap 执行一次fullGC查看当前存活对象, 看看老年代是否能消去, 如果能, 那说明不是内存泄露 (内存泄露是没法通过GC减退的)
内存比之前占用高了不少, 并且是逐步在升高, 此时不应直接判定为内存泄露, 很可能是正常的内存攀升. 应该把内存设置大/小各一次, 看看在内存足够的时候, 是否随着GC, 内存使用是否还在不断攀升. 如果逐步稳定到了一个高范围, 那说明也不是内存泄露, 因为内存泄露随着时间增长只会不断增大.

2. 没有细心查看火焰图

这里主要存在这几个问题:

开始火焰图的时间设置过短, 导致分层不明显, 从而疏忽了区别, 误以为看起来**”差不多”**…
第二次输出火焰图, 结果多个环境复制错了pid, 结果两个火焰图其实都是新版打印出来的, 导致真的没看出区别…
最后正确对比长时间的火焰图, 还是没及时发现问题, 因为粗看新版分叉的地方在连接Client, 然后大量HTTP的方法调用, 误以为是异步发送HTTP请求. 这还是掉以轻心, 轻易下结论的毛病.

3. 优化代码的局限性

最后回到代码本身, 这里也有一些本来可以避免的问题:

最初的思路是分析新旧代码改动了哪些功能, 列举了出来准备一个个排除, 但是最先就把枚举单例先剔除了 (因为觉得不会是这里出错…), 惯性思维不可取.
看到单例的模型, 惯性认为就是在生成本类的单例, 没有去想Wrapper 的包装含义. 如果是单纯的单例, 为什么会叫XxxWrapper呢
其次, 没有跟着代码逻辑去推断, 加载顶点的时候, 为什么会莫名需要一个单例呢? 这个单例到底是做什么的, 如果细看一下就会发现这是在调Client, 自然也会明白本质是取的Client的单例. 而并非Wrapper本身
最后, 看了书或文章之后, 可以试着自己写写demo, 但是别急着改源码, 特别是没细看单例到底封装的是哪个对象之前, 代码也应该多人review 一下, 以免出现这种惯性忽视的问题.

综上, 也是通过这次案例, 给大家一个很好的教训参考, 并告诫大家不要轻视火焰图. 在很多时候, 它能最快的全局性帮你找到性能的瓶颈, 以及一些低级错误导致的问题.. (至于关于JVM的堆内存分析的部分我就都删掉了… 因为分析半天也没得到有用结论, 以后再细说它了…)

补充: 这次排查里其实也用到了Arthas和唯品会出品的Vjtools(快速分析当前pid里CPU/内存/磁盘占用topN), 但是由于和本质错误也无关, 就先不说了, 以后遇到合适的场景再具体介绍.