Archive for the ‘Java’ category

Springboot 拦截器的坑 WebMvcConfigurationSupport 失效

October 16th, 2020

今天遇到一个拦截器失效的问题,具体看源码分析下。

环境:

springboot 2.x

spring 5.x

===================

拦截器创建的几种方式

  • extends WebMvcConfigurationSupport
  • implements WebMvcConfigurer

如果项目中出现了一次 extends WebMvcConfigurationSupport ,其他的 extends WebMvcConfigurationSupport 和 implements WebMvcConfigurer 会失效 。

先看下 WebMvcConfigurationSupport 这个类, addInterceptors 这个方法,默认继承的是 DelegatingWebMvcConfiguration,这个类就是获取 `所有 ` 实现 WebMvcConfigurer 的子类,调用他们的方法,如果有多个 通过实现 WebMvcConfigurer 创建的拦截器,是都可以生效的。

那多个 继承 WebMvcConfigurationSupport 为啥只有一个生效呢,答案在这个类WebMvcAutoConfiguration 的 ConditionalOnMissingBean 注解,只实例化一个Bean,多个继承也只有一个生效。
再看下 addInterceptors 啥时候触发的,获取拦截器的时候,获取过就不再获取了,所以 addInterceptors 在项目启动触发才有效。而 getInterceptors 这个方法是在 handerMapping映射的时候触发的(比如 RequestMappingHandlerMapping、BeanNameUrlHandlerMapping)。

解决方案

针对不同的场景解决方案也不一样,我想到的有3个方案。

  • 不继承 WebMvcConfigurationSupport ,拦截器全部通过实现 WebMvcConfigurer 接口(推荐)
  • 只继承一次 WebMvcConfigurationSupport ,在这个类管理所有的拦截器(不推荐,耦合性太高)
  • 针对我的场景,通过过滤器实现的。注入的代码就不贴了,before 和 fater 方法实现了类似拦截器的 preHandle 和 afterCompletion。有一点需要注意的是指定过滤器的排序(默认已经是最高了,可以忽略),由于过滤器是链式调用,如果想当拦截器用,必须指定最先加载,还有就是过滤器会拦截静态资源,做好对静态资源的放行。

 

https://www.lyscms.info/blog/detail/33A55BEE2FD94E66B40990EA4967D3F7

https://blog.csdn.net/pengdandezhi/article/details/81182701

Java8 中Stream尝鲜

December 16th, 2019

Stream简介

  • Java 8引入了全新的Stream API。这里的Stream和I/O流不同,它更像具有Iterable的集合类,但行为和集合类又有所不同。
  • stream是对集合对象功能的增强,它专注于对集合对象进行各种非常便利、高效的聚合操作,或者大批量数据操作。
  • 只要给出需要对其包含的元素执行什么操作,比如 “过滤掉长度大于 10 的字符串”、“获取每个字符串的首字母”等,Stream 会隐式地在内部进行遍历,做出相应的数据转换。

为什么要使用Stream

  • 函数式编程带来的好处尤为明显。这种代码更多地表达了业务逻辑的意图,而不是它的实现机制。易读的代码也易于维护、更可靠、更不容易出错。
  • 高端

Filter

  • 遍历数据并检查其中的元素时使用。
  • filter接受一个函数作为参数,该函数用Lambda表达式表示。

/**
     * 过滤所有的男性
     */
    public static void fiterSex(){
        List<PersonModel> data = Data.getData();

        //old
        List<PersonModel> temp=new ArrayList<>();
        for (PersonModel person:data) {
            if ("男".equals(person.getSex())){
                temp.add(person);
            }
        }
        System.out.println(temp);
        //new
        List<PersonModel> collect = data
                .stream()
                .filter(person -> "男".equals(person.getSex()))
                .collect(toList());
        System.out.println(collect);
    }

    /**
     * 过滤所有的男性 并且小于20岁
     */
    public static void fiterSexAndAge(){
        List<PersonModel> data = Data.getData();

        //old
        List<PersonModel> temp=new ArrayList<>();
        for (PersonModel person:data) {
            if ("男".equals(person.getSex())&&person.getAge()<20){
                temp.add(person);
            }
        }

        //new 1
        List<PersonModel> collect = data
                .stream()
                .filter(person -> {
                    if ("男".equals(person.getSex())&&person.getAge()<20){
                        return true;
                    }
                    return false;
                })
                .collect(toList());
        //new 2
        List<PersonModel> collect1 = data
                .stream()
                .filter(person -> ("男".equals(person.getSex())&&person.getAge()<20))
                .collect(toList());

    }

