JDK8的JVM优化实操及部分原理加深理解-CSDN博客

2019独角兽企业重金招聘Python工程师标准>>>

最近在搭建ELK集群，继logstash年前被我优化之后，今天又遇到一个新的问题。我使用es的restHighLevelClient写了一个复杂的高级聚合查询，使用了piplelineAggregation及多种Aggregations对大量数据进行聚合并过滤，结果给我报超时。我修改了springboot项目下es的配置，将超时时间增大到一分钟：

if (restHighLevelClient == null) {
   HttpHost[] httpHosts =  new HttpHost[elasticsearchConfig.getClusterNodes().size()];
   for(int i=0;i<elasticsearchConfig.getClusterNodes().size();i++){
      httpHosts[i] = new HttpHost(elasticsearchConfig.getClusterNodes().get(i).getIp(),elasticsearchConfig.getClusterNodes().get(i).getPort());
   }
   restHighLevelClient = new RestHighLevelClient(RestClient.builder(httpHosts).setMaxRetryTimeoutMillis(1*60*1000)
      .setHttpClientConfigCallback(new RestClientBuilder.HttpClientConfigCallback(){
         @Override
         public HttpAsyncClientBuilder customizeHttpClient(
               HttpAsyncClientBuilder httpClientBuilder) {
            RequestConfig.Builder requestConfigBuilder = RequestConfig.custom()
               .setConnectTimeout(1*60*1000)
               .setSocketTimeout(1*60*1000)
               .setConnectionRequestTimeout(90*1000);
            httpClientBuilder.setDefaultRequestConfig(requestConfigBuilder.build());
            return httpClientBuilder;
         }
      }));
}

结果是涛声依旧。

于是查看日志，发现给我报CMS (concurrent mode failure)，这是JVM使用的CMS并发收集器在回收老年代和meta空间的时候，因为参数设置问题，导致JVM采用停顿的方式进行full gc。原因经过百度其实是有两个：一个是在老年代被耗光之前，无法完成对无引用对象的回收，一个是一个新的空间分配请求无法在老年代的剩余空间中获得足够的空间，则系统会被暂停，触发full gc。说白了，就是老年代没空间了！

我打开es的jvm.options，想看一下配置。本来目标对准新生代，看新生代的空间是不是太大导致的，结果意外的发现，整个Xmx(JVM最大可用内存)才2G。果断增加参数，将-Xmx和-Xms增加到12G。

为何要增加到12G？因为这是由es的特性决定的。服务器内存整个的是31G，分配给logstash5G，经过free -h命令查询内存使用情况，得知空闲空间有26G。这26G得由es和es底层的Lucene共同分配。es在运行的时候会jvm会吃掉内存，同时lucene也会缓存segment，以便于加快访问速度，所以二者分配比例一般建议为一比一。26G分配12G给es，剩下的操作系统会自己分配的。

改正之后，重启es，发现开始不停地出现minor GC，间隔大概7~8秒，每次GC耗时0.045~0.048秒之间。其实一开始是懵逼的，因为GC的日志长这样子：

2019-02-20T14:19:50.653+0800: 9231.185: [GC (Allocation Failure) 2019-02-20T14:19:50.653+0800: 9231.186: [ParNew
Desired survivor size 34865152 bytes, new threshold 6 (max 6)
- age   1:   13429768 bytes,   13429768 total
- age   2:     675840 bytes,   14105608 total
- age   3:     731784 bytes,   14837392 total
- age   4:     698176 bytes,   15535568 total
- age   5:     551024 bytes,   16086592 total
- age   6:     399024 bytes,   16485616 total
: 576778K->29568K(613440K), 0.0484032 secs] 1229114K->681908K(12514816K), 0.0486516 secs] [Times: user=0.37 sys=0.00, real=0.05 secs]

有没有看到那个大大的 GC (Allocation Failure)？

我以为GC失败了，网上也有很多猿各种博客和论坛说怎么解决。直到我找到了Stack Overflow，上面明确的说这只是一次正常的GC，只是括弧告诉你GC的触发原因是Allocation Failure，也就是新的空间分配请求在eden区无法完成了，eden区满了，导致了此次GC的而已。是个正常的GC操作。虚惊一场。这个时候，我看了一眼这个：

: 576778K->29568K(613440K), 0.0484032 secs] 1229114K->681908K(12514816K), 0.0486516 secs] [Times: user=0.37 sys=0.00, real=0.05 secs]

576778K->29568K(613440K), 0.0484032 secs]意思是：新生代GC前的空间->新生代GC后的空间（新生代总空间），新生代GC耗时

1229114K->681908K(12514816K), 0.0486516 secs意思是：堆区GC前的空间->堆区GC后的空间（堆区总空间），堆区GC耗时

