DZone
Thanks for visiting DZone today,
Edit Profile
  • Manage Email Subscriptions
  • How to Post to DZone
  • Article Submission Guidelines
Sign Out View Profile
  • Post an Article
  • Manage My Drafts
Over 2 million developers have joined DZone.
Log In / Join
Please enter at least three characters to search
Refcards Trend Reports
Events Video Library
Refcards
Trend Reports

Events

View Events Video Library

Zones

Culture and Methodologies Agile Career Development Methodologies Team Management
Data Engineering AI/ML Big Data Data Databases IoT
Software Design and Architecture Cloud Architecture Containers Integration Microservices Performance Security
Coding Frameworks Java JavaScript Languages Tools
Testing, Deployment, and Maintenance Deployment DevOps and CI/CD Maintenance Monitoring and Observability Testing, Tools, and Frameworks
Culture and Methodologies
Agile Career Development Methodologies Team Management
Data Engineering
AI/ML Big Data Data Databases IoT
Software Design and Architecture
Cloud Architecture Containers Integration Microservices Performance Security
Coding
Frameworks Java JavaScript Languages Tools
Testing, Deployment, and Maintenance
Deployment DevOps and CI/CD Maintenance Monitoring and Observability Testing, Tools, and Frameworks

The software you build is only as secure as the code that powers it. Learn how malicious code creeps into your software supply chain.

Apache Cassandra combines the benefits of major NoSQL databases to support data management needs not covered by traditional RDBMS vendors.

Generative AI has transformed nearly every industry. How can you leverage GenAI to improve your productivity and efficiency?

Modernize your data layer. Learn how to design cloud-native database architectures to meet the evolving demands of AI and GenAI workloads.

Related

  • Actuator Enhancements: Spring Framework 6.2 and Spring Boot 3.4
  • How Spring Boot Starters Integrate With Your Project
  • A Practical Guide to Creating a Spring Modulith Project
  • Structured Logging in Spring Boot 3.4 for Improved Logs

Trending

  • Next Evolution in Integration: Architecting With Intent Using Model Context Protocol
  • Building Resilient Networks: Limiting the Risk and Scope of Cyber Attacks
  • Building Resilient Identity Systems: Lessons from Securing Billions of Authentication Requests
  • Unlocking Data with Language: Real-World Applications of Text-to-SQL Interfaces
  1. DZone
  2. Coding
  3. Frameworks
  4. Measuring Method Execution Times With Spring AOP and AspectJ in Spring Boot

Measuring Method Execution Times With Spring AOP and AspectJ in Spring Boot

Want to learn more about measuring method execution times? Check out this tutorial where we look at measuring method execution times with Spring AOP and AspectJ.

By 
Murat Derman user avatar
Murat Derman
·
Updated Nov. 02, 18 · Tutorial
Likes (8)
Comment
Save
Tweet
Share
61.2K Views

Join the DZone community and get the full member experience.

Join For Free

Hey, all! Today, I will be talking about how to measure average method execution times using AspectJ with a Spring Boot application. We will declare a quartz job and log the average method executions.

First, we will define our pom.xml, like the following:

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>AspectProgramming</groupId>
    <artifactId>com.sample</artifactId>
    <version>1.0-SNAPSHOT</version>

    <packaging>war</packaging>

    <properties>
        <java.version>1.8</java.version>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
    </properties>

    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>2.0.0.RELEASE</version>
    </parent>

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-context-support</artifactId>
        </dependency>


        <dependency>
            <groupId>org.quartz-scheduler</groupId>
            <artifactId>quartz</artifactId>
            <version>2.2.1</version>
        </dependency>

        <dependency>
            <groupId>log4j</groupId>
            <artifactId>log4j</artifactId>
            <version>1.2.17</version>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-log4j12</artifactId>
            <version>1.7.13</version>
        </dependency>
        <dependency>
            <groupId>org.apache.commons</groupId>
            <artifactId>commons-lang3</artifactId>
            <version>3.4</version>
        </dependency>
        <dependency>
            <groupId>commons-logging</groupId>
            <artifactId>commons-logging</artifactId>
            <version>1.2</version>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-tomcat</artifactId>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
    </dependencies>


    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
        </plugins>
    </build>


</project>


Next, we need to create a Spring Boot application configuration:

@SpringBootApplication
public class MyApplication {
    public static void main(String[] args) throws InterruptedException {
            SpringApplication.run(MyApplication.class, args);
        }
}


In order to activate our aspect logging in Spring beans, we declare a new annotation named as  “Loggable."

@Target({ElementType.METHOD, ElementType.TYPE})
@Retention(RetentionPolicy.RUNTIME)
public @interface  Loggable {
}


We use Target with the attribute ElementType.Method, which is used for method definitions, and we use ElementType.Type for class definitions.

In order to make annotations available at runtime in the JVM, we use the RetiontionPolicy.Runtime  configuration.

