如何统计一段函数耗时？你一定会想到在我们执行函数的前后记录时间戳，作差值即函数的耗时时间
long begin = SystemClock.uptimeMillis();
method1();
long durTime = SystemClock.uptimeMillis() - begin;
手动实现非常简单，但是作为一个性能监控框架想要无侵入的统计业务方的函数耗时就行不通了，我们不可能让业务方全部自己手动调，那样即不优雅也很效率低下。高效的方法就是我们自动把这段代码插入到监听函数前后，最后进行统计即可知道时间。也就是业内常说的插桩.
属性安卓打包流程的会知道从Java代码转成Class再到Dex文件以及DEX生成APK得过程中，这期间我们都可以进行hook插入自己的代码。
Matrix的原理是在class转dex文件阶段，通过自定义transform插件，利用ASM工具来操作修改.class文件。在每个方法执行前后插入AppMethodBeat.i 和AppMethodBeat.o方法，在运行期计算两个的差值就得到方法的耗时。
如下图所示
- 在onMethodEnter()中插入AppMethodBeat.i方法
- 收集所有的Activity及其子类，在onWindowFocusChange方法中插入AppMethodBeat.at方法
- 在onMethodExit() 插入 AppMethodBeat.o 方法
- 注意：并不是所有的方法都执行插桩，只有属于我们需要收集的方法才会走插桩逻辑，优化插桩性能
i和o就是记录的函数前后的时间戳，当然这只是一个通俗简单的说法，内部的细节比我们想象的要复杂，非常值得研究和学习，在学习编译插桩以及耗时的最终分析原理以前深入了解AppMethodBeat是我们往后阅读的基础。
AppMethodBeat类是一个核心类，主要负责方法调用耗时的统计和存储、堆栈的获取等。 和 StartupTracer、LooperAnrTrace、EvilMethodTrace都有着密不可分的联系。
下面我们从初始化入口和提供的功能API入手
为了更好的阅读，先提前暴露个彩蛋，函数耗时因为也涉及到APP启动耗时的监控，所以会先在Application初始化，当进行第一个函数时间记录时，首先会执行i()
public static void i(int methodId) {
if (status <= STATUS_STOPPED) {
return;
}
if (methodId >= METHOD_ID_MAX) {
return;
}
if (status == STATUS_DEFAULT) {
synchronized (statusLock) {
if (status == STATUS_DEFAULT) {
//只有第一个方法进来的时候才会走这里,
realExecute();
//修改状态为STATUS_READY
status = STATUS_READY;
}
}
}
//省略...
最终走到realExecute()方法:
private static void realExecute() {
MatrixLog.i(TAG, "[realExecute] timestamp:%s", System.currentTimeMillis());
//1， 更新耗时偏移
sCurrentDiffTime = SystemClock.uptimeMillis() - sDiffTime;
//2，移除静态代码块中的第一次自毁task
sHandler.removeCallbacksAndMessages(null);
//3， 5ms 更新下时间戳。
sHandler.postDelayed(sUpdateDiffTimeRunnable, Constants.TIME_UPDATE_CYCLE_MS);
//4， 在第一个方法进入后的15s内如果app没有启用AppMethodBeat功能（也就是没有调用onStart方法，默认是true是启用的），那么我们就自己主动关闭，我愿意称之为第二次自毁task。
sHandler.postDelayed(checkStartExpiredRunnable = new Runnable() {
@Override
public void run() {
synchronized (statusLock) {
MatrixLog.i(TAG, "[startExpired] timestamp:%s status:%s", System.currentTimeMillis(), status);
if (status == STATUS_DEFAULT || status == STATUS_READY) {
status = STATUS_EXPIRED_START;
}
}
}
}, Constants.DEFAULT_RELEASE_BUFFER_DELAY);
//5， hook 系统的handlerCallback ，处理自己的逻辑
ActivityThreadHacker.hackSysHandlerCallback();
//6，注册looper的回调监听
LooperMonitor.register(looperMonitorListener);
}
1 耗时偏移量 sCurrentDiffTime是什么鬼？我们先看成员变量：
//偏移量
private volatile static long sCurrentDiffTime = SystemClock.uptimeMillis();
//sDiffTime 被赋值一次，后面不会变化。只需要通过在子线程中5ms间隔，维护一个偏移量
private volatile static long sDiffTime = sCurrentDiffTime;
平时我们计算某个函数的耗时，就是在方法执行前后两次调用SystemClock.uptimeMillis()，计算差值即可。但是SystemClock.uptimeMillis()本身就存在耗时，matrix存在大量的计算耗时逻辑。如果直接调用势必会影响到调用链底层的方法耗时统计，造成误差。
因此，matrix做了如下优化： 通过维护基准计时变量sDiffTime（这个值是不会变的）。然后在通过开启一个子线程每隔5ms去更新这个值 sCurrentDiffTime = SystemClock.uptimeMillis() - sDiffTime。所以，随着程序的运行，这个值会慢慢变大。
举个例子：
当某个方法A进入i方法时，我们存入sCurrentDiffTime值如：50ms。当A方法执行完毕时调用o方法，由于sCurrentDiffTime一直会被更新，此时为500ms。那么，我们直接做一次差值就知道A方法的耗时为： 450ms。这样虽然有5ms左右的误差，但是对于卡顿耗时来说并不影响。确实不错呀！
2 移除静态代码块中的第一次自毁task 我们先看静态代码块：
static {
sHandler.postDelayed(new Runnable() {
@Override
public void run() {
realRelease();
}
// 常量为15s
}, Constants.DEFAULT_RELEASE_BUFFER_DELAY);
}
我们知道，静态代码块在类加载的时候就执行了，且执行一次。
private static void realRelease() {
synchronized (statusLock) {
// 15s后，如果还没方法进入则自我销毁吧
if (status == STATUS_DEFAULT) {
MatrixLog.i(TAG, "[realRelease] timestamp:%s", System.currentTimeMillis());
sHandler.removeCallbacksAndMessages(null);
//解绑
LooperMonitor.unregister(looperMonitorListener);
//停止更新线程
sTimerUpdateThread.quit();
//情况数组
sBuffer = null;
//修改状态为
status = STATUS_OUT_RELEASE;
}
}
}
等待15后，如果还没有方法方法，就销毁资源。
因此，一旦我们进入realExecute方法就要先移除这个自毁task。
3 5ms更新下偏移量。上面已经分析了偏移量的更新原理。这里我们看sUpdateDiffTimeRunnable的具体代码：
/**
* 更新时间
* update time runnable
*/
private static Runnable sUpdateDiffTimeRunnable = new Runnable() {
@Override
public void run() {
try {
//死循环
while (true) {
while (!isPauseUpdateTime && status > STATUS_STOPPED) {
sCurrentDiffTime = SystemClock.uptimeMillis() - sDiffTime;
//5ms后在更新
SystemClock.sleep(Constants.TIME_UPDATE_CYCLE_MS);
}
//不需要更新时间偏移量，进入wait状态，不要浪费CPU。什么时候唤醒？ 当消息分发主线或告诉你的时候！
//进入等待状态：释放锁、释放CPU，等待其他线程唤醒
synchronized (updateTimeLock) {
updateTimeLock.wait();
}
}
} catch (Exception e) {
MatrixLog.e(TAG, "" + e.toString());
}
}
};
通过死循环5ms去更新下耗时偏移量。但是！！并不是一直都在更新。当dispatcheEnd的时候就停止更新，为什么? 因为此时没有消息要处理，没必要更新浪费CPU资源。一旦有消息处理，则会开启isPauseUpdateTime标志，主线程会通过锁对象updateTimeLock来唤醒正在等待的更新线程 wait notify锁的基本功有没有。
来自UIMonitor的回调
private static void dispatchBegin() {
//消息开始，更新偏移量
sCurrentDiffTime = SystemClock.uptimeMillis() - sDiffTime;
//开始更新偏移量
isPauseUpdateTime = false;
//唤醒更新线程
synchronized (updateTimeLock) {
updateTimeLock.notify();
}
}
private static void dispatchEnd() {
//优秀啊，并不是时刻在更新时间戳的。
isPauseUpdateTime = true;
}
4 启动第二次自毁task，在第一个方法进入后的15s内如果app没有启用AppMethodBeat功能（也就是没有调用onStart方法，默认是true。是启用的），那么我们就自己主动关闭，我愿意称之为第二次自毁。
sHandler.postDelayed(checkStartExpiredRunnable = new Runnable() {
@Override
public void run() {
synchronized (statusLock) {
MatrixLog.i(TAG, "[startExpired] timestamp:%s status:%s", System.currentTimeMillis(), status);
if (status == STATUS_DEFAULT || status == STATUS_READY) {
status = STATUS_EXPIRED_START;
}
}
}
}, Constants.DEFAULT_RELEASE_BUFFER_DELAY);
5 hook 系统的handlerCallback
public static void hackSysHandlerCallback() {
try {
sApplicationCreateBeginTime = SystemClock.uptimeMillis();
sApplicationCreateBeginMethodIndex = AppMethodBeat.getInstance().maskIndex("ApplicationCreateBeginMethodIndex");
Class<?> forName = Class.forName("android.app.ActivityThread");
Field field = forName.getDeclaredField("sCurrentActivityThread");
field.setAccessible(true);
Object activityThreadValue = field.get(forName);
Field mH = forName.getDeclaredField("mH");
mH.setAccessible(true);
Object handler = mH.get(activityThreadValue);
Class<?> handlerClass = handler.getClass().getSuperclass();
if (null != handlerClass) {
Field callbackField = handlerClass.getDeclaredField("mCallback");
callbackField.setAccessible(true);
Handler.Callback originalCallback = (Handler.Callback) callbackField.get(handler);
HackCallback callback = new HackCallback(originalCallback);
callbackField.set(handler, callback);
}
MatrixLog.i(TAG, "hook system handler completed. start:%s SDK_INT:%s", sApplicationCreateBeginTime, Build.VERSION.SDK_INT);
} catch (Exception e) {
MatrixLog.e(TAG, "hook system handler err! %s", e.getCause().toString());
}
}
主要工作：
- 记录应用启动时间戳
- 反射
ActivityThread类中的mHhandler变量。在反射mH中的mCallback对象。代理接管程序的所有handleMessage回调。 handleMessage中的第一个activity或者service或者receiver启动的时候，认为是application结束回调，记录结束时间戳。
具体内容可查看源码，比较简单。
6 注册looper的回调监听，通过监听消息处理的前后回调来控制耗时偏移量更新线程的开启和暂停。
经过前面章节的分析，我们知道onStart方法是在tracePlugin的start方法中调用的：
>>>TracePlugin.java
public void start() {
if (traceConfig.isAppMethodBeatEnable()) {
AppMethodBeat.getInstance().onStart();
} else {
AppMethodBeat.getInstance().forceStop();
}
}
@Override
public void onStart() {
synchronized (statusLock) {
if (status < STATUS_STARTED && status >= STATUS_EXPIRED_START) {
//1，移除过期自毁程序！！
sHandler.removeCallbacks(checkStartExpiredRunnable);
if (sBuffer == null) {
throw new RuntimeException(TAG + " sBuffer == null");
}
MatrixLog.i(TAG, "[onStart] preStatus:%s", status, Utils.getStack());
//2, 修改状态
status = STATUS_STARTED;
} else {
MatrixLog.w(TAG, "[onStart] current status:%s", status);
}
}
}
- 先移除第二次的自毁task
- 修改状态为STATUS_STARTED
至此，AppMethodBeat算是成功启动起来了。
我们继续深入函数i()
/**
* hook method when it's called in.
*
* @param methodId
*/
public static void i(int methodId) {
if (status <= STATUS_STOPPED) {
return;
}
if (methodId >= METHOD_ID_MAX) {
return;
}
// 状态的启动，
if (status == STATUS_DEFAULT) {
synchronized (statusLock) {
if (status == STATUS_DEFAULT) {
//只有第一个方法进来的时候才会走这里,
realExecute();
status = STATUS_READY;
}
}
}
long threadId = Thread.currentThread().getId();
if (sMethodEnterListener != null) {
sMethodEnterListener.enter(methodId, threadId);
}
//主线程才会执行这个逻辑
if (threadId == sMainThreadId) {
if (assertIn) {
android.util.Log.e(TAG, "ERROR!!! AppMethodBeat.i Recursive calls!!!");
return;
}
assertIn = true;
if (sIndex < Constants.BUFFER_SIZE) {
//合并该方法调用信息为一个long数据
mergeData(methodId, sIndex, true);
} else {
//index超过数组长度，则重新从0开始
sIndex = 0;
mergeData(methodId, sIndex, true);
}
//自增
++sIndex;
assertIn = false;
}
}
主要的工作是记录函数进入时候的方法id和耗时，封装为一个long数据存入到buffer数组中。然后index自增。
我们看下mergeData方法：
private static void mergeData(int methodId, int index, boolean isIn) {
//前提： 消息分发前后都会调用到这里。传入的都是METHOD_ID_DISPATCH。作为一个消息消息帧。
//在每个帧中间或者两帧之间的方法会被记录下来。
if (methodId == AppMethodBeat.METHOD_ID_DISPATCH) {
sCurrentDiffTime = SystemClock.uptimeMillis() - sDiffTime;
}
long trueId = 0L; //默认是out，方法结束标记。那么就是在long的高63位是0。
if (isIn) { //如果是方法开始：，那么就是在long的高63位是1。
trueId |= 1L << 63; //共 1位
}
// 43~62位 是methodId的存储区间，共 20位
trueId |= (long) methodId << 43;
//0~42位 则是耗时存储的位置。 共 43位
//& 0x7FFFFFFFFFFL ,得到是原值：sCurrentDiffTime。
trueId |= sCurrentDiffTime & 0x7FFFFFFFFFFL;
//把以上三个参数组成一个完整的long数据，存入下标中。
sBuffer[index] = trueId;
//标记链表数据为无效，
checkPileup(index);
// 上一次mergeData的下标， 整个数组长度是100万。
sLastIndex = index;
}
- isIn：true表示
i方法，false是o方法 63位 - methodId： 方法id，在编译期插桩分配的 43~62位
- 耗时偏移量：sCurrentDiffTime 0~42位
- 标记链表数据为无效
long的长度是8个字节，所以总共64位刚好存储一个方法的耗时信息。来个图片更形象(图片来自官方)：
checkPileup比较奇怪，我们进入看看
//处理堆积状态，也就是 处理 sBuffer装满后 数据被覆盖的情况 因为当index超过数组长度，则重新从0开始
private static void checkPileup(int index) {
IndexRecord indexRecord = sIndexRecordHead;
//遍历链表
while (indexRecord != null) {
if (indexRecord.index == index || (indexRecord.index == -1 && sLastIndex == Constants.BUFFER_SIZE - 1)) {
//标记无效
indexRecord.isValid = false;
MatrixLog.w(TAG, "[checkPileup] %s", indexRecord.toString());
//删除当前节点，更新头结点。继续遍历
sIndexRecordHead = indexRecord = indexRecord.next;
} else {
//直到，不等则退出循环。至此，链表已经排除掉了旧数据。
break;
}
}
}
sIndexRecordHead代表链表的头结点。如果一直不获取链表中数据（也就是不发生卡顿），那么链表势必会变长，此时buffer数组中存储还是旧数据，当然此时数据也就没有用了。同时index当超过buffer的size后又会重新开始计数。所以当新的index下标处要插入新数据时候，必须要删除之前跟index绑定的链表节点，避免数据冗余。
下面看O()方法
public static void o(int methodId) {
if (status <= STATUS_STOPPED) {
return;
}
if (methodId >= METHOD_ID_MAX) {
return;
}
if (Thread.currentThread().getId() == sMainThreadId) {
if (sIndex < Constants.BUFFER_SIZE) {
mergeData(methodId, sIndex, false);
} else {
sIndex = 0;
mergeData(methodId, sIndex, false);
}
++sIndex;
}
}
同i方法逻辑，存入方法结束时的耗时信息。
at()方法
public static void at(Activity activity, boolean isFocus) {
String activityName = activity.getClass().getName();
if (isFocus) {
if (sFocusActivitySet.add(activityName)) {
synchronized (listeners) {
//回调给startupTrace用来计算activity的启动耗时
for (IAppMethodBeatListener listener : listeners) {
listener.onActivityFocused(activity);
}
}
MatrixLog.i(TAG, "[at] visibleScene[%s] has %s focus!", getVisibleScene(), "attach");
}
} else {
if (sFocusActivitySet.remove(activityName)) {
MatrixLog.i(TAG, "[at] visibleScene[%s] has %s focus!", getVisibleScene(), "detach");
}
}
}
该方法会在activity的onWindowFocusChange时候回调。
- 维护一个activity列表，方便获取顶层activity名字
- 回调给StartupTrace用来计算activity的启动耗时
再看看每一条信息的IndexRecord 内部类
//这玩意儿 是个链表 就是用来记录 重要节点的(index 和 source的对应关系的)
public static final class IndexRecord {
public IndexRecord(int index) {
this.index = index;
}
public IndexRecord() {
this.isValid = false;
}
public int index;
private IndexRecord next;
public boolean isValid = true;
public String source;
//标记为不可用，并从链表中移除
public void release() {
isValid = false;
IndexRecord record = sIndexRecordHead;
IndexRecord last = null;
while (null != record) {
if (record == this) {
if (null != last) {
last.next = record.next;
} else {
sIndexRecordHead = record.next;
}
record.next = null;
break;
}
last = record;
record = record.next;
}
}
@Override
public String toString() {
return "index:" + index + ",\tisValid:" + isValid + " source:" + source;
}
}
maskIndex()方法
创建一个链表的头，或者新建一个节点插入到链表index所属的位置，通过该方法可以标记函数的起点
public IndexRecord maskIndex(String source) {
//链表为空，则新建一个节点。application调用的第一次肯定是null
if (sIndexRecordHead == null) {
//index是数组中的下标。
sIndexRecordHead = new IndexRecord(sIndex - 1);
sIndexRecordHead.source = source;
return sIndexRecordHead;
} else {
IndexRecord indexRecord = new IndexRecord(sIndex - 1);
indexRecord.source = source;
IndexRecord record = sIndexRecordHead;
IndexRecord last = null;
while (record != null) {
if (indexRecord.index <= record.index) {
//last 为空条件：第一次循环
if (null == last) {
// 新节点插到链表头部
IndexRecord tmp = sIndexRecordHead;
sIndexRecordHead = indexRecord;
indexRecord.next = tmp;
} else {
// 把新节点插到last和 next节点的中间。
IndexRecord tmp = last.next;
last.next = indexRecord;
indexRecord.next = tmp;
}
return indexRecord;
}
//last保存的就是最后一个节点
last = record;
//遍历之前的链表节点，直到末尾
record = record.next;
}
//新节点插入到链表末尾
last.next = indexRecord;
//返回新插入的节点
return indexRecord;
}
}
维护了一个链表结构，专门用来存储准备要（有可能不要，不发生卡顿就不需要获取了）获取堆栈的开始节点，绑定index。后面去获取堆栈的时候才知道开始节点（mask的节点）和结束节点（当前的index）。最后去数组中根据开始和结束的下标进行截取堆栈调用信息。
copyData()方法
public long[] copyData(IndexRecord startRecord) {
// startRecord：之前标记的indexRecord。
//endRecord: 当前indexRecord。
return copyData(startRecord, new IndexRecord(sIndex - 1));
}
startRecord就是之前maskIndex()方法标记的节点。结束节点自然是跟当前index绑定的，且next节点为null。
private long[] copyData(IndexRecord startRecord, IndexRecord endRecord) {
// 本质就是index--区间
long current = System.currentTimeMillis();
long[] data = new long[0];
try {
if (startRecord.isValid && endRecord.isValid) {
int length;
int start = Math.max(0, startRecord.index);
int end = Math.max(0, endRecord.index);
//正常逻辑。直接从buffer中拷贝堆栈段
if (end > start) {
length = end - start + 1;
data = new long[length];
System.arraycopy(sBuffer, start, data, 0, length);
} else if (end < start) {
// 因为超过buffer的size后index重新从0计数
// 所以数据就是后半截+前半截，需要copy两次 按照顺序先后半节，然后前半节
length = 1 + end + (sBuffer.length - start);
data = new long[length];
//先获取start-->buffer末尾的数据
System.arraycopy(sBuffer, start, data, 0, sBuffer.length - start);
//再获取0-->end下标的数据
System.arraycopy(sBuffer, 0, data, sBuffer.length - start, end + 1);
}
return data;
}
return data;
} catch (OutOfMemoryError e) {
MatrixLog.e(TAG, e.toString());
return data;
} finally {
MatrixLog.i(TAG, "[copyData] [%s:%s] length:%s cost:%sms", Math.max(0, startRecord.index), endRecord.index, data.length, System.currentTimeMillis() - current);
}
}
通过开始节点和结束节点，从buffer数组中获取调用链信息。注释比较详细~
总结
AppMethodBeat类，维护了方法耗时的统计和获取的核心逻辑，其中涉及到很多精妙思想
- 如子线程更新耗时偏移量，避免获取时间戳本身的耗时就很巧妙
- 数据的增删，插入，合并的操作非常考验链表基本功
- hook 系统的handlercallback来监控活动app的生命周期 本篇不是重点不详细阐述了
- 为了节省空间，存储的数据用long不同位来记录，最多只有7mb!
- 延迟handler的炸弹涉及以及统计开关的状态维护，非常精妙
掌握了该类的基础以后，下章我们就可以具体分析如何把散乱的统计信息进行整合裁剪统计，谢谢你的点赞，是我最大的动力。
