Android 函數耗時統計工具之Hugo

Hugo

在前文Android AspectJ詳解中，咱們瞭解了AspectJ的使用場景、特色和基本語法，這篇將從沃神開源的Hugo項目實戰分析AspectJ的用法，加深對AspectJ的理解。

Hugo項目是一個調試函數調用耗時的工具，經過對方法或者類添加@DebugLog註解，在運行時會將函數的耗時打印在控制檯中，一般用於排查函數耗時，或者用於卡頓檢測。

我在舊文中分析過一些卡頓檢測工具，好比Android卡頓檢測之BlockCanary，Matrix系列文章(一) 卡頓分析工具之Trace Canary，與這兩個工具不一樣的是，Hugo需手動經過註解打點，侵入性較高，但量級輕、集成簡單、不受卡頓閾值限制，適合小項目測試使用。

使用方法

1. 項目根目錄build.gradle添加hugo插件依賴

classpath 'com.jakewharton.hugo:hugo-plugin:1.2.1'
複製代碼

2. 主工程或者library的錄build.gradle中聲明hugo插件。

apply plugin: 'com.jakewharton.hugo'
複製代碼

可經過配置開啓或關閉hugo功能。

hugo {
  enabled false
}
複製代碼

3. 在類或方法上聲明@DebugLog註解。

@DebugLog
public String getName(String first, String last) {
  SystemClock.sleep(15);
  return first + " " + last;
}
複製代碼

運行程序會在控制檯會打印函數耗時日誌：

V/Example: ⇢ getName(first="Wandering", last="Guy")
V/Example: ⇠ getName [16ms] = "Wandering Guy"
複製代碼

可見日誌不只會打印函數的耗時 [16ms] ，若是該方法有參數，同時會把實參打印出來。

原理分析

其實整個Hugo項目的源碼很是簡單，也就一百多行代碼，咱們徹底能夠手擼一份。

咱們已經有了AspectJ的預備知識，如今若是讓你實現一個Hugo項目，你會怎麼作呢？三秒思考...

---

個人思路是這樣的，既然要統計方法的耗時，那須要解決的問題主要有兩個：

1. 如何標識須要統計耗時的方法？
2. 如何統計方法的耗時？

對於問題1 一般的作法就是使用自定義註解標識目標方法。

對於問題2 咱們這裏使用AspectJ完成代碼的織入，因爲目標是統計方法的耗時，最簡單的辦法就是在方法執行先後各打一點，而後計算這個時間差，而這裏說的方法先後打點，在AspectJ中不就能夠用 @Around 註解實現嗎？bingo!

使用註解須要額外關注一下保留策略（RetentionPolicy）

這個屬性有三個可選值：

• SOURCE 只保留在源碼中，編譯成class文件後將丟失。
• CLASS 保留在class文件中，加載到虛擬機中將丟棄。
• RUNTIME 運行時仍保留，可經過反射獲取註解信息。

因此三者保留範圍的關係是 RUNTIME > CLASS > SOURCE。

若是咱們使用AspectJ做爲技術方案，應該使用哪一種保留策略呢？

CLASS，由於AspectJ的做用時機是在class文件生成後，所以不能選擇SOURCE，其次切點pattern支持使用註解做爲過濾條件，這就是說在運行時徹底用不到註解信息，所以使用RUNTIME是浪費的。

源碼分析

在Hugo中使用的自定義註解就是@DebugLog。

@Target({TYPE, METHOD, CONSTRUCTOR}) @Retention(CLASS)
public @interface DebugLog {
}
複製代碼

Retention屬性上面已經分析過了，Target表示能夠註解在哪些地方，咱們要統計方法的耗時天然是要註解在方法上，所以須要 METHOD和CONSTRUCTOR ，爲了方便的統計整個類中全部方法的耗時，Hugo支持 TYPE 。

切面代碼是重點，定義在了Hugo類中。

@Aspect
public class Hugo {
  //①
  @Pointcut("within(@hugo.weaving.DebugLog *)")
  public void withinAnnotatedClass() {}

  //②
  @Pointcut("execution(!synthetic * *(..)) && withinAnnotatedClass()")
  public void methodInsideAnnotatedType() {}

  //③
  @Pointcut("execution(!synthetic *.new(..)) && withinAnnotatedClass()")
  public void constructorInsideAnnotatedType() {}

  //④
  @Pointcut("execution(@hugo.weaving.DebugLog * *(..)) || methodInsideAnnotatedType()")
  public void method() {}
  
