译：在 Spring Boot 中使用 Spring AOP 和 AspectJ 来测量方法的执行时间

用户1516716

发布于 2018-12-26 14:57:08

9920

发布于 2018-12-26 14:57:08

文章被收录于专栏：A周立SpringCloudA周立SpringCloud

原文链接：https://dzone.com/articles/logging-average-method-execution-times-via-aspectj

作者：Murat Derman

译者：Darren Luo

想要了解更多有关测量方法执行时间的信息？查看本教程，我们将着眼于使用 Spring AOP 和 AspectJ 来测量方法的执行时间。

大家好！今天，我将讨论如何在 Spring Boot 应用程序中使用 AspectJ 来测量方法执行的平均时间。我们将声明一个 quarts 作业并记录其平均方法执行时间。

首先，我们将定义我们的 pom.xml，如下所示：

<?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>

下面，我们需要创建一个 Spring Boot 应用程序配置：

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

为了激活我们在 Spring beans 中的切面记录，我们声明了一个名为“Loggable”的新注解。

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

我们为 Taget 设置属性 ElementType.Method，它用于方法定义，我们并为类定义使用 ELemenetType.Type。

为了使注解在 JVM 运行是可用，我们使用 RetentionPolicy.Runtime 配置。

接下来，我们创建一个名为 LoggingAspect 的类，它包含了一个名为“loggable”的空方法。我们使用带有 within 的 @Pointcut 通知来确定何时通知注解将被执行。

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

我们创建两个名为 beforeMethodStatistics 和 afterMethodStatistics 的方法。

我们在 beforeMethodStatistics 方法使用”Before“通知，以便于在方法发生之前以毫秒为单位获取时间。它调用 JoinPoint 作为参数来捕获方法执行中传递的参数。

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

在 afterMethodStatistics 方法中，我们使用“After”通知来计算方法在执行后的总时间。

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

我们创建 calculateStatistics 方法来设置方法在执行计数和总执行时间。logMethodStatistics 方法被用于记录平均时间。

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

让我们创建三个服务 ControllerService、PersistService 和 FetchDataService。

为了拦截这些服务方法，我们使用“Loggable”注解并激活方法拦截。

@Loggable@Servicepublic class ControlServiceImpl implements ControlService {    public void makeSomeCheck(FetchDataRequest request)
    {        try {
            Thread.sleep(new Random().nextInt(2000)+1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

    }

}

@Loggable@Servicepublic 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@Servicepublic class PersistDataServiceImpl implements PersistDataService {    @Override
    public void persist(FetchDataRequest request) {        try {
            Thread.sleep(new Random().nextInt(2000)+1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

因此，我们生成一个叫做 SomeJob 的作业来执行我们的服务。高作业将获取数据、执行检查并持久化到数据库。

之后，它将记录每个作业的平均执行时间。

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

这里是结果：

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

本文参与腾讯云自媒体分享计划，分享自微信公众号。

原始发表：2018-12-10，如有侵权请联系 cloudcommunity@tencent.com 删除

java

本文分享自 A周立SpringCloud 微信公众号，前往查看

如有侵权，请联系 cloudcommunity@tencent.com 删除。

本文参与腾讯云自媒体分享计划，欢迎热爱写作的你一起参与！

java

登录后参与评论

0 条评论

热度

译：在 Spring Boot 中使用 Spring AOP 和 AspectJ 来测量方法的执行时间

译：在 Spring Boot 中使用 Spring AOP 和 AspectJ 来测量方法的执行时间

社区

活动

资源

关于

腾讯云开发者

热门产品

热门推荐

更多推荐