Map

  • map生成的是个一对一映射,for的作用
  • 比较常用
  • 而且很简单

 /**
     * 取出所有的用户名字
     */
    public static void getUserNameList(){
        List<PersonModel> data = Data.getData();

        //old
        List<String> list=new ArrayList<>();
        for (PersonModel persion:data) {
            list.add(persion.getName());
        }
        System.out.println(list);

        //new 1
        List<String> collect = data.stream().map(person -> person.getName()).collect(toList());
        System.out.println(collect);

        //new 2
        List<String> collect1 = data.stream().map(PersonModel::getName).collect(toList());
        System.out.println(collect1);

        //new 3
        List<String> collect2 = data.stream().map(person -> {
            System.out.println(person.getName());
            return person.getName();
        }).collect(toList());
    }

FlatMap

  • 顾名思义,跟map差不多,更深层次的操作
  • 但还是有区别的
  • map和flat返回值不同
  • Map 每个输入元素,都按照规则转换成为另外一个元素。
    还有一些场景,是一对多映射关系的,这时需要 flatMap。
  • Map一对一
  • Flatmap一对多
  • map和flatMap的方法声明是不一样的
    • <r> Stream<r> map(Function mapper);
    • <r> Stream<r> flatMap(Function> mapper);
  • map和flatMap的区别:我个人认为,flatMap的可以处理更深层次的数据,入参为多个list,结果可以返回为一个list,而map是一对一的,入参是多个list,结果返回必须是多个list。通俗的说,如果入参都是对象,那么flatMap可以操作对象里面的对象,而map只能操作第一层。
public static void flatMapString() {
        List<PersonModel> data = Data.getData();
        //返回类型不一样
        List<String> collect = data.stream()
                .flatMap(person -> Arrays.stream(person.getName().split(" "))).collect(toList());

        List<Stream<String>> collect1 = data.stream()
                .map(person -> Arrays.stream(person.getName().split(" "))).collect(toList());

        //用map实现
        List<String> collect2 = data.stream()
                .map(person -> person.getName().split(" "))
                .flatMap(Arrays::stream).collect(toList());
        //另一种方式
        List<String> collect3 = data.stream()
                .map(person -> person.getName().split(" "))
                .flatMap(str -> Arrays.asList(str).stream()).collect(toList());
}

Collect

  • collect在流中生成列表,map,等常用的数据结构
  • toList()
  • toSet()
  • toMap()
  • 自定义
/**
     * toList
     */
    public static void toListTest(){
        List<PersonModel> data = Data.getData();
        List<String> collect = data.stream()
                .map(PersonModel::getName)
                .collect(Collectors.toList());
    }

    /**
     * toSet
     */
    public static void toSetTest(){
        List<PersonModel> data = Data.getData();
        Set<String> collect = data.stream()
                .map(PersonModel::getName)
                .collect(Collectors.toSet());
    }

    /**
     * toMap
     */
    public static void toMapTest(){
        List<PersonModel> data = Data.getData();
        Map<String, Integer> collect = data.stream()
                .collect(
                        Collectors.toMap(PersonModel::getName, PersonModel::getAge)
                );

        data.stream()
                .collect(Collectors.toMap(per->per.getName(), value->{
            return value+"1";
        }));
    }

    /**
     * 指定类型
     */
    public static void toTreeSetTest(){
        List<PersonModel> data = Data.getData();
        TreeSet<PersonModel> collect = data.stream()
                .collect(Collectors.toCollection(TreeSet::new));
        System.out.println(collect);
    }

    /**
     * 分组
     */
    public static void toGroupTest(){
        List<PersonModel> data = Data.getData();
        Map<Boolean, List<PersonModel>> collect = data.stream()
                .collect(Collectors.groupingBy(per -> "男".equals(per.getSex())));
        System.out.println(collect);
    }

    /**
     * 分隔
     */
    public static void toJoiningTest(){
        List<PersonModel> data = Data.getData();
        String collect = data.stream()
                .map(personModel -> personModel.getName())
                .collect(Collectors.joining(",", "{", "}"));
        System.out.println(collect);
    }

    /**
     * 自定义
     */
    public static void reduce(){
        List<String> collect = Stream.of("1", "2", "3").collect(
                Collectors.reducing(new ArrayList<String>(), x -> Arrays.asList(x), (y, z) -> {
                    y.addAll(z);
                    return y;
                }));
        System.out.println(collect);
    }

调试

  • list.map.fiter.map.xx 为链式调用,最终调用collect(xx)返回结果
  • 分惰性求值和及早求值
  • 判断一个操作是惰性求值还是及早求值很简单:只需看它的返回值。如果返回值是 Stream,那么是惰性求值;如果返回值是另一个值或为空,那么就是及早求值。使用这些操作的理想方式就是形成一个惰性求值的链,最后用一个及早求值的操作返回想要的结果。
  • 通过peek可以查看每个值,同时能继续操作流
private static void peekTest() {
        List<PersonModel> data = Data.getData();

        //peek打印出遍历的每个per
        data.stream().map(per->per.getName()).peek(p->{
            System.out.println(p);
        }).collect(toList());
}

GC调优

October 12th, 2019

1.问题的发现与定位

1.1统计nginx每秒中流量时发现轮询到每台机器上的流量不均衡,找到后端机器,看gc 日志发现出现大量的full gc,对比gc时间和流量统计的时间,发现时间是完全吻合的,从而定位流量不均衡问题是因为线上服务full gc引起的。

2019-08-30T11:33:06.130+0800: 780570.463: [GC pause (G1 Evacuation Pause) (young)2019-08-30T11:33:06.352+0800: 780570.685: [SoftReference, 0 refs, 0.0000547 secs]2019-08-30T11:33:06.352+0800: 780570.685: [WeakReference, 0 refs, 0.0000128 secs]2019-08-30T11:33:06.352+0800: 780570.685: [FinalReference, 0 refs, 0.0000103 secs]2019-08-30T11:33:06.352+0800: 780570.685: [PhantomReference, 0 refs, 0 refs, 0.0000147 secs]2019-08-30T11:33:06.352+0800: 780570.685: [JNI Weak Reference, 0.0000183 secs] (to-space exhausted), 0.2410054 secs]
   [Parallel Time: 212.0 ms, GC Workers: 23]
      [GC Worker Start (ms): Min: 780570465.3, Avg: 780570465.5, Max: 780570465.9, Diff: 0.6]
      [Ext Root Scanning (ms): Min: 0.4, Avg: 0.8, Max: 2.2, Diff: 1.9, Sum: 18.4]
      [Update RS (ms): Min: 33.8, Avg: 37.4, Max: 40.3, Diff: 6.4, Sum: 861.1]
         [Processed Buffers: Min: 9, Avg: 30.3, Max: 137, Diff: 128, Sum: 697]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 169.7, Avg: 173.0, Max: 176.7, Diff: 7.0, Sum: 3979.6]
      [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 5.8]
         [Termination Attempts: Min: 1, Avg: 1.3, Max: 3, Diff: 2, Sum: 30]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.4, Diff: 0.4, Sum: 0.8]
      [GC Worker Total (ms): Min: 211.2, Avg: 211.6, Max: 211.8, Diff: 0.7, Sum: 4865.7]
      [GC Worker End (ms): Min: 780570677.0, Avg: 780570677.1, Max: 780570677.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 28.8 ms]
      [Evacuation Failure: 18.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 7.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 1.5 ms]
      [Humongous Reclaim: 0.2 ms]
      [Free CSet: 0.1 ms]
   [Eden: 44.0M(6116.0M)->0.0B(6144.0M) Survivors: 28.0M->0.0B Heap: 9482.2M(12.0G)->9482.2M(12.0G)]
Heap after GC invocations=266041 (full 14579):
 garbage-first heap   total 12582912K, used 9709773K [0x00000004c0000000, 0x00000004c0406000, 0x00000007c0000000)
  region size 4096K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 59825K, capacity 60428K, committed 62016K, reserved 1103872K
  class space    used 6597K, capacity 6776K, committed 7056K, reserved 1048576K
}
 [Times: user=0.57 sys=0.08, real=0.24 secs]
