原创:扣钉日记(微信大众号ID:codelogs),欢迎共享,转载请保存出处。

简介

最近,咱们体系配置了GC耗时的监控,但配置上之后,体系会偶然出现GC耗时大于1s的报警,排查花了一些力气,故在这儿共享下。

发现问题

咱们体系分多个环境布置,出现GC长耗时的是俄罗斯环境,其它环境没有这个问题,这儿比较奇怪的是,俄罗斯环境是流量最低的一个环境,并且大多数GC长耗时发生在深夜。

发现报警后,我立马查看了GC日志,如下:

GC耗时高,原因竟是服务流量小?

日志中出现了to-space exhausted,通过一番了解,出现这个是由于g1在做gc时,都是先仿制存活目标,再收回原region,当没有闲暇空间仿制存活目标时,就会出现to-space exhausted,而这种GC场景价值是非常大的。

一起,在这个gc发生之前,还发现了一些如下的日志。

GC耗时高,原因竟是服务流量小?

这儿能够看到,体系在分配约30M+的大目标,莫非是有代码频频分配大目标导致的gc问题。

定位大目标发生位置

jdk在分配大目标时,会调用G1CollectedHeap::humongous_obj_allocate办法,而运用async-profiler能够很容易知道哪里调用了这个办法,如下:

# 开启搜集
./profiler.sh start --all-user -e G1CollectedHeap::humongous_obj_allocate -f ./humongous.jfr jps
# 停止搜集
./profiler.sh stop -f ./humongous.jfr jps

将humongous.jfr文件用jmc翻开,如下:

GC耗时高,原因竟是服务流量小?

依据调用栈我发现,这是咱们的一个守时使命,它会守时调用一个接口获取配置信息并缓存它,而这个接口返回的数据量达14M之多。

莫非是这个接口导致的gc问题?但这个守时使命调用也不频频呀,5分钟才调用一次,不至于让gc忙不过来吧!
另一个疑问是,这个守时使命在其它环境也会运转,并且其它环境的事务流量大得多,为什么其它环境没有问题?

至此,我也不确认是这个守时使命导致的问题,仍是体系本身特色导致偶然的高gc耗时。

由于咱们有固定的上线日,所以我打算先优化发生大目标的代码,然后在上线前的期间试着优化一下jvm gc参数。

优化发生大目标的代码

咱们运用的是httpclient调用接口,调用接口时,代码会先将接口返回数据读取成String,然后再运用jackson把String转成map目标,简化如下:

rsp = httpClient.execute(request);
String result = IOUtils.toString(rsp.getEntity().getContent());
Map resultMap = JSONUtil.getMapper().readValue(result, Map.class);

要优化它也很简单,运用jackson的readValue有一个传入InputStream的重载办法,用它来读取json数据,而不是将其加载成一个大的String目标再读,如下:

rsp = httpClient.execute(request);
InputStream is = rsp.getEntity().getContent();
Map resultMap = JSONUtil.getMapper().readValue(is, Map.class);

注:这儿面map从逻辑上来说是一个大目标,但对jvm来说,它只是很多个小目标然后用指针连接起来而已,大目标一般由大数组形成,大String之所以是大目标,是由于它里边有一个很大的char[]数组。

优化GC参数

优化完代码后,我开端研究优化jvm gc参数了,咱们运用的是jdk8,废物搜集器是g1,为了了解g1的调优参数,又简单学习了下g1的关键概念。

  1. g1是分region搜集的,但region也分年青代与老时代。
  2. g1的gc分young gcmixed gc,young gc用于搜集年青代region,mixed gc会搜集年青代与老时代region。
  3. mixed gc收回之前,需求先经历一个并发周期(Concurrent Cycles),用来符号各region的目标存活情况,让mixed gc能够判别出需求收回哪些region。
  4. 并发周期分为如下4个子阶段:
    a. 初始符号(initial marking)
    b. 并发符号(concurrent marking)
    c. 从头符号(remarking)
    d. 清理(clean up)
    需求留意的是,初始符号(initial marking)这一步是凭借young gc完成的。

在g1中,young gc简直没有什么可调参数,而mixed gc有一些,常见如下:

