騰訊效能監控框架Matrix原始碼分析之第一篇
概述
前幾天騰訊將一款Android應用效能監控的框架matrix開源了，原始碼地址在github.com/Tencent/mat…，作者是微信終端團隊。matrix到底是什麼？據官方說法如下：
Matrix 是一款微信研發並日常使用的 APM（Application Performance Manage），當前主要執行在 Android 平臺上。 Matrix 的目標是建立統一的應用效能接入框架，通過各種效能監控方案，對效能監控項的異常資料進行採集和分析，輸出相應的問題分析、定位與優化建議，從而幫助開發者開發出更高質量的應用。
Matrix 當前監控範圍包括：應用安裝包大小，幀率變化，啟動耗時，卡頓，慢方法，SQLite 操作優化，檔案讀寫，記憶體洩漏等等（此段擷取自matrix的GitHub介紹）
下面直接看原始碼：
程式碼的入口在application的onCreate()裡進行初始化的，
Matrix.Builder builder = new Matrix.Builder(this);
```
//省略了一部分構造器建立物件的一段程式碼，這裡僅說明是入口
```
Matrix.init(builder.build());
複製程式碼和leakcanary等庫一樣在application初始化，Matrix的建立採用了常用的構造器模式，現在進入Matrix內部看看
private static volatile Matrix sInstance;
private final HashSet<Plugin> plugins;//外掛集合
private final Application application;
private final PluginListener pluginListener;
private Matrix(Application app, PluginListener listener, HashSet<Plugin> plugins) {
this.application = app;
this.pluginListener = listener;
this.plugins = plugins;
for (Plugin plugin : plugins) {
plugin.init(application, pluginListener);
pluginListener.onInit(plugin);
}
}
public static void setLogIml(MatrixLog.MatrixLogImp imp) {
MatrixLog.setMatrixLogImp(imp);
}
public static boolean isInstalled() {
return sInstance != null;
}
public static Matrix init(Matrix matrix) {
if (matrix == null) {
throw new RuntimeException("Matrix init, Matrix should not be null.");
}
synchronized (Matrix.class) {
if (sInstance == null) {
sInstance = matrix;
} else {
MatrixLog.e(TAG, "Matrix instance is already set. this invoking will be ignored");
}
}
return sInstance;
}
複製程式碼matrix裡持有一個外掛的集合plugins，使用的是hashSet來保證不出現重複，還有一個plugin狀態的監聽pluginListener。Matrix採用了單例模式，volatile sInstance保證執行緒可見行，初始化的時候採用了雙重檢查，在建構函式裡給變數賦值並遍歷plugins集合，並逐個呼叫外掛的初始化方法plugin.init()。
那外掛plugin是什麼呢？下面是plugin的程式碼：
public abstract class Plugin implements IPlugin, IssuePublisher.OnIssueDetectListener {
private static final String TAG = "Matrix.Plugin";
public static final int PLUGIN_CREATE = 0x00;
public static final int PLUGIN_INITED = 0x01;
public static final int PLUGIN_STARTED = 0x02;
public static final int PLUGIN_STOPPED = 0x04;
public static final int PLUGIN_DESTROYED = 0x08;
private PluginListener pluginListener;
private Application application;
private boolean isSupported = true;
private int status = PLUGIN_CREATE;
@Override
public void init(Application app, PluginListener listener) {
if (application != null || pluginListener != null) {
throw new RuntimeException("plugin duplicate init, application or plugin listener is not null");
}
status = PLUGIN_INITED;
this.application = app;
this.pluginListener = listener;
}
@Override
public void onDetectIssue(Issue issue) {
pluginListener.onReportIssue(issue);
}
public Application getApplication() {
return application;
}
@Override
public void start() {
//省略部分程式碼
pluginListener.onStart(this);
}
@Override
public void stop() {
//省略部分程式碼
pluginListener.onStop(this);
}
@Override
public void destroy() {
//省略部分程式碼
pluginListener.onDestroy(this);
}
}
複製程式碼plugin它是個抽象類，繼承了IPlugin和 IssuePublisher.OnIssueDetectListener，IPlugin包括了五種外掛的狀態分別是CREATE、INITED、STARTED、STOPPED和DESTROYED，當plugin狀態發生變化時將回撥交給pluginListener來處理。OnIssueDetectListener介面是IssuePublisher類裡的內部介面，IssuePublisher具體做了兩件事，記錄問題和暴露問題，其暴露問題的方法就是空實現然後暴露介面，交給實現OnIssueDetectListener介面的具體類來處理，Plugin繼承了這個OnIssueDetectListener介面，但它也沒自己處理，也是同樣交留pluginListener來處理。
第一段小結
- Matrix是個單例，它維護著外掛的集合plugins和外掛不同狀態及報錯的處理介面
- pluginListener，這個pluginListener是plugins集合共有的，
- matrix初始化的時候會逐個呼叫plugin 的init方法。
- 外掛Plugin是個抽象類，具體的外掛需要實現的，matrix框架裡自帶的外掛有
TracePlugin、IOCanaryPlugin、SQLiteLintPlugin、ResourcePlugin。
下面會一一檢視它們的作用和具體實現
TracePlugin
首先來看TracePlugin，它繼承自plugin，裡面包括四個維度FrameTracer、FPSTracer、 EvilMethodTracer、StartUpTracer來分析app的，初始化的方法如下：
@Override
public void init(Application app, PluginListener listener) {
super.init(app, listener);
MatrixLog.i(TAG, "trace plugin init, trace config: %s", mTraceConfig.toString());
//低版本不支援
if (Build.VERSION.SDK_INT < Build.VERSION_CODES.JELLY_BEAN) {
MatrixLog.e(TAG, "[FrameBeat] API is low Build.VERSION_CODES.JELLY_BEAN(16), TracePlugin is not supported");
unSupportPlugin();
return;
}
ApplicationLifeObserver.init(app);
mFrameTracer = new FrameTracer(this);
//開關，可以選擇不開
if (mTraceConfig.isMethodTraceEnable()) {
mStartUpTracer = new StartUpTracer(this, mTraceConfig);
}
if (mTraceConfig.isFPSEnable()) {
mFPSTracer = new FPSTracer(this, mTraceConfig);
}
if (mTraceConfig.isMethodTraceEnable()) {
mEvilMethodTracer = new EvilMethodTracer(this, mTraceConfig);
}
}
複製程式碼ApplicationLifeObserver.init(app)是利用了application的ActivityLifecycleCallbacks可以對每個activity的生命週期進行監控做了個觀察者模式，另外加了判斷分析當前app是在前臺還是後臺，具體實現方式是記錄onActivityResumed和onActivityPaused的生命週期，由於新起的activity的onResume會在底層activity的onPause之後，如果onActivityPaused之後600ms沒有執行到onActivityResumed則認為當前處於後臺。仔細想想這麼做會有誤傷，如果有個activity啟動特別慢，此時超過600ms則判定已經處於後臺了，不過這個影響比較小，因為activity啟動之後到resume時就又恢復成正常的前臺，即使誤判也不影響檢測，具體實現可以看原始碼。
在TracePlugin初始化的時候，分別新建了mStartUpTracer、mFPSTracer、mFrameTracer和mEvilMethodTracer，其中的引數mTraceConfig是個簡單的配置類，只是記錄了開關就不在這展開了。檢視matrix的demo開始檢測的入口是tracePlugin.start()裡，程式碼如下：
@Override
public void start() {
super.start();
if (!isSupported()) {
return;
}
new Handler(Looper.getMainLooper()).post(new Runnable() {
@Override
public void run() {
//保證在主執行緒呼叫
FrameBeat.getInstance().onCreate();
}
});
if (null != mFPSTracer) {
mFPSTracer.onCreate();
}
if (null != mEvilMethodTracer) {
mEvilMethodTracer.onCreate();
}
if (null != mFrameTracer) {
mFrameTracer.onCreate();
}
if (null != mStartUpTracer) {
mStartUpTracer.onCreate();
}
}
複製程式碼在onstart時在主執行緒中呼叫了FrameBeat.getInstance().onCreate()，這裡是做UI分析用的。
目前做UI效能卡頓分析一般有兩種方式：
一是利用主執行緒looper的loop方法在尋找msg.target.dispatchMessage(msg)時的前後會分別列印一段log，可以利用log的內容不同或者log的前後次數記錄兩次log的時間差，這樣就可以大致認為是主執行緒處理msg的時間，如果時間過長則認為卡頓；
二是利用Choreographer，Choreographer就是一個訊息處理器，根據vsync 訊號 來計算frame，在doFrame方法裡可以收到回撥的當前時間，正常繪製兩次doFrame的時間差應該是1000/60=16.6666毫秒（每秒60幀），但是遇到卡頓或過度重繪等會導致時間拉長。
這裡採用的是第二種方式，其doFrame的實現如下：
@Override
public void doFrame(long frameTimeNanos) {
if (isPause) {
return;
}
if (frameTimeNanos < mLastFrameNanos || mLastFrameNanos <= 0) {
mLastFrameNanos = frameTimeNanos;
if (null != mChoreographer) {
mChoreographer.postFrameCallback(this);
}
return;
}
if (null != mFrameListeners) {
for (IFrameBeatListener listener : mFrameListeners) {
listener.doFrame(mLastFrameNanos, frameTimeNanos);
}
if (null != mChoreographer) {
mChoreographer.postFrameCallback(this);
}
mLastFrameNanos = frameTimeNanos;
}
}
複製程式碼記錄兩次doFrame的時間，交給mFrameListeners執行回撥。
下面會分析mFPSTracer 、mFrameTracer、mFrameTracer和mStartUpTracer 的onCreate方法的具體實現，這四個類都繼承了BaseTracer類，因此在分析得前先看下BaseTracer，
public abstract class BaseTracer extends IssuePublisher implements ApplicationLifeObserver.IObserver, IFrameBeatListener, IMethodBeatListener {
private final TracePlugin mPlugin;
private static final MethodBeat sMethodBeat = new MethodBeat();
private static final HashMap<Class<BaseTracer>, BaseTracer> sTracerMap = new HashMap<>();
BaseTracer(TracePlugin plugin) {
super(plugin);
this.mPlugin = plugin;
sTracerMap.put((Class<BaseTracer>) this.getClass(), this);
}
@Override
public void doFrame(long lastFrameNanos, long frameNanos) {
}
public void onCreate() {
MatrixLog.i(TAG, "[onCreate] name:%s process:%s", this.getClass().getCanonicalName(), Process.myPid());
if (isEnableMethodBeat()) {
if (!getMethodBeat().isHasListeners()) {
getMethodBeat().onCreate();
}
getMethodBeat().registerListener(this);
}
ApplicationLifeObserver.getInstance().register(this);
FrameBeat.getInstance().addListener(this);
isCreated = true;
}
public void onDestroy() {
MatrixLog.i(TAG, "[onDestroy] name:%s process:%s", this.getClass().getCanonicalName(), Process.myPid());
if (isEnableMethodBeat()) {
getMethodBeat().unregisterListener(this);
if (!getMethodBeat().isHasListeners()) {
getMethodBeat().onDestroy();
}
}
ApplicationLifeObserver.getInstance().unregister(this);
FrameBeat.getInstance().removeListener(this);
isCreated = false;
}
protected void sendReport(JSONObject jsonObject, String tag) {
Issue issue = new Issue();
issue.setTag(tag);
issue.setContent(jsonObject);
mPlugin.onDetectIssue(issue);
}
}
複製程式碼這裡擷取了一部分核心的程式碼，BaseTracer裡有個靜態的hashMap，類名作為key，value是具體的BaseTracer物件，它是靜態的所以只會有一份，在onCreate裡註冊了前面說到的ApplicationLifeObserver和FrameBeat的監聽，監聽activity的生命週期的回撥和Choreographer兩次繪製的時間的介面回撥，回撥是交給自己來處理的。另外暴露了sendReport方法，方法裡呼叫的是本地持有的TracePlugin物件的onDetectIssue來處理，這裡和前文Matrix裡plugins與pluginListener相對應上了，plugins裡的onDetectIssue最終都是由pluginListener來處理的。
TracePlugin初步小結
TracePlugin分成四個部分mStartUpTracer、mFPSTracer、mFrameTracer和mEvilMethodTracer，它們都繼承了BaseTracer；
BaseTracer裡監聽了ApplicationLifeObserver，即每個activity的生命週期和前後臺狀態的監聽；
BaseTracer監聽著FrameBeat的每一幀重新整理前後的時間即doFrame(long lastFrameNanos, long frameNanos);
第一個緯度：mFrameTracer
下面我們來看看mFrameTracer
mFrameTracer的具體實現的關鍵方法doFrame
@Override
public void doFrame(final long lastFrameNanos, final long frameNanos) {
if (!isDrawing) {
return;
}
isDrawing = false;
final int droppedCount = (int) ((frameNanos - lastFrameNanos) / REFRESH_RATE_MS);
if (droppedCount > 1) {
for (final IDoFrameListener listener : mDoFrameListenerList) {
listener.doFrameSync(lastFrameNanos, frameNanos, getScene(), droppedCount);
if (null != listener.getHandler()) {
listener.getHandler().post(new Runnable() {
@Override
public void run() {
listener.getHandler().post(new AsyncDoFrameTask(listener,
lastFrameNanos, frameNanos, getScene(), droppedCount));
}
});
}
}
}
}
複製程式碼在doFrame里根據介面繪製的時間差計算，如果超過了正常繪製16.67秒就會在監聽裡把資料回撥出去，這個有兩個回撥方法doFrameSync和doFrameAsync，對應的是同步呼叫和非同步呼叫，非同步的實現方式利用handler機制，其中getScene是當前的activity或fragment的類名。
第二個緯度：EvilMethodTracer
EvilMethodTracer顧名思義就是找到那些邪惡的方法，也就是耗時多的方法，具體實現來看程式碼，
首先EvilMethodTracer繼承了LazyScheduler介面，LazyScheduler介面是個利用handler實現的定時器，程式碼如下：
public class LazyScheduler {
//延遲即間隔時間
private final long delay;
private final Handler mHandler;
private volatile boolean isSetUp = false;
public LazyScheduler(HandlerThread handlerThread, long delay) {
this.delay = delay;
mHandler = new Handler(handlerThread.getLooper());
}
public boolean isSetUp() {
return isSetUp;
}
//開始
public void setUp(final ILazyTask task, boolean cycle) {
if (null != mHandler) {
this.isSetUp = true;
mHandler.removeCallbacksAndMessages(null);
RetryRunnable retryRunnable = new RetryRunnable(mHandler, delay, task, cycle);
mHandler.postDelayed(retryRunnable, delay);
}
}
public void cancel() {
if (null != mHandler) {
this.isSetUp = false;
mHandler.removeCallbacksAndMessages(null);
}
}
public void setOff() {
cancel();
}
public interface ILazyTask {
void onTimeExpire();
}
static class RetryRunnable implements Runnable {
private final Handler handler;
private final long delay;
private final ILazyTask lazyTask;
private final boolean cycle;
RetryRunnable(Handler handler, long delay, ILazyTask lazyTask, boolean cycle) {
this.handler = handler;
this.delay = delay;
this.lazyTask = lazyTask;
this.cycle = cycle;
}
@Override
public void run() {
lazyTask.onTimeExpire();
if (cycle) {
handler.postDelayed(this, delay);
}
}
}
複製程式碼這個定時器的實現利用了handler機制，handler的looper直接從引數handlerThread的執行緒裡獲得，這裡的程式碼並不複雜，只要記住一條就可以，一是定時器支援是否迴圈，執行是會呼叫ILazyTask的onTimeExpire方法。
EvilMethodTracer也是重寫了定時器的onTimeExpire方法，下面來看EvilMethodTracer的具體程式碼。
public EvilMethodTracer(TracePlugin plugin, TraceConfig config) {
super(plugin);
this.mTraceConfig = config;
mLazyScheduler = new LazyScheduler(MatrixHandlerThread.getDefaultHandlerThread(), Constants.DEFAULT_ANR);
mActivityCreatedInfoMap = new HashMap<>();
}
複製程式碼建立時初始化了mLazyScheduler和mActivityCreatedInfoMap，mLazyScheduler，這裡的mLazyScheduler是個定時器Constants.DEFAULT_ANR預設值5秒，用於記錄介面5秒沒響應及ANR，中間有句MatrixHandlerThread.getDefaultHandlerThread()，MatrixHandlerThread是個hadlerThread執行緒管理類，它裡面包含了Matrix預設工作執行緒、主執行緒和一個動態建立新執行緒的容器，getDefaultHandlerThread()方法獲取的是預設工作執行緒的handlerThread。mActivityCreatedInfoMap是用於記錄activity的啟動耗時資訊。具體是怎麼做到的呢？讓我們一步步來看，首先啟動EvilMethodTracer的程式碼如下：
@Override
public void onCreate() {
super.onCreate();
if (!getMethodBeat().isRealTrace()) {
MatrixLog.e(TAG, "MethodBeat don`t work, maybe it`s wrong in trace Build!");
onDestroy();
return;
}
if (this.mAnalyseThread == null) {
this.mAnalyseThread = MatrixHandlerThread.getNewHandlerThread("matrix_trace_analyse_thread");
mHandler = new Handler(mAnalyseThread.getLooper());
}
// set up when onCreate
mLazyScheduler.cancel();
if (ApplicationLifeObserver.getInstance().isForeground()) {
onFront(null);
}
}
複製程式碼這裡先判斷了getMethodBeat().isRealTrace()，MethodBeat是統計ANR和超時Method的重要類，可以說是核心類，一會在展開。
mAnalyseThread是利用MatrixHandlerThread新起了一個執行緒，將並它的looer交給mHandler。EvilMethodTracer重新了doFrame方法：
@Override
public void doFrame(long lastFrameNanos, long frameNanos) {
//isIgnoreFrame為true的時候，一是出現了ANR，二是正在記錄方法的快取滿了
if (isIgnoreFrame) {
//清理快取
mActivityCreatedInfoMap.clear();
//改變標識
setIgnoreFrame(false);
//重置編號
getMethodBeat().resetIndex();
return;
}
//index指的是當前執行的方法對應快取裡的編號
int index = getMethodBeat().getCurIndex();
//hasEntered說明activity已經存在；
if (hasEntered && frameNanos - lastFrameNanos > mTraceConfig.getEvilThresholdNano()) {
MatrixLog.e(TAG, "[doFrame] dropped frame too much! lastIndex:%s index:%s", 0, index);
//兩幀之間相差超過一秒，將快取裡的資料進行分析
handleBuffer(Type.NORMAL, 0, index - 1, getMethodBeat().getBuffer(), (frameNanos - lastFrameNanos) / Constants.TIME_MILLIS_TO_NANO);
}
//重置編號
getMethodBeat().resetIndex();
//取消mLazyScheduler，即清空對應的messageQueue
mLazyScheduler.cancel();
//傳送延遲訊息，預設5秒，意味著五秒中之內沒有回到doframe會執行mLazyScheduler裡的runnable
mLazyScheduler.setUp(this, false);
}
複製程式碼doFrame時間差超過1秒會執行handleBuffer，時間差超過5秒會執行mLazyScheduler裡的onTimeExpire。先來看onTimeExpire方法：
public void onTimeExpire() {
// 進到這裡說明doframe延遲了5秒，視為介面的ANR
//在後臺就忽略
if (isBackground()) {
MatrixLog.w(TAG, "[onTimeExpire] pass this time, on Background!");
return;
}
//起始時間
long happenedAnrTime = getMethodBeat().getCurrentDiffTime();
MatrixLog.w(TAG, "[onTimeExpire] maybe ANR!");
//暫停一次Frame捕捉
setIgnoreFrame(true);
//快取裡的資料可以清空
getMethodBeat().lockBuffer(false);
//分析快取，Type為ANR
handleBuffer(Type.ANR, 0, getMethodBeat().getCurIndex() - 1, getMethodBeat().getBuffer(), null, Constants.DEFAULT_ANR, happenedAnrTime, -1);
}
複製程式碼當執行到onTimeExpire這裡如果是前臺就視為ANR，到目前ANR的捕捉大致知道了，分析資料和doframe一樣也是執行handleBuffer，這裡也再次提到了getMethodBeat()，getMethodBeat返回的是本地持有的物件sMethodBeat，分析資料的方法handleBuffer也會用到sMethodBeat裡的東西，所以分析之前我們先檢視下MethodBeat這個類究竟是做什麼的，分析MethodBeat之後再來看看handleBuffer。
插曲—MethodBeat
MethodBeat類主要做的事是用一個陣列記錄應用執行的每個方法和方法耗時，用的是long[]，使用方法id和耗時進行按位換算得要一個long值作為元素，快取預設長度是一百萬。在MethodBeat開始有這段程式碼：
static {
Hacker.hackSysHandlerCallback();
sCurrentDiffTime = sLastDiffTime = System.nanoTime() / Constants.TIME_MILLIS_TO_NANO;
sReleaseBufferHandler.sendEmptyMessageDelayed(RELEASE_BUFFER_MSG_ID, Constants.DEFAULT_RELEASE_BUFFER_DELAY);
}
複製程式碼進入Hacker.hackSysHandlerCallback
public class Hacker {
private static final String TAG = "Matrix.Hacker";
public static boolean isEnterAnimationComplete = false;
public static long sApplicationCreateBeginTime = 0L;
public static int sApplicationCreateBeginMethodIndex = 0;
public static long sApplicationCreateEndTime = 0L;
public static int sApplicationCreateEndMethodIndex = 0;
public static int sApplicationCreateScene = -100;
public static void hackSysHandlerCallback() {
try {
sApplicationCreateBeginTime = System.currentTimeMillis();
sApplicationCreateBeginMethodIndex = MethodBeat.getCurIndex();
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();
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", sApplicationCreateBeginTime);
} catch (Exception e) {
MatrixLog.e(TAG, "hook system handler err! %s", e.getCause().toString());
}
}
複製程式碼}
這裡利用了反射機制進行了hook，程式碼比較清晰，目的很明確就是利用自己寫的HackCallback來替換ActivityThread類裡的mCallback，達到偷樑換柱的效果，這樣做的意義就是可以攔截mCallback的原有的訊息，然後選擇自己要處理的訊息，HackCallback裡的handleMessage實現如下：
public boolean handleMessage(Message msg) {
if (msg.what == LAUNCH_ACTIVITY) {
Hacker.isEnterAnimationComplete = false;
} else if (msg.what == ENTER_ANIMATION_COMPLETE) {
Hacker.isEnterAnimationComplete = true;
}
if (!isCreated) {
if (msg.what == LAUNCH_ACTIVITY || msg.what == CREATE_SERVICE || msg.what == RECEIVER) {
Hacker.sApplicationCreateEndTime = System.currentTimeMillis();
Hacker.sApplicationCreateEndMethodIndex = MethodBeat.getCurIndex();
Hacker.sApplicationCreateScene = msg.what;
isCreated = true;
}
}
if (null == mOriginalCallback) {
return false;
}
return mOriginalCallback.handleMessage(msg);
}
複製程式碼攔截到了LAUNCH_ACTIVITY和ENTER_ANIMATION_COMPLETE訊息，這樣就知道當前的activity建立到完成的時機。
現在再回到MethodBeat，它繼承了IMethodBeat和ApplicationLifeObserver.IObserver介面，IObserver就是之前用於activity生命週期的監聽，IMethodBeat是用於方法快取資料相關的。在看到這裡原始碼時，我就有個疑惑，相信大多數人和我一樣會有這樣的疑惑：它是如何記錄每個方法的，這些方法的執行時間是怎麼樣計算的？粗略看了一下MethodBeat並沒有找到資料的來源，但是我找到了下面這兩個個方法：
//hook method when it`s called in
public static void i(int methodId) {
if (isBackground) {
return;
}
if (!isRealTrace) {
updateDiffTime();
sTimeUpdateHandler.sendEmptyMessage(UPDATE_TIME_MSG_ID);
sBuffer = new long[Constants.BUFFER_TMP_SIZE];
}
isRealTrace = true;
if (isCreated && Thread.currentThread() == sMainThread) {
if (sIsIn) {
android.util.Log.e(TAG, "ERROR!!! MethodBeat.i Recursive calls!!!");
return;
}
sIsIn = true;
if (sIndex >= Constants.BUFFER_SIZE) {
for (IMethodBeatListener listener : sListeners) {
listener.pushFullBuffer(0, Constants.BUFFER_SIZE - 1, sBuffer);
}
sIndex = 0;
} else {
mergeData(methodId, sIndex, true);
}
++sIndex;
sIsIn = false;
} else if (!isCreated && Thread.currentThread() == sMainThread && sBuffer != null) {
if (sIsIn) {
android.util.Log.e(TAG, "ERROR!!! MethodBeat.i Recursive calls!!!");
return;
}
sIsIn = true;
if (sIndex < Constants.BUFFER_TMP_SIZE) {
mergeData(methodId, sIndex, true);
++sIndex;
}
sIsIn = false;
}
}
//hook method when it`s called out.
public static void o(int methodId) {
if (isBackground || null == sBuffer) {
return;
}
if (isCreated && Thread.currentThread() == sMainThread) {
if (sIndex < Constants.BUFFER_SIZE) {
mergeData(methodId, sIndex, false);
} else {
for (IMethodBeatListener listener : sListeners) {
listener.pushFullBuffer(0, Constants.BUFFER_SIZE - 1, sBuffer);
}
sIndex = 0;
}
++sIndex;
} else if (!isCreated && Thread.currentThread() == sMainThread) {
if (sIndex < Constants.BUFFER_TMP_SIZE) {
mergeData(methodId, sIndex, false);
++sIndex;
}
}
}
複製程式碼這兩個方法的註釋很值得注意：hook method when it`s called in 和hook method when it`s called out，意思是通過hook來執行的，於是大致猜想它實現記錄方法的思路就是在應用執行的每個方法之前呼叫i()，在每個方法結尾呼叫方法o()，記錄方法名稱和o-i的時間差。這兩個方法的最後會執行mergeData方法：
private static void mergeData(int methodId, int index, boolean isIn) {
long trueId = 0L;
if (isIn) {
trueId |= 1L << 63;
}
trueId |= (long) methodId << 43;
trueId |= sCurrentDiffTime & 0x7FFFFFFFFFFL;
sBuffer[index] = trueId;
}
複製程式碼這裡的sCurrentDiffTime就是o()、i()兩個方法直接的時間差，和methodId一起儲存在long裡。
思路有了，它的實現方式呢？既然是用的hook，於是全域性搜尋了這個class的名稱，在matrix-gradle-plugin庫裡找到了MethodTracer這個類，這個類裡找到了如下這段程式碼：
protected TraceMethodAdapter(int api, MethodVisitor mv, int access, String name, String desc, String className,
boolean hasWindowFocusMethod, boolean isMethodBeatClass) {
super(api, mv, access, name, desc);
TraceMethod traceMethod = TraceMethod.create(0, access, className, name, desc);
this.methodName = traceMethod.getMethodName();
this.isMethodBeatClass = isMethodBeatClass;
this.hasWindowFocusMethod = hasWindowFocusMethod;
this.className = className;
this.name = name;
}
@Override
protected void onMethodEnter() {
TraceMethod traceMethod = mCollectedMethodMap.get(methodName);
if (traceMethod != null) {
traceMethodCount.incrementAndGet();
mv.visitLdcInsn(traceMethod.id);
mv.visitMethodInsn(INVOKESTATIC, TraceBuildConstants.MATRIX_TRACE_CLASS, "i", "(I)V", false);
}
}
@Override
protected void onMethodExit(int opcode) {
TraceMethod traceMethod = mCollectedMethodMap.get(methodName);
if (traceMethod != null) {
if (hasWindowFocusMethod && mTraceConfig.isActivityOrSubClass(className, mCollectedClassExtendMap)
&& mCollectedMethodMap.containsKey(traceMethod.getMethodName())) {
TraceMethod windowFocusChangeMethod = TraceMethod.create(-1, Opcodes.ACC_PUBLIC, className,
TraceBuildConstants.MATRIX_TRACE_ON_WINDOW_FOCUS_METHOD, TraceBuildConstants.MATRIX_TRACE_ON_WINDOW_FOCUS_METHOD_ARGS);
if (windowFocusChangeMethod.equals(traceMethod)) {
traceWindowFocusChangeMethod(mv);
}
}
traceMethodCount.incrementAndGet();
mv.visitLdcInsn(traceMethod.id);
mv.visitMethodInsn(INVOKESTATIC, TraceBuildConstants.MATRIX_TRACE_CLASS, "o", "(I)V", false);
}
}
}
private void traceApplicationContext(MethodVisitor mv, TraceMethod traceMethod) {
mv.visitVarInsn(Opcodes.ALOAD, 0);
mv.visitLdcInsn(traceMethod.methodName);
mv.visitLdcInsn(traceMethod.desc);
mv.visitMethodInsn(Opcodes.INVOKESTATIC, TraceBuildConstants.MATRIX_TRACE_CLASS, "trace", "(Ljava/lang/Object;Ljava/lang/String;Ljava/lang/String;)V", false);
}
private void traceWindowFocusChangeMethod(MethodVisitor mv) {
mv.visitVarInsn(Opcodes.ALOAD, 0);
mv.visitVarInsn(Opcodes.ILOAD, 1);
mv.visitMethodInsn(Opcodes.INVOKESTATIC, TraceBuildConstants.MATRIX_TRACE_CLASS, "at", "(Landroid/app/Activity;Z)V", false);
複製程式碼}
這段程式碼是在內部類TraceMethodAdapter裡的，這個內部類又繼承了AdviceAdapter，AdviceAdapter的實現來自引用的org.wo2.asm下的庫，從網上搜了一下，asm是個java位元組碼操縱框架，它可以直接以二進位制形式動態地生成 stub 類或其他代理類，或者在裝載時動態地修改類。ASM 提供類似於 BCEL 和 SERP 之類的工具包的功能，但是被設計得更小巧、更快速，這使它適用於實時程式碼插裝。對於matrix來說，意思就是可以利用asm這個框架進行方法的裝載，在方法前執行“com/tencent/matrix/trace/core/MethodBeat”這個class裡的i()方法，在每個方法最後執行o()方法。頓時覺得漲姿勢了，欲知詳情可以自己這塊的原始碼。
回到EvilMethodTracer
methodBeat裡的方法快取的來源終於有了，現在回到EvilMethodTracer的handleBuffer分析來，先看方法原始碼：
private void handleBuffer(Type type, int start, int end, long[] buffer, ViewUtil.ViewInfo viewInfo, long cost, long happenTime, int subType) {
if (null == buffer) {
MatrixLog.e(TAG, "null == buffer");
return;
}
if (cost < 0 || cost >= Constants.MAX_EVIL_METHOD_COST) {
MatrixLog.e(TAG, "[analyse] trace cost invalid:%d", cost);
return;
}
start = Math.max(0, start);
end = Math.min(buffer.length - 1, end);
if (start <= end) {
long[] tmp = new long[end - start + 1];
System.arraycopy(buffer, start, tmp, 0, end - start + 1);
if (null != mHandler) {
AnalyseExtraInfo info = new AnalyseExtraInfo(type, viewInfo, cost, happenTime);
info.setSubType(subType);
mHandler.post(new AnalyseTask(tmp, info));
}
}
}
複製程式碼這段程式碼比較簡單，意思就是截圖有效的那段資料交給mHandler所在的執行緒來執行，有效的資料即tmp，真正執行的是AnalyseTask的run方法。AnalyseTask的分析方法比較長，大致的思路就是，根據儲存裡的資料即每個方法id和執行時間，找到時間異常的方法，將異常的方法資訊和一些基本資訊儲存在一個JSONObject裡，然後呼叫plugin的sendReport方法，這裡直接擷取分析後釋出的方法：
try {
JSONObject jsonObject = new JSONObject();
jsonObject = DeviceUtil.getDeviceInfo(jsonObject, getPlugin().getApplication());
jsonObject.put(SharePluginInfo.ISSUE_STACK_TYPE, analyseExtraInfo.type.name());
jsonObject.put(SharePluginInfo.ISSUE_SUB_TYPE, analyseExtraInfo.subType);
jsonObject.put(SharePluginInfo.ISSUE_COST, analyseExtraInfo.cost);
if (analyseExtraInfo.type == Type.ENTER) {
JSONObject viewInfoJson = new JSONObject();
ViewUtil.ViewInfo viewInfo = analyseExtraInfo.viewInfo;
viewInfoJson.put(SharePluginInfo.ISSUE_VIEW_DEEP, null == viewInfo ? 0 : viewInfo.mViewDeep);
viewInfoJson.put(SharePluginInfo.ISSUE_VIEW_COUNT, null == viewInfo ? 0 : viewInfo.mViewCount);
viewInfoJson.put(SharePluginInfo.ISSUE_VIEW_ACTIVITY, null == viewInfo ? 0 : viewInfo.mActivityName);
jsonObject.put(SharePluginInfo.ISSUE_VIEW_INFO, viewInfoJson);
}
jsonObject.put(SharePluginInfo.ISSUE_STACK, reportBuilder.toString());
jsonObject.put(SharePluginInfo.ISSUE_STACK_KEY, key);
sendReport(jsonObject);
} catch (JSONException e) {
MatrixLog.e(TAG, "[JSONException for stack %s, error: %s", reportBuilder.toString(), e);
}
複製程式碼最終的格式如下：
{
"machine": 2015,
"detail": "ENTER",
"cost": 3205,
"viewInfo": {
"viewDeep": 10,
"viewCount": 6,
"activity": "TestFpsActivity"
},
"stack": "3,195,1,10
1,33,1,58
2,206,1,21
3,161,1,16
4,180,1,16
5,169,1,16
6,96,1,10
7,98,1,10
4,183,2,5
5,211,6,0
0,30,1,56
",
"stackKey": "0,30,1,56
",
"tag": "Trace_EvilMethod",
"process": "sample.tencent.matrix"
}
複製程式碼EvilMethodTracer就先分析到這裡，下面來看看StartUpTracer
StartUpTracer
StartUpTracer是用於分析activity的啟動時間的，之前在分析MethodBeat時提到了通過hook記錄activity在LAUNCH_ACTIVITY和ENTER_ANIMATION_COMPLETE兩個時間點，兩個時間點在這裡便是利用了起來。實現的核心方法在onActivityEntered()裡：
String activityName = activity.getComponentName().getClassName();
if (!mActivityEnteredMap.containsKey(activityName) || isFocus) {
mActivityEnteredMap.put(activityName, System.currentTimeMillis());
}
if (!isFocus) {
MatrixLog.i(TAG, "[onActivityEntered] isFocus false,activityName:%s", activityName);
return;
}
if (mTraceConfig.isHasSplashActivityName() && activityName.equals(mTraceConfig.getSplashActivityName())) {
MatrixLog.i(TAG, "[onActivityEntered] has splash activity! %s", mTraceConfig.getSplashActivityName());
return;
}
getMethodBeat().lockBuffer(false);
long activityEndTime = getValueFromMap(mActivityEnteredMap, activityName);
long firstActivityStart = getValueFromMap(mFirstActivityMap, mFirstActivityName);
if (activityEndTime <= 0 || firstActivityStart <= 0) {
MatrixLog.w(TAG, "[onActivityEntered] error activityCost! [%s:%s]", activityEndTime, firstActivityStart);
mFirstActivityMap.clear();
mActivityEnteredMap.clear();
return;
}
複製程式碼這是方法的前一段，這裡有兩個hashmap，mFirstActivityMap記錄activity在onCreate時的時間，mActivityEnteredMap記錄activity在onActivityEntered時的時間，onActivityEntered這個方法的呼叫是通過hook實現的在WindowFocusChange執行的，
OnActivityEnter()方法後面的內容是：
long activityCost = activityEndTime - firstActivityStart;
//sApplicationCreateEndTime是methodBeat通過hook得到的
long appCreateTime = Hacker.sApplicationCreateEndTime - Hacker.sApplicationCreateBeginTime;
long betweenCost = firstActivityStart - Hacker.sApplicationCreateEndTime;
long allCost = activityEndTime - Hacker.sApplicationCreateBeginTime;
if (isWarnStartUp) {
betweenCost = 0;
allCost = activityCost;
}
long splashCost = 0;
if (mTraceConfig.isHasSplashActivityName()) {
long tmp = getValueFromMap(mActivityEnteredMap, mTraceConfig.getSplashActivityName());
splashCost = tmp == 0 ? 0 : getValueFromMap(mActivityEnteredMap, activityName) - tmp;
}
if (appCreateTime <= 0) {
MatrixLog.e(TAG, "[onActivityEntered] appCreateTime is wrong! appCreateTime:%s", appCreateTime);
mFirstActivityMap.clear();
mActivityEnteredMap.clear();
return;
}
if (mTraceConfig.isHasSplashActivityName() && splashCost < 0) {
MatrixLog.e(TAG, "splashCost < 0! splashCost:%s", splashCost);
return;
}
EvilMethodTracer tracer = getTracer(EvilMethodTracer.class);
if (null != tracer) {
long thresholdMs = isWarnStartUp ? mTraceConfig.getWarmStartUpThresholdMs() : mTraceConfig.getStartUpThresholdMs();
int startIndex = isWarnStartUp ? mFirstActivityIndex : Hacker.sApplicationCreateBeginMethodIndex;
int curIndex = getMethodBeat().getCurIndex();
if (allCost > thresholdMs) {
MatrixLog.i(TAG, "appCreateTime[%s] is over threshold![%s], dump stack! index[%s:%s]", appCreateTime, thresholdMs, startIndex, curIndex);
EvilMethodTracer evilMethodTracer = getTracer(EvilMethodTracer.class);
if (null != evilMethodTracer) {
evilMethodTracer.handleBuffer(EvilMethodTracer.Type.STARTUP, startIndex, curIndex, MethodBeat.getBuffer(), appCreateTime, Constants.SUBTYPE_STARTUP_APPLICATION);
}
}
}
MatrixLog.i(TAG, "[onActivityEntered] firstActivity:%s appCreateTime:%dms betweenCost:%dms activityCreate:%dms splashCost:%dms allCost:%sms isWarnStartUp:%b ApplicationCreateScene:%s",
mFirstActivityName, appCreateTime, betweenCost, activityCost, splashCost, allCost, isWarnStartUp, Hacker.sApplicationCreateScene);
mHandler.post(new StartUpReportTask(activityName, appCreateTime, activityCost, betweenCost, splashCost, allCost, isWarnStartUp, Hacker.sApplicationCreateScene));
mFirstActivityMap.clear();
mActivityEnteredMap.clear();
isFirstActivityCreate = false;
mFirstActivityName = null;
onDestroy();
複製程式碼這段程式碼統計了application啟動耗時、SplashActivity（歡迎頁）耗時、應用和activity之間的耗時，統計好的格式如下：
{
"machine": 4,
"application_create": 415,
"first_activity_create": 240,
"stage_between_app_and_activity": 0,
"scene": "com.tencent.mm.app.WeChatSplashActivity",
"is_warm_start_up": false,
"tag": "Trace_StartUp",
"process": "com.tencent.mm",
"time": 1528278018147
}
複製程式碼StartUpTracer先分析到這，還剩下最後一個FPSTracer
FPSTracer
FPSTracer統計的是幀率，統計對應的activity、fragment的掉幀水平，利用的也是Choreographer的doFrame(),我們直接來看它的實現：
@Override
public void doFrame(long lastFrameNanos, long frameNanos) {
//isInvalid是值是否在前臺，isDrawing是否開始繪製
if (!isInvalid && isDrawing && isEnterAnimationComplete() && mTraceConfig.isTargetScene(getScene())) {
//分析
handleDoFrame(lastFrameNanos, frameNanos, getScene());
}
isDrawing = false;
}
複製程式碼在開始onDraw開始後，呼叫了handleDoFrame
private void handleDoFrame(long lastFrameNanos, long frameNanos, String scene) {
int sceneId;
if (mSceneToSceneIdMap.containsKey(scene)) {
sceneId = mSceneToSceneIdMap.get(scene);
} else {
//記錄介面的名稱和介面的編號
sceneId = mSceneToSceneIdMap.size() + 1;
mSceneToSceneIdMap.put(scene, sceneId);
mSceneIdToSceneMap.put(sceneId, scene);
}
int trueId = 0x0;
trueId |= sceneId;
trueId = trueId << 22;
//計算此幀的耗時
long offset = frameNanos - lastFrameNanos;
trueId |= ((offset / FACTOR) & 0x3FFFFF);
//超過5秒
if (offset >= 5 * 1000000000L) {
MatrixLog.w(TAG, "[handleDoFrame] WARNING drop frame! offset:%s scene%s", offset, scene);
}
synchronized (this.getClass()) {
//記錄
mFrameDataList.add(trueId);
}
}
複製程式碼在這裡只是做了記錄，內部的定時器mLazyScheduler在onCreate是啟動，時間間隔預設是120秒，
public void onTimeExpire() {
doReport();
}
複製程式碼呼叫doReport()
private void doReport() {
LinkedList<Integer> reportList;
synchronized (this.getClass()) {
if (mFrameDataList.isEmpty()) {
return;
}
reportList = mFrameDataList;
mFrameDataList = new LinkedList<>();
}
//reportList裡的元素包含了sceneId和幀耗時
for (int trueId : reportList) {
int scene = trueId >> 22;
int durTime = trueId & 0x3FFFFF;
LinkedList<Integer> list = mPendingReportSet.get(scene);
if (null == list) {
list = new LinkedList<>();
mPendingReportSet.put(scene, list);
}
list.add(durTime);
}
reportList.clear();
//mPendingReportSet裡取到了scene和其對應的幀內容
for (int i = 0; i < mPendingReportSet.size(); i++) {
int key = mPendingReportSet.keyAt(i);
LinkedList<Integer> list = mPendingReportSet.get(key);
if (null == list) {
continue;
}
int sumTime = 0;
int markIndex = 0;
int count = 0;
int[] dropLevel = new int[DropStatus.values().length]; // record the level of frames dropped each time
int[] dropSum = new int[DropStatus.values().length]; // record the sum of frames dropped each time
int refreshRate = (int) Constants.DEFAULT_DEVICE_REFRESH_RATE * OFFSET_TO_MS;
for (Integer period : list) {
sumTime += period;
count++;
int tmp = period / refreshRate - 1;
if (tmp >= Constants.DEFAULT_DROPPED_FROZEN) {
dropLevel[DropStatus.DROPPED_FROZEN.index]++;
dropSum[DropStatus.DROPPED_FROZEN.index] += tmp;
} else if (tmp >= Constants.DEFAULT_DROPPED_HIGH) {
dropLevel[DropStatus.DROPPED_HIGH.index]++;
dropSum[DropStatus.DROPPED_HIGH.index] += tmp;
} else if (tmp >= Constants.DEFAULT_DROPPED_MIDDLE) {
dropLevel[DropStatus.DROPPED_MIDDLE.index]++;
dropSum[DropStatus.DROPPED_MIDDLE.index] += tmp;
} else if (tmp >= Constants.DEFAULT_DROPPED_NORMAL) {
dropLevel[DropStatus.DROPPED_NORMAL.index]++;
dropSum[DropStatus.DROPPED_NORMAL.index] += tmp;
} else {
dropLevel[DropStatus.DROPPED_BEST.index]++;
dropSum[DropStatus.DROPPED_BEST.index] += (tmp < 0 ? 0 : tmp);
}
if (sumTime >= mTraceConfig.getTimeSliceMs() * OFFSET_TO_MS) { // if it reaches report time
float fps = Math.min(60.f, 1000.f * OFFSET_TO_MS * (count - markIndex) / sumTime);
MatrixLog.i(TAG, "scene:%s fps:%s sumTime:%s [%s:%s]", mSceneIdToSceneMap.get(key), fps, sumTime, count, markIndex);
try {
JSONObject dropLevelObject = new JSONObject();
dropLevelObject.put(DropStatus.DROPPED_FROZEN.name(), dropLevel[DropStatus.DROPPED_FROZEN.index]);
dropLevelObject.put(DropStatus.DROPPED_HIGH.name(), dropLevel[DropStatus.DROPPED_HIGH.index]);
dropLevelObject.put(DropStatus.DROPPED_MIDDLE.name(), dropLevel[DropStatus.DROPPED_MIDDLE.index]);
dropLevelObject.put(DropStatus.DROPPED_NORMAL.name(), dropLevel[DropStatus.DROPPED_NORMAL.index]);
dropLevelObject.put(DropStatus.DROPPED_BEST.name(), dropLevel[DropStatus.DROPPED_BEST.index]);
JSONObject dropSumObject = new JSONObject();
dropSumObject.put(DropStatus.DROPPED_FROZEN.name(), dropSum[DropStatus.DROPPED_FROZEN.index]);
dropSumObject.put(DropStatus.DROPPED_HIGH.name(), dropSum[DropStatus.DROPPED_HIGH.index]);
dropSumObject.put(DropStatus.DROPPED_MIDDLE.name(), dropSum[DropStatus.DROPPED_MIDDLE.index]);
dropSumObject.put(DropStatus.DROPPED_NORMAL.name(), dropSum[DropStatus.DROPPED_NORMAL.index]);
dropSumObject.put(DropStatus.DROPPED_BEST.name(), dropSum[DropStatus.DROPPED_BEST.index]);
JSONObject resultObject = new JSONObject();
resultObject = DeviceUtil.getDeviceInfo(resultObject, getPlugin().getApplication());
resultObject.put(SharePluginInfo.ISSUE_SCENE, mSceneIdToSceneMap.get(key));
resultObject.put(SharePluginInfo.ISSUE_DROP_LEVEL, dropLevelObject);
resultObject.put(SharePluginInfo.ISSUE_DROP_SUM, dropSumObject);
resultObject.put(SharePluginInfo.ISSUE_FPS, fps);
sendReport(resultObject);
} catch (JSONException e) {
MatrixLog.e(TAG, "json error", e);
}
dropLevel = new int[DropStatus.values().length];
dropSum = new int[DropStatus.values().length];
markIndex = count;
sumTime = 0;
}
}
// delete has reported data
if (markIndex > 0) {
for (int index = 0; index < markIndex; index++) {
list.removeFirst();
}
}
if (!list.isEmpty()) {
MatrixLog.d(TAG, "[doReport] sumTime:[%sms < %sms], scene:[%s]", sumTime / OFFSET_TO_MS, mTraceConfig.getTimeSliceMs(), mSceneIdToSceneMap.get(key));
}
}
}
複製程式碼最終解析出來的就是activity對應的幀耗時資料，資料格式如下：
{
"machine": 2015,
"scene": "sample.tencent.matrix.trace.TestFpsActivity",
"dropLevel": {
"DROPPED_HIGH": 4,
"DROPPED_MIDDLE": 12,
"DROPPED_NORMAL": 18,
"DROPPED_BEST": 113
},
"dropSum": {
"DROPPED_HIGH": 60,
"DROPPED_MIDDLE": 96,
"DROPPED_NORMAL": 51,
"DROPPED_BEST": 6
},
"fps": 24.476625442504883,
"tag": "Trace_FPS",
"process": "sample.tencent.matrix"
}
複製程式碼目前tracePlugin的內容分析完了，其中有些資料的計算沒有去展開，大家可以自己檢視。
tracePlugin總結
這裡主要分析得失TracePlugin的實現，其中包括了ANR記錄、超時函式記錄、幀數統計和啟動記錄，這還只是Plugins中的一個，內容已經顯得有點長了，所以我決定後面的IOCanaryPlugin、SQLiteLintPlugin、ResourcePlugin都分成不同文章來分析。
自己才疏學淺，肯定有很多不足的地方，有遺漏或錯誤的地方歡迎指正。
歡迎轉載，註明出處即可，後面的文章還在書寫中。 原文地址www.dahei.me