Back to Posts

老年代的垃圾回收器

Posted in GC

在一次微服务中遇到过GC长时间停顿，jconsole中显示堆内存一直飙升从不下降的过程，这里进行一下模拟；

开启JMX监控

在springboot中可以很方便添加jmx启动配置：

@Configuration
class ConfigureRMI {



    @Value("${jmx.rmi.hostname:localhost}")
    private String rmiHost;

    @Value("${jmx.rmi.port:5000}")
    private Integer rmiPort;

    @Bean
    public RmiRegistryFactoryBean rmiRegistry() {
        final RmiRegistryFactoryBean rmiRegistryFactoryBean = new RmiRegistryFactoryBean();
        rmiRegistryFactoryBean.setPort(rmiPort);
        rmiRegistryFactoryBean.setAlwaysCreate(true);
        return rmiRegistryFactoryBean;
    }

    @Bean
    @DependsOn("rmiRegistry")
    public ConnectorServerFactoryBean connectorServerFactoryBean() throws Exception {
        final ConnectorServerFactoryBean connectorServerFactoryBean = new ConnectorServerFactoryBean();
        connectorServerFactoryBean.setObjectName("connector:name=rmi");
        connectorServerFactoryBean.setServiceUrl(String.format("service:jmx:rmi://%s:%s/jndi/rmi://%s:%s/jmxrmi", rmiHost, rmiPort, rmiHost, rmiPort));
        return connectorServerFactoryBean;
    }
}

GC日志配置

在IDEA的Edit configuration中配置VM参数：

-XX:+PrintGCDetails
-Xloggc:./logs/gc.log
-XX:+PrintGCTimeStamps

提高创建对象频率

在程序入口开启多线程高频创建对象：

@SpringBootApplication
@ServletComponentScan //以便支持@WebFilter注解
public class ServerMain {
    public static Logger logger = LoggerFactory.getLogger(ServerMain.class);

    public static void main(String[] args) {

        logger.debug("classPath={}", Thread.currentThread().getContextClassLoader().getResource(""));


        SpringApplication springApplication = new SpringApplication(ServerMain.class);
        springApplication.addListeners(new AppInitListener());
        ConfigurableApplicationContext context = springApplication.run(args);
        context.registerShutdownHook();

        // 多线程创建对象
        ExecutorService executorService = Executors.newFixedThreadPool(4);
        while (true) {
            executorService.execute(Object::new); // 对象没有引用，迅速进入了老年代等待垃圾回收
        }
    }

}

jconsole观察内存变化：

image image image

可以看到新生代、老年代、幸存区默认使用的都是并行收集器； 并且老年代占用已经达到最大值

GClog观察