2019-08-30T11:33:06.372+0800: 780570.705: Total time for which application threads were stopped: 0.2499226 seconds, Stopping threads took: 0.0007422 seconds
{Heap before GC invocations=266041 (full 14579):
 garbage-first heap   total 12582912K, used 9709773K [0x00000004c0000000, 0x00000004c0406000, 0x00000007c0000000)
  region size 4096K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 59825K, capacity 60428K, committed 62016K, reserved 1103872K
  class space    used 6597K, capacity 6776K, committed 7056K, reserved 1048576K
2019-08-30T11:33:06.380+0800: 780570.712: [GC pause (G1 Evacuation Pause) (young) (initial-mark)2019-08-30T11:33:06.392+0800: 780570.725: [SoftReference, 0 refs, 0.0000740 secs]2019-08-30T11:33:06.392+0800: 780570.725: [WeakReference, 0 refs, 0.0000127 secs]2019-08-30T11:33:06.392+0800: 780570.725: [FinalReference, 0 refs, 0.0000103 secs]2019-08-30T11:33:06.392+0800: 780570.725: [PhantomReference, 0 refs, 0 refs, 0.0000147 secs]2019-08-30T11:33:06.392+0800: 780570.725: [JNI Weak Reference, 0.0000174 secs], 0.0144402 secs]
   [Parallel Time: 10.2 ms, GC Workers: 23]
      [GC Worker Start (ms): Min: 780570714.5, Avg: 780570715.2, Max: 780570716.2, Diff: 1.7]
      [Ext Root Scanning (ms): Min: 1.1, Avg: 1.9, Max: 2.8, Diff: 1.7, Sum: 44.1]
      [Update RS (ms): Min: 6.1, Avg: 6.5, Max: 7.3, Diff: 1.2, Sum: 150.3]
         [Processed Buffers: Min: 3, Avg: 9.9, Max: 18, Diff: 15, Sum: 227]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 4.7]
      [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 12.5]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 23]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
      [GC Worker Total (ms): Min: 8.3, Avg: 9.2, Max: 10.0, Diff: 1.7, Sum: 211.9]
      [GC Worker End (ms): Min: 780570724.4, Avg: 780570724.4, Max: 780570724.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 3.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 1.4 ms]
      [Humongous Reclaim: 0.2 ms]
      [Free CSet: 0.0 ms]
   [Eden: 0.0B(6144.0M)->0.0B(6144.0M) Survivors: 0.0B->0.0B Heap: 9482.2M(12.0G)->9482.2M(12.0G)]
Heap after GC invocations=266042 (full 14579):
 garbage-first heap   total 12582912K, used 9709773K [0x00000004c0000000, 0x00000004c0406000, 0x00000007c0000000)
  region size 4096K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 59825K, capacity 60428K, committed 62016K, reserved 1103872K
  class space    used 6597K, capacity 6776K, committed 7056K, reserved 1048576K
}
 [Times: user=0.13 sys=0.01, real=0.02 secs]
2019-08-30T11:33:06.394+0800: 780570.727: [GC concurrent-root-region-scan-start]
2019-08-30T11:33:06.394+0800: 780570.727: [GC concurrent-root-region-scan-end, 0.0000314 secs]
2019-08-30T11:33:06.394+0800: 780570.727: [GC concurrent-mark-start]
2019-08-30T11:33:06.394+0800: 780570.727: Total time for which application threads were stopped: 0.0225686 seconds, Stopping threads took: 0.0003015 seconds
{Heap before GC invocations=266042 (full 14579):
 garbage-first heap   total 12582912K, used 9709773K [0x00000004c0000000, 0x00000004c0406000, 0x00000007c0000000)
  region size 4096K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 59825K, capacity 60428K, committed 62016K, reserved 1103872K
  class space    used 6597K, capacity 6776K, committed 7056K, reserved 1048576K
2019-08-30T11:33:06.402+0800: 780570.735: [Full GC (Allocation Failure) 2019-08-30T11:33:06.812+0800: 780571.145: [SoftReference, 155 refs, 0.0000827 secs]2019-08-30T11:33:06.812+0800: 780571.145: [WeakReference, 4919 refs, 0.0004444 secs]2019-08-30T11:33:06.812+0800: 780571.145: [FinalReference, 38797 refs, 0.0256226 secs]2019-08-30T11:33:06.838+0800: 780571.171: [PhantomReference, 0 refs, 4 refs, 0.0000267 secs]2019-08-30T11:33:06.838+0800: 780571.171: [JNI Weak Reference, 0.0000255 secs] 9482M->3317M(12G), 1.3316541 secs]
   [Eden: 0.0B(6144.0M)->0.0B(6144.0M) Survivors: 0.0B->0.0B Heap: 9482.2M(12.0G)->3317.3M(12.0G)], [Metaspace: 59825K->59825K(1103872K)]
Heap after GC invocations=266043 (full 14580):
 garbage-first heap   total 12582912K, used 3396899K [0x00000004c0000000, 0x00000004c0406000, 0x00000007c0000000)
  region size 4096K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 59825K, capacity 60428K, committed 62016K, reserved 1103872K
  class space    used 6597K, capacity 6776K, committed 7056K, reserved 1048576K
}
 [Times: user=1.83 sys=0.12, real=1.34 secs]