参数 作用
-XX:InitiatingHeapOccupancyPercent 开端mixed gc并发周期的堆占用阈值,当大于此份额,发动并发周期,默许45%
-XX:ConcGCThreads 在并发符号时,运用多少个并发线程。
-XX:G1HeapRegionSize 每个region大小,当分配目标尺寸大于region一半时,才认为这是一个大目标。
-XX:G1MixedGCLiveThresholdPercent region存活份额,默许85%,当并发符号后发现region中存活目标份额小于这个值,mixed gc才会收回这个region,究竟一个region假如都是存活的目标,那还有什么收回的必要呢。
-XX:G1HeapWastePercent 答应浪费的堆份额,默许5%,当可收回的内存份额大于此值时,mixed gc才会去履行收回,究竟没什么可收回的目标时,还有什么收回的必要呢。
-XX:G1MixedGCCountTarget mixed gc履行的次数,一旦并发符号周期确认了收回哪些region后,mixed gc就进行收回,但mixed gc会分少数屡次来收回这些region,默许8次。
-XX:G1OldCSetRegionThresholdPercent 每次mixed gc收回old region的份额,默许10%,假如G1MixedGCCountTarget是8的话,mixed gc整体能收回80%。
-XX:G1ReservePercent 堆保存空间份额,默许10%,这部分空间g1会保存下来,用来在gc时仿制存活目标。

出现to-space exhausted会不会是mixed gc太慢了呢?所以我调整了如下参数:

  1. 让并发符号周期发动更早,运转得更快,将-XX:InitiatingHeapOccupancyPercent从默许值45%调整到35%,-XX:ConcGCThreads从1调整为3。
  2. -XX:G1MixedGCLiveThresholdPercent-XX:G1HeapWastePercent确认收回哪些region,有多少份额废物才履行收回,我觉得它们的值本来就蛮激进,就没有调整。
  3. -XX:G1MixedGCCountTarget-XX:G1OldCSetRegionThresholdPercent操控mixed gc履行多少次,每次收回多少region,我将-XX:G1OldCSetRegionThresholdPercent从10%调整到了15%,让它一次多收回些old region。
  4. 增加保存空间,避免仿制存活目标失利,将-XX:G1ReservePercent从10%调整到20%。
  5. 尽量避免发生大目标,将-XX:G1HeapRegionSize增加到16m。

所以我按照上面调整了jvm参数,可是第二天我发现仍是有GC长耗时,次数也没有减少,看来问题根因和我调整的参数没有关系。

问题根因

就这样,到了上线日,所以我上线了前面优化大目标的代码,一天后,我发现偶然的GC长耗时竟然没有了!

问题就这样处理了!!!

可是我心里仍是有一个大大的问号,其它环境相同有这个守时使命,相同的运转频率,jvm配置也全是相同的,为啥其它环境没有问题呢?其它环境事务流量还大一些!

为此,我查找了很多关于g1大目标的文章,我发现大目标的分配与收回进程有点特殊,如下:

  1. 大于region size一半的目标是大目标,会直接分配在old region,且gc时大目标不会被仿制或移动,而是直接收回。
  2. 大目标收回发生在2个地方,一个是并发周期的clean up子阶段,另一个是young gc(这个特性在jdk8u60才参加)。

我忽然想到,莫非是俄罗斯环境流量太低,触发不了young gc,且并发周期又由于什么原因没履行,但守时使命又渐渐生成大目标将old region占满,导致了to-space exhausted?

所以,我打算写段代码实验一下,渐渐的只生成大目标,看g1会不会收回,如下:

GC耗时高,原因竟是服务流量小?

这个一个命令行交互程序,运用如下jvm参数发动它:

# 1600m的堆,16m的region size
# rlwrap作用是使得这个命令行程序更好用
rlwrap java -server -Xms1600m -Xmx1600m -Xss1m -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=1g -Xloggc:/home/work/logs/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:G1HeapRegionSize=16m -XX:MaxGCPauseMillis=200 -jar command-cli.jar

运用了1600M的堆,16M的region size,所以总共有100个region,jdk版别是1.8.0_222
通过在这个交互程序中输入gc 9437184 20 0,能够生成20个9M的大目标。

当我输入3次gc 9437184 20 0后,如下:
我从gc日志中发现了一次由initial marking触发的young gc,阐明g1发动了并发周期,之所以发生young gc,是由于initial marking是凭借ygc履行的。

GC耗时高,原因竟是服务流量小?

