Monthly Archives: May 2020

Performance Monitoring with Spring Boot

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.

Features for Performance Monitoring

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

  1. Spring Framework Features
  2. CommonsRequestLoggingFilter

 

Error with Spring Context Lookup Failed

In this post, I will show how to resolve the error Spring context lookup failed. This scenario resembles if you are using Spring Boot 2.x or Spring Boot 1.5. I was recently using Spring Boot 2.x and ran into an error like below:

org.glassfish.jersey.server.spring.SpringComponentProvider: Spring context lookup failed, 
skipping spring component provider initialization.

 

Why did I see this error?

Before I can explain why I saw this error. Let’s sort of some basic concepts about what  ContextLoaderListner is and what DispatcherServlet is.

Spring boot creates multiple contexts. It will start with a root context and the rest of the contexts will be child contexts. Child contexts can access the beans defined in the root context, but not vice versa.

ContextLoaderListener

When you start the Spring Boot application, ContextLoaderListener creates the root application context. Spring boot will share this root context with all other child contexts that DispatcherServlet will create. Usually, you define ContextLoaderListener in web.xml like below:


<listener>
  <listener-class>
    org.springframework.web.context.ContextLoaderListener
  </listener-class>
</listener>
  
<context-param>
  <param-name>contextConfigLocation</param-name>
  <param-value>/WEB-INF/spring/applicationContext.xml</param-value>
</context-param>

ServletContext stores this root application context and one can use WebApplicationContextUtils to retrieve this context.

DispatcherServlet

DispatcherServlet is a HttpServlet whose primary purpose is to handle incoming web requests matching the configured URL pattern. When you define DispatcherServlet in Spring configuration, Spring will use a configured configuration file or creates its own configuration file based on controllers and views in the code.

DispatcherServlet creates one child application context per servlet entry.

Why Spring Context Lookup Failed:

Spring Boot 2.x offers a programmatic way to configure your contexts and servlets. In my particular case, I was using this programmatic way. But I had configured anyway to load application context, especially root application context.

To configure this root application context, I needed ContextLoaderListener . Since I didn’t want to use web.xml , I looked for a programmatic way. Spring boot 2.x offers this through SpringBootServletInitializer . Basically, when we extend the root application class with SpringBootServletInitializer, it binds Servlet, Filter, and ServletInitializer beans from the application context to the server. This also allows us to create a WAR archive of our application and run in any web container.

Once I added SpringBootServletInitializer in my main Spring Boot Application class, I was able to resolve this error. The code for that will look like below:


@SpringBootApplication
public class Application extends SpringBootServletInitializer 
{    
    public static void main(String[] args) 
    {
        SpringApplication sa = new SpringApplication(Application.class);
        sa.run(args);
    }
}

 

Conclusion

In this post, we showed how we can resolve an error Spring Context Lookup Failed. If you have any feedback about this post, please comment and I will be happy to answer.

References

  1. ContextLoaderListener vs DispatcherServlet
  2. Spring Boot Servlet Initializer
  3. Upgrade Spring Boot and adding Spring Boot Actuator – Spring Boot Actuator