爱凑网

IT技术日记

Jackson JSON 巧遇 G1 回收器的 Bug

上一篇blog介绍了NMT分析堆外内存分析，但是并未有详细解释为什么我们会遇到JDK8的bug，这篇blog主要来解释清楚，为什么我们会遇到了整个问题。

JDK Bug分析

先对这个JDK Bug做个分析，JDK-8180048 : Interned string and symbol table leak memory during parallel unlinking

注：此bug已经在下面的JDK版本中被修复

问题原因是JDK8 G1回收器并未对已经没有被使用的的intern String进行回收，从而导致堆外内存不断增加，主要就是Symbol域 （参见上一篇关于NMT的介绍）；使用CMS不会有这个问题。

可以通过下面2组不同的测试来对比并重现这个问题：

  • 测试源码
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
public class StringInterner {
    public static volatile String lastString;

    public static void main(String[] args) {
        for (int iterations = 0; iterations < 40;) {
            String baseName = UUID.randomUUID().toString();
            for (int i = 0; i < 1_000_000; i++) {
                lastString = (baseName + i).intern();
            }
            if (++iterations % 10 == 0) {
                System.gc();
            }
            LockSupport.parkNanos(500_000_000);
        }
    }
}

  • 不使用G1 Collector
1
2
java -XX:NativeMemoryTracking=detail -XX:+UnlockDiagnosticVMOptions -XX:+PrintNMTStatistics -XX:MetaspaceSize=100m -XX:MaxMetaspaceSize=100m -XX:+UseStringDeduplication -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Xloggc:gc-jdk8-marksweep.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms256m -Xmx256m -cp classes StringInterner

  • 使用G1 Collector重现问题
1
2
java -XX:NativeMemoryTracking=detail -XX:+UnlockDiagnosticVMOptions -XX:+PrintNMTStatistics -XX:+UseG1GC -XX:MetaspaceSize=100m -XX:MaxMetaspaceSize=100m -Xloggc:gc-jdk8-g1.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms256m -Xmx256m -cp classes StringInterner

检查NMT报告并且搜索Symbol，可以发现使用CMS和G1 Collector的Symbol域内存差异很大，而且G1 Collector的Symbol区域会持续增加。

1
2
3
Symbol (reserved=27549KB, committed=27549KB)
Symbol (reserved=424789KB, committed=424789KB)

Jackson JSON 处理 其实到这里已经比较清楚了，为什么Jackson JSON处理会触发JDK这个问题，基本上可以确定的是Jackson一定是在某个地方使用了Intern String导致的。

从Jackson Parser的Feature定义中找到一个选项

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
/**
        * Feature that determines whether JSON object field names are
        * to be canonicalized using {@link String#intern} or not:
        * if enabled, all field names will be intern()ed (and caller
        * can count on this being true for all such names); if disabled,
        * no intern()ing is done. There may still be basic
        * canonicalization (that is, same String will be used to represent
        * all identical object property names for a single document).
        *<p>
        * Note: this setting only has effect if
        * {@link #CANONICALIZE_FIELD_NAMES} is true -- otherwise no
        * canonicalization of any sort is done.
        *<p>
        * This setting is enabled by default.
        */
       INTERN_FIELD_NAMES(true),

       /**
        * Feature that determines whether JSON object field names are
        * to be canonicalized (details of how canonicalization is done
        * then further specified by
        * {@link #INTERN_FIELD_NAMES}).
        *<p>
        * This setting is enabled by default.
        */

JVM NativeMemoryTracking 分析堆外内存泄露

Native Memory Tracking (NMT) 是Hotspot VM用来分析VM内部内存使用情况的一个功能。我们可以利用jcmd（jdk自带）这个工具来访问NMT的数据。

NMT介绍

工欲善其事必先利其器，我们先把相关需要的配置和工具介绍清楚，再通过例子来看看具体如何使用NMT。

打开NMT

NMT必须先通过VM启动参数中打开，不过要注意的是，打开NMT会带来5%-10%的性能损耗。

1
2
3
4
-XX:NativeMemoryTracking=[off | summary | detail]
# off: 默认关闭
# summary: 只统计各个分类的内存使用情况.
# detail: Collect memory usage by individual call sites.

jcmd查看NMT报告

通过jcmd查看NMT报告以及查看对比情况。

