记一次JVM GC优化过程

现有项目迁移Docker后遇到了GC问题，无论是YGC还是CMSGC，都出现了STW过长的情况，影响到了线上服务。现在将整个优化过程记录下，以做参考。图片内容可能不是当时的现场，因为服务较多而且中间也走了一些弯路导致截图乱掉了，但是情况原因是一致的。

Docker与虚拟机不同的地方

我们直观上很容易将Docker容器当成虚拟机，更好的理解应该是一种资源隔离的机制。Docker基于Linux CGroups实现了资源的限制与隔离，但容器并不是真正的虚拟机，没有完整的操作系统。

如果我们在容器内执行top，ps命令就可以看到，拿到的信息是属于整个宿主机的信息。对JVM(JDK 9之前的版本)来讲，JVM并没有针对容器做优化，默认的资源只会读到宿主机的资源情况，所以我们需要用 -Xms -Xmx 做内存资源的限制，用-XX:ParallelGCThreads 做GC线程的限制。

我们线上容器资源分配4C6G，JVM 参数配置 -Xms5602m -Xmx5602m -Xmn1536m -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=70 -XX:ParallelGCThreads=4 记住这两个个配置，后面GC问题和它有关。

CMS Remark阶段GC时间过长

迁移后服务线上跑了一段时间之后，通过日志监控发现接口的响应时间加长了，甚至3s的超时也出现了。我查了Nginx日志，发现应该不是网络的抖动，老大怀疑是GC问题，指明了方向。于是加上 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/opt/logs/gc.log 将日志输出到gc.log,又跑了一天后，看到如下的日志： CMS

CMS GC remark阶段属于STW阶段，GC时间过长是会影响接口的响应的。看到这个日志之后，怀疑到了发生了Swap，后面也证实该猜测是正确的。起了个shell后台任务，通过vmstat命令打印了日志，又等了一天，当CMS GC过长时果然发生了内存的置换。GC时间过长时，日志截图：

CMSGC

vmstat

时间点完全对的上，时间正常的GC就没有这种情况，内存置换是概率发生。

注意上面说了我们Docker容器的内存限制是6G，但是其实Xmx配置了5602m ，堆外的内存其实是不够的。参数不合理导致了swap的发生，那么应该配置多少合适呢？

通过jstack 首先看了下线程数，服务的线程数达到了2000+的水平，而我们的JVM参数又没有限制栈大小（JDK8 默认栈大小1M），这就已经需要2G的内存了。另外还有一块是MetaSpace区域，通过jstat 跟了下GC情况，用jmap histo:live 触发了Full GC后，MetatSpace空间大约需要150M，Old Gen剩下的活跃数据大概200M。美团技术博客给过一个经验值的参数（美团-从实际案例聊聊Java应用的GC优化)

空间	倍数
总大小	3-4 倍活跃数据的大小
新生代	1-1.5 活跃数据的大小
老年代	2-3 倍活跃数据的大小
永久代	1.2-1.5 倍Full GC后的永久代空间占用

同时栈大小一般不需要1M，给到256K即可，通过参数-Xss256k控制。

参考后，结合我们的情况修改后JVM参数：

-Xms2048m -Xmx2048m -Xmn1024m -Xss256k -XX:+UseConcMarkSweepGC -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSScavengeBeforeRemark -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m -XX:CompressedClassSpaceSize=64m

容器内存给到了3.5G，机器空闲资源比较多，任性一点。

修改为上述JVM参数与容器参数后，没有再发生CMS GC时间过长，该问题解决。

YGC 时间缓慢增长至不可接受

CMS GC的问题相对来讲是比较好定位的，修改JVM参数后3s的超时基本上消失了，但是还有另外一个现象，就是我们的YGC耗时是一个缓慢增长的过程，当CMS GC或者Full GC后，耗时就会变短，重新一点一点增长直到下一个CMS GC。上面的图能看到，刚开始的YGC仅仅只要20ms左右，跑了几个小时后

越来越长的YGC

慢慢的就达到了YGC 80ms，直到发生下一次CMS最长能到120ms。这对我们服务是不能接受的，只能继续定位。

YGC的日志过于简单，不好定位。于是就在网上查找一些资料，看到寒泉子提到String Intern过多使用的话会导致YGC耗时长。而String Table本身的回收又是在CMS GC或者Full GC阶段才会去做，那么就导致了 YGC越来越慢，在经过CMS 或Full GC后耗时恢复的情况。我在本地用demo复现了下问题，和我们的现象一致。

import java.util.UUID;

public class StringTableTest {
  public static void main(String args[]) {
      for (int i = 0; i < 10000000; i++) {
          uuid();
          if (i>=100000 && i%100000==0){
                System.gc();
          }
      }
  }

  public static void uuid() {
      UUID.randomUUID().toString().intern();
  }
}

JVM字符串常量池在JDK8 中是将字符串对象放在堆中，通过StringTable来维护引用，StringTable 结构是类HashMap的实现，如果数组长度过短（String Table (JDK8)默认长度时60013 ），那么会导致链表过长，影响查找效率，耗时过长。

于是我们在线上的服务加上了-XX:+PrintStringTableStatistics 参数灰度升级了一台服务，该参数在JVM进程结束时会打印StringTable的统计信息。结果发现我们线上的服务竟然达到了惊人的250w+的entry，比起60013这个数字实在太夸张了。原因已经确定了。

在IDE中搜索我们的代码调用，发现拼接redis key的Util类调用了intern方法以期望能够减少字符串对象的创建。把这块代码改掉，不再做intern操作。部署上线一台服务，观察后发现问题并没有完全解决，那还有哪里调用了intern方法呢？本来想用Btrace跟踪下调用关系，尝试后发现没有办法跟踪native方法，只能放弃。

那有没有办法打印下Stringtable存的数据对应到字符串内容呢，通过强大的SA可以外挂到JVM进程来完成这个动作，其实我们熟用的jmap -heap也是利用了这个原理。工具代码来自SO

需要注意的是该操作会导致应用程序暂停，线上的话慎用。如果进程变T之后没有恢复的话，Linux下可以执行kill -18 $PID 发送SIGCONT信号重新激活目标进程。

package com.sohu.example;

import sun.jvm.hotspot.memory.SystemDictionary;
import sun.jvm.hotspot.oops.InstanceKlass;
import sun.jvm.hotspot.oops.OopField;
import sun.jvm.hotspot.runtime.VM;
import sun.jvm.hotspot.tools.Tool;

public class InternTool extends Tool {
        @Override
        public void run() {
            // Use Reflection-like API to reference String class and String.value field
            SystemDictionary dict = VM.getVM().getSystemDictionary();
            InstanceKlass stringKlass = (InstanceKlass) dict.find("java/lang/String", null, null);
            OopField valueField = (OopField) stringKlass.findField("value", "[C");

            // Counters
            long[] stats = new long[2];

            // Iterate through the String Pool printing out each String object
            VM.getVM().getStringTable().stringsDo(s -> {
                s.printValueOn(System.out);
                System.out.println();
                stats[0]++;
                stats[1] += s.getObjectSize() + valueField.getValue(s).getObjectSize();
            });

            System.out.printf("%d strings with total size %d\n", stats[0], stats[1]);
        }

        public static void main(String[] args) {
            // Use default SA tool launcher
            new InternTool().execute(args);
        }
}

把字符串打印后发现，基本上都是我们服务的参数或者返回值。其实上面寒泉子的文章也提到了毕玄大神遇到的一个case ，讲了是由于jackson本身的优化，会对json的key 做intern的操作。由于我对业务不够熟悉，刚开始没确认我们也有这种key会变的业务场景，把StringTable字符串打印出来后，跟老大确认后，确认有这种场景，那么很明确了，踏到了同一个坑了。毕玄大大的文章只讲了有接口可以关闭，并没有说怎么关。查了查Jackson的源码，可以直接方法调用来关闭key的intern操作。

1	objectMapper.getFactory().disable(JsonFactory.Feature.INTERN_FIELD_NAMES);

由于StringTable本身存的只是引用，仅8字节，如果将StringTable扩容的话也仅仅是浪费一点内存，所以我将StringTable扩容到1000003（最好是素数）。将上述代码一起上线后，YGC耗时变得正常了，平均耗时仅10-20ms，CMS STW阶段加在一起耗时150ms。

至此优化结束，最终的JVM参数

-Xms2048m -Xmx2048m -Xmn1024m -Xss256k -XX:+UseConcMarkSweepGC -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSScavengeBeforeRemark -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m -XX:CompressedClassSpaceSize=64m -XX:StringTableSize=1000003 -XX:ParallelGCThreads=4 -XX:+PrintFlagsFinal -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/opt/logs/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=10M -XX:+PrintStringTableStatistics

总结

Docker 容器不是真正的虚拟机，是采用CGroups机制做的资源的隔离，需要自己指定JVM参数

Docker 容器本身的资源限制要和JVM参数的限制做好配合，避免发生swap

StringTable本身存的引用，可以适当扩容，慎用intern方法

Docker与虚拟机不同的地方

CMS Remark阶段GC时间过长

YGC 时间缓慢增长至不可接受

总结

参考文献