转载

使用 SpringAOP 获取一次请求流经方法的调用次数和调用耗时

引语

作为工程师，不能仅仅满足于实现了现有的功能逻辑，还必须深入认识系统。一次请求，流经了哪些方法，执行了多少次DB操作，访问了多少次文件操作，调用多少次API操作，总共有多少次IO操作，多少CPU操作，各耗时多少？开发者应当知道这些运行时数据，才能对系统的运行有更深入的理解，更好滴提升系统的性能和稳定性。

完成一次订单导出任务，实际上是一个比较复杂的过程：需要访问ES 来查询订单，调用批量API接口及访问 Hbase 获取订单详情数据，格式化报表字段数据，写入和上传报表文件，更新数据库，上报日志数据等；在大流量导出的情形下，采用批量并发策略，多线程来获取订单详情数据，整个请求的执行流程会更加复杂。

本文主要介绍使用AOP拦截器来获取一次请求流经方法的调用次数和调用耗时。

总体思路

使用AOP思想来解决。增加一个注解，然后增加一个AOP methodAspect ，记录方法的调用次数及耗时。

methodAspect 内部含有两个变量 methodCount, methodCost ，都采用了 ConcurrentHashMap 。这是因为方法执行时，可能是多线程写入这两个变量。

使用：

(1) 将需要记录次数和耗时的方法加上 MethodMeasureAnnotation 即可；

(2) 将 MethodMeasureAspect 作为组件注入到 ServiceAspect 中，并在 ServiceAspect 中打印 MethodMeasureAspect 的内容。

关注哪些方法

通常重点关注一个任务流程中的如下方法：

IO阻塞操作：文件操作， DB操作，API操作， ES访问，Hbase访问；
同步操作：lock, synchronized, 同步工具所施加的代码块等；
CPU耗时：大数据量的format, sort 等。

一般集中在如下包：

service, core , report, sort 等。根据具体项目而定。

源代码

package zzz.study.aop;

import zzz.study.util.MapUtil;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

import java.lang.reflect.Method;
import java.util.ArrayList;
import java.util.IntSummaryStatistics;
import java.util.List;
import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
import java.util.stream.Collectors;

/**
 * 记录一次请求中,流经的所有方法的调用耗时及次数
 *
 */
@Component
@Aspect
public class MethodMeasureAspect {

  private static final Logger logger = LoggerFactory.getLogger(MethodMeasureAspect.class);

  private Map<String, Integer> methodCount = new ConcurrentHashMap();

  private Map<String, List<Integer>> methodCost = new ConcurrentHashMap();

  @SuppressWarnings(value = "unchecked")
  @Around("@annotation(zzz.study.aop.MethodMeasureAnnotation)")
  public Object process(ProceedingJoinPoint joinPoint) {
    Object obj = null;
    String className = joinPoint.getTarget().getClass().getSimpleName();
    String methodName = className + "_" + getMethodName(joinPoint);
    long startTime = System.currentTimeMillis();
    try {
      obj = joinPoint.proceed();
    } catch (Throwable t) {
      logger.error(t.getMessage(), t);
    } finally {
      long costTime = System.currentTimeMillis() - startTime;
      logger.info("method={}, cost_time={}", methodName, costTime);
      methodCount.put(methodName, methodCount.getOrDefault(methodName, 0) + 1);
      List<Integer> costList = methodCost.getOrDefault(methodName, new ArrayList<>());
      costList.add((int)costTime);
      methodCost.put(methodName, costList);
    }
    return obj;
  }

  public String getMethodName(ProceedingJoinPoint joinPoint) {
    Signature signature = joinPoint.getSignature();
    MethodSignature methodSignature = (MethodSignature) signature;
    Method method = methodSignature.getMethod();
    return method.getName();
  }