2 问题分析与处理

2.1 分析日志发现在新生代回收时触发了老年代的担保机制,导致新生代对象直接晋升到了老年代,然后触发并发周期,这时由于老年代对象太多已经不足以触发mixed GC,而是采用了最耗时的Full GC进行垃圾回收,由于Full GC耗时很长导致,后续的新生代在垃圾回收时还是会触发老年代担保机制,从而整个程序陷入循环Full GC的状态。

2.2 根据to-space exhausted我们知道,调整空闲区域预留百分比是能缓解新生代垃圾回收空间溢出问题,我们尝试增加XX:G1ReservePercent=15;另外我们为了降低Full GC触发概率,减小了InitiatingHeapOccupancyPercent的大小,这样我们可以用更加频繁的mixed gc降低 full gc问题

2.3 根据G1的启发式算法,我们为了控制gc时间,决定放弃原有的gc用法,让g1决定新生代和老年代大小,我们删除了Xmn参数设置

2-4 在gc日志中我们也发现了大对象分配与回收的现象,考虑到我们线上视频大小,我们调整region大小到16M

3 观察对比后再次处理

3.1 通过上述调整对比观察四台机器,两天以后,原有的机器出现Full GC 调整后的机器运行正常

3.2 观察调整后日志发现新调整的gc没有出现Full gc,但是mixed gc问题出现频率在20min一次,这个频率出现理论上对整个gc的吞吐几乎没有影响,但是分析后会发现mixed gc回收效率很低,所以我们尝试改善mixed gc的效率

3.3 根据上述我们对InitiatingHeapOccupancyPercent参数的调整,我们根据线上观察到的老年代大小和新生代大小,调整值为50

3.4 对比观察后发现调整后mixed gc频率在流量高峰期间为2小时一次,流量低峰期间为6小时一次,并且mixed gc 回收效率大大提高

4.调优后效果

经过调优后线上没有触发 full gc, yang gc 和mixed gc 效率都很高,整个gc的吞吐达到 99%以上

G1 算法总结

August 20th, 2019

G1收集器堆结构:

  • heap被划分为一个个相等的不连续的内存区域(regions),每个regions都有一个分代的角色:eden、survivor、old。
  • 对每个角色的数量并没有强制的限定,也就是说对每种分代内存的大小,可以动态变化。
  • G1最大的特点就是高效的执行回收,优先去执行那些大量对象可回收的区域(region)。

G1分成四个阶段回收:

新生代收集 -> 并发垃圾收集 -> 混合收集(Mixed GC) -> Full GC

其中新生代蕴含着CMS的清理:

当对象生成在EDEN区失败时,出发一次YGC,先扫描EDEN区中的存活对象,进入S0区,S0放不下的进入OLD区,再扫描S1区,若存活次数超过阀值则进入OLD区,其它进入S0区,然后S0和S1交换一次。

那么当发生YGC时,JVM会首先检查老年代最大的可用连续空间是否大于新生代所有对象的总和,如果大于,那么这次YGC是安全的,如果不大于的话,JVM就需要判断HandlePromotionFailure是否允许空间分配担保。