1
2
3
4
5
6
7
8
jcmd <pid> VM.native_memory [summary | detail | baseline | summary.diff | detail.diff | shutdown] [scale= KB | MB | GB]

# summary: 分类内存使用情况.
# detail: 详细内存使用情况，除了summary信息之外还包含了虚拟内存使用情况。
# baseline: 创建内存使用快照，方便和后面做对比
# summary.diff: 和上一次baseline的summary对比
# detail.diff: 和上一次baseline的detail对比
# shutdown: 关闭NMT

VM退出时打印NMT

可以通过下面VM参数在JVM退出时打印NMT报告。

1
-XX:+UnlockDiagnosticVMOptions -XX:+PrintNMTStatistics

NMT实战

症状

某个服务（C）在客户环境使用后发现其内存占用不断变大且远超Xmx指定的大小，导致整个系统因缺少内存造成其他服务无法启动。当时查看到其RSS大约为11G，-Xmx=6G而且heap利用率不到50%。

1
2
3
4
5
6
7
user@hostxxx> prstat -p 2780
PID USERNAME  SIZE   RSS   STATE  PRI   NICE  TIME     CPU   PROCESS/NLWP
2780 user    11G     11G   sleep   59    0    44:16:39 0.0%  java/196

user@hostxxx> /opt/jdk1.8.0_40/bin/jstat -gcutil 2780
S0     S1     E      O      M     CCS    YGC     YGCT       FGC    FGCT     GCT
0.00 100.00  90.60  46.80  98.02  97.10  11323   4049.745   11     225.345   4275.090

分析

服务通过-Xmx=6G指定最大堆分配为6G，但实际RSS已达到11G，开始怀疑堆外内存是否有内存泄露。为了有更好详细的数据，就在本地重现这个问题，并且打开了NMT持续监控。

NMT的Report如下，重点关注每个分类下的commit大小，这个是实际使用的内存大小。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
6739: #进程ID

Native Memory Tracking:

Total: reserved=8491110KB, committed=7220750KB
-                 Java Heap (reserved=6293504KB, committed=6291456KB) 
                            (mmap: reserved=6293504KB, committed=6291456KB) 
 