  //⑤
  @Pointcut("execution(@hugo.weaving.DebugLog *.new(..)) || constructorInsideAnnotatedType()")
  public void constructor() {}
  
  //⑥
  @Around("method() || constructor()")
  public Object logAndExecute(ProceedingJoinPoint joinPoint) throws Throwable {
    ...
  }
 }
複製代碼

切點表達式比較複雜，大體分爲兩類，一類是方法一類是構造函數，知足其一就能夠，對應⑥。

①處within表達式聲明的是一個TypePattern，也就是類型限制，範圍是任意聲明DebugLog註解的類型。

②處使用條件運算，指代任意聲明瞭DebugLog註解的類中全部非內部類中的方法。再結合④處，加上那些被DebugLog註解修飾的任意方法，這樣就構成了全部method的範圍。簡而言之，也分爲兩部分：

• 全部聲明瞭DebugLog註解的類中全部的方法。
• 全部聲明瞭DebugLog註解的方法。

切點表達式中使用了 !synthetic 排除內部類中的方法 是爲了不再次爲內部類聲明DebugLog註解時重複織入的問題。

對於構造函數的切點表達式，同理。

切點選好了，咱們來看具體織入的代碼。

@Around("method() || constructor()")
public Object logAndExecute(ProceedingJoinPoint joinPoint) throws Throwable {
    enterMethod(joinPoint);
    //start 打點
    long startNanos = System.nanoTime();
    Object result = joinPoint.proceed();
    //end 打點
    long stopNanos = System.nanoTime();
    //計算耗時
    long lengthMillis = TimeUnit.NANOSECONDS.toMillis(stopNanos - startNanos);
    
    exitMethod(joinPoint, result, lengthMillis);
    
    return result;
}
複製代碼

顯然就是在切點代碼 joinPoint.proceed() 先後打上時間戳。

來看enterMethod：

private static void enterMethod(JoinPoint joinPoint) {
    if (!enabled) return;

    CodeSignature codeSignature = (CodeSignature) joinPoint.getSignature();

    Class<?> cls = codeSignature.getDeclaringType();
    //獲取方法名
    String methodName = codeSignature.getName();
    //方法參數列表
    String[] parameterNames = codeSignature.getParameterNames();
    //方法參數值列表
    Object[] parameterValues = joinPoint.getArgs();

    //字符串拼接
    StringBuilder builder = new StringBuilder("\u21E2 ");
    builder.append(methodName).append('(');
    for (int i = 0; i < parameterValues.length; i++) {
      if (i > 0) {
        builder.append(", ");
      }
      builder.append(parameterNames[i]).append('=');
      builder.append(Strings.toString(parameterValues[i]));
    }
    builder.append(')');

    if (Looper.myLooper() != Looper.getMainLooper()) {
      builder.append(" [Thread:\"").append(Thread.currentThread().getName()).append("\"]");
    }
    //打印日誌
    Log.v(asTag(cls), builder.toString());
    ...
  }
複製代碼

執行完enterMethod方法就打印出了相似這樣的日誌。

V/Example: ⇢ getName(first="Wandering", last="Guy")
複製代碼

再來看exitMethod：

private static void exitMethod(JoinPoint joinPoint, Object result, long lengthMillis) {
    if (!enabled) return;
    
    Signature signature = joinPoint.getSignature();
    
    Class<?> cls = signature.getDeclaringType();
    String methodName = signature.getName();
    //判斷是否有返回值
    boolean hasReturnType = signature instanceof MethodSignature
    && ((MethodSignature) signature).getReturnType() != void.class;
    
    //打印函數耗時
    StringBuilder builder = new StringBuilder("\u21E0 ")
    .append(methodName)
    .append(" [")
    .append(lengthMillis)
    .append("ms]");
    
    //打印返回值
    if (hasReturnType) {
    builder.append(" = ");
    builder.append(Strings.toString(result));
    }
    
    Log.v(asTag(cls), builder.toString());
}
複製代碼

這樣就輸出了相似這樣的日誌：

V/Example: ⇠ getName [16ms] = "Wandering Guy"
複製代碼

總結

整個流程分析下來，並無很複雜的地方，咱們徹底能夠借鑑Hugo的思路完成一些常見場景的AOP需求。

咱們經常使用的滬江 aspectjx插件 正是受Hugo項目的影響而設計，並在AspectJ的基礎上擴展支持AAR, JAR及Kotlin。

開源是神器，吾輩共勉之！