在 Spring Boot 中使用 Spring AOP 和 AspectJ 來測量方法的執行時間
阿新 • • 發佈：2018-12-12
原文連結：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 應用程式配置：
@SpringBootApplication
public 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
@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();
}
}
}因此，我們生成一個叫做 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)mak