Spring性能日志记录

1. 概述

在这个教程中，我们将探讨Spring框架提供的几个基本性能监控选项。

2. 性能监控拦截器

为了获取方法执行时间的基本监控功能，我们可以利用Spring AOP（面向切面编程）中的PerformanceMonitorInterceptor类。

Spring AOP允许我们在应用程序中定义跨切面关注点，即拦截一个或多个方法的执行，以添加额外的功能。

PerformanceMonitorInterceptor类是一个可以与任何自定义方法关联的拦截器，它会在同一时间执行。这个类使用StopWatch实例来确定方法运行的开始和结束时间。

让我们创建一个简单的Person类和一个PersonService类，其中我们将监控的方法：

public class Person {
    private String lastName;
    private String firstName;
    private LocalDate dateOfBirth;

    // standard constructors, getters, setters
}

public class PersonService {
    
    public String getFullName(Person person){
        return person.getLastName()+" "+person.getFirstName();
    }
    
    public int getAge(Person person){
        Period p = Period.between(person.getDateOfBirth(), LocalDate.now());
        return p.getYears();
    }
}

为了使用Spring监控拦截器，我们需要定义一个切点和顾问：

@Configuration
@EnableAspectJAutoProxy
@Aspect
public class AopConfiguration {
    
    @Pointcut(
      "execution(public String com.baeldung.performancemonitor.PersonService.getFullName(..))"
    )
    public void monitor() { }
    
    @Bean
    public PerformanceMonitorInterceptor performanceMonitorInterceptor() {
        return new PerformanceMonitorInterceptor(true);
    }

    @Bean
    public Advisor performanceMonitorAdvisor() {
        AspectJExpressionPointcut pointcut = new AspectJExpressionPointcut();
        pointcut.setExpression("com.baeldung.performancemonitor.AopConfiguration.monitor()");
        return new DefaultPointcutAdvisor(pointcut, performanceMonitorInterceptor());
    }
    
    @Bean
    public Person person(){
        return new Person("John","Smith", LocalDate.of(1980, Month.JANUARY, 12));
    }
 
    @Bean
    public PersonService personService(){
        return new PersonService();
    }
}

切点包含一个表达式，用于标识我们想要被拦截的方法——在我们的例子中，是PersonService类的getFullName()方法。

配置了performanceMonitorInterceptor() bean后，我们需要将拦截器与切点关联。这通过顾问实现，如上例所示。

最后，@EnableAspectJAutoProxy注解启用了对AspectJ的支持。简单来说，AspectJ是一个库，旨在通过像@Pointcut这样的便利注解使Spring AOP的使用更加方便。

创建配置后，我们需要将拦截器类的日志级别设置为TRACE，因为这是它记录消息的级别。

例如，使用Jog4j，我们可以通过log4j.properties文件实现这一点：

log4j.logger.org.springframework.aop.interceptor.PerformanceMonitorInterceptor=TRACE, stdout

对于getAge()方法的每次执行，我们将在控制台日志中看到TRACE消息：

2017-01-08 19:19:25 TRACE 
  PersonService:66 - StopWatch 
  'com.baeldung.performancemonitor.PersonService.getFullName': 
  running time (millis) = 10

3. 定制性能监控拦截器

如果我们想要对性能监控方式有更多控制，我们可以实现自己的自定义拦截器。

为此，我们将扩展AbstractMonitoringInterceptor类，并重写invokeUnderTrace()方法，以记录方法的开始、结束和持续时间，以及如果方法执行超过10ms则发出警告：

public class MyPerformanceMonitorInterceptor extends AbstractMonitoringInterceptor {
    
    public MyPerformanceMonitorInterceptor() {
    }

    public MyPerformanceMonitorInterceptor(boolean useDynamicLogger) {
            setUseDynamicLogger(useDynamicLogger);
    }

    @Override
    protected Object invokeUnderTrace(MethodInvocation invocation, Log log) 
      throws Throwable {
        String name = createInvocationTraceName(invocation);
        long start = System.currentTimeMillis();
        log.info("Method " + name + " execution started at:" + new Date());
        try {
            return invocation.proceed();
        }
        finally {
            long end = System.currentTimeMillis();
            long time = end - start;
            log.info("Method "+name+" execution lasted:"+time+" ms");
            log.info("Method "+name+" execution ended at:"+new Date());
            
            if (time > 10){
                log.warn("Method execution longer than 10 ms!");
            }            
        }
    }
}

与前一节中将自定义拦截器与一个或多个方法关联的步骤相同，我们需要遵循这些步骤。

让我们为PersonService的getAge()方法定义一个切点，并将其与我们创建的拦截器关联起来：

@Pointcut("execution(public int com.baeldung.performancemonitor.PersonService.getAge(..))")
public void myMonitor() { }
    
@Bean
public MyPerformanceMonitorInterceptor myPerformanceMonitorInterceptor() {
    return new MyPerformanceMonitorInterceptor(true);
}
    
@Bean
public Advisor myPerformanceMonitorAdvisor() {
    AspectJExpressionPointcut pointcut = new AspectJExpressionPointcut();
    pointcut.setExpression("com.baeldung.performancemonitor.AopConfiguration.myMonitor()");
    return new DefaultPointcutAdvisor(pointcut, myPerformanceMonitorInterceptor());
}

将自定义拦截器的日志级别设置为INFO：

log4j.logger.com.baeldung.performancemonitor.MyPerformanceMonitorInterceptor=INFO, stdout

执行getAge()方法时，输出如下：

2017-01-08 19:19:25 INFO PersonService:26 - 
  Method com.baeldung.performancemonitor.PersonService.getAge 
  execution started at:Sun Jan 08 19:19:25 EET 2017
2017-01-08 19:19:25 INFO PersonService:33 - 
  Method com.baeldung.performancemonitor.PersonService.getAge execution lasted:50 ms
2017-01-08 19:19:25 INFO PersonService:34 - 
  Method com.baeldung.performancemonitor.PersonService.getAge 
  execution ended at:Sun Jan 08 19:19:25 EET 2017
2017-01-08 19:19:25 WARN PersonService:37 - 
  Method execution longer than 10 ms!

4. 总结

在这篇快速教程中，我们介绍了Spring中的简单性能监控。

如往常一样，本文的完整源代码可以在GitHub上找到。