JVM继续检查老年代最大的可用连续空间是否大于历次晋升到老年代的对象的平均大小,如果大于,则正常进行一次YGC,尽管有风险(因为判断的是平均大小,有可能这次的晋升对象比平均值大很多);

如果小于,或者HandlePromotionFailure设置不允许空间分配担保,这时要进行一次Full GC。

==========

另外Mixed GC既包括YGC也包括Old GC,另外会把Humongous regions给清除掉

For G1 GC, any object that is more than half a region size is considered a “Humongous object“. Such an object is allocated directly in the old generation into “Humongous regions”. These Humongous regions are a contiguous set of regions.

Dead Humongous objects are freed at the end of the marking cycle during the cleanup phase also during a full garbage collection cycle.

Full GC 就不说了,会清理整个Heap,就是STW,在生产环境中尽量避免Full GC,另外无论什么GC,都要注意thread的停止时间。

https://stackoverflow.com/questions/35380827/g1-what-are-the-differences-between-mixed-gc-and-full-gc

G1 日志查看

August 12th, 2019

如果你要在生产环境中使用G1 GC,下面这些跟日志相关的参数是必备的,有了这些参数,你才能排查基本的垃圾回收问题。

使用-XX:GCLogFileSize设置合适的GC日志文件大小,使用-XX:NumberOfGCLogFiles设置要保留的GC日志文件个数,使用-Xloggc:/path/to/gc.log设置GC日志文件的位置,通过上面三个参数保留应用在运行过程中的GC日志信息,我建议最少保留一个星期的GC日志,这样应用的运行时信息足够多的,方便排查问题。

新生代收集

和其他垃圾收集器一样,G1也使用-XX:PrintGCDetails打印出详细的垃圾收集日志,下面这张图是新生代收集的标准流程,我在这里将它分成了6个步骤:

四个关键信息

  • 新生代垃圾收集发生的时间——2016-12-12T10:40:18.811-0500,通过设置-XX:+PrintGCDateStamps参数可以打印出这个时间;
  • JVM启动后的相对时间——25.959
  • 这次收集的类型——新生代收集,只回收Eden分区
  • 这次收集花费的时间——0.0305171s,即30ms

列出了新生代收集中并行收集的详细过程

  • Parallel Time:并行收集任务在运行过程中引发的STW(Stop The World)时间,从新生代垃圾收集开始到最后一个任务结束,共花费26.6ms
  • GC Workers:有4个线程负责垃圾收集,通过参数-XX:ParallelGCThreads设置,这个参数的值的设置,跟CPU有关,如果物理CPU支持的线程个数小于8,则最多设置为8;如果物理CPU支持的线程个数大于8,则默认值为number * 5/8
  • GC Worker Start:第一个垃圾收集线程开始工作时JVM启动后经过的时间(min);最后一个垃圾收集线程开始工作时JVM启动后经过的时间(max);diff表示min和max之间的差值。理想情况下,你希望他们几乎是同时开始,即diff趋近于0。
  • Ext Root Scanning:扫描root集合(线程栈、JNI、全局变量、系统表等等)花费的时间,扫描root集合是垃圾收集的起点,尝试找到是否有root集合中的节点指向当前的收集集合(CSet)
  • Update RS(Remembered Set or RSet):每个分区都有自己的RSet,用来记录其他分区指向当前分区的指针,如果RSet有更新,G1中会有一个post-write barrier管理跨分区的引用——新的被引用的card会被标记为dirty,并放入一个日志缓冲区,如果这个日志缓冲区满了会被加入到一个全局的缓冲区,在JVM运行的过程中还有线程在并发处理这个全局日志缓冲区的dirty card。Update RS表示允许垃圾收集线程处理本次垃圾收集开始前没有处理好的日志缓冲区,这可以确保当前分区的RSet是最新的。
    • Processed Buffers,这表示在Update RS这个过程中处理多少个日志缓冲区。
  • Scan RS:扫描每个新生代分区的RSet,找出有多少指向当前分区的引用来自CSet。
  • Code Root Scanning:扫描代码中的root节点(局部变量)花费的时间
  • Object Copy:在疏散暂停期间,所有在CSet中的分区必须被转移疏散,Object Copy就负责将当前分区中存活的对象拷贝到新的分区。
  • Termination:当一个垃圾收集线程完成任务时,它就会进入一个临界区,并尝试帮助其他垃圾线程完成任务(steal outstanding tasks),min表示该垃圾收集线程什么时候尝试terminatie,max表示该垃圾收集回收线程什么时候真正terminated。
    • Termination Attempts:如果一个垃圾收集线程成功盗取了其他线程的任务,那么它会再次盗取更多的任务或再次尝试terminate,每次重新terminate的时候,这个数值就会增加。
  • GC Worker Other:垃圾收集线程在完成其他任务的时间
  • GC Worker Total:展示每个垃圾收集线程的最小、最大、平均、差值和总共时间。
  • GC Worker End:min表示最早结束的垃圾收集线程结束时该JVM启动后的时间;max表示最晚结束的垃圾收集线程结束时该JVM启动后的时间。理想情况下,你希望它们快速结束,并且最好是同一时间结束。