  public String toString() {

    StringBuilder sb = new StringBuilder("MethodCount:/n");
    Map<String,Integer> sorted =  MapUtil.sortByValue(methodCount);
    sorted.forEach(
        (method, count) -> {
          sb.append("method=" + method + ", " + "count=" + count+'/n');
        }
    );
    sb.append('/n');
    sb.append("MethodCosts:/n");
    methodCost.forEach(
        (method, costList) -> {
          IntSummaryStatistics stat = costList.stream().collect(Collectors.summarizingInt(x->x));
          String info = String.format("method=%s, sum=%d, avg=%d, max=%d, min=%d, count=%d", method,
                                      (int)stat.getSum(), (int)stat.getAverage(), stat.getMax(), stat.getMin(), (int)stat.getCount());
          sb.append(info+'/n');
        }
    );

    sb.append('/n');
    sb.append("DetailOfMethodCosts:/n");
    methodCost.forEach(
        (method, costList) -> {
          String info = String.format("method=%s, cost=%s", method, costList);
          sb.append(info+'/n');
        }
    );
    return sb.toString();
  }
}

MethodMeasureAnnotation.java

package zzz.study.aop;

import java.lang.annotation.Documented;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

/**
 * 记录方法调用
 */
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
@Documented
public @interface MethodMeasureAnnotation {

}

MapUtil.java

public class MapUtil {

  public static <K, V extends Comparable<? super V>> Map<K, V> sortByValue(Map<K, V> map) {
    Map<K, V> result = new LinkedHashMap<>();
    Stream<Map.Entry<K, V>> st = map.entrySet().stream();

    st.sorted(Comparator.comparing(e -> e.getValue())).forEach(e -> result.put(e.getKey(), e.getValue()));

    return result;
  }

}

AOP基本概念

理解概念至关重要。优雅设计的框架，通常包含一组相互紧密关联的概念。这些概念经过精心抽象和提炼而成。 AOP的基本概念主要有：

Aspect：应用程序的某个模块化的关注点；通常是日志、权限、事务、打点、监控等。
JointPoint：连接点，程序执行过程中明确的点，一般是方法的调用。
Pointcut: 切点。指定施加于满足指定表达式的方法集合。Spring 默认使用 AspectJ pointcut 表达式。
Advance: 通知。指定在方法执行的什么时机，不同的Advance对应不同的切面方法；有before,after,afterReturning,afterThrowing,around。
TargetObject: 目标对象。通过Pointcut表达式指定的将被通知执行切面逻辑的实际对象。
AOP proxy: 代理对象。由AOP框架创建的代理，用于回调实际对象的方法，并执行切面逻辑。Spring实现中，若目标对象实现了至少一个接口，则使用JDK动态代理，否则使用 CGLIB 代理。优先使用JDK动态代理。
Weaving：织入。将切面类与应用对象关联起来。Spring使用运行时织入。通常 Pointcut 和 Advance 联合使用。即在方法上加上 @Advance(@Pointcut)

采用多种策略

@Around(“@annotation(zzz.study.aop.MethodMeasureAnnotation)”) 仅仅指定了在携带指定注解的方法上执行。实际上，可以指定多种策略，比如指定类，指定包下。可以使用逻辑运算符 || , && , ! 来指明这些策略的组合。例如：

@Around("@annotation(zzz.study.aop.MethodMeasureAnnotation) "
          + "|| execution(* zzz.study.service.inner.BizOrderDataService.*(..))"
          + "|| execution(* zzz.study.core.service.*.*(..)) "
          + "|| execution(* zzz.study.core.strategy..*.*(..)) "
          + "|| execution(* zzz.study.core.report.*.generate*(..)) "
  )

指明了五种策略的组合：带有 MethodMeasureAnnotation 注解的方法； BizOrderDataService 类的所有方法； zzz.study.core.service 下的所有类的方法； zzz.study.core.strategy 包及其子包下的所有类的方法；zzz.study.core.report 包下所有类的以 generate 开头的方法。

execution表达式

@Pointcut 中， execution 使用最多。其格式如下：

execution(modifiers-pattern? ret-type-pattern declaring-type-pattern? name-pattern(param-pattern)throws-pattern?)

括号中各个pattern分别表示：

修饰符匹配（modifier-pattern?）
返回值匹配（ret-type-pattern）可以为*表示任何返回值,全路径的类名等
类路径匹配（declaring-type-pattern?）
方法名匹配（name-pattern）可以指定方法名或者代表所有, set 代表以set开头的所有方法
参数匹配（(param-pattern)）可以指定具体的参数类型，多个参数间用“,”隔开，各个参数也可以用“”来表示匹配任意类型的参数，如(String)表示匹配一个String参数的方法；(,String) 表示匹配有两个参数的方法，第一个参数可以是任意类型，而第二个参数是String类型；可以用(..)表示零个或多个任意参数
异常类型匹配（throws-pattern?）其中后面跟着“?”的是可选项。

何时不会被通知

并不是满足 pointcut 指定条件的所有方法都会执行切面逻辑。如果类 C 有三个公共方法，a,b,c ; a 调用 b ，b 调用 c 。会发现 b,c 是不会执行切面逻辑的。这是因为Spring的AOP主要基于动态代理机制。当调用 a 时，会调用代理的 a 方法，也就进入到切面逻辑，但是当 a 调用 b 时， b 是直接在目标对象上执行，而不是在代理对象上执行，因此，b 是不会进入到切面逻辑的。总结下，如下情形是不会执行切面逻辑的：

被切面方法调用的内部方法；
final 方法；
private 方法；
静态方法。

可参阅参考文献的 “8.6.1 Understanding AOP proxies”

However, once the call has finally reached the target object, the SimplePojo reference in this case, any method calls that it may make on itself, such as this.bar() or this.foo(), are going to be invoked against the this reference, and not the proxy. This has important implications. It means that self-invocation is not going to result in the advice associated with a method invocation getting a chance to execute.

Okay, so what is to be done about this? The best approach (the term best is used loosely here) is to refactor your code such that the self-invocation does not happen. For sure, this does entail some work on your part, but it is the best, least-invasive approach.

其含义是说，a, b 都是类 C 的方法，a 调用了 b ；如果需要对 b 方法进行切面，那么最好能将 b 抽离出来放在类D的公共方法中，因为 b 是一个需要切面关注点的重要方法。

再比如，排序方法实现为静态方法 DefaultReportItemSorter.sort ，这样是不能被通知到切面的。需要将 DefaultReportItemSorter 改为组件 @Component 注入到依赖的类里，然后将 sort 改为实例方法。

运行数据分析

运行结果

导出订单数处于[11500,12000]区间的一次运行结果截取如下：

// ...
method=BatchOrderDetailService_getAllOrderDetails, count=23
method=GoodsDimensionExportStrategy_generateReportDatas, count=23
method=BizOrderDataService_generateFinalReportItemList, count=23
method=CsvFileOutputStrategy_output, count=23
method=BaseReportService_appendItemsReportCommon, count=23
method=ExportStrategyFactory_getExportDimensionStrategy, count=24
method=FileService_appendFile, count=24
method=ExportStrategyFactory_getOutputStrategy, count=25
method=BatchGetInfoService_batchGetAllInfo, count=46
method=HAHbaseService_getRowsWithColumnPrefixFilter, count=92
method=HAHbaseService_scanByPrefixFilterList, count=115

MethodCosts:
method=BatchOrderDetailService_getAllOrderDetails, sum=12684, avg=551, max=727, min=504, count=23
method=ReportService_generateReportForExport, sum=46962, avg=46962, max=46962, min=46962, count=1
method=DbOperation_updateExportRecord, sum=63, avg=63, max=63, min=63, count=1
method=HAHbaseService_scanByPrefixFilterList, sum=1660, avg=14, max=115, min=3, count=115
method=GoodsDimensionExportStrategy_generateReportDatas, sum=6764, avg=294, max=668, min=165, count=23
method=BatchGetInfoService_batchGetAllInfo, sum=14885, avg=323, max=716, min=0, count=46
method=CsvFileOutputStrategy_appendHeader, sum=23, avg=23, max=23, min=23, count=1
method=BaseReportService_appendHeader, sum=60, avg=60, max=60, min=60, count=1
method=BizOrderDataService_generateFinalReportItemList, sum=37498, avg=1630, max=4073, min=1326, count=23
method=ExportStrategyFactory_getOutputStrategy, sum=35, avg=1, max=35, min=0, count=25
method=HAHbaseService_getRowsWithColumnPrefixFilter, sum=3709, avg=40, max=112, min=23, count=92
method=BaseReportService_appendItemReport, sum=46871, avg=46871, max=46871, min=46871, count=1
method=FileService_uploadFileWithRetry, sum=138, avg=138, max=138, min=138, count=1
method=GeneralEsSearchService_search, sum=4470, avg=4470, max=4470, min=4470, count=1
method=CsvFileOutputStrategy_generateReportFile, sum=57, avg=57, max=57, min=57, count=1
method=SerialExportStrategy_appendItemReport, sum=46886, avg=46886, max=46886, min=46886, count=1
method=CsvFileOutputStrategy_output, sum=2442, avg=106, max=311, min=39, count=23
method=CommonService_getGeneralEsSearchService, sum=23, avg=23, max=23, min=23, count=1
method=BaseReportService_appendItemsReportCommon, sum=46818, avg=2035, max=5033, min=1655, count=23
method=CommonJobFlow_commonRun, sum=52638, avg=52638, max=52638, min=52638, count=1
method=DefaultReportItemSorter_sort, sum=304, avg=13, max=80, min=2, count=23
method=FileService_getExportFile, sum=29, avg=29, max=29, min=29, count=1
method=FileService_createFile, sum=1, avg=1, max=1, min=1, count=1
method=FileService_appendFile, sum=213, avg=8, max=69, min=2, count=24
method=GoodsDimensionExportStrategy_generateColumnTitles, sum=15, avg=15, max=15, min=15, count=1

DetailOfMethodCosts:
method=BatchOrderDetailService_getAllOrderDetails, cost=[727, 562, 533, 560, 544, 527, 526, 541, 531, 526, 556, 534, 554, 537, 567, 576, 562, 531, 562, 533, 522, 569, 504]
method=HAHbaseService_scanByPrefixFilterList, cost=[115, 54, 34, 12, 13, 36, 31, 19, 7, 6, 21, 18, 10, 6, 4, 24, 16, 13, 7, 8, 39, 17, 10, 9, 11, 21, 18, 9, 6, 8, 23, 17, 9, 10, 8, 24, 15, 11, 5, 6, 19, 15, 11, 5, 8, 21, 18, 9, 10, 10, 19, 16, 10, 5, 6, 24, 16, 6, 7, 5, 22, 17, 8, 12, 9, 19, 19, 8, 11, 8, 19, 36, 6, 6, 4, 20, 19, 6, 4, 4, 20, 17, 10, 7, 3, 20, 17, 4, 5, 7, 20, 16, 7, 4, 4, 37, 32, 4, 5, 3, 17, 14, 6, 9, 6, 18, 48, 6, 4, 3, 20, 16, 8, 7, 9]
method=GoodsDimensionExportStrategy_generateReportDatas, cost=[668, 383, 369, 543, 438, 272, 222, 231, 238, 311, 310, 297, 296, 165, 253, 217, 211, 222, 211, 185, 234, 221, 267]
method=BatchGetInfoService_batchGetAllInfo, cost=[716, 103, 562, 103, 533, 101, 559, 100, 544, 101, 526, 101, 525, 101, 541, 101, 530, 100, 525, 103, 556, 100, 534, 100, 554, 101, 537, 100, 567, 101, 576, 101, 562, 100, 531, 101, 562, 100, 530, 0, 522, 101, 569, 100, 504, 101]
method=BizOrderDataService_generateFinalReportItemList, cost=[4073, 1895, 1668, 1713, 1687, 1498, 1606, 1534, 1476, 1505, 1499, 1578, 1493, 1433, 1515, 1488, 1406, 1438, 1459, 1416, 1326, 1457, 1335]
method=HAHbaseService_getRowsWithColumnPrefixFilter, cost=[86, 49, 40, 112, 35, 33, 33, 72, 32, 30, 30, 78, 31, 30, 29, 83, 70, 28, 29, 81, 30, 28, 28, 91, 26, 28, 24, 109, 30, 29, 26, 56, 27, 29, 28, 54, 26, 27, 23, 61, 27, 28, 24, 57, 25, 27, 26, 107, 28, 28, 26, 59, 41, 36, 25, 54, 43, 23, 23, 59, 34, 31, 30, 63, 29, 32, 28, 54, 31, 27, 27, 61, 28, 33, 26, 64, 36, 47, 26, 62, 27, 26, 24, 50, 26, 23, 24, 47, 28, 29, 25, 54]
// ...