-                     Class (reserved=1107429KB, committed=66189KB) 
                            (classes #11979)
                            (malloc=1509KB #18708) 
                            (mmap: reserved=1105920KB, committed=64680KB) 
 
-                    Thread (reserved=159383KB, committed=159383KB) 
                            (thread #156)
                            (stack: reserved=158720KB, committed=158720KB)
                            (malloc=482KB #788) 
                            (arena=182KB #310)
 
-                      Code (reserved=255862KB, committed=41078KB) 
                            (malloc=6262KB #9319) 
                            (mmap: reserved=249600KB, committed=34816KB) 
 
-                        GC (reserved=449225KB, committed=449225KB) 
                            (malloc=166601KB #1714646) 
                            (mmap: reserved=282624KB, committed=282624KB) 
 
-                  Compiler (reserved=395KB, committed=395KB) 
                            (malloc=265KB #856) 
                            (arena=131KB #3)
 
-                  Internal (reserved=146041KB, committed=146041KB) 
                            (malloc=132185KB #276370) 
                            (mmap: reserved=13856KB, committed=13856KB) 
 
-                    Symbol (reserved=31487KB, committed=31487KB) 
                            (malloc=29209KB #91080) 
                            (arena=2278KB #1)
 
-    Native Memory Tracking (reserved=33212KB, committed=33212KB) 
                            (malloc=168KB #2575) 
                            (tracking overhead=33044KB)
 
-               Arena Chunk (reserved=2284KB, committed=2284KB)
                            (malloc=2284KB) 
 
-                   Unknown (reserved=12288KB, committed=0KB)
                            (mmap: reserved=12288KB, committed=0KB) 
 
Virtual memory map:
......

并且在服务器上通过cron job来定期抓取NMT的report保存下来做分析，而且同时也把其对应的RSS和PMAP都抓取了一份。

1
2
3
4
5
6
7
8
9
COLLECTOR_PID=`ps -ef|grep "ProcessName" | grep -v grep | awk '{print $2}'`
OUTDIR=/opt/chkmem
HOSTNAME=`hostname`

prstat -s rss 1 1 > ${OUTDIR}/${HOSTNAME}_coll_${COLLECTOR_PID}_prstat_`date '+%Y%m%d_%H%M%S'`.txt

/opt/jdk1.8.0_40/bin/jcmd ${COLLECTOR_PID} VM.native_memory detail > ${OUTDIR}/${HOSTNAME}_coll_${COLLECTOR_PID}_nmd_`date '+%Y%m%d_%H%M%S'`.txt

pmap -x ${COLLECTOR_PID} > ${OUTDIR}/${HOSTNAME}_coll_${COLLECTOR_PID}_pmap_`date '+%Y%m%d_%H%M%S'`.txt

分析发现NMT中的Symbol域持续增大，从最开始的几十兆已经增加到了2G左右，而且整个jvm的内存使用量也在持续增加。见下图：

验证后发现问题和JDK8的bug https://bugs.java.com/view_bug.do?bug_id=8180048 非常类似，测试后也证实确实如此，最后通过升级JDK解决了这个问题。
导致这个问题的组件是Jackson Streaming API 中的 JsonFactory.Feature.INTERN_FIELD_NAMES 引起的，由于项目中需要大量解析动态json文件，并且key都被intern到JVM native 内存无法释放导致内存泄露。

Java 泛型 PECS 原则

我们偶尔会看到针对泛型的一些用法：比如<? extends T> 和 <? super T>，那么这两种定义有什么区别？分别适合用在什么场合？ 在回答这2个问题之前，我们先看一下几个相关的例子:

假设我们有5个类，结构如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
class Animal {
}

class Dog extends Animal {
}

class SmallDog extends Dog {
}

class BigDog extends Dog {
}

class Cat extends Animal {
}

理解<? extends T> 的限制

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
public static void producerExtends(List<? extends Animal> animals) {
    // 读取animals
    Animal a1 = animals.get(0);
    
    // 添加animal
    //animals.add(new Animal());     //编译错
    //animals.add(new Dog());        //编译错
}


public static void main(String[] args) {
    List<Dog> dogs = new ArrayList<Dog>();
    dogs.add(new Dog());
    producerExtends(dogs);
}

把以上代码放入IDE中并且取消添加animal下方的注释后，animals.add(new Animal())/animals.add(new Dog())均提示编译错。为什么读取没有问题，但是写入会报错呢？

animals是一个List<? extends Animal>类型，其中对象必须是Animal或其后代类，读取的时候可以的安全的转换成Animal类型。

那为什么添加Animal和Dog就编译错呢?

因为会违反类型安全(violate type safe)，animals在例子中是List，但是也可以是 List, List, List。这个时候向容器写入对象的时候无法做类型安全检查（比如 List是无法添加Animal类型），所以就禁止写入任何对象。

因为这个特性，所以说<? extnebds T>适合进行读取操作，不能写入，也就是PECS中的PE(Producer Extends)。

注意：不能写入不代表不能修改List，还是可以调用list.clear()方法清空列表。

理解<? super T>的限制

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
public static void consumerSuper(List<? super SmallDog> dogs) {
    dogs.add(new SmallDog());

    //dogs.add(new Dog());         //编译错
    //SmallDog dog1 = dogs.get(0);       //编译错

}

public static void main(String[] args) {

    List<Animal> animals = new ArrayList<>();
    animals.add(new Animal());
    animals.add(new BigDog());
    consumerSuper(animals);
}

如果理解了之前对于<? extends T>的解释，这里应该就更好理解了。这里对于添加Dog对象没问题，但是添加Animal或者读取都会编译错。

为什么add(new Dog())编译错？因为这里的<? super SmallDog>限制了传入的list中的对象必须是SmallDog或其父类（具体类型未知，可能是Animal，也可能是Dog），所以添加的对象必须是SmallDog或其子类，这样才能保证类型安全。

为什么SmallDog dog1 = dogs.get(0)编译错？因为这个list中的对象可能是SmallDog的任意祖先，是无法保证一定可以转化成SmallDog类型 （父类转化为子类必会失败 ClassCastException）。

所以说<? super T>适合进行写操作，不能读取，也就是PECS中的CS(Consumer Super)。

这就是Java泛型中的PECS (Producer Exnteds Consumer Super)，如果说还是不了解应用场景的话，可以看看JDk自带的 Collections.addAll()和Collection.addAll()各自函数的定义有什么区别。

REF:

https://howtodoinjava.com/core-java/generics/java-generics-what-is-pecs-producer-extends-consumer-super/

https://en.wikipedia.org/wiki/Generics\_in\_Java