列出了新生代GC中的一些任务:

  • Code Root Fixup :释放用于管理并行垃圾收集活动的数据结构,应该接近于0,该步骤是线性执行的;
  • Code Root Purge:清理更多的数据结构,应该很快,耗时接近于0,也是线性执行。
  • Clear CT:清理card table

包含一些扩展功能

  • Choose CSet:选择要进行回收的分区放入CSet(G1选择的标准是垃圾最多的分区优先,也就是存活对象率最低的分区优先)
  • Ref Proc:处理Java中的各种引用——soft、weak、final、phantom、JNI等等。
  • Ref Enq:遍历所有的引用,将不能回收的放入pending列表
  • Redirty Card:在回收过程中被修改的card将会被重置为dirty
  • Humongous Register:JDK8u60提供了一个特性,巨型对象可以在新生代收集的时候被回收——通过G1ReclaimDeadHumongousObjectsAtYoungGC设置,默认为true。
  • Humongous Reclaim:做下列任务的时间:确保巨型对象可以被回收、释放该巨型对象所占的分区,重置分区类型,并将分区还到free列表,并且更新空闲空间大小。
  • Free CSet:将要释放的分区还回到free列表。
  • 展示了不同代的大小变化,以及堆大小的自适应调整。
    • Eden:1097.0M(1097.0M)->0.0B(967.0M):(1)当前新生代收集触发的原因是Eden空间满了,分配了1097M,使用了1097M;(2)所有的Eden分区都被疏散处理了,在新生代结束后Eden分区的使用大小成为了0.0B;(3)Eden分区的大小缩小为967.0M
    • Survivors:13.0M->139.0M:由于年轻代分区的回收处理,survivor的空间从13.0M涨到139.0M;
    • Heap:1694.4M(2048.0M)->736.3M(2048.0M):(1)在本次垃圾收集活动开始的时候,堆空间整体使用量是1694.4M,堆空间的最大值是2048M;(2)在本次垃圾收集结束后,堆空间的使用量是763.4M,最大值保持不变。
  • 第6点展示了本次新生代垃圾收集的时间
    • user=0.8:垃圾收集线程在新生代垃圾收集过程中消耗的CPU时间,这个时间跟垃圾收集线程的个数有关,可能会比real time大很多;
    • sys=0.0:内核态线程消耗的CPU时间 –real=0.03:本次垃圾收集真正消耗的时间;

并发垃圾收集

G1的第二种收集活动是并发垃圾收集,并发垃圾收集的触发条件有很多,但是做的工作都相同,它的日志如下图所示:

标志着并发垃圾收集阶段的开始:

  • GC pause(G1 Evacuation Pause)(young)(initial-mark):为了充分利用STW的机会来trace所有可达(存活)的对象,initial-mark阶段是作为新生代垃圾收集中的一部分存在的(搭便车)。initial-mark设置了两个TAMS(top-at-mark-start)变量,用来区分存活的对象和在并发标记阶段新分配的对象。在TAMS之前的所有对象,在当前周期内都会被视作存活的。

表示第并发标记阶段做的第一个事情:根分区扫描

  • GC concurrent-root-region-scan-start:根分区扫描开始,根分区扫描主要扫描的是新的survivor分区,找到这些分区内的对象指向当前分区的引用,如果发现有引用,则做个记录;
  • GC concurrent-root-region-scan-end:根分区扫描结束,耗时0.0030613s

