引語

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

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

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

總體思路

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

methodAspect 內(nèi)部含有兩個變量 methodCount, methodCost ，都采用了 ConcurrentHashMap 。這是因為方法執(zhí)行時，可能是多線程寫入這兩個變量。

使用：

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

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

關(guān)注哪些方法

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

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

一般集中在如下包：

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

源代碼

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;

/**
 * 記錄一次請求中,流經(jīng)的所有方法的調(diào)用耗時及次數(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è)計的框架，通常包含一組相互緊密關(guān)聯(lián)的概念。這些概念經(jīng)過精心抽象和提煉而成。 AOP的基本概念主要有：

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

采用多種策略

@Around(“@annotation(zzz.study.aop.MethodMeasureAnnotation)”) 僅僅指定了在攜帶指定注解的方法上執(zhí)行。實(shí)際上，可以指定多種策略，比如指定類，指定包下。可以使用邏輯運(yùn)算符 || , && , ! 來指明這些策略的組合。 例如：

@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表達(dá)式

@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開頭的所有方法
• 參數(shù)匹配（(param-pattern)）可以指定具體的參數(shù)類型，多個參數(shù)間用“,”隔開，各個參數(shù)也可以用“”來表示匹配任意類型的參數(shù)，如(String)表示匹配一個String參數(shù)的方法；(,String) 表示匹配有兩個參數(shù)的方法，第一個參數(shù)可以是任意類型，而第二個參數(shù)是String類型；可以用(..)表示零個或多個任意參數(shù)
• 異常類型匹配（throws-pattern?）其中后面跟著“?”的是可選項。

何時不會被通知

并不是滿足 pointcut 指定條件的所有方法都會執(zhí)行切面邏輯。 如果類 C 有三個公共方法，a,b,c ; a 調(diào)用 b ，b 調(diào)用 c 。會發(fā)現(xiàn) b,c 是不會執(zhí)行切面邏輯的。這是因為Spring的AOP主要基于動態(tài)代理機(jī)制。當(dāng)調(diào)用 a 時，會調(diào)用代理的 a 方法，也就進(jìn)入到切面邏輯，但是當(dāng) a 調(diào)用 b 時， b 是直接在目標(biāo)對象上執(zhí)行，而不是在代理對象上執(zhí)行，因此，b 是不會進(jìn)入到切面邏輯的。總結(jié)下，如下情形是不會執(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.

其含義是說，a, b 都是類 C 的方法，a 調(diào)用了 b ；如果需要對 b 方法進(jìn)行切面，那么最好能將 b 抽離出來放在類D的公共方法中，因為 b 是一個需要切面關(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]
// ...

耗時占比

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

耗時細(xì)分

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

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

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

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

小結(jié)

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

參考資料

• Aspect Oriented Programming with Spring

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

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