紧接着,我发现了并发符号、从头符号与清理阶段的日志。

GC耗时高,原因竟是服务流量小?

然后我在jstat中发现老时代运用率下降了,由于young gc会收回大目标,所以老时代运用率下降也是正常的。

GC耗时高,原因竟是服务流量小?

当我又履行了2次gc 9437184 20 0后,使得堆占用率再次大于45%,我发现gc日志中出现如下内容:

GC耗时高,原因竟是服务流量小?

看字面意思是,由于mixed gc正在履行,没有再次发动并发周期。

可是,我在这种状态下等了好久,也没有看到mixed gc的日志出来,不是说mixed gc正在履行嚒,它一定是有什么问题!

所以,我又履行了好几次gc 9437184 20 0,我在gc日志中发现了to-space exhausted!

GC耗时高,原因竟是服务流量小?

GC耗时高,原因竟是服务流量小?

  1. 从上面do not start mixed GCs, reason: candidate old regions not available的日志中看到,mixed gc日志之所以长期没出来,是由于没有可收回的region导致mixed gc没有履行,由于咱们只创建了大目标,但mixed gc不收回大目标分区,所以的确是没有可收回的region的。
  2. Humongous Reclaimed: 98能够发现,这次young gc,收回了98个大目标分区,而咱们总共只要100个分区,阐明在inital marking之后创建的大目标,的确一向都没有收回。

注:增加-XX:G1LogLevel=finest参数,才能输出Humongous Reclaimed这一项。

可是,大目标分区占了98个,堆占用率必定超过了45%,为何一向没有再次发动并发周期呢?

感觉这或许是jdk的bug,所以我分别下了最新的jdk8u与jdk11u验证,发现问题在最新的jdk8u中仍然存在,而jdk11u中则不存在,这应该就是JDK的Bug!
所以我通过二分查找法屡次编译了不同版别的JDK,最终确认问题fix在jdk9_b93与jdk9_b94之间。

GC耗时高,原因竟是服务流量小?

并在jdk的bug库中,查找到了相同描绘的bug反应,如下:
GC耗时高,原因竟是服务流量小?

bugs.openjdk.org/browse/JDK-…

Bug改动代码如下:

GC耗时高,原因竟是服务流量小?

大致瞄了下代码,或许了解得不完全正确,改动逻辑如下:

  1. G1再次发动并发周期之前,至少需求履行过一次mixed gcyoung gc,类似于Concurrent Cycles -> mixed gc|young gc -> Concurrent Cycles -> mixed gc|young gc
  2. 咱们的场景是,在并发周期完毕之后,由于没有需求收回的分区,导致mixed gc实践没有履行,可是咱们只分配了大目标,且大目标又只分配在old region,所以young gc也不或许被触发,而由于上面的条件,Concurrent Cycles也不会被触发,因而最终大目标将堆占满触发了to-space exhausted。
  3. 修复逻辑是,当并发周期完毕后,没有需求收回的分区时,should_continue_with_reclaim=false,进而使得答应不履行纯young gc而直接发动并发周期,类似于Concurrent Cycles -> Concurrent Cycles

所以在运用JDK8时,像那种体系流量很小,新生代较大,又有守时使命不断发生大目标的场景,堆简直必然会被渐渐占满,要处理这个问题,可参考如下处理:

  1. 优化代码,避免分配大目标。
  2. 代码无法优化时,可考虑升级jdk11。
  3. 无法升级jdk11时,可考虑减小-XX:G1MaxNewSizePercent让新生代小一点,让young gc能履行得更频频些,一起老时代更大,能缓冲更多大目标分配。

考虑到咱们负责的其它体系中,时不时就有一波大呼应体的请求,也无法快速修正代码,所以我统一将-XX:G1MaxNewSizePercent减小到30%,通过调查,修正后GC频率有所增加,但暂停时刻有所下降,这是符合希望的。

总结

当我在jdk的bug库中查找问题时,发现不少和G1大目标相关的优化,早期JDK(如JDK8)的G1实现或许在大目标收回上不太完善,所以写代码时要留意尽量少创建大目标,以逃避这些隐性问题。

注:这之后又遇到了Update RS (ms)耗时高,竟也和大目标有关,增加-XX:-ReduceInitialCardMarks后处理,看来大目标是万恶之源啊