表示并发标记阶段

  • GC Concurrent-mark-start:并发标记阶段开始。(1)并发标记阶段的线程是跟应用线程一起运行的,不会STW,所以称为并发;并发标记阶段的垃圾收集线程,默认值是Parallel Thread个数的25%,这个值也可以用参数-XX:ConcGCThreads设置;(2)trace整个堆,并使用位图标记所有存活的对象,因为在top TAMS之前的对象是隐式存活的,所以这里只需要标记出那些在top TAMS之后、阈值之前的;(3)记录在并发标记阶段的变更,G1这里使用了SATB算法,该算法要求在垃圾收集开始的时候给堆做一个快照,在垃圾收集过程中这个快照是不变的,但实际上肯定有些对象的引用会发生变化,这时候G1使用了pre-write barrier记录这种变更,并将这个记录存放在一个SATB缓冲区中,如果该缓冲区满了就会将它加入到一个全局的缓冲区,同时G1有一个线程在并行得处理这个全局缓冲区;(4)在并发标记过程中,会记录每个分区的存活对象占整个分区的大小的比率;
  • GC Concurrent-mark-end:并发标记阶段结束,耗时0.3055438s
  • 重新标记阶段,会Stop the World
    • Finalize Marking:Finalizer列表里的Finalizer对象处理,耗时0.0014099s;
    • GC ref-proc:引用(soft、weak、final、phantom、JNI等等)处理,耗时0.0000480s;
    • Unloading:类卸载,耗时0.0025840s;
    • 除了前面这几个事情,这个阶段最关键的结果是:绘制出当前并发周期中整个堆的最后面貌,剩余的SATB缓冲区会在这里被处理,所有存活的对象都会被标记;
  • 清理阶段,也会Stop the World
    • 计算出最后存活的对象:标记出initial-mark阶段后分配的对象;标记出至少有一个存活对象的分区;
    • 为下一个并发标记阶段做准备,previous和next位图会被清理;
    • 没有存活对象的老年代分区和巨型对象分区会被释放和清理;
    • 处理没有任何存活对象的分区的RSet;
    • 所有的老年代分区会按照自己的存活率(存活对象占整个分区大小的比例)进行排序,为后面的CSet选择过程做准备;
  • 并发清理阶段
    • GC concurrent-cleanup-start:并发清理阶段启动。完成第5步剩余的清理工作;将完全清理好的分区加入到二级free列表,等待最终还会到总体的free列表;
    • GC concurrent-cleanup-end:并发清理阶段结束,耗时0.0012954s

混合收集

在并发收集阶段结束后,你会看到混合收集阶段的日志,如下图所示,该日志的大部分跟之前讨论的新生代收集相同,只有第1部分不一样:GC pause(G1 Evacuation Pause)(mixed),0.0129474s,这一行表示这是一个混合垃圾收集周期;在混合垃圾收集处理的CSet不仅包括新生代的分区,还包括老年代分区——也就是并发标记阶段标记出来的那些老年代分区。

Full GC

如果堆内存空间不足以分配新的对象,或者是Metasapce空间使用率达到了设定的阈值,那么就会触发Full GC——你在使用G1的时候应该尽量避免这种情况发生,因为G1的Full Gc是单线程、会Stop The World,代价非常高。Full GC的日志如下图所示,从中你可以看出三类信息

  1. Full GC的原因,这个图里是Allocation Failure,还有一个常见的原因是Metadata GC Threshold;
  2. Full GC发生的频率,每隔几天发生一次Full GC还可以接受,但是每隔1小时发生一次Full GC则不可接受;
  3. Full GC的耗时,这张图里的Full GC耗时150ms(PS:按照我的经验,实际运行中如果发生Full GC,耗时会比这个多很多)

基础配置参数中,我这里还想介绍两个:-XX:+PrintGCApplicationStoppedTime-XX:+PrintGCApplicationConcurrentTime,这两个参数也可以为你提供有用的信息,如下图所示:
  1. 记录了应用线程在安全点被暂停的总时间(也就是STW的总时间)
  2. 记录了让所有应用线程进入安全点所花费的总时间
  3. 记录了在两个安全点之间应用线程运行的时间

https://www.redhat.com/en/blog/collecting-and-reading-g1-garbage-collector-logs-part-2?source=author&term=22991