使用 SpringAOP 獲取一次請(qǐng)求流經(jīng)方法的調(diào)用次數(shù)和調(diào)用耗時(shí)

2018-07-30 來(lái)源：importnew

容器云強(qiáng)勢(shì)上線！快速搭建集群，上萬(wàn)Linux鏡像隨意使用

原文出處：琴水玉

引語(yǔ)

作為工程師，不能僅僅滿足于實(shí)現(xiàn)了現(xiàn)有的功能邏輯，還必須深入認(rèn)識(shí)系統(tǒng)。一次請(qǐng)求，流經(jīng)了哪些方法，執(zhí)行了多少次DB操作，訪問(wèn)了多少次文件操作，調(diào)用多少次API操作，總共有多少次IO操作，多少CPU操作，各耗時(shí)多少？開(kāi)發(fā)者應(yīng)當(dāng)知道這些運(yùn)行時(shí)數(shù)據(jù)，才能對(duì)系統(tǒng)的運(yùn)行有更深入的理解，更好滴提升系統(tǒng)的性能和穩(wěn)定性。

完成一次訂單導(dǎo)出任務(wù)，實(shí)際上是一個(gè)比較復(fù)雜的過(guò)程：需要訪問(wèn)ES 來(lái)查詢訂單，調(diào)用批量API接口及訪問(wèn) Hbase 獲取訂單詳情數(shù)據(jù)，格式化報(bào)表字段數(shù)據(jù)，寫入和上傳報(bào)表文件，更新數(shù)據(jù)庫(kù)，上報(bào)日志數(shù)據(jù)等；在大流量導(dǎo)出的情形下，采用批量并發(fā)策略，多線程來(lái)獲取訂單詳情數(shù)據(jù)，整個(gè)請(qǐng)求的執(zhí)行流程會(huì)更加復(fù)雜。

本文主要介紹使用AOP攔截器來(lái)獲取一次請(qǐng)求流經(jīng)方法的調(diào)用次數(shù)和調(diào)用耗時(shí)。

總體思路

使用AOP思想來(lái)解決。增加一個(gè)注解，然后增加一個(gè)AOP methodAspect ，記錄方法的調(diào)用次數(shù)及耗時(shí)。

methodAspect 內(nèi)部含有兩個(gè)變量 methodCount, methodCost ，都采用了 ConcurrentHashMap 。這是因?yàn)榉椒▓?zhí)行時(shí)，可能是多線程寫入這兩個(gè)變量。

使用：

(1) 將需要記錄次數(shù)和耗時(shí)的方法加上 MethodMeasureAnnotation 即可；

(2) 將 MethodMeasureAspect 作為組件注入到 ServiceAspect 中，并在 ServiceAspect 中打印 MethodMeasureAspect 的內(nèi)容。

關(guān)注哪些方法

通常重點(diǎn)關(guān)注一個(gè)任務(wù)流程中的如下方法：

IO阻塞操作：文件操作， DB操作，API操作， ES訪問(wèn)，Hbase訪問(wèn)；
同步操作：lock, synchronized, 同步工具所施加的代碼塊等；
CPU耗時(shí)：大數(shù)據(jù)量的format, sort 等。

一般集中在如下包：

service, core , report, sort 等。根據(jù)具體項(xiàng)目而定。

源代碼

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;

/**
 * 記錄一次請(qǐng)求中,流經(jīng)的所有方法的調(diào)用耗時(shí)及次數(shù)
 *
 */
@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;

/**
 * 記錄方法調(diào)用
 */
@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基本概念

理解概念至關(guān)重要。優(yōu)雅設(shè)計(jì)的框架，通常包含一組相互緊密關(guān)聯(lián)的概念。這些概念經(jīng)過(guò)精心抽象和提煉而成。 AOP的基本概念主要有：

