Android 函数耗时统计工具之Hugo

Hugo

在前文Android AspectJ详解中，我们了解了AspectJ的使用场景、特点和基本语法，这篇将从沃神开源的Hugo项目实战分析AspectJ的用法，加深对AspectJ的理解。

Hugo项目是一个调试函数调用耗时的工具，通过对方法或者类添加@DebugLog注解，在运行时会将函数的耗时打印在控制台中，通常用于排查函数耗时，或者用于卡顿检测。

我在旧文中分析过一些卡顿检测工具，比如Android卡顿检测之BlockCanary，Matrix系列文章(一) 卡顿分析工具之Trace Canary，与这两个工具不同的是，Hugo需手动通过注解打点，侵入性较高，但量级轻、集成简单、不受卡顿阈值限制，适合小项目测试使用。

使用方法

项目根目录build.gradle添加hugo插件依赖

classpath 'com.jakewharton.hugo:hugo-plugin:1.2.1'

主工程或者library的录build.gradle中声明hugo插件。

apply plugin: 'com.jakewharton.hugo'

可通过配置开启或关闭hugo功能。

hugo {
  enabled false
}

在类或方法上声明@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 我们这里使用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。

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