备注：虽然日志中的GC没有full，不是full gc，但不代表minor GC只回收新生代，还有其他工作要完成。至于什么工作，现在还不清楚，我也没查到，经过计算，新生代GC掉的空间总是略微大于堆区GC掉的空间大小，怀疑是标记对象的age，GC后改变对象指针等操作占用了部分时间和空间。

可以计算得出，新生代总空间仅堆区总空间的4.9%。这个占比太小了！

于是在linux上用命令jmap -heap pid搞出JVM堆区空间图，发现确实太小，但-XX:NewRatio又确实是2，这样算下来，新生代：老年代=1:2，新生代应该占比为三分之一才对啊！难道这个参数无效？！陷入迷惑。

经过百度，得到答案。原来es的jvm.options配置了参数-XX:+UseConcMarkSweepGC，一旦配置该参数，-XX:NewRatio随即失效。于是我增加了参数-Xmn，将新生代的大小设为12G的3/8（官方建议新生代大小设为堆区大小的四分之一到一半之间，取值3/8）。设置-Xmn参数相当于设置了-XX:NewSize -XX:MaxNewSize 两个参数。

重启es，打印出如下日志

2019-02-20T17:18:16.003+0800: 6532.997: [GC (Allocation Failure) 2019-02-20T17:18:16.003+0800: 6532.997: [ParNew
Desired survivor size 241565696 bytes, new threshold 6 (max 6)
- age   1:   12612192 bytes,   12612192 total
- age   2:       6528 bytes,   12618720 total
- age   3:     148592 bytes,   12767312 total
- age   4:        384 bytes,   12767696 total
- age   5:        568 bytes,   12768264 total
- age   6:         88 bytes,   12768352 total
: 3796348K->20113K(4246784K), 0.0321983 secs] 4347964K->571730K(12111104K), 0.0324709 secs] [Times: user=0.24 sys=0.01, real=0.03 secs]
2019-02-20T17:18:16.036+0800: 6533.030: Total time for which application threads were stopped: 0.0333961 seconds, Stopping threads took: 0.0001016 seconds
2019-02-20T17:18:16.037+0800: 6533.031: .........
2019-02-20T17:19:21.025+0800: 6598.019: [GC (Allocation Failure) 2019-02-20T17:19:21.025+0800: 6598.019: [ParNew
Desired survivor size 241565696 bytes, new threshold 6 (max 6)
- age   1:   14302232 bytes,   14302232 total
- age   2:       4384 bytes,   14306616 total
- age   3:       3560 bytes,   14310176 total
- age   4:     148176 bytes,   14458352 total
- age   5:        256 bytes,   14458608 total
- age   6:        440 bytes,   14459048 total
: 3795089K->20943K(4246784K), 0.0337087 secs] 4346706K->572560K(12111104K), 0.0339818 secs] [Times: user=0.25 sys=0.00, real=0.04 secs]

两次minor gc的间隔增加到一分钟左右，每次GC的时间减少到0.33~0.37之间。效果很明显，既减少了GC的耗时，又减少了GC的次数。

查看堆区内存的使用情况：

细心的你，如果仔细看，就会发现这个截图里有这么一句：

New Generation (Eden + 1 Survivor Space):

翻译过来就是新生代（eden区+一个survivor区空间）。我看到之后大惑不解，新生代明明是eden+两个survivor区啊！

计算，计算。经过计算，图中的maxHeapSize确实是eden+2*survivor+old(也就是concurrent mark-sweep generation)，那么，New Generation (Eden + 1 Survivor Space):这句描述中缺少的那个survivor空间去了哪里？？？？

我与同事讨论这个问题，最终认为可能是在实际使用过程中，from survivor和to survivor始终有一个空的，所以才产生了这一句，因为两个survivor最终实际使用的空间大小是一个survivor的空间大小，所以会写1 Survivor Space而不是1 Survivor 。至于GC的过程，具体可看这里https://www.jianshu.com/p/314272e6d35b，特别是这里http://www.cnblogs.com/iceAeterNa/p/5028155.html

简而言之，minor GC的触发条件是eden区满了，这个是可以确定的；触发GC后会对整个新生代区进行GC，将对-XX:MaxTenuringThreshold设置的年龄阈值进行判断，对from区是否满了进行判断，是否需要晋升到老年代，剩余的存活对象大小是否大于to survivor区大小等，将所有eden区和from survivor区的存活对象换到to survivor区，清空eden区和from survivor区，然后to survivor区交换成新的from survivor区。过程比较复杂，而且不同的GC方式实现不一致，很多时候两个人说的不一致，未必都错，很有可能说的不是同一个GC方式，例如一个说的是DefNew，一个说的是ParNew...............

转载于:https://my.oschina.net/forever9999/blog/3012576