Spring Performance Logging – Spring的性能日志

最后修改: 2017年 1月 8日

中文/混合/英文(键盘快捷键:t)

1. Overview

1.概述

In this tutorial, we’ll look into a couple of basic options the Spring Framework offers for performance monitoring.

在本教程中,我们将研究Spring框架为性能监控提供的几个基本选项。

2. PerformanceMonitorInterceptor

2.PerformanceMonitorInterceptor

A simple solution to get basic monitoring functionality for the execution time of our methods, we can make use of the PerformanceMonitorInterceptor class out of Spring AOP (Aspect Oriented Programming).

为了获得方法执行时间的基本监控功能,我们可以利用Spring AOP(面向方面的编程)中的PerformanceMonitorInterceptor类。

Spring AOP allows the defining of cross-cutting concerns in applications, meaning code that intercepts the execution of one or more methods, in order to add extra functionality.

Spring AOP允许在应用程序中定义跨领域的关注点,这意味着拦截一个或多个方法的执行的代码,以增加额外的功能。

The PerformanceMonitorInterceptor class is an interceptor that can be associated with any custom method to be executed at the same time. This class uses a StopWatch instance to determine the beginning and ending time of the method run.

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

Let’s create a simple Person class and a PersonService class with two methods that we will monitor:

让我们创建一个简单的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();
    }
}

In order to make use of the Spring monitoring interceptor, we need to define a pointcut and advisor:

为了利用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();
    }
}

The pointcut contains an expression that identifies the methods that we want to be intercepted — in our case the getFullName() method of the PersonService class.

该切点包含一个表达式,该表达式确定了我们希望被拦截的方法–在我们的例子中,是PersonService类的getFullName()方法。

After configuring the performanceMonitorInterceptor() bean, we need to associate the interceptor with the pointcut. This is achieved through an advisor, as shown in the example above.

在配置了performanceMonitorInterceptor() bean之后,我们需要将拦截器与指向性关联起来。这可以通过顾问来实现,如上面的例子所示。

Finally, the @EnableAspectJAutoProxy annotation enables AspectJ support for our beans. Simply put, AspectJ is a library created to make the use of Spring AOP easier through convenient annotations like @Pointcut.

最后,@EnableAspectJAutoProxy注解使AspectJ支持我们的bean。简单地说,AspectJ是一个库,它通过像@Pointcut这样方便的注解使Spring AOP的使用更加容易。

After creating the configuration, we need to set the log level of the interceptor class to TRACE, as this is the level at which it logs messages.

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

For example, using Jog4j, we can achieve this through the log4j.properties file:

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

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

For every execution of the getAge() method, we will see the TRACE message in the console log:

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

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

3. Custom Performance Monitoring Interceptor

3.自定义性能监测拦截器

If we want more control over the way the performance monitoring is done, we can implement our own custom interceptor.

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

For this, let’s extend the AbstractMonitoringInterceptor class and override the invokeUnderTrace() method to log the start, end, and duration of a method, as well as a warning if the method execution lasts more than 10 ms:

为此,让我们扩展AbstractMonitoringInterceptor类,并覆盖 invokeUnderTrace()方法,以记录一个方法的开始、结束和持续时间,以及在方法执行超过10毫秒时发出警告。

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!");
            }            
        }
    }
}

The same steps for associating the custom interceptor to one or more methods as in the preceding section need to be followed.

将自定义拦截器与一个或多个方法相关联的步骤与上一节相同,需要遵循。

Let’s define a pointcut for the getAge() method of PersonService and associate it to the interceptor we have created:

让我们为PersonServicegetAge()方法定义一个点切,并将其与我们创建的拦截器相关联。

@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());
}

Let’s sets the log level to INFO for the custom interceptor:

让我们为自定义拦截器设置日志级别为INFO

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

The execution of the getAge() method produced the following output:

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. Conclusion

4.结论

In this quick tutorial, we’ve introduced simple performance monitoring in Spring.

在这个快速教程中,我们已经介绍了Spring中简单的性能监控。

As always, the full source code for this article can be found over on Github.

一如既往,本文的完整源代码可以在Github上找到over