In this post, I want to show some interesting features that Spring Boot offers for performance monitoring.
Once the application starts to scale, performance becomes the topmost priority. We over-optimize the application to lose simplicity. That’s how software development works. In a production scenario, we monitor our application for performance. With most applications moving to the cloud, it is essential to monitor the application and improve the performance constantly.
If you have used a spring actuator, it provides a number of statistics to monitor. Previously, I covered this topic Spring-Actuator.
Subsequently, we will be covering some different features of Spring Boot. We will be talking about CustomizableTraceInterceptor, PerformanceMonitorInterceptor, and CommonsRequestLoggingFilter.
Using CustomizableTraceInterceptor
You can add CustomizableTraceInterceptor as a Bean and use that Bean as an advisor for what expressions you want to intercept. Basically, this interceptor allows us to intercept the method calls and add custom log messages.
To show this in the working example, we will be tracking repository timings. Firstly, create a class that will extend CustomizableTraceInterceptor as follows:
package com.abccompany.home.performance;
import org.aopalliance.intercept.MethodInvocation;
import org.apache.commons.logging.Log;
import org.springframework.aop.framework.AopProxyUtils;
import org.springframework.aop.interceptor.CustomizableTraceInterceptor;
import org.springframework.data.jpa.repository.support.SimpleJpaRepository;
public class RepositoryMethodInterceptor extends CustomizableTraceInterceptor
{
@Override
protected Class<?> getClassForLogging(Object target)
{
Class<?> classForLogging = super.getClassForLogging(target);
if (SimpleJpaRepository.class.equals(classForLogging))
{
Class<?>[] interfaces = AopProxyUtils.proxiedUserInterfaces(target);
if (interfaces.length > 0)
{
return interfaces[0];
}
}
return classForLogging;
}
protected void writeToLog(Log logger, String message, Throwable ex)
{
if (ex != null)
{
logger.info(message, ex);
}
else
{
logger.info(message);
}
}
protected boolean isInterceptorEnabled(MethodInvocation invocation, Log logger)
{
return true;
}
}
Likewise, I will explain in a bit what this class is doing. We need a @Bean that will use this interceptor to intercept repository methods. The code for this will look like below:
package com.abccompany.home.performance;
import org.springframework.aop.Advisor;
import org.springframework.aop.aspectj.AspectJExpressionPointcut;
import org.springframework.aop.support.DefaultPointcutAdvisor;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.EnableAspectJAutoProxy;
@Configuration
@EnableAspectJAutoProxy(proxyTargetClass = true)
public class TraceLoggerConfig
{
@Bean
public RepositoryMethodInterceptor repositoryMethodInterceptor()
{
RepositoryMethodInterceptor repositoryMethodInterceptor = new RepositoryMethodInterceptor();
repositoryMethodInterceptor.setHideProxyClassNames(true);
repositoryMethodInterceptor.setUseDynamicLogger(false);
repositoryMethodInterceptor.setExitMessage("Executed $[methodName] in $[invocationTime] " +
"ms");
return repositoryMethodInterceptor;
}
@Bean
public Advisor advisor()
{
AspectJExpressionPointcut aspectJExpressionPointcut = new AspectJExpressionPointcut();
aspectJExpressionPointcut.setExpression("execution(public * com.abccompany.home" +
".repositories.*Repository+.*(..))");
return new DefaultPointcutAdvisor(aspectJExpressionPointcut, repositoryMethodInterceptor());
}
}
Now if we look at this configuration, this is creating a bean for using RepositoryMethodInterceptor which is a subclass of CustomizableTraceInterceptor. You can see we have used an exit message to log the timing that the repository method took in this bean.
repositoryMethodInterceptor.setExitMessage("Executed $[methodName] in $[invocationTime] " + "ms");
AspectJExpression creates an expression for which the packages interception should happen. The class RepositoryMethodInterceptor does a few useful things. Firstly, it helps us to track the class information of Repository classes. Secondly, it logs the message in our log file. Once you run the application, you will see the log messages as below:
2020-05-24 19:08:04.870 INFO 14724 --- [nio-8443-exec-9] c.r.h.p.RepositoryMethodInterceptor : Entering method 'findUserByEmail' of class [com.abccompany.home.repositories.UserdataRepository] Hibernate: select userdata0_.id as id1_4_, userdata0_.email as email2_4_, userdata0_.firstname as firstnam3_4_, userdata0_.guid as guid4_4_, userdata0_.lastname as lastname5_4_, userdata0_.middlename as middlena6_4_, userdata0_.confirmpassword as confirmp7_4_, userdata0_.passwordtxt as password8_4_, userdata0_.phonenumber as phonenum9_4_, userdata0_.role as role10_4_ from userdata userdata0_ where userdata0_.email=?
2020-05-24 19:08:04.872 INFO 14724 --- [nio-8443-exec-9] c.r.h.p.RepositoryMethodInterceptor : Executed findUserByEmail in 2 ms
2020-05-24 19:08:04.872 INFO 14724 --- [nio-8443-exec-9] c.r.h.p.RepositoryMethodInterceptor : Entering method 'findAll' of class [com.abccompany.home.repositories.FeedbackRepository] Hibernate: select feedback0_.id as id1_1_, feedback0_.createdon as createdo2_1_, feedback0_.fromdate as fromdate3_1_, feedback0_.guid as guid4_1_, feedback0_.rating as rating5_1_, feedback0_.rentalpropertyid as rentalpr8_1_, feedback0_.review as review6_1_, feedback0_.todate as todate7_1_, feedback0_.userid as userid9_1_ from feedback feedback0_
2020-05-24 19:08:04.876 INFO 14724 --- [nio-8443-exec-9] c.r.h.p.RepositoryMethodInterceptor : Executed findAll in 4 ms
Using PerformanceMonitorInterceptor feature
So, in order to use PerformanceMonitorInterceptor , we will create a configuration class and add a bean that will create PerformanceMonitorInterceptor. AspectJExpressionPointcut will point to the expression that will evaluate our controller classes.
Like CustomizableTraceInterceptor, we will have a subclass that will extend PerformanceMonitoringInterceptor so we can log our messages in Spring Boot logging. This will look like below:
package com.abccompany.home.performance;
import org.aopalliance.intercept.MethodInvocation;
import org.apache.commons.logging.Log;
import org.springframework.aop.interceptor.PerformanceMonitorInterceptor;
public class ControllerMonitoringInterceptor extends PerformanceMonitorInterceptor
{
protected void writeToLog(Log logger, String message, Throwable ex)
{
if (ex != null)
{
logger.info(message, ex);
}
else
{
logger.info(message);
}
}
protected boolean isInterceptorEnabled(MethodInvocation invocation, Log logger)
{
return true;
}
}
We will create a bean for ControllerMonitoringInterceptor . This bean will be part of our logger configuration which will also evaluate AspectJExpression for Controller classes. Therefore, it will look like below:
package com.abccompany.home.performance;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.aop.Advisor;
import org.springframework.aop.aspectj.AspectJExpressionPointcut;
import org.springframework.aop.interceptor.PerformanceMonitorInterceptor;
import org.springframework.aop.support.DefaultPointcutAdvisor;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.EnableAspectJAutoProxy;
@Configuration
@EnableAspectJAutoProxy
@Aspect
public class ControllerLoggerConfig
{
@Pointcut("execution(* com.abccompany.home.controllers.*Controller+.*(..))")
public void monitor()
{
}
@Bean
public ControllerMonitoringInterceptor controllerMonitoringInterceptor()
{
return new ControllerMonitoringInterceptor();
}
@Bean
public Advisor advisorPerformance()
{
AspectJExpressionPointcut aspectJExpressionPointcut = new AspectJExpressionPointcut();
aspectJExpressionPointcut.setExpression("com.abccompany.home.performance" +
".ControllerLoggerConfig.monitor()");
return new DefaultPointcutAdvisor(aspectJExpressionPointcut,
controllerMonitoringInterceptor());
}
}
Now if we execute the application, the log messages will show latencies for Controller classes.
2020-05-24 20:12:09.237 INFO 9280 --- [nio-8443-exec-6] c.r.h.p.ControllerMonitoringInterceptor : StopWatch 'com.abccompany.home.controllers.LoginController.signin': running time (millis) = 0
2020-05-24 20:12:18.263 INFO 9280 --- [nio-8443-exec-2] c.r.h.p.ControllerMonitoringInterceptor : StopWatch 'com.abccompany.home.controllers.MainController.home': running time (millis) = 43
2020-05-24 20:12:20.025 INFO 9280 --- [nio-8443-exec-9] c.r.h.p.ControllerMonitoringInterceptor : StopWatch 'com.abccompany.home.controllers.MainController.logout': running time (millis) = 12
2020-05-24 20:12:20.042 INFO 9280 --- [nio-8443-exec-5] c.r.h.p.ControllerMonitoringInterceptor : StopWatch 'com.abccompany.home.controllers.LoginController.login': running time (millis) = 0
How to use CommonsRequestLoggingFilter
Additionally, Spring Boot offers one useful feature of logging incoming requests. This helps in monitoring the application and to see how the requests are coming. To use this feature, we will create a @Configuration class RequestLoggingFilter as below:
package com.abccompany.home.performance;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.filter.AbstractRequestLoggingFilter;
import org.springframework.web.filter.CommonsRequestLoggingFilter;
import javax.servlet.http.HttpServletRequest;
@Configuration
public class RequestLoggingFilter extends AbstractRequestLoggingFilter
{
@Bean
public CommonsRequestLoggingFilter requestLoggingFilterConfig()
{
CommonsRequestLoggingFilter commonsRequestLoggingFilter = new CommonsRequestLoggingFilter();
commonsRequestLoggingFilter.setIncludeClientInfo(true);
commonsRequestLoggingFilter.setIncludeQueryString(true);
commonsRequestLoggingFilter.setIncludePayload(true);
return commonsRequestLoggingFilter;
}
@Override
protected void beforeRequest (HttpServletRequest request, String message)
{
logger.info(message);
}
@Override
protected void afterRequest (HttpServletRequest request, String message)
{
logger.info(message);
}
}
Once, we add this, we will see beforeRequest and afterRequest messages in the log as below:
2020-05-24 21:07:15.161 INFO 11984 --- [nio-8443-exec-1] gFilter$$EnhancerBySpringCGLIB$$cb4fdaab : Before request [uri=/css/bootstrap.min.css]
2020-05-24 21:07:15.171 INFO 11984 --- [nio-8443-exec-2] gFilter$$EnhancerBySpringCGLIB$$cb4fdaab : Before request [uri=/js/jquery.min.js]
2020-05-24 21:07:15.203 INFO 11984 --- [nio-8443-exec-7] gFilter$$EnhancerBySpringCGLIB$$cb4fdaab : Before request [uri=/js/bootstrap.min.js]
2020-05-24 21:07:15.290 INFO 11984 --- [nio-8443-exec-7] gFilter$$EnhancerBySpringCGLIB$$cb4fdaab : After request [uri=/js/bootstrap.min.js]
2020-05-24 21:07:15.306 INFO 11984 --- [nio-8443-exec-2] gFilter$$EnhancerBySpringCGLIB$$cb4fdaab : After request [uri=/js/jquery.min.js]
2020-05-24 21:07:15.318 INFO 11984 --- [nio-8443-exec-1] gFilter$$EnhancerBySpringCGLIB$$cb4fdaab : After request [uri=/css/bootstrap.min.css]
Conclusion
In conclusion, I showed three features for performance monitoring – CustomizableTraceInterceptor, PerformanceMonitorInterceptor, and CommonsRequestLoggingFilter to log useful performance metrics.
References