Spring Performance Logging – Spring的性能日志

最后修改: 2017年 1月 8日


1. Overview


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


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.


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


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:


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

    public Advisor performanceMonitorAdvisor() {
        AspectJExpressionPointcut pointcut = new AspectJExpressionPointcut();
        return new DefaultPointcutAdvisor(pointcut, performanceMonitorInterceptor());
    public Person person(){
        return new Person("John","Smith", LocalDate.of(1980, Month.JANUARY, 12));
    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.


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.


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


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:


2017-01-08 19:19:25 TRACE 
  PersonService:66 - StopWatch 
  running time (millis) = 10

3. Custom Performance Monitoring Interceptor


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) {

    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:


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

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


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

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


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


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


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