Aspect：應(yīng)用程序的某個(gè)模塊化的關(guān)注點(diǎn)；通常是日志、權(quán)限、事務(wù)、打點(diǎn)、監(jiān)控等。
JointPoint：連接點(diǎn)，程序執(zhí)行過(guò)程中明確的點(diǎn)，一般是方法的調(diào)用。
Pointcut: 切點(diǎn)。指定施加于滿足指定表達(dá)式的方法集合。Spring 默認(rèn)使用 AspectJ pointcut 表達(dá)式。
Advance: 通知。指定在方法執(zhí)行的什么時(shí)機(jī)，不同的Advance對(duì)應(yīng)不同的切面方法；有before,after,afterReturning,afterThrowing,around。
TargetObject: 目標(biāo)對(duì)象。通過(guò)Pointcut表達(dá)式指定的將被通知執(zhí)行切面邏輯的實(shí)際對(duì)象。
AOP proxy: 代理對(duì)象。由AOP框架創(chuàng)建的代理，用于回調(diào)實(shí)際對(duì)象的方法，并執(zhí)行切面邏輯。Spring實(shí)現(xiàn)中，若目標(biāo)對(duì)象實(shí)現(xiàn)了至少一個(gè)接口，則使用JDK動(dòng)態(tài)代理，否則使用 CGLIB 代理。優(yōu)先使用JDK動(dòng)態(tài)代理。
Weaving：織入。將切面類與應(yīng)用對(duì)象關(guān)聯(lián)起來(lái)。Spring使用運(yùn)行時(shí)織入。通常 Pointcut 和 Advance 聯(lián)合使用。即在方法上加上 @Advance(@Pointcut)

采用多種策略

@Around(“@annotation(zzz.study.aop.MethodMeasureAnnotation)”) 僅僅指定了在攜帶指定注解的方法上執(zhí)行。實(shí)際上，可以指定多種策略，比如指定類，指定包下�？梢允褂眠壿嬤\(yùn)算符 || , && , ! 來(lái)指明這些策略的組合。例如：

@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 開(kāi)頭的方法。

execution表達(dá)式

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

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

括號(hào)中各個(gè)pattern分別表示：

修飾符匹配（modifier-pattern?）
返回值匹配（ret-type-pattern）可以為*表示任何返回值,全路徑的類名等
類路徑匹配（declaring-type-pattern?）
方法名匹配（name-pattern）可以指定方法名或者代表所有, set 代表以set開(kāi)頭的所有方法
參數(shù)匹配（(param-pattern)）可以指定具體的參數(shù)類型，多個(gè)參數(shù)間用“,”隔開(kāi)，各個(gè)參數(shù)也可以用“”來(lái)表示匹配任意類型的參數(shù)，如(String)表示匹配一個(gè)String參數(shù)的方法；(,String) 表示匹配有兩個(gè)參數(shù)的方法，第一個(gè)參數(shù)可以是任意類型，而第二個(gè)參數(shù)是String類型；可以用(..)表示零個(gè)或多個(gè)任意參數(shù)
異常類型匹配（throws-pattern?）其中后面跟著“?”的是可選項(xiàng)。

何時(shí)不會(huì)被通知

并不是滿足 pointcut 指定條件的所有方法都會(huì)執(zhí)行切面邏輯。如果類 C 有三個(gè)公共方法，a,b,c ; a 調(diào)用 b ，b 調(diào)用 c 。會(huì)發(fā)現(xiàn) b,c 是不會(huì)執(zhí)行切面邏輯的。這是因?yàn)镾pring的AOP主要基于動(dòng)態(tài)代理機(jī)制。當(dāng)調(diào)用 a 時(shí)，會(huì)調(diào)用代理的 a 方法，也就進(jìn)入到切面邏輯，但是當(dāng) a 調(diào)用 b 時(shí)， b 是直接在目標(biāo)對(duì)象上執(zhí)行，而不是在代理對(duì)象上執(zhí)行，因此，b 是不會(huì)進(jìn)入到切面邏輯的�？偨Y(jié)下，如下情形是不會(huì)執(zhí)行切面邏輯的：

被切面方法調(diào)用的內(nèi)部方法；
final 方法；
private 方法；
靜態(tài)方法。

可參閱參考文獻(xiàn)的 “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.

其含義是說(shuō)，a, b 都是類 C 的方法，a 調(diào)用了 b ；如果需要對(duì) b 方法進(jìn)行切面，那么最好能將 b 抽離出來(lái)放在類D的公共方法中，因?yàn)?b 是一個(gè)需要切面關(guān)注點(diǎn)的重要方法。

再比如，排序方法實(shí)現(xiàn)為靜態(tài)方法 DefaultReportItemSorter.sort ，這樣是不能被通知到切面的。需要將 DefaultReportItemSorter 改為組件 @Component 注入到依賴的類里，然后將 sort 改為實(shí)例方法。

運(yùn)行數(shù)據(jù)分析

運(yùn)行結(jié)果

導(dǎo)出訂單數(shù)處于[11500,12000]區(qū)間的一次運(yùn)行結(jié)果截取如下：

// ...
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]
// ...

耗時(shí)占比