Next, we create a class named LoggingAspect, which contains an empty method named “loggable." We use@Pointcut advice using the within designator in order to determine when advice annotations will be executed.

public class LoggingAspect {
@Pointcut("within(@com.aspect.logging.Loggable *)")
public void loggable() 
}
}


We create two methods named beforeMethodStatistics and afterMethodStatistics.

We use "Before" advice in the method beforeMethodStatistics in order to get time in milliseconds just before the method execution occurs. It calls JointPoint as a parameter to capture the parameters passed in the method execution.

@Before("loggable()")
public void beforeMethodStatistics(JoinPoint jp) throws Throwable {
    Object[] args = jp.getArgs();
    if (null != args && args.length > 0) {
        for (Object arg : args) {
            if (arg instanceof BaseRequest) {
                ((BaseRequest) arg).setStartTimeInMillis(Calendar.getInstance().getTimeInMillis());
                break;
            }
        }
    }
}


Inside the afterMethodStatistics method, we use "After"  advice to calculate the total time after the method execution.

@After("loggable()")
public void afterMethodStatistics(JoinPoint jp) {
    Object[] args = jp.getArgs();
    if (null != args && args.length > 0) {
        for (Object arg : args) {
            if (arg instanceof BaseRequest) {
                StatisticsUtils.calculateStatistics(jp, arg, StatisticsMapEnum.ASPECT_LOGGER_STATISTICS_MAP);
                break;
            }
        }
    }
}


We create the calculateStatistics method to set up the method execution count and total execution time. The LogMethodStatistics method is used to log the average time.

public class StatisticUtils {

    private static AppLogger logger = AppLoggerFactory.getLogger(StatisticUtils.class);

    public static void calculateStatistics(JoinPoint jp, Object arg, StatisticsMapEnum  statisticsMapEnum) {

        try {
            long resultTimemMillis = Calendar.getInstance().getTimeInMillis() - ((BaseRequest) arg).getStartTimeInMillis();


            StatisticsDto statisticsDto;
            Map<String, StatisticsDto> statisticsMap = CacheUtils.statisticsMap.get(statisticsMapEnum);
            if (GeneralUtils.isNullOrEmptyMap(statisticsMap))
                statisticsMap = new HashMap<>();
            if (GeneralUtils.isNullObject(statisticsMap.get(jp.getSignature().getName()))) {
                statisticsDto = new StatisticsDto();
                statisticsDto.setMethodName(jp.getSignature().getName());
                statisticsDto.setTotalTimeInMillis(resultTimemMillis);
 statisticsDto.setMethodCallCount(1);
            } else {
                statisticsDto = statisticsMap.get(jp.getSignature().getName());
                long totalTimeInMillis = statisticsDto.getTotalTimeMillis() + resultTimemMillis;
                statisticsDto.setTotalTimeInMillis((totalTimeInMillis));
                statisticsDto.setMethodCallCount(statisticsDto.getMethodCallCount() +1);
            }
            statisticsMap.put(jp.getSignature().getName(), statisticsDto);
            CacheUtils.statisticsMap.put(statisticsMapEnum,statisticsMap);
        } catch (Exception ex) {
            logger.error("Exception Occured while calculating statistics:" + ExceptionUtils.getStackTrace(ex));
        }
    }

    public static void logMethodStatistics(StatisticsMapEnum  statisticsMapEnum, BatchTypeEnum batchTypeEnum) {

        try {
            Map<String, StatisticsDto> statisticsDtoMap = CacheUtils.statisticsMap.get(statisticsMapEnum);
            if (!GeneralUtils.isNullOrEmptyMap(statisticsDtoMap)) {
                logger.info(batchTypeEnum.toString() + " Statistics: MethodName  -  MethodAverageTime (millis)");
                Set<Map.Entry<String, StatisticsDto>> entrySet = statisticsDtoMap.entrySet();
                Iterator<Map.Entry<String, StatisticsDto>> iterator = entrySet.iterator();
                while (iterator.hasNext()) {
                    Map.Entry<String, StatisticsDto> entry = iterator.next();
                    StatisticsDto statisticsDto = entry.getValue();
                    logger.info(statisticsDto.getMethodName() + " - " + Long.valueOf(statisticsDto.getTotalTimeMillis() / statisticsDto.getMethodCallCount()) + " ms");
                }
            }
            statisticsDtoMap = new HashMap<>();
            CacheUtils.statisticsMap.put(statisticsMapEnum,statisticsDtoMap);
        } catch (Exception ex) {
            logger.error("Exception Occured while logging statistics:" + ExceptionUtils.getStackTrace(ex));
        }
    }}


So, let's create three services as ControlService, PersistService, and  FetchDataService.

In order to intercept those services methods, we use our "Loggable" annotation and activate the method interception.

@Loggable
@Service
public class ControlServiceImpl implements ControlService {