56.042: [Full GC (Ergonomics) [PSYoungGen: 222784K->0K(461824K)] [ParOldGen: 1268384K->1276018K(1384448K)] 1491168K->1276018K(1846272K), [Metaspace: 48684K->48684K(1093632K)], 6.5768526 secs] [Times: user=23.06 sys=0.06, real=6.58 secs] 
63.377: [Full GC (Ergonomics) [PSYoungGen: 231424K->12705K(461824K)] [ParOldGen: 1276018K->1384339K(1384448K)] 1507442K->1397045K(1846272K), [Metaspace: 48703K->48703K(1093632K)], 6.4469733 secs] [Times: user=21.55 sys=0.13, real=6.45 secs] 
70.662: [Full GC (Ergonomics) [PSYoungGen: 231424K->89427K(461824K)] [ParOldGen: 1384339K->1384328K(1384448K)] 1615763K->1473755K(1846272K), [Metaspace: 48726K->48726K(1093632K)], 6.2785042 secs] [Times: user=21.61 sys=0.14, real=6.28 secs] 
77.365: [Full GC (Ergonomics) [PSYoungGen: 231424K->173516K(461824K)] [ParOldGen: 1384328K->1384220K(1384448K)] 1615752K->1557737K(1846272K), [Metaspace: 48740K->48740K(1093632K)], 10.1273822 secs] [Times: user=34.92 sys=0.03, real=10.13 secs] 
87.730: [Full GC (Ergonomics) [PSYoungGen: 231424K->187171K(461824K)] [ParOldGen: 1384220K->1384009K(1384448K)] 1615644K->1571181K(1846272K), [Metaspace: 48763K->48763K(1093632K)], 8.1089442 secs] [Times: user=27.94 sys=0.06, real=8.11 secs] 
95.987: [Full GC (Ergonomics) [PSYoungGen: 231424K->208481K(461824K)] [ParOldGen: 1384009K->1384404K(1384448K)] 1615433K->1592886K(1846272K), [Metaspace: 48784K->48784K(1093632K)], 8.1457827 secs] [Times: user=28.69 sys=0.09, real=8.15 secs] 
104.212: [Full GC (Ergonomics) [PSYoungGen: 231424K->217892K(461824K)] [ParOldGen: 1384404K->1384061K(1384448K)] 1615828K->1601953K(1846272K), [Metaspace: 48807K->48807K(1093632K)], 6.8055503 secs] [Times: user=23.00 sys=0.17, real=6.81 secs] 
111.056: [Full GC (Ergonomics) [PSYoungGen: 231424K->224998K(461824K)] [ParOldGen: 1384061K->1384248K(1384448K)] 1615485K->1609246K(1846272K), [Metaspace: 48821K->48821K(1093632K)], 6.8810041 secs] [Times: user=23.88 sys=0.16, real=6.88 secs] 
117.956: [Full GC (Ergonomics) [PSYoungGen: 231424K->227480K(461824K)] [ParOldGen: 1384248K->1384200K(1384448K)] 1615672K->1611681K(1846272K), [Metaspace: 48821K->48821K(1093632K)], 7.0253504 secs] [Times: user=20.86 sys=0.05, real=7.03 secs] 
124.992: [Full GC (Ergonomics) [PSYoungGen: 231424K->228740K(461824K)] [ParOldGen: 1384200K->1384059K(1384448K)] 1615624K->1612799K(1846272K), [Metaspace: 48821K->48821K(1093632K)], 7.2935447 secs] [Times: user=25.27 sys=0.19, real=7.29 secs] 
132.297: [Full GC (Ergonomics) [PSYoungGen: 231424K->228753K(461824K)] [ParOldGen: 1384059K->1384277K(1384448K)] 1615483K->1613031K(1846272K), [Metaspace: 48824K->48824K(1093632K)], 7.0277621 secs] [Times: user=22.84 sys=0.13, real=7.03 secs] 
139.329: [Full GC (Ergonomics) [PSYoungGen: 231424K->230947K(461824K)] [ParOldGen: 1384277K->1384275K(1384448K)] 1615701K->1615222K(1846272K), [Metaspace: 48824K->48824K(1093632K)], 20.7557997 secs] [Times: user=70.81 sys=0.25, real=20.76 secs] 
160.085: [Full GC (Ergonomics) [PSYoungGen: 231424K->230580K(461824K)] [ParOldGen: 1384275K->1384420K(1384448K)] 1615699K->1615001K(1846272K), [Metaspace: 48824K->48824K(1093632K)], 12.9206682 secs] [Times: user=44.17 sys=0.19, real=12.92 secs] 
173.008: [Full GC (Ergonomics) [PSYoungGen: 231424K->231367K(461824K)] [ParOldGen: 1384420K->1384071K(1384448K)] 1615844K->1615439K(1846272K), [Metaspace: 48824K->48824K(1093632K)], 8.9141901 secs] [Times: user=30.69 sys=0.16, real=8.91 secs] 
181.924: [Full GC (Ergonomics) [PSYoungGen: 231424K->230886K(461824K)] [ParOldGen: 1384071K->1384103K(1384448K)] 1615495K->1614989K(1846272K), [Metaspace: 48827K->48827K(1093632K)], 9.6083507 secs] [Times: user=31.67 sys=0.28, real=9.61 secs] 
191.533: [Full GC (Ergonomics) [PSYoungGen: 231424K->230380K(461824K)] [ParOldGen: 1384103K->1384261K(1384448K)] 1615527K->1614641K(1846272K), [Metaspace: 48827K->48827K(1093632K)], 9.5366337 secs] [Times: user=30.78 sys=0.13, real=9.54 secs]

