背景
需要对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; protected int mLevel = 0 ; public BaseTimeTracer (int maxLevel) { mMaxLevel = maxLevel; mTimes = new long [mMaxLevel]; mNames = new String[mMaxLevel]; } 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(); 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]; 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 { 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 { 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,使用不同的颜色和尺寸,直观的展示每个耗时方法;还可以对结果进行排序,显示最耗时的方法等。