简介最近我们的系统配置了GC耗时监控，但是配置之后系统偶尔会出现GC耗时大于1s的告警。查了下功夫，这里分享一下。发现了问题。我们的系统部署在多个环境中。俄罗斯环境GC耗时长，其他环境没有这个问题。这里比较奇怪的是，俄罗斯环境是流量最低的环境，长时间的GC耗时大多发生在深夜。发现告警后，立即查看GC日志，如下：日志中出现了to-spaceexhausted。经过一番了解，出现这个是因为g1在做GC的时候先复制了存活的对象，然后回收了原来的区域。当没有可用空间复制存活对象时，就会出现to-spaceexhausted，这种GC场景的代价非常高。同时，在本次gc发生之前，还发现了如下日志。这里可以看到系统正在分配30M+左右的大对象。会不会是代码频繁分配大对象导致的gc问题。找到生成大对象的位置。jdk分配大对象时，会调用G1CollectedHeap::humongous_obj_allocate方法。使用async-profiler，很容易知道这个方法是在哪里调用的，如下：#开启collection./profiler.shstart--all-user-eG1CollectedHeap::humongous_obj_allocate-f./humongous.jfrjps#停止collection./profiler.shstop-f./humongous.jfrjps用jmc打开humongous.jfr文件，如下：根据调用栈，发现这是我们的定时任务。它会周期性地调用一个接口获取配置信息并缓存起来，这个接口返回的数据量有14M之多。是不是这个接口导致的gc问题？但是这个定时任务调用的并不频繁，5分钟才调用一次，所以不会让gc忙不过来！还有一个问题就是这个定时任务也会在其他环境运行，而其他环境的业务流量要大很多。为什么在其他环境下没有问题？到现在我也不确定是这个定时任务导致的问题，还是系统本身的特性导致偶尔的gc耗时偏高。由于我们有一个固定的发布日期，我打算先优化生成大对象的代码，然后在发布前尝试优化jvmgc参数。优化生成大对象的代码。我们使用httpclient来调用接口。调用接口时，代码会先将接口返回的数据读取成String，然后使用jackson将String转换成map对象。简化如下：rsp=httpClient.execute(request);Stringresult=IOUtils.toString(rsp.getEntity().getContent());MapresultMap=JSONUtil.getMapper().readValue(result,Map.class);要优化它也很简单，使用jackson的readValue有一个重载的方法，传入InputStream，用它来读取json数据，而不是加载到一个大的String对象中再读取，如下：rsp=httpClient.execute（要求）;InputStreamis=rsp.getEntity().getContent();MapresultMap=JSONUtil.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会收集新生代和oldgenerationregion。在mixedgc回收之前，需要经过一个并发循环（ConcurrentCycles），用来标记每个region中对象的存活情况，这样mixedgc才能判断哪些region需要回收。并发周期分为以下四个子阶段：初始标记（initialmarking）b．并发标记（concurrentmarking）c．备注（remarking）d．这一步是在younggc的帮助下完成的。g1中younggc几乎没有可调整的参数，而mixedgc有一些，常见的如下：参数函数-XX:InitiatingHeapOccupancyPercent启动mixedgc并发周期的堆占用阈值，当大于这个比例时，并发循环开始，默认为45%-XX:ConcGCThreads标记并发时使用多少个并发线程。-XX:G1HeapRegionSize每个region的大小，当分配的对象的大小大于region的一半时，就认为是大对象。-XX:G1MixedGCLiveThresholdPercentregion生存率，默认85%。当concurrentmarking发现region中存活对象的比例小于这个值时，mixedgc会回收这个region。毕竟如果一个区域全是幸存物，那就没必要回收毛布了。-XX:G1HeapWastePercent允许堆浪费比例，默认为5%。当可回收内存比例大于该值时，混合gc将进行回收。毕竟，当没有可回收的物品时，还需要回收什么？-XX:G1MixedGCCountTarget混合gc执行次数。一旦concurrentmarkingcycle确定了回收哪些region，mixedgc就会回收，但是mixedgc会回收这些region的次数很少。默认为8次。-XX:G1OldCSetRegionThresholdPercent每次mixedgc回收oldregion的比例，默认10%。如果G1MixedGCCountTarget为8，混合gc可以回收整体的80%。-XX:G1ReservePercent堆保留空间比例，默认为10%，g1的这部分空间会在gc时保留给复制存活对象。to-spaceexhausted的出现会不会是mixedgc太慢了？所以我调整了以下参数：让并发标记周期启动得更早，运行得更快，将-XX:InitiatingHeapOccupancyPercent从默认值45%调整为35%，将-XX:ConcGCThreads从1调整为3。-XX:G1MixedGCLiveThresholdPercent和-XX:G1HeapWastePercent决定回收哪些区域，回收多少百分比的垃圾。我觉得他们的价值观比较激进，没有调整过。-XX:G1MixedGCCountTarget和-XX:G1OldCSetRegionThresholdPercent控制mixedgc执行多少次，每次回收多少region。我将-XX:G1OldCSetRegionThresholdPercent从10%调整为15%，这样它可以一次回收更多的旧区域。增加保留空间以避免复制存活对象失败，将-XX:G1ReservePercent从10%调整为20%。尽量避免大对象，将-XX:G1HeapRegionSize增加到16m。于是我按照上面调整了jvm参数，但是第二天发现GC还是耗了很久，而且次数并没有减少。问题的根源似乎与我调整的参数无关。问题的根本原因是这样的。当发布日到来时，我发布了之前优化大对象的代码。一天后发现偶尔的GC耗时没了！就是这样！！！但是，我心里还是打了一个大大的问号。其他环境也有这个定时任务，同样的运行频率，同样的jvm配置。为什么其他环境没有问题？其他环境的业务流量更大！为此，我搜索了很多关于g1大对象的文章，发现大对象的分配和回收过程有点特殊，如下：大于regionsize一半的对象就是大对象，会直接分配在old区，gc是一个大对象，不会被复制或移动，而是直接回收。大对象回收发生在两个地方，一个是并发循环的cleanupsubphase，另一个是younggc（jdk8u60才加入这个特性）。突然想到，俄罗斯环境流量太低，触发younggc，并发循环不知为何没有执行，但是定时任务慢慢产生大对象填满oldregion，导致to-空间耗尽？于是，打算写一段代码测试一下，慢慢只生成大对象，看看g1会不会回收，如下：这是一个命令行交互程序，使用如下jvm参数启动它：#1600mheap,16mregionsize#rlwrap的作用是让这个命令行程序更易用applogs/gc-%t.log-XX:+HeapDumpOnOutOfMemoryError-XX:HeapDumpPath=/home/work/logs/applogs/-XX:+PrintClassHistogram-XX:+PrintGCDetails-XX:+PrintGCTimeStamps-XX:+PrintHeapAtGC-XX:+PrintGCDateStamps-XX:+PrintGCApplicationStoppedTime-XX:+PrintAdaptiveSizePolicy-XX:+UseG1GC-XX:G1LogLevel=finest-XX:G1HeapReinotallow=16m-XX:MaxGCPauseMillis=200-jarcommand-cli.jar使用1600M的heap和一个region大小为16M，所以有100个区域，jdk版本为1.8.0_222。在这个交互程序中输入gc9437184200，可以生成20个9M的大对象。当我输入3次gc9437184200时，如下：我从gc日志中发现了一个由initialmarking触发的younggc，说明g1开始了并发循环。之所以发生younggc，是因为initialmarking是借助ygc执行的。接下来，我找到了并发标记、注释和清理阶段的日志。然后在jstat中发现老年代的使用率下降了，因为younggc会回收大对象，所以老年代的使用率下降是正常的。当我再执行两次gc9437184200时，堆占用率再次大于45%，在gc日志中发现如下内容：字面意思是并发循环没有再次启动，因为混合gc被执行。然而我在这个状态下等待了很久，也没有看到混合gc的日志。并不是说mixedgc在运行，一定有问题！于是，我执行了几次gc9437184200，在gc日志中发现to-spaceexhausted！从上面donotstartmixedGCs,reason:candidateoldregionsnotavailable的日志可以看出，久久不释放mixedgc日志的原因是没有可回收region，mixedgc是没有执行是因为我们只创建了一个大对象，但是mixedgc并没有回收大对象分区，所以确实没有可回收区域。从HumongousReclaimed:98可以发现younggc这次回收了98个大对象分区，而我们总共只有100个分区，说明inital标记后创建的大对象确实没有被回收。注意：添加-XX:G1LogLevel=finest参数输出HumongousReclaimed。但是大对象分区有98个，堆占用率肯定超过了45%。为什么没有重新开始并发循环？感觉这可能是jdk的bug，于是分别下载了最新的jdk8u和jdk11u，发现最新的jdk8u问题依旧，但jdk11u没有，这应该是JDK的bug！于是通过二分查找的方式多次编译不同版本的JDK，最终确定问题修复在jdk9_b93和jdk9_b94之间。并且在jdk的bug库中搜索了同样描述的bug反馈，如下：https://bugs.openjdk.org/browse/JDK-8140689Bug代码改成如下：大致看了一下代码，理解未必完全正确。变化逻辑如下：G1再次开始并发循环前，需要至少执行一次mixedgc或younggc，类似ConcurrentCycles->mixedgc|younggc->ConcurrentCycles->mixedgc|younggc.我们的场景是，并发循环结束后，并没有真正执行mixedgc，因为没有需要回收的partition，但是我们只分配了大对象，大对象只分配在oldregion，所以younggc不能usedTriggered，而由于上面的条件，ConcurrentCycles不会被触发，所以最终大对象会填满堆，触发to-spaceexhausted。修复逻辑是，当concurrentcycle结束，没有分区需要回收时，should_continue_with_reclaim=false，这样就可以直接启动concurrentcycle，而不用执行pureyounggc，类似ConcurrentCycles->ConcurrentCycles。因此，在使用JDK8时，在系统流量小、新生代大、定时任务不断产生大对象的场景下，堆几乎不可避免地会慢慢变满。解决这个问题，可以参考以下解决方案：优化代码，避免分配大对象。当代码无法优化时，考虑升级jdk11。当不能升级jdk11时，可以考虑减小-XX:G1MaxNewSizePercent，让新生代更小，这样younggc执行的更频繁，老年代更大，可以缓冲更多的大对象分配。考虑到在我们负责的其他系统中，时不时有一波响应体较大的请求，无法快速修改代码，所以我统一将-XX:G1MaxNewSizePercent降低为30%。经过观察，修改后GC频率增加了，但是停顿时间减少了，这是意料之中的。总结在jdkbug库中查找问题时，发现了很多与G1大对象相关的优化。早期JDK（如JDK8）的G1实现在大对象回收方面可能还不够完善，写代码的时候要注意。创建较小的大对象以避免这些隐藏的问题。注意：这之后遇到了高耗时的UpdateRS(ms)，也跟大对象有关。添加-XX:-ReduceInitialCardMarks即可解决。似乎大对象是万恶之源。