从GClog也可以看到老年代使用的是并行收集器，并且长时间停顿了GC，而唯一一次GC还引发了full GC，若为了减少服务的等待时间，可以将老年代的GC收集器换成CMS：
增加-XX:+UseConcMarkSweepGC

老年代使用CMS

image

GC日志信息：

886.828: [CMS-concurrent-mark-start]
886.957: [CMS-concurrent-mark: 0.129/0.129 secs] [Times: user=0.34 sys=0.09, real=0.13 secs] 
886.957: [CMS-concurrent-preclean-start]
887.000: [CMS-concurrent-preclean: 0.043/0.043 secs] [Times: user=0.11 sys=0.05, real=0.04 secs] 
887.001: [CMS-concurrent-abortable-preclean-start]
887.070: [GC (Allocation Failure) 887.070: [ParNew887.148: [CMS-concurrent-abortable-preclean: 0.048/0.147 secs] [Times: user=0.50 sys=0.08, real=0.15 secs] 
: 39296K->4352K(39296K), 0.1133847 secs] 185776K->162160K(320272K), 0.1134771 secs] [Times: user=0.44 sys=0.00, real=0.11 secs] 
887.184: [GC (CMS Final Remark) [YG occupancy: 4354 K (39296 K)]887.184: [Rescan (parallel) , 0.0282956 secs]887.212: [weak refs processing, 0.0000139 secs]887.212: [class unloading, 0.0156801 secs]887.228: [scrub symbol table, 0.0090492 secs]887.237: [scrub string table, 0.0006291 secs][1 CMS-remark: 157808K(280976K)] 162162K(320272K), 0.0557370 secs] [Times: user=0.16 sys=0.00, real=0.06 secs] 
887.240: [CMS-concurrent-sweep-start]
887.424: [CMS-concurrent-sweep: 0.184/0.184 secs] [Times: user=0.45 sys=0.17, real=0.18 secs] 
887.424: [CMS-concurrent-reset-start]
887.426: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
887.441: [GC (Allocation Failure) 887.441: [ParNew: 39296K->4352K(39296K), 0.0384796 secs] 133360K->101508K(320272K), 0.0385506 secs] [Times: user=0.19 sys=0.00, real=0.04 secs] 
887.607: [GC (Allocation Failure) 887.607: [ParNew: 39296K->4352K(39296K), 0.1279949 secs] 136452K->118435K(320272K), 0.1280712 secs] [Times: user=0.45 sys=0.00, real=0.13 secs] 
887.882: [GC (Allocation Failure) 887.882: [ParNew: 39296K->4352K(39296K), 0.1877190 secs] 153379K->143069K(320272K), 0.1878078 secs] [Times: user=0.59 sys=0.00, real=0.19 secs] 
888.294: [GC (Allocation Failure) 888.294: [ParNew: 39294K->4352K(39296K), 0.1083139 secs] 178012K->156216K(320272K), 0.1083924 secs] [Times: user=0.34 sys=0.00, real=0.11 secs] 
888.539: [GC (Allocation Failure) 888.539: [ParNew: 39296K->4352K(39296K), 0.1877198 secs] 191160K->181053K(320272K), 0.1878044 secs] [Times: user=0.66 sys=0.00, real=0.19 secs] 
888.727: [GC (CMS Initial Mark) [1 CMS-initial-mark: 176701K(280976K)] 181729K(320272K), 0.0023637 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
888.729: [CMS-concurrent-mark-start]
888.843: [CMS-concurrent-mark: 0.114/0.114 secs] [Times: user=0.38 sys=0.05, real=0.11 secs] 
888.843: [CMS-concurrent-preclean-start]
888.879: [CMS-concurrent-preclean: 0.035/0.036 secs] [Times: user=0.06 sys=0.05, real=0.04 secs] 
888.879: [CMS-concurrent-abortable-preclean-start]
888.951: [GC (Allocation Failure) 888.951: [ParNew889.026: [CMS-concurrent-abortable-preclean: 0.047/0.147 secs] [Times: user=0.41 sys=0.08, real=0.15 secs] 
: 39296K->4350K(39296K), 0.0919004 secs] 215997K->190194K(320272K), 0.0919675 secs] [Times: user=0.30 sys=0.02, real=0.09 secs] 
889.044: [GC (CMS Final Remark) [YG occupancy: 4352 K (39296 K)]889.044: [Rescan (parallel) , 0.0252387 secs]889.069: [weak refs processing, 0.0000214 secs]889.069: [class unloading, 0.0163528 secs]889.085: [scrub symbol table, 0.0097985 secs]889.095: [scrub string table, 0.0006755 secs][1 CMS-remark: 185843K(280976K)] 190196K(320272K), 0.0541622 secs] [Times: user=0.11 sys=0.00, real=0.05 secs] 
889.098: [CMS-concurrent-sweep-start]
889.303: [CMS-concurrent-sweep: 0.205/0.205 secs] [Times: user=0.70 sys=0.11, real=0.21 secs] 
889.303: [CMS-concurrent-reset-start]
889.305: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
889.306: [GC (Allocation Failure) 889.306: [ParNew: 39294K->4352K(39296K), 0.0156674 secs] 125580K->90714K(320272K), 0.0157603 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
889.443: [GC (Allocation Failure) 889.443: [ParNew: 39296K->4352K(39296K), 0.1164356 secs] 125658K->105895K(320272K), 0.1165202 secs] [Times: user=0.41 sys=0.00, real=0.12 secs] 
889.678: [GC (Allocation Failure) 889.678: [ParNew: 39296K->4352K(39296K), 0.2154267 secs] 140839K->135397K(320272K), 0.2154930 secs] [Times: user=0.80 sys=0.00, real=0.22 secs] 
890.009: [GC (Allocation Failure) 890.009: [ParNew: 39296K->4352K(39296K), 0.2119881 secs] 170341K->164651K(320272K), 0.2120630 secs] [Times: user=0.81 sys=0.00, real=0.21 secs] 
890.221: [GC (CMS Initial Mark) [1 CMS-initial-mark: 160299K(280976K)] 165326K(320272K), 0.0022808 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
890.223: [CMS-concurrent-mark-start]
890.350: [CMS-concurrent-mark: 0.127/0.127 secs] [Times: user=0.39 sys=0.11, real=0.13 secs] 
890.350: [CMS-concurrent-preclean-start]
890.379: [CMS-concurrent-preclean: 0.029/0.029 secs] [Times: user=0.05 sys=0.00, real=0.03 secs] 
890.379: [CMS-concurrent-abortable-preclean-start]
890.455: [GC (Allocation Failure) 890.456: [ParNew: 39296K->4352K(39296K), 0.2525984 secs] 199595K->193392K(320272K), 0.2526758 secs] [Times: user=1.02 sys=0.00, real=0.25 secs] 
890.841: [CMS-concurrent-abortable-preclean: 0.209/0.462 secs] [Times: user=1.53 sys=0.14, real=0.46 secs] 
890.842: [GC (CMS Final Remark) [YG occupancy: 26079 K (39296 K)]890.842: [Rescan (parallel) , 0.0103580 secs]890.852: [weak refs processing, 0.0000128 secs]890.852: [class unloading, 0.0159117 secs]890.868: [scrub symbol table, 0.0099422 secs]890.878: [scrub string table, 0.0006397 secs][1 CMS-remark: 189040K(280976K)] 215120K(320272K), 0.0389487 secs] [Times: user=0.09 sys=0.00, real=0.04 secs] 
890.881: [CMS-concurrent-sweep-start]
890.946: [GC (Allocation Failure) 890.946: [ParNew: 39296K->4352K(39296K), 0.2189633 secs] 201006K->192719K(320272K), 0.2190348 secs] [Times: user=0.83 sys=0.00, real=0.22 secs] 
891.278: [CMS-concurrent-sweep: 0.178/0.397 secs] [Times: user=1.28 sys=0.13, real=0.40 secs] 
891.278: [CMS-concurrent-reset-start]
891.279: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
891.328: [GC (Allocation Failure) 891.328: [ParNew: 39296K->4351K(39296K), 0.2162281 secs] 178470K->172742K(320272K), 0.2163008 secs] [Times: user=0.84 sys=0.02, real=0.22 secs] 
891.544: [GC (CMS Initial Mark) [1 CMS-initial-mark: 168391K(280976K)] 173414K(320272K), 0.0023593 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
891.546: [CMS-concurrent-mark-start]
891.671: [CMS-concurrent-mark: 0.124/0.124 secs] [Times: user=0.39 sys=0.09, real=0.13 secs] 
891.671: [CMS-concurrent-preclean-start]
891.716: [CMS-concurrent-preclean: 0.045/0.045 secs] [Times: user=0.11 sys=0.05, real=0.05 secs] 
891.716: [CMS-concurrent-abortable-preclean-start]
891.765: [GC (Allocation Failure) 891.765: [ParNew891.863: [CMS-concurrent-abortable-preclean: 0.047/0.147 secs] [Times: user=0.49 sys=0.03, real=0.15 secs] 
: 39295K->4351K(39296K), 0.1492355 secs] 207686K->188709K(320272K), 0.1493101 secs] [Times: user=0.63 sys=0.00, real=0.15 secs] 
891.915: [GC (CMS Final Remark) [YG occupancy: 5018 K (39296 K)]891.915: [Rescan (parallel) , 0.0307885 secs]891.945: [weak refs processing, 0.0000222 secs]891.945: [class unloading, 0.0159681 secs]891.961: [scrub symbol table, 0.0083946 secs]891.970: [scrub string table, 0.0006289 secs][1 CMS-remark: 184358K(280976K)] 189377K(320272K), 0.0578733 secs] [Times: user=0.14 sys=0.00, real=0.06 secs] 
891.973: [CMS-concurrent-sweep-start]
892.166: [CMS-concurrent-sweep: 0.193/0.193 secs] [Times: user=0.55 sys=0.17, real=0.19 secs] 
892.166: [CMS-concurrent-reset-start]
892.168: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
892.197: [GC (Allocation Failure) 892.197: [ParNew: 39295K->4350K(39296K), 0.0340612 secs] 138319K->105606K(320272K), 0.0341298 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
892.342: [GC (Allocation Failure) 892.342: [ParNew: 39294K->4352K(39296K), 0.1560819 secs] 140550K->127063K(320272K), 0.1561610 secs] [Times: user=0.47 sys=0.00, real=0.16 secs] 
892.639: [GC (Allocation Failure) 892.639: [ParNew: 39296K->4352K(39296K), 0.2126361 secs] 162007K->156342K(320272K), 0.2127180 secs] [Times: user=0.63 sys=0.00, real=0.21 secs] 
892.851: [GC (CMS Initial Mark) [1 CMS-initial-mark: 151990K(280976K)] 157016K(320272K), 0.0023659 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
892.854: [CMS-concurrent-mark-start]
892.977: [CMS-concurrent-mark: 0.123/0.123 secs] [Times: user=0.39 sys=0.09, real=0.12 secs] 
892.977: [CMS-concurrent-preclean-start]
893.025: [CMS-concurrent-preclean: 0.047/0.048 secs] [Times: user=0.13 sys=0.03, real=0.05 secs] 
893.025: [CMS-concurrent-abortable-preclean-start]

可以看到老年代的GC频率非常频繁，至少没有没有像使用并行收集器一样长时间未GC

关于老年代使用CMS的其它问题，参考官网

  1. 碎片太多：由于CMS标记清除的特性，使用该收集器的部分更容易出现这种情况，导致Full GC。 由于CMS的FullGG不可避免只能在FullGC的时候对CMS进行处理： -XX:+UseCMSCompactAtFullCollection：允许在 Full GC 时，启用压缩式 GC -XX:CMSFullGCBeforeCompaction=n ： 在进行 n 次，CMS 后，进行一次压缩的 Full GC，用以减少 CMS 产生的碎片

  2. GC时有其他内存交互，这个的解决办法就是这个程序所在的服务器尽量不要搞其他的磁盘IO，就专门供该程序运行好了。。。

你看那个人好像一条狗啊

Read Next

Hadoop quick start