基于AOP思想的Android方法耗时开源分析工具TimeTracer

背景

需要对APP的运行速度进行性能优化,在可能有性能问题的地方手工埋点的做法非常繁琐、效率低下,希望能有一个可以直观易用、自动化、精细化的分析代码耗时的工具。

Android Studio 提供了Profiler工具,其中 CPU Profiler(Instrument模式)可以实现方法耗时的精确追踪并生成火焰图,但是开启后对App的运行性能影响很大,会导致严重的卡顿,影响性能分析。特别是分析滚动卡顿的时候,页面滚动受到了很大影响,几乎没法正常操作App和分析问题。

备注:CPU Profiler有两种模式:

  • Sample模式,每隔一段指定的时长采样堆栈,然后利用堆栈推断方法调用(不保证完全准确)。采样间隔如果设置太大,则不能分析到耗时短但连续多次调用的方法;如果间隔设置太小,会影响性能。
  • Instrument模式,在方法起始和终止时记录时间,精确度高但是对性能影响较大。

另一个可用的方案就是Uber提供的 nanoscope 工具,对性能影响比较小,但是只能在模拟器或者Nexus 6P手机(需要刷机)中使用。

本文介绍一种基于AOP思想实现的分析工具TimeTracer,通过Javassist修改class字节码,对代码进行插桩,再配合一些Java代码,实现精确的方法级耗时分析,并且实测对性能影响很小。

AOP = Aspect Oriented Programming,意为面向切面编程,相关介绍可以网上找到,这里不细说。

整体思路

TimeTracer的源码和Demo工程可在GitHub获取:

https://github.com/jzj1993/TimeTracer

TimeTracer由Gradle插件和Java代码两部分组成。

Gradle插件在每个方法(包括构造函数)的起始和结束处插入一段特定的耗时统计代码。

Java耗时统计代码在方法的起始和结束时获取时间戳,并按照代码调用层级保存到栈中,然后按层级直接输出方法运行耗时。当然也可以进一步开发完善,输出更详细的结果。

TimeTracer可以:

  • 分析指定包 / 类 / 方法中的耗时
  • 分析主线程或指定线程

实现细节

Gradle插件实现

Gradle插件使用Google提供的Transform API,将源码和AAR包中的class取出来,用javassist库修改字节码。为了加速编译过程,用ForkJoinPool并行处理任务。

Gradle插件在每个方法的起始和结束处插入对TimeTracer的调用。

例如原始代码如下:

1
2
3
4
5
6
7
8
9
public class MainActivity {
public void method1() {
method2();
}

private void method2() {
// ...
}
}

经过插件处理后,如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
public class MainActivity {
public void method1() {
TimeTracer.methodStart("MainActivity.method1");
method2();
TimeTracer.methodEnd("MainActivity.method1");
}

private void method2() {
TimeTracer.methodStart("MainActivity.method2");
// ...
TimeTracer.methodEnd("MainActivity.method2");
}
}

Java耗时统计实现

被统计方法的开头和结尾,都会调用TimeTracer的methodStart和methodEnd,TimeTracer中再调用ITracer实例的相应方法。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
public interface ITracer {
void traceStart();
void traceEnd();
void methodStart(String method);
void methodEnd(String method);
}

public class TimeTracer {
private static ITracer TRACER = ITracer.EMPTY_TRACER;
// ...
public static void methodStart(String method) {
TRACER.methodStart(method);
}

public static void methodEnd(String method) {
TRACER.methodEnd(method);
}
}

BaseTimeTracer是ITracer的抽象实现,用于实现通用的分析逻辑。

BaseTimeTracer中用数组实现了一个栈结构,栈指针为level变量,该变量同时也代表方法调用层级。当一个方法调用开始时,将level加一,时间戳入栈。当一个方法调用结束时,将level减一,再次读取时间戳,并从栈中取出一个时间戳。对于同一个线程,方法调用的start和end是对称的,因此这个时间戳就是该方法调用开始时的时间戳,将这两个时间戳相减,即可算出方法耗时。

由于每个方法执行前后都会调用methodStart和methodEnd方法,因此为了减少统计方法自身对性能的影响,这两个方法中应避免耗时操作。