耗时占比

总耗时 52638 ms ，报表生成部分 46962 ms (89.2%)，ES 查询订单部分 4470 ms (8.5%) , 其他 1206 ms (2.3%) 。
报表生成部分：每批次的“报表数据生成+格式化报表行数据+写入文件” appendItemsReportCommon 耗时 46818 ms ；批次切分及进度打印耗时 53ms；报表报表头写入文件 60 ms；appendItemsReportCommon ≈ generateFinalReportItemList + generateReportDatas + output ；
报表生成部分(★)：批量详情API接口 getAllOrderDetails 耗时 12684 ms (24%), 除详情API之外的其他详情数据拉取耗时37498-12684=24814 ms (47%) ，获取所有订单的详情数据 generateFinalReportItemList 总占比 71%。
报表生成部分(2) : 生成报表行数据 generateReportDatas 耗时 6764 ms (12.9%)，写入文件 output 耗时 2442 ms (4.6%)。

耗时细分

这里部分方法的调用次数取决于获取订单详情时对keyList的切分策略。方法调用耗时是值得关注的点。重点关注耗时区间。

访问ES的耗时平均 4062 ~ 4798ms。随着要查询的订单数线性增长。
批量调用详情API 的平均 532 ~ 570 ms (5个并发)。
Hbase 访问的 getRowsWithColumnPrefixFilter 平均 40 ~ 45 ms , scanByPrefixFilterList 平均 10 ~ 15 ms 。注意，这并不代表 batchGet 的性能比 scanByPrefixFilterList 差。因为 batchGet 一次取 500 个 rowkey 的数据，而 scanByPrefixFilterList 为了避免超时一次才取 200 个 rowkey 数据。
appendItemsReportCommon：平均 1996 ~ 2304 ms 。这个方法是生成报表加格式化报表字段数据加写文件。可见，格式化报表字段数据的耗时还是比较多的。
generateReportDatas：报表字段格式化耗时，平均 294 ms。
output：向报表追加数据耗时，平均 104 ms。
更新数据库操作平均 40 ~ 88ms。
创建和写文件的操作平均 6~15 ms 。 append 内容在 100KB ~ 200KB 之间。
上传文件的操作平均 151~279 ms 。整个文件的上传时间，取决于文件的大小。

注意到，以上是串行策略下运行的结果。也就是所有过程都是顺序执行的。顺序执行策略的优点是排除并发干扰，便于分析基本耗时。

在多线程情形下，单个IO操作会增大，有时会达到 1s ~ 3s 左右。此时，很容易造成线程阻塞，进而影响系统稳定性。