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。

开源是神器，吾辈共勉之！