總耗時(shí) 52638 ms ，報(bào)表生成部分 46962 ms (89.2%)，ES 查詢訂單部分 4470 ms (8.5%) , 其他 1206 ms (2.3%) 。
報(bào)表生成部分：每批次的“報(bào)表數(shù)據(jù)生成+格式化報(bào)表行數(shù)據(jù)+寫入文件” appendItemsReportCommon 耗時(shí) 46818 ms ；批次切分及進(jìn)度打印耗時(shí) 53ms；報(bào)表報(bào)表頭寫入文件 60 ms；appendItemsReportCommon ≈ generateFinalReportItemList + generateReportDatas + output ；
報(bào)表生成部分(★)：批量詳情API接口 getAllOrderDetails 耗時(shí) 12684 ms (24%), 除詳情API之外的其他詳情數(shù)據(jù)拉取耗時(shí)37498-12684=24814 ms (47%) ，獲取所有訂單的詳情數(shù)據(jù) generateFinalReportItemList 總占比 71%。
報(bào)表生成部分(2) : 生成報(bào)表行數(shù)據(jù) generateReportDatas 耗時(shí) 6764 ms (12.9%)，寫入文件 output 耗時(shí) 2442 ms (4.6%)。

耗時(shí)細(xì)分

這里部分方法的調(diào)用次數(shù)取決于獲取訂單詳情時(shí)對(duì)keyList的切分策略。方法調(diào)用耗時(shí)是值得關(guān)注的點(diǎn)。重點(diǎn)關(guān)注耗時(shí)區(qū)間。

訪問(wèn)ES的耗時(shí)平均 4062 ~ 4798ms。隨著要查詢的訂單數(shù)線性增長(zhǎng)。
批量調(diào)用詳情API 的平均 532 ~ 570 ms (5個(gè)并發(fā))。
Hbase 訪問(wèn)的 getRowsWithColumnPrefixFilter 平均 40 ~ 45 ms , scanByPrefixFilterList 平均 10 ~ 15 ms 。注意，這并不代表 batchGet 的性能比 scanByPrefixFilterList 差。因?yàn)?batchGet 一次取 500 個(gè) rowkey 的數(shù)據(jù)，而 scanByPrefixFilterList 為了避免超時(shí)一次才取 200 個(gè) rowkey 數(shù)據(jù)。
appendItemsReportCommon：平均 1996 ~ 2304 ms 。這個(gè)方法是生成報(bào)表加格式化報(bào)表字段數(shù)據(jù)加寫文件�？梢�(jiàn)，格式化報(bào)表字段數(shù)據(jù)的耗時(shí)還是比較多的。
generateReportDatas：報(bào)表字段格式化耗時(shí)，平均 294 ms。
output：向報(bào)表追加數(shù)據(jù)耗時(shí)，平均 104 ms。
更新數(shù)據(jù)庫(kù)操作平均 40 ~ 88ms。
創(chuàng)建和寫文件的操作平均 6~15 ms 。 append 內(nèi)容在 100KB ~ 200KB 之間。
上傳文件的操作平均 151~279 ms 。整個(gè)文件的上傳時(shí)間，取決于文件的大小。

注意到，以上是串行策略下運(yùn)行的結(jié)果。也就是所有過(guò)程都是順序執(zhí)行的。順序執(zhí)行策略的優(yōu)點(diǎn)是排除并發(fā)干擾，便于分析基本耗時(shí)。

在多線程情形下，單個(gè)IO操作會(huì)增大，有時(shí)會(huì)達(dá)到 1s ~ 3s 左右。此時(shí)，很容易造成線程阻塞，進(jìn)而影響系統(tǒng)穩(wěn)定性。

小結(jié)

通過(guò)方法調(diào)用的次數(shù)統(tǒng)計(jì)及耗時(shí)分析，更清晰地理解了一個(gè)導(dǎo)出請(qǐng)求的總執(zhí)行流程及執(zhí)行耗時(shí)占比，為性能和穩(wěn)定性優(yōu)化提供了有力的數(shù)據(jù)依據(jù)。

參考資料

Aspect Oriented Programming with Spring

標(biāo)簽：大數(shù)據(jù) 代碼開(kāi)發(fā)者權(quán)限數(shù)據(jù)分析數(shù)據(jù)庫(kù)

版權(quán)申明：本站文章部分自網(wǎng)絡(luò)，如有侵權(quán)，請(qǐng)聯(lián)系：west999com@outlook.com
特別注意：本站所有轉(zhuǎn)載文章言論不代表本站觀點(diǎn)！
本站所提供的圖片等素材，版權(quán)歸原作者所有，如需使用，請(qǐng)與原作者聯(lián)系。