GC耗时高，原因竟是服务流量小？

　　原创：扣钉日记（微信公众号ID：codelogs），欢迎分享，转载请保留出处。简介
　　最近，我们系统配置了GC耗时的监控，但配置上之后，系统会偶尔出现GC耗时大于1s的报警，排查花了一些力气，故在这里分享下。发现问题
　　我们系统分多个环境部署，出现GC长耗时的是俄罗斯环境，其它环境没有这个问题，这里比较奇怪的是，俄罗斯环境是流量最低的一个环境，而且大多数GC长耗时发生在深夜。
　　发现报警后，我立马查看了GC日志，如下：
　　日志中出现了tospaceexhausted，经过一番了解，出现这个是由于g1在做gc时，都是先复制存活对象，再回收原region，当没有空闲空间复制存活对象时，就会出现tospaceexhausted，而这种GC场景代价是非常大的。
　　同时，在这个gc发生之前，还发现了一些如下的日志。
　　这里可以看到，系统在分配约30M的大对象，难道是有代码频繁分配大对象导致的gc问题。定位大对象产生位置
　　jdk在分配大对象时，会调用G1CollectedHeap：：humongousobjallocate方法，而使用asyncprofiler可以很容易知道哪里调用了这个方法，如下：开启收集。profiler。shstartallusereG1CollectedHeap：：humongousobjallocatef。humongous。jfrjps停止收集。profiler。shstopf。humongous。jfrjps
　　将humongous。jfr文件用jmc打开，如下：
　　根据调用栈我发现，这是我们的一个定时任务，它会定时调用一个接口获取配置信息并缓存它，而这个接口返回的数据量达14M之多。
　　难道是这个接口导致的gc问题？但这个定时任务调用也不频繁呀，5分钟才调用一次，不至于让gc忙不过来吧！
　　另一个疑问是，这个定时任务在其它环境也会运行，而且其它环境的业务流量大得多，为什么其它环境没有问题？
　　至此，我也不确定是这个定时任务导致的问题，还是系统自身特点导致偶尔的高gc耗时。
　　由于我们有固定的上线日，于是我打算先优化产生大对象的代码，然后在上线前的期间试着优化一下jvmgc参数。优化产生大对象的代码
　　我们使用的是httpclient调用接口，调用接口时，代码会先将接口返回数据读取成String，然后再使用jackson把String转成map对象，简化如下：rsphttpClient。execute（request）；StringresultIOUtils。toString（rsp。getEntity（）。getContent（））；MapresultMapJSONUtil。getMapper（）。readValue（result，Map。class）；
　　要优化它也很简单，使用jackson的readValue有一个传入InputStream的重载方法，用它来读取json数据，而不是将其加载成一个大的String对象再读，如下：rsphttpClient。execute（request）；InputStreamisrsp。getEntity（）。getContent（）；MapresultMapJSONUtil。getMapper（）。readValue（is，Map。class）；
　　注：这里面map从逻辑上来说是一个大对象，但对jvm来说，它只是很多个小对象然后用指针连接起来而已，大对象一般由大数组造成，大String之所以是大对象，是因为它里面有一个很大的char〔〕数组。优化GC参数
　　优化完代码后，我开始研究优化jvmgc参数了，我们使用的是jdk8，垃圾收集器是g1，为了理解g1的调优参数，又简单学习了下g1的关键概念。g1是分region收集的，但region也分年轻代与老年代。g1的gc分younggc与mixedgc，younggc用于收集年轻代region，mixedgc会收集年轻代与老年代region。在mixedgc回收之前，需要先经历一个并发周期（ConcurrentCycles），用来标记各region的对象存活情况，让mixedgc可以判断出需要回收哪些region。并发周期分为如下4个子阶段：
　　a。初始标记（initialmarking）
　　b。并发标记（concurrentmarking）
　　c。重新标记（remarking）
　　d。清理（cleanup）
　　需要注意的是，初始标记（initialmarking）这一步是借助younggc完成的。
　　在g1中，younggc几乎没有什么可调参数，而mixedgc有一些，常见如下：
　　参数
　　作用
　　XX：InitiatingHeapOccupancyPercent
　　开始mixedgc并发周期的堆占用阈值，当大于此比例，启动并发周期，默认45
　　XX：ConcGCThreads
　　在并发标记时，使用多少个并发线程。
　　XX：G1HeapRegionSize
　　每个region大小，当分配对象尺寸大于region一半时，才认为这是一个大对象。
　　XX：G1MixedGCLiveThresholdPercent
　　region存活比例，默认85，当并发标记后发现region中存活对象比例小于这个值，mixedgc才会回收这个region，毕竟一个region如果都是存活的对象，那还有什么回收的必要呢。
　　XX：G1HeapWastePercent
　　允许浪费的堆比例，默认5，当可回收的内存比例大于此值时，mixedgc才会去执行回收，毕竟没什么可回收的对象时，还有什么回收的必要呢。
　　XX：G1MixedGCCountTarget
　　mixedgc执行的次数，一旦并发标记周期确认了回收哪些region后，mixedgc就进行回收，但mixedgc会分少量多次来回收这些region，默认8次。
　　XX：G1OldCSetRegionThresholdPercent
　　每次mixedgc回收oldregion的比例，默认10，如果G1MixedGCCountTarget是8的话，mixedgc整体能回收80。
　　XX：G1ReservePercent
　　堆保留空间比例，默认10，这部分空间g1会保留下来，用来在gc时复制存活对象。
　　出现tospaceexhausted会不会是mixedgc太慢了呢？于是我调整了如下参数：让并发标记周期启动更早，运行得更快，将XX：InitiatingHeapOccupancyPercent从默认值45调整到35，XX：ConcGCThreads从1调整为3。XX：G1MixedGCLiveThresholdPercent与XX：G1HeapWastePercent确定回收哪些region，有多少比例垃圾才执行回收，我觉得它们的值本来就蛮激进，就没有调整。XX：G1MixedGCCountTarget与XX：G1OldCSetRegionThresholdPercent控制mixedgc执行多少次，每次回收多少region，我将XX：G1OldCSetRegionThresholdPercent从10调整到了15，让它一次多回收些oldregion。增加保留空间，避免复制存活对象失败，将XX：G1ReservePercent从10调整到20。尽量避免产生大对象，将XX：G1HeapRegionSize增加到16m。
　　于是我按照上面调整了jvm参数，可是第二天我发现还是有GC长耗时，次数也没有减少，看来问题根因和我调整的参数没有关系。问题根因
　　就这样，到了上线日，于是我上线了前面优化大对象的代码，一天后，我发现偶尔的GC长耗时竟然没有了！
　　问题就这样解决了！！！
　　然而我心里还是有一个大大的问号，其它环境同样有这个定时任务，一样的运行频率，jvm配置也全是一样的，为啥其它环境没有问题呢？其它环境业务流量还大一些！
　　为此，我搜索了大量关于g1大对象的文章，我发现大对象的分配与回收过程有点特殊，如下：大于regionsize一半的对象是大对象，会直接分配在oldregion，且gc时大对象不会被复制或移动，而是直接回收。大对象回收发生在2个地方，一个是并发周期的cleanup子阶段，另一个是younggc（这个特性在jdk8u60才加入）。
　　我忽然想到，莫非是俄罗斯环境流量太低，触发不了younggc，且并发周期又因为什么原因没执行，但定时任务又慢慢生成大对象将oldregion占满，导致了tospaceexhausted？
　　于是，我打算写段代码试验一下，慢慢的只生成大对象，看g1会不会回收，如下：
　　这个一个命令行交互程序，使用如下jvm参数启动它：1600m的堆，16m的regionsizerlwrap作用是使得这个命令行程序更好用rlwrapjavaserverXms1600mXmx1600mXss1mXX：MetaspaceSize512mXX：MaxMetaspaceSize1gXloggc：homeworklogsapplogsgct。logXX：HeapDumpOnOutOfMemoryErrorXX：HeapDumpPathhomeworklogsapplogsXX：PrintClassHistogramXX：PrintGCDetailsXX：PrintGCTimeStampsXX：PrintHeapAtGCXX：PrintGCDateStampsXX：PrintGCApplicationStoppedTimeXX：PrintAdaptiveSizePolicyXX：UseG1GCXX：G1LogLevelfinestXX：G1HeapRegionSize16mXX：MaxGCPauseMillis200jarcommandcli。jar
　　使用了1600M的堆，16M的regionsize，所以总共有100个region，jdk版本是1。8。0222。
　　通过在这个交互程序中输入gc9437184200，可以生成20个9M的大对象。
　　当我输入3次gc9437184200后，如下：
　　我从gc日志中发现了一次由initialmarking触发的younggc，说明g1启动了并发周期，之所以发生younggc，是因为initialmarking是借助ygc执行的。
　　紧接着，我发现了并发标记、重新标记与清理阶段的日志。
　　然后我在jstat中发现老年代使用率降低了，因为younggc会回收大对象，所以老年代使用率降低也是正常的。
　　当我又执行了2次gc9437184200后，使得堆占用率再次大于45，我发现gc日志中出现如下内容：
　　看字面意思是，由于mixedgc正在执行，没有再次启动并发周期。
　　可是，我在这种状态下等了好久，也没有看到mixedgc的日志出来，不是说mixedgc正在执行嚒，它一定是有什么问题！
　　于是，我又执行了好几次gc9437184200，我在gc日志中发现了tospaceexhausted！
　　从上面donotstartmixedGCs，reason：candidateoldregionsnotavailable的日志中看到，mixedgc日志之所以长时间没出来，是因为没有可回收的region导致mixedgc没有执行，因为我们只创建了大对象，但mixedgc不回收大对象分区，所以确实是没有可回收的region的。从HumongousReclaimed：98可以发现，这次younggc，回收了98个大对象分区，而我们总共只有100个分区，说明在initalmarking之后创建的大对象，确实一直都没有回收。
　　注：添加XX：G1LogLevelfinest参数，才能输出HumongousReclaimed这一项。
　　但是，大对象分区占了98个，堆占用率肯定超过了45，为何一直没有再次启动并发周期呢？
　　感觉这可能是jdk的bug，于是我分别下了最新的jdk8u与jdk11u验证，发现问题在最新的jdk8u中依然存在，而jdk11u中则不存在，这应该就是JDK的Bug！
　　于是我通过二分搜索法多次编译了不同版本的JDK，最终确定问题fix在jdk9b93与jdk9b94之间。
　　并在jdk的bug库中，搜索到了相同描述的bug反馈，如下：
　　https：bugs。openjdk。orgbrowseJDK8140689
　　Bug改动代码如下：
　　大致瞄了下代码，可能理解得不完全正确，改动逻辑如下：G1再次启动并发周期之前，至少需要执行过一次mixedgc或younggc，类似于ConcurrentCyclesmixedgcyounggcConcurrentCyclesmixedgcyounggc。我们的场景是，在并发周期结束之后，由于没有需要回收的分区，导致mixedgc实际没有执行，可是我们只分配了大对象，且大对象又只分配在oldregion，所以younggc也不可能被触发，而由于上面的条件，ConcurrentCycles也不会被触发，因此最终大对象将堆占满触发了tospaceexhausted。修复逻辑是，当并发周期结束后，没有需要回收的分区时，shouldcontinuewithreclaimfalse，进而使得允许不执行纯younggc而直接启动并发周期，类似于ConcurrentCyclesConcurrentCycles。
　　所以在使用JDK8时，像那种系统流量很小，新生代较大，又有定时任务不断产生大对象的场景，堆几乎必然会被慢慢占满，要解决这个问题，可参考如下处理：优化代码，避免分配大对象。代码无法优化时，可考虑升级jdk11。无法升级jdk11时，可考虑减小XX：G1MaxNewSizePercent让新生代小一点，让younggc能执行得更频繁些，同时老年代更大，能缓冲更多大对象分配。
　　考虑到我们负责的其它系统中，时不时就有一波大响应体的请求，也没法快速修改代码，于是我统一将XX：G1MaxNewSizePercent减小到30，经过观察，修改后GC频率有所增加，但暂停时间有所下降，这是符合期望的。总结
　　当我在jdk的bug库中搜索问题时，发现不少和G1大对象相关的优化，早期JDK（如JDK8）的G1实现可能在大对象回收上不太完善，所以写代码时要注意尽量少创建大对象，以回避这些隐性问题。
　　注：这之后又遇到了UpdateRS（ms）耗时高，竟也和大对象有关，添加XX：ReduceInitialCardMarks后解决，看来大对象是万恶之源啊