AOP日志记录引发性能开销，求高效执行时间日志实现方案

问题背景 #

我计划为REST API的所有方法记录执行时间，采用Spring AOP实现，代码如下：

AOP切面类 #

@Aspect
@Component
@Slf4j
@ConditionalOnExpression("${aspect.enabled:true}")
public class ExecutionTimeAdvice {
  @Around("@annotation(TrackExecutionTime)")
  public Object executionTime(ProceedingJoinPoint point) throws Throwable {
    long startTime = System.currentTimeMillis();
    Object object = point.proceed();
    long endtime = System.currentTimeMillis();
    log.info("Class Name: " + point.getSignature().getDeclaringTypeName() + ". Method Name: " + point.getSignature().getName() + ". Time taken for Execution is : " + (endtime - startTime) + "ms");
    return object;
  }
}

业务服务类 #

@Service
public class MessageService {
  @TrackExecutionTime
  @Override
  public List<AlbumEntity> getMessage() {
    return "Hello message"; // 注：此处存在类型不匹配问题，List<AlbumEntity>与String返回值冲突
  }
}

自定义注解 #

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface TrackExecutionTime {}

依赖配置 #

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

实际使用中发现AOP带来的性能开销过大，服务响应延迟超200ms，现针对以下问题给出解决方案：

解决方案 #

一、更高效使用现有Spring AOP的优化点 #

1. 优化日志输出方式：用SLF4J参数化日志替代字符串拼接，减少临时字符串对象创建：

   log.info("Class Name: {}. Method Name: {}. Time taken for Execution is : {}ms",
            point.getSignature().getDeclaringTypeName(),
            point.getSignature().getName(),
            (endtime - startTime));
   

2. 降低日志级别并按需开启：生产环境将日志级别设为debug或trace，通过配置开关关闭非必要日志，减少IO开销。
3. 缩小切面织入范围：仅针对@RestController下的API方法织入，而非所有标注TrackExecutionTime的方法，减少代理次数。
4. 使用更高效的时间工具：用System.nanoTime()替代System.currentTimeMillis()，精度更高且开销更低，最后转换为毫秒：

   long startTime = System.nanoTime();
   Object object = point.proceed();
   long duration = (System.nanoTime() - startTime) / 1_000_000; // 转换为毫秒
   

5. 缓存签名信息：避免重复调用point.getSignature()，减少反射开销：

   Signature signature = point.getSignature();
   log.info("Class Name: {}. Method Name: {}. Time taken for Execution is : {}ms",
            signature.getDeclaringTypeName(),
            signature.getName(),
            duration);
   

二、使用AspectJ提升效率 #

Spring AOP基于动态代理（运行时织入），而AspectJ支持编译时织入（CTW）和加载时织入（LTW），性能远高于Spring AOP：

• 编译时织入会在编译阶段直接将切面代码写入目标类字节码，运行时无代理开销，适合生产环境。
• 配置方式：
  1. 引入AspectJ依赖：

     <dependency>
       <groupId>org.aspectj</groupId>
       <artifactId>aspectjrt</artifactId>
     </dependency>
     <dependency>
       <groupId>org.aspectj</groupId>
       <artifactId>aspectjweaver</artifactId>
     </dependency>
     

  2. 启用AspectJ自动代理：在配置类添加@EnableAspectJAutoProxy(proxyTargetClass = true)，或通过Maven插件实现编译时织入。
• 注意：AspectJ语法与Spring AOP基本兼容，性能开销可降低90%以上，适合对性能敏感的场景。

三、AOP的替代方案 #

1. 手动埋点（轻量但侵入性强）：在核心方法首尾手动记录时间，适合少量关键API：

   public List<AlbumEntity> getMessage() {
     long startTime = System.nanoTime();
     try {
       // 业务逻辑
       return albumRepository.findAll();
     } finally {
       long duration = (System.nanoTime() - startTime) / 1_000_000;
       log.info("Method getMessage executed in {}ms", duration);
     }
   }
   

2. Spring MVC拦截器：针对REST API，通过HandlerInterceptor拦截所有请求，记录从请求进入到响应返回的时间，无需逐个方法加注解：

   @Component
   public class ExecutionTimeInterceptor implements HandlerInterceptor {
     @Override
     public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
       request.setAttribute("startTime", System.nanoTime());
       return true;
     }
   
     @Override
     public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
       long startTime = (long) request.getAttribute("startTime");
       long duration = (System.nanoTime() - startTime) / 1_000_000;
       HandlerMethod handlerMethod = (HandlerMethod) handler;
       log.info("Controller: {}, Method: {}, Execution Time: {}ms",
                handlerMethod.getBeanType().getName(),
                handlerMethod.getMethod().getName(),
                duration);
     }
   }
   

   注册拦截器：

   @Configuration
   public class WebConfig implements WebMvcConfigurer {
     @Autowired
     private ExecutionTimeInterceptor executionTimeInterceptor;
   
     @Override
     public void addInterceptors(InterceptorRegistry registry) {
       registry.addInterceptor(executionTimeInterceptor).addPathPatterns("/**");
     }
   }
   

3. 监控工具替代日志：用Micrometer记录方法执行时间指标，通过Prometheus等工具收集分析，性能开销极小：

   @Service
   public class MessageService {
     private final Timer timer;
   
     public MessageService(MeterRegistry meterRegistry) {
       this.timer = Timer.builder("message.service.get.execution.time")
                         .register(meterRegistry);
     }
   
     public List<AlbumEntity> getMessage() {
       return timer.record(() -> albumRepository.findAll());
     }
   }
   

4. 字节码增强工具：使用ByteBuddy、Javassist等工具在类加载时动态修改字节码添加时间记录，性能接近AspectJ编译时织入，但实现复杂度较高。

四、其他高效优化要点 #

• 异步日志：用Logback异步Appender避免日志IO阻塞业务线程：

  <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="CONSOLE"/>
    <queueSize>1024</queueSize>
    <discardingThreshold>0</discardingThreshold>
  </appender>
  

• 采样日志：生产环境按比例采样（如1%请求）记录执行时间，平衡监控需求与性能开销：

  if (ThreadLocalRandom.current().nextDouble() < 0.01) { // 1%采样率
    log.info("...");
  }
  

内容的提问来源于stack exchange，提问作者dev333