spring boot程序频繁 GC (Allocation Failure)

Question

问题描述

项目中想将日志打印统一格式，所以针对controller层或者service层统一记录入参和出参，以及耗时时间。
使用的技术是spring boot aop拦截器，拦截切面针对自定义注解，注解有自身的description描述，用户打印日志时记录，打印入参和出参使用Google Gson来将对象转化为json串。
**问题：**
代码上线后系统频繁GC，分析GC日志发现都是年轻代minorGC, 分配新对象时年轻代空间不足触发了GC，需要找到具体哪个操作导致频繁GC？

问题出现的环境背景及自己尝试过哪些方法

• jdk 1.8
• spring boot 项目直接启动
• 配置的JVM参数如下：

-XX:MetaspaceSize=128m
-XX:MaxMetaspaceSize=128m
-Xms1024m
-Xmx1024m
-Xmn256m
-Xss256k
-XX:SurvivorRatio=8
-XX:+UseConcMarkSweepGC
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintHeapAtGC
-Xloggc:/Users/wjn/Downloads/gc.log
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=./java.hprof

尝试的方法：
Gson使用如下方式创建实例对象，效果没任何变化。

Gson gson = (new GsonBuilder()).enableComplexMapKeySerialization().create();

相关代码 粘贴代码文本（请勿用截图）

自定义注解：

package com.core.weed.config;

import java.lang.annotation.Documented;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
@Documented
public @interface LoggableInfoTest {
    boolean loggable() default true;

    String description() default "";
}

AOP切面

package com.core.weed.config.resolver;


import com.core.sdk.whale.config.log.LoggableInfo;
import com.google.gson.Gson;
import com.google.gson.GsonBuilder;
import java.lang.reflect.Method;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;

@Order(-2147483548)
@Aspect
@Component
public class LoggableTestResolver {
    private static final Logger log = LoggerFactory.getLogger(com.core.sdk.whale.config.log.resolver.LoggableResolver.class);
    private static final Gson gson = (new GsonBuilder()).enableComplexMapKeySerialization().create();

    public LoggableTestResolver() {
    }

    @Pointcut("@annotation(com.core.weed.config.LoggableInfoTest)")
    private void doLoggablePct() {
    }

    @Around("doLoggablePct()")
    private Object doLoggable(ProceedingJoinPoint jp) throws Throwable {
        long bt = System.currentTimeMillis();
        Object result = null;

        try {
            Method method = ((MethodSignature)jp.getSignature()).getMethod();
            LoggableInfo loggableInfo = (LoggableInfo)method.getAnnotation(LoggableInfo.class);
            if (loggableInfo == null) {
                log.warn("checkApiAkSkToken(), api ak sk validator, annotation is null.");
                return jp.proceed();
            } else if (!loggableInfo.loggable()) {
                return jp.proceed();
            } else {
                this.handleRequestLog(jp, loggableInfo);
                result = jp.proceed();
                this.handleResponseLog(jp, loggableInfo, result, bt);
                return result;
            }
        } catch (Exception var7) {
            log.error("doLoggable(), exception, e", var7);
            throw var7;
        }
    }

    private void handleRequestLog(ProceedingJoinPoint joinPoint, LoggableInfo loggableInfo) {
        try {
            String className = joinPoint.getTarget().getClass().getName();
            String methodName = joinPoint.getSignature().getName();
            log.info("【{}】方法入参成功!, 类:【{}】, 方法:【{}】, 请求参数:【{}】", loggableInfo.description(), className, methodName, gson.toJson(joinPoint.getArgs()));
        } catch (Exception var5) {
            log.error("handleRequestLog(), e", var5);
        }
    }

    private void handleResponseLog(ProceedingJoinPoint joinPoint, LoggableInfo loggableInfo, Object response, long bt) {
        try {
            String className = joinPoint.getTarget().getClass().getName();
            String methodName = joinPoint.getSignature().getName();
            log.info("【{}】方法处理成功!, 类:【{}】, 方法:【{}】, 返回数据:【{}】, 耗时【{}】毫秒", loggableInfo.description(), className, methodName, gson.toJson(response), System.currentTimeMillis() - bt);
        } catch (Exception var8) {
            log.error("handleRequestLog(), e", var8);
        }
    }
}

你期待的结果是什么？实际看到的错误信息又是什么？

GC 日志：

Heap after GC invocations=10 (full 0):
 par new generation   total 235968K, used 12235K [0x00000007b8800000, 0x00000007c8800000, 0x00000007c8800000)
  eden space 209792K,   0% used [0x00000007b8800000, 0x00000007b8800000, 0x00000007c54e0000)
  from space 26176K,  46% used [0x00000007c54e0000, 0x00000007c60d2c40, 0x00000007c6e70000)
  to   space 26176K,   0% used [0x00000007c6e70000, 0x00000007c6e70000, 0x00000007c8800000)
 concurrent mark-sweep generation total 786432K, used 49450K [0x00000007c8800000, 0x00000007f8800000, 0x00000007f8800000)
 Metaspace       used 53026K, capacity 55608K, committed 55808K, reserved 1097728K
  class space    used 6904K, capacity 7347K, committed 7424K, reserved 1048576K
}
{Heap before GC invocations=10 (full 0):
 par new generation   total 235968K, used 222027K [0x00000007b8800000, 0x00000007c8800000, 0x00000007c8800000)
  eden space 209792K, 100% used [0x00000007b8800000, 0x00000007c54e0000, 0x00000007c54e0000)
  from space 26176K,  46% used [0x00000007c54e0000, 0x00000007c60d2c40, 0x00000007c6e70000)
  to   space 26176K,   0% used [0x00000007c6e70000, 0x00000007c6e70000, 0x00000007c8800000)
 concurrent mark-sweep generation total 786432K, used 49450K [0x00000007c8800000, 0x00000007f8800000, 0x00000007f8800000)
 Metaspace       used 53026K, capacity 55608K, committed 55808K, reserved 1097728K
  class space    used 6904K, capacity 7347K, committed 7424K, reserved 1048576K
99.805: [GC (Allocation Failure) 99.805: [ParNew: 222027K->9146K(235968K), 0.0068090 secs] 271477K->58597K(1022400K), 0.0069031 secs] [Times: user=0.04 sys=0.00, real=0.00 secs]

使用VisualVM

平均22秒进行一次GC

Answer 1

只是gc次数多，但能正常回收释放内存的话，基本排除内存泄露，看你年轻代只有256M，也确实小了点，配大点看看