    public void makeSomeCheck(FetchDataRequest request)
    {

        try {
            Thread.sleep(new Random().nextInt(2000)+1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

    }

}
@Loggable
@Service
public class FetchDataServiceImpl  implements FetchDataService{
    @Override
    public void fetchSomeData(FetchDataRequest request) {

        try {
            FetchDataDto fetchDto=new FetchDataDto();
            List<FetchDataDto> fetchDataDtoList=new ArrayList<>();

            fetchDto.setId(1001L);
            fetchDto.setName("Tom");
            fetchDto.setSurName("Walker");
            fetchDto.setAddressInfo("Chicago");
            fetchDataDtoList.add(fetchDto);

            fetchDto.setId(1002L);
            fetchDto.setName("Clark");
            fetchDto.setSurName("Michigan");
            fetchDto.setAddressInfo("New York");
            fetchDataDtoList.add(fetchDto);
            fetchDto.setId(1003L);
            fetchDto.setName("Tom");
            fetchDto.setSurName("Walker");
            fetchDto.setAddressInfo("Chicago");
            fetchDataDtoList.add(fetchDto);

            fetchDto.setId(1004L);
            fetchDto.setName("Clark");
            fetchDto.setSurName("Michigan");
            fetchDto.setAddressInfo("New York");
            fetchDataDtoList.add(fetchDto);
            fetchDto.setId(1005L);
            fetchDto.setName("Tom");
            fetchDto.setSurName("Walker");
            fetchDto.setAddressInfo("Chicago");
            fetchDataDtoList.add(fetchDto);

            fetchDto.setId(1006L);
            fetchDto.setName("Clark");
            fetchDto.setSurName("Michigan");
            fetchDto.setAddressInfo("New York");
            fetchDataDtoList.add(fetchDto);

            request.setFetchDataDtoList(fetchDataDtoList);

            Thread.sleep(new Random().nextInt(2000)+1000);

        } catch (InterruptedException e) {
            e.printStackTrace();
        }


    }
}

@Loggable
@Service
public class PersistDataServiceImpl implements PersistDataService {

    @Override
    public void persist(FetchDataRequest request) {

        try {
            Thread.sleep(new Random().nextInt(2000)+1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}


So, we generate a job called SomeJob to execute our services. The job will fetch data, perform a check, and persist to DB.

After that, it will log the average execution time on every job that execution occurs.

@Component
public class SomeJob implements Job {

    @Override
    public void execute(JobExecutionContext context) throws JobExecutionException {


        FetchDataService fetchDataService = (FetchDataService) ApplicationContextProvider.getApplicationContext().getBean("fetchDataServiceImpl");
        ThreadPoolService threadPoolService = (ThreadPoolService) ApplicationContextProvider.getApplicationContext().getBean("threadPoolServiceImpl");
        PersistDataService persistDataService =(PersistDataService) ApplicationContextProvider.getApplicationContext().getBean("persistDataServiceImpl");
        ControlService controlService =(ControlService) ApplicationContextProvider.getApplicationContext().getBean("controlServiceImpl");
        FetchDataRequest request=new FetchDataRequest() ;
        fetchDataService.fetchSomeData(request);
        controlService.makeSomeCheck(request);
        persistDataService.persist(request);

        StatisticsUtils.logMethodStatistics(BatchTypeEnum.ASPECT_LOGGER_JOB);

    }
}


Here are the results:

ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 2936 ms
persist - 1825 ms
fetchSomeData - 1487 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 1777 ms
persist - 2040 ms
fetchSomeData - 2790 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 1364 ms
persist - 1677 ms
fetchSomeData - 2531 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 2515 ms
persist - 1711 ms
fetchSomeData - 1470 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 2321 ms
persist - 2967 ms
fetchSomeData - 1789 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 1672 ms
persist - 1699 ms
fetchSomeData - 2559 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 1042 ms
persist - 2975 ms
fetchSomeData - 1165 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 1004 ms
persist - 1531 ms
fetchSomeData - 1151 ms


Spring Framework Spring Boot Execution (computing) AspectJ

Opinions expressed by DZone contributors are their own.

Related

  • Actuator Enhancements: Spring Framework 6.2 and Spring Boot 3.4
  • How Spring Boot Starters Integrate With Your Project
  • A Practical Guide to Creating a Spring Modulith Project
  • Structured Logging in Spring Boot 3.4 for Improved Logs

Partner Resources

×

Comments
Oops! Something Went Wrong

The likes didn't load as expected. Please refresh the page and try again.

ABOUT US

  • About DZone
  • Support and feedback
  • Community research
  • Sitemap

ADVERTISE

  • Advertise with DZone

CONTRIBUTE ON DZONE

  • Article Submission Guidelines
  • Become a Contributor
  • Core Program
  • Visit the Writers' Zone

LEGAL

  • Terms of Service
  • Privacy Policy

CONTACT US

  • 3343 Perimeter Hill Drive
  • Suite 100
  • Nashville, TN 37211
  • support@dzone.com

Let's be friends:

Likes
There are no likes...yet! 👀
Be the first to like this post!
It looks like you're not logged in.
Sign in to see who liked this post!