Android 函数耗时统计工具之Hugo

·  阅读 4642

Hugo

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

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

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

使用方法

  1. 项目根目录build.gradle添加hugo插件依赖
classpath 'com.jakewharton.hugo:hugo-plugin:1.2.1'
复制代码
  1. 主工程或者library的录build.gradle中声明hugo插件。
apply plugin: 'com.jakewharton.hugo'
复制代码

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

hugo {
  enabled false
}
复制代码
  1. 在类或方法上声明@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。

开源是神器,吾辈共勉之!

分类:
Android
标签:
分类:
Android
标签: