完成一次訂單導出任務，實際上是一個比較復雜的過程：需要訪問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
  br/>@Component
  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)")
  br/>@Around("@annotation(zzz.study.aop.MethodMeasureAnnotation)")
  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)
  br/>*/
  @Retention(RetentionPolicy.RUNTIME)
  br/>@Documented
  

}

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 使用最多。 其格式如下：

1
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 左右。此時，很容易造成線程阻塞，進而影響系統穩定性。

小結
通過方法調用的次數統計及耗時分析，更清晰地理解了一個導出請求的總執行流程及執行耗時占比，為性能和穩定性優化提供了有力的數據依據。

使用 SpringAOP 獲取一次請求流經方法的調用次數和調用耗時