下面给出BaseTimeTracer中的关键代码:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
public abstract class BaseTimeTracer implements ITracer {
/**
* 调用时间。直接用数组实现栈,减小对方法调用耗时的影响。
*/
protected final long[] mTimes;
/**
* 方法名。直接用数组实现栈,减小对方法调用耗时的影响。
*/
protected final String[] mNames;
/**
* 最大调用嵌套层级,也就是栈的容量。调用嵌套深度不能超过此数值,否则可能导致统计出错
*/
private final int mMaxLevel;
/**
* 当前Level,相当于栈的指针
*/
protected int mLevel = 0;

// ....
public BaseTimeTracer(int maxLevel) {
mMaxLevel = maxLevel;
mTimes = new long[mMaxLevel];
mNames = new String[mMaxLevel];
}

// 检查是否满足要求,包括线程的检查。只有在同一个线程,start和end的调用才是对称的。
protected abstract boolean checkMatchStart(String method);
protected abstract boolean checkMatchEnd(String method);
protected abstract long timestamp();

@Override
public void methodStart(String method) {
if (!mEnable !checkMatchStart(method)) {
return;
}
if (mLevel >= mMaxLevel) {
err("max level exceeded, maxLevel = " + mMaxLevel);
return;
}
mTimes[mLevel] = timestamp(); // push
mNames[mLevel] = method;
++mLevel;
}

@Override
public void methodEnd(String method) {
if (!mEnable mLevel <= 0 !checkMatchEnd(method)) {
return;
}
String name = mNames[mLevel - 1];
if (!methodEquals(name, method)) {
return;
}
--mLevel;
long time = timestamp() - mTimes[mLevel]; // pop
output(method, mLevel, time);
}

/**
* 方法耗时输出,可根据需要过滤。
*/
protected void output(String method, int level, long time) {
// ...
log("%s%s: %d ms", space(level), method, time);
}

protected void log(String msg, Object... args) {
Log.w(TAG, String.format(msg, args));
}

protected void err(String msg, Object... args) {
Log.e(TAG, String.format(msg, args));
}

private String space(int level) {
if (level <= 0) {
return "";
}
char[] chars = new char[level];
Arrays.fill(chars, '\t');
return new String(chars);
}
}

ThreadTimeTracer继承自BaseTimeTracer,用于统计指定线程中的耗时操作,其时间戳为当前线程执行时间。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
public class ThreadTimeTracer extends BaseTimeTracer {

private final Looper mLooper;

public ThreadTimeTracer(Looper looper) {
mLooper = looper;
}

@Override
protected boolean checkMatchStart(String method) {
return Looper.myLooper() == mLooper;
}

@Override
protected boolean checkMatchEnd(String method) {
return Looper.myLooper() == mLooper;
}

protected long timestamp() {
return SystemClock.currentThreadTimeMillis();
}
}

Gradle插件配置

在工程中的配置:

1
2
3
4
5
6
7
buildscript {
dependencies {
// 简单起见,这里直接引用plugin模块编译生成的jar文件,不发布maven
classpath files('plugin/output/plugin.jar')
classpath 'org.javassist:javassist:3.20.0-GA'
}
}
1
2
3
4
5
6
7
8
9
10
11
apply plugin: 'TimeTracer'
TimeTracer {
// 指定要处理的完整类名,正则表达式匹配,可以过滤特定的包,
// 不指定则默认处理所有类(TimeTracer自身的实现除外)
// processClassesRegex 'com\\.paincker\\.timetracer\\.demo.*'

// 指定插入到方法开头和结束处的代码,
// 支持简单变量,包括<class-name>,<simple-class-name>,<method-name>
codeBeforeMethod "com.paincker.timetracer.tracer.TimeTracer.methodStart(\"<simple-class-name>.<method-name>\");";
codeAfterMethod "com.paincker.timetracer.tracer.TimeTracer.methodEnd(\"<simple-class-name>.<method-name>\");";
}

使用示例

Demo工程中写了一个简单的RecyclerView,其中onBindView中进行了一些耗时代码调用,导致RecyclerView的滑动卡顿。

为了定位滑动卡顿的具体代码,在Demo工程中配置使用TimeTracer,追踪方法调用。在Demo工程中执行10s,期间滑动RecyclerView,得出Log信息如图,可以看出方法调用层级和耗时。

很容易看出来耗时的方法,stringOperation占用了较多时间,是造成滑动卡顿的主要原因。

备注:

  • 这里只是一个简单示例,onBindView中代码不多,因此直接人工也能定位到问题,代码调用层级复杂的时候,工具才能更充分的发挥优势。
  • 统计插件自身也有性能消耗,调用层级越深,消耗越多。不过由于其中的代码较简单,每次执行时间都是微秒级别的,而且所有方法都有相似的逻辑,因此采集到数据的参考价值仍然较高。

下图为使用Android Studio自带CPU Profiler生成的结果(Trace模式)。

CPU Profiler和TimeTracer对比

CPU Profiler

TimeTracer

使用方法

AndroidStudio在Debug环境下直接按钮启动、停止分析,并查看数据

先写代码,编译打包后测试,通过代码控制启动时机

测试范围

APP范围内所有线程所有方法,包括系统API的调用

工程中的所有方法,可根据需要写代码进行过滤,重点分析某个包、某个线程、特定条件下的代码

数据查看

支持火焰图等形式

使用Log输出,能满足最简单基本的需要,也可以自行开发扩展

优点

图形化界面比较直观

运行速度快,不影响App操作;可定制性强(例如分析指定条件下的数据,结合自动化工具实现数据收集等)

缺点

容易导致电脑和手机卡死,特别是影响手机App正常操作;功能灵活度有限

不能查看APP以外的代码耗时,不过问题不大,因为一般都是优化项目本身的代码;Log输出的方式比较简陋

总结

由于TimeTracer需要对大量方法插入代码,进行精确耗时分析,数据量较大,本身对性能有一定的影响。因此主要用于开发和测试阶段分析性能,不宜用于线上环境。

从进一步优化的角度来看,可以将统计信息输出成可视化的HTML,使用不同的颜色和尺寸,直观的展示每个耗时方法;还可以对结果进行排序,显示最耗时的方法等。