背景

最近遇到一个不常见的GC问题，觉得有必要记录并分享出来。服务本身是个普通的Spring Boot应用，运行在K8S环境中，主要工作是进行大量的网络调用，本身无缓存，也没有太多CPU计算。

JVM版本：Oracle JDK 1.8.161

CPU6核，JVM堆内存6G，新生代2G，使用CMS + ParNew。

问题发现

这个服务在上线压测的时候有GC时间偏高的问题。于是本着出现问题大概率是负载过高的原则，无脑扩容了一波。运行了几天后，开始出现频繁超时。本来响应时间几十毫秒的服务TP9999已经达到300ms！

再看看GC监控，更夸张了：新生代的GC时间居然就能达到300ms！

新生代GC一般就是十来毫秒的事，这个300ms确实是突破认知了。

再回头看看当初疯狂扩容的实例，CPU使用率低的可怜。可见扩容不能包治百病啊。

解决过程

解决新生代GC时间过长

首先一顿搜索新生代GC长的问题，发现了这个宝藏： blog.ragozin.info/p/garbage-c…

讨论新生代的GC：blog.ragozin.info/2011/06/und…

讨论CMS：blog.ragozin.info/2011/06/und…

原来新生代的GC停顿主要是四部分时间：

其中栈扫描显然可以忽略不计；而Survior区的拷贝时间也往往因为存活率很低，需要拷贝的对象很少而时间很短（除非新生代存活率不正常地高）。所以主要消耗的时间是卡表扫描时间和老年代扫描，老年代扫描又依赖于卡表扫描的脏表信息。总结下来就是老年代越大，新生代GC停顿时间越长。

为了确认新生代的对象创建率和晋升率，可以开启一些GC日志分析。这里我观察了Survivor区的大小，发现确实很低：

而老年代占用确实挺高：

原来我们的惯性思维就是新生代要比老年代内存少。JVM的默认分配比例就给了我们这个暗示。没想到对于无状态的IO密集型应用来说，老年代只是个沉重的负担。

所以接下来的思路就是减少老年代。

1.调小老年代到500M

可以观察到，新生代gc时间从10ms逐渐爬升到60ms。因为老年代有限，所以新生代gc时间就有了上限。

观察应用的TP9999，则从50ms爬升到了150ms

这个应用的老年代增长非常地缓慢，迟迟没有触发Major GC。而老年代在内存比较高时，新生代的gc时间又会变长。

老年代内存不减少，新生代GC就会一直慢，因此我们希望老年代能GC得频繁一点。

2.减少晋升代数到2

加入JVM参数：-XX:MaxTenuringThreshold=2，老年代增长速度变快了一些:

3.设置触发老年代GC的内存上限为50%

老年代终于发生了GC：

现在新生代GC时间不会无限上涨了。

解决老年代的问题

后面我们又对新生代大小做了更多尝试。后来发现仅仅通过调整新生代1800M，CMSInitiatingOccupancyFraction=50，可以把GC耗时限制在可接受的范围内。

到这里本以为问题圆满解决，但还是不放心，再看看GC日志，果然有问题：

2021-04-07T19:23:47.633+0800: 1486.331: [GC (Allocation Failure) 2021-04-07T19:23:47.633+0800: 1486.331: [ParNew: 1314975K->3548K(1474560K), 0.0098219 secs] 1544334K->233151K(1933312K), 0.0101444 secs] [Times: user=0.21 sys=0.01, real=0.01 secs] 
2021-04-07T19:23:47.643+0800: 1486.341: Total time for which application threads were stopped: 0.0114859 seconds, Stopping threads took: 0.0001502 seconds
2021-04-07T19:23:47.644+0800: 1486.341: Application time: 0.0000415 seconds
2021-04-07T19:23:47.644+0800: 1486.342: [GC (CMS Initial Mark) [1 CMS-initial-mark: 229603K(458752K)] 233279K(1933312K), 0.0017650 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-04-07T19:23:47.646+0800: 1486.344: Total time for which application threads were stopped: 0.0028056 seconds, Stopping threads took: 0.0001077 seconds
2021-04-07T19:23:47.646+0800: 1486.344: [CMS-concurrent-mark-start]
2021-04-07T19:23:47.668+0800: 1486.365: [CMS-concurrent-mark: 0.021/0.021 secs] [Times: user=0.16 sys=0.00, real=0.02 secs] 
2021-04-07T19:23:47.668+0800: 1486.365: [CMS-concurrent-preclean-start]
2021-04-07T19:23:47.670+0800: 1486.368: [CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-04-07T19:23:47.670+0800: 1486.368: [CMS-concurrent-abortable-preclean-start]
2021-04-07T19:23:49.870+0800: 1488.567: [CMS-concurrent-abortable-preclean: 1.098/2.199 secs] [Times: user=2.13 sys=0.09, real=2.20 secs] 
2021-04-07T19:23:49.870+0800: 1488.567: Application time: 2.2235089 seconds
2021-04-07T19:23:49.871+0800: 1488.568: [GC (CMS Final Remark) [YG occupancy: 685116 K (1474560 K)]2021-04-07T19:23:49.871+0800: 1488.568: [Rescan (parallel) , 0.0901161 secs]2021-04-07T19:23:49.961+0800: 1488.659: [weak refs processing, 0.0003090 secs]2021-04-07T19:23:49.962+0800: 1488.659: [class unloading, 0.0307997 secs]2021-04-07T19:23:49.992+0800: 1488.690: [scrub symbol table, 0.0118417 secs]2021-04-07T19:23:50.004+0800: 1488.702: [scrub string table, 0.1605043 secs][1 CMS-remark: 229603K(458752K)] 914720K(1933312K), 0.2950712 secs] [Times: user=0.88 sys=0.01, real=0.29 secs] 
2021-04-07T19:23:50.166+0800: 1488.864: Total time for which application threads were stopped: 0.2964125 seconds, Stopping threads took: 0.0001767 seconds
2021-04-07T19:23:50.166+0800: 1488.864: Application time: 0.0000984 seconds
2021-04-07T19:23:50.166+0800: 1488.864: [CMS-concurrent-sweep-start]
...
2021-04-07T19:23:50.298+0800: 1488.995: [CMS-concurrent-sweep: 0.108/0.131 secs] [Times: user=0.51 sys=0.04, real=0.13 secs] 
2021-04-07T19:23:50.298+0800: 1488.995: [CMS-concurrent-reset-start]
2021-04-07T19:23:50.299+0800: 1488.996: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

我们监控的老年代时间不准，从日志看到的应用暂停时间实际上长的多。具体来看，CMS的2个STW阶段，CMS Initial Mark倒是没花啥时间，CMS Final Remark却花了290ms，有点要命……

TP9999确实因为Major GC出现了毛刺，不爽，要解决～

1.CMS进行GC前强制做一次新生代GC

怎么解决呢？一般来说CMS在Initial Mark前会先等待一次新生代GC，以减少扫描时间。从日志来看，在发生CMS之前很短的时间确实发生了一次新生代GC。

本次出现问题的是Final Remark阶段，增加-XX:+CMSScavengeBeforeRemark命令可以在Remark之前强制再来一次新生代GC，从而让新生代对象少点，减少扫描时间。加上了之后，第二天再来看看。

这次监控里Final Remark的耗时也有了，但是它不准（这个问题后面再跟）！因为服务在GC时TP9999还是会显著上升。再看GC日志：

2021-04-08T13:39:17.892+0800: 61397.551: [GC (CMS Final Remark) [YG occupancy: 304654 K (1474560 K)]2021-04-08T13:39:17.892+0800: 61397.551: [GC (CMS Final Remark) 2021-04-08T13:39:17.892+0800: 61397.552: [ParNew: 304654K->3064K(1474560K), 0.0084983 secs] 534121K->232738K(1933312K), 0.0087050 secs] [Times: user=0.18 sys=0.01, real=0.01 secs] 
2021-04-08T13:39:17.901+0800: 61397.560: [Rescan (parallel) , 0.0020656 secs]2021-04-08T13:39:17.903+0800: 61397.562: [weak refs processing, 0.0005887 secs]2021-04-08T13:39:17.904+0800: 61397.563: [class unloading, 0.0299760 secs]2021-04-08T13:39:17.934+0800: 61397.593: [scrub symbol table, 0.0105486 secs]2021-04-08T13:39:17.944+0800: 61397.604: [scrub string table, 0.1656738 secs][1 CMS-remark: 229674K(458752K)] 232738K(1933312K), 0.2302244 secs] [Times: user=0.44 sys=0.01, real=0.23 secs] 

好家伙，这次真的先进行了一次ParNew的新生代GC，使得新生代从600多M降低到了3M。再看新生代的扫描时间，则从之前的90ms降到了3ms。总时间确实降低到了230ms，然而还是太高了。

2.解决String table问题

进一步查看CMS的详细日志，下面的片段展示了CMS的内部过程：

2021-04-08T13:39:17.901+0800: 61397.560: [Rescan (parallel) , 0.0020656 secs]
2021-04-08T13:39:17.903+0800: 61397.562: [weak refs processing, 0.0005887 secs]
2021-04-08T13:39:17.904+0800: 61397.563: [class unloading, 0.0299760 secs]
2021-04-08T13:39:17.934+0800: 61397.593: [scrub symbol table, 0.0105486 secs]
2021-04-08T13:39:17.944+0800: 61397.604: [scrub string table, 0.1656738 secs]

在日志里面的几个步骤中，[scrub string table, 0.1656738 secs]就很反常了，原来是它占了大头！

拿这个专有术语搜索了一下，发现了这篇文章，跟我们的问题几乎一模一样。

文章里指出Jackson使用的String.intern()是罪魁祸首。

进一步又找到三篇文章。1、2、3

回忆我们使用jmap -histo:live得到的靠前对象，确实有String（一般都这样好吧！），但也不是大的那么离谱。

 num     #instances         #bytes  class name
----------------------------------------------
   1:         44126       42924632  [Ljava.lang.Object;
   2:         22542       14787552  io.netty.util.internal.shaded.org.jctools.queues.MpscArrayQueue
   3:         12673       11341144  [B
   4:        120882        9288568  [C
   5:        118651        2847624  java.lang.String

用MAT分析堆dump，也没有什么明显异常。

为了确认问题，再加入一个-XX:+PrintStringTableStatistics参数。坑爹地是它只能在JVM退出的时候打印String Table，而程序的运行环境是k8s，看不到这个信息。

最后只能用jmap -heap命令，输出的最后一行就是String Table信息。

• 修改Jackson之前的结果：307321 interned Strings occupying 23220408 bytes.

• 修改Jackson之后的结果：26352 interned Strings occupying 2853024 bytes.

前后差了10倍。修改之后重新上线，新的CMS GC日志如下。老年代GC时间降低到了110ms，非常理想了。

2021-04-20T17:25:03.781+0800: 452505.107: [GC (CMS Final Remark) 2021-04-20T17:25:03.781+0800: 452505.107: [ParNew
Desired survivor size 38109184 bytes, new threshold 15 (max 15)
- age   1:    4111480 bytes,    4111480 total
- age   2:      45496 bytes,    4156976 total
- age   3:      12184 bytes,    4169160 total
- age   4:      42608 bytes,    4211768 total
- age   5:       5104 bytes,    4216872 total
- age   6:       7472 bytes,    4224344 total
- age   7:       2256 bytes,    4226600 total
- age   8:      36400 bytes,    4263000 total
- age   9:       2152 bytes,    4265152 total
- age  10:       5056 bytes,    4270208 total
- age  11:        664 bytes,    4270872 total
- age  12:       1784 bytes,    4272656 total
- age  13:        480 bytes,    4273136 total
- age  14:      34808 bytes,    4307944 total
- age  15:       1232 bytes,    4309176 total
: 753754K->5633K(1563968K), 0.0100232 secs] 1175833K->427712K(2022720K), 0.0101724 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
Heap after GC invocations=73456 (full 3):
 par new generation   total 1563968K, used 5633K [0x0000000080000000, 0x00000000e4000000, 0x00000000e4000000)
  eden space 1489536K,   0% used [0x0000000080000000, 0x0000000080000000, 0x00000000daea0000)
  from space 74432K,   7% used [0x00000000daea0000, 0x00000000db420600, 0x00000000df750000)
  to   space 74432K,   0% used [0x00000000df750000, 0x00000000df750000, 0x00000000e4000000)
 concurrent mark-sweep generation total 458752K, used 422079K [0x00000000e4000000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 81187K, capacity 84281K, committed 84384K, reserved 1124352K
  class space    used 9988K, capacity 10542K, committed 10548K, reserved 1048576K
}
2021-04-20T17:25:03.792+0800: 452505.118: [Rescan (parallel) , 0.0047549 secs]2021-04-20T17:25:03.797+0800: 452505.122: [weak refs processing, 0.0146939 secs]2021-04-20T17:25:03.811+0800: 452505.137: [class unloading, 0.0408517 secs]2021-04-20T17:25:03.852+0800: 452505.178: [scrub symbol table, 0.0147520 secs]2021-04-20T17:25:03.867+0800: 452505.193: [scrub string table, 0.0013593 secs][1 CMS-remark: 422079K(458752K)] 427712K(2022720K), 0.1081788 secs] [Times: user=0.14 sys=0.01, real=0.11 secs]

最后的JVM参数

java -server -Xmx2g -Xms2g -Xmn1600m -XX:+UseParNewGC -XX:MaxTenuringThreshold=2 -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=50 -XX:+UseCMSInitiatingOccupancyOnly -XX:+CMSScavengeBeforeRemark -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -Xloggc:gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=7 -XX:GCLogFileSize=128m

总结

本文讨论了一个非典型的GC问题的解决过程，由于过程记录地比较详细，从而有一定参考价值。最后谈一谈一些心得：

调试Java的GC问题，首先要做到对垃圾收集器比较熟悉。这个熟悉不是指对源码了如指掌，而是说对它的原理、特性比较了解。比如，我们需要知道某种垃圾收集器的主要时间会花在哪里，这样当现状不符合理论时，就有调查方向了。

另外，一般来说，我们遇到的问题前人一定也遇到过，所以只要定位到一个具体的细节，靠搜索引擎大概就能找到解决方案。

第三，详细的GC日志对理解垃圾收集器的工作过程非常关键。有了初步的判断之后，剩下的就是不断实验、测量，直到将系统调优到一个较好的状态。

参考资料

tech.meituan.com/2020/11/12/… （系统总结了GC的各类问题，不可不看）

blog.ragozin.info/p/garbage-c…

cloud.tencent.com/developer/a…

dzone.com/articles/ho…

www.jianshu.com/p/051d566e1…

www.jianshu.com/p/4e96beb37…

mp.weixin.qq.com/s/aYwIH0TN3…