Tencent performance monitoring framework Matrix source code analysis of the first

Tencent performance monitoring framework Matrix source code analysis of the first

An overview of the

A few days ago Tencent will be an Android application performance monitoring framework matrix open source, source address at github.com/Tencent/mat… , the author is the wechat terminal team. What exactly is matrix? Matrix is an APM (Application Performance Manage) developed by wechat and used daily. Currently, it mainly runs on Android platform. Matrix aims to establish a unified application performance access framework, collect and analyze abnormal data of performance monitoring items through various performance monitoring schemes, and output corresponding problem analysis, positioning and optimization suggestions, so as to help developers develop higher-quality applications. Matrix currently monitors application package size, frame rate changes, startup time, lag, slow methods, SQLite operation optimization, file read and write, memory leaks, etc.

The entry to the code is initialized in application onCreate(),

Matrix.Builder builder = new Matrix.Builder(this); Matrix. Init (builder.build());Copy the code

As with leakcanary and other libraries, the Matrix is created using the common constructor pattern at application initialization. Now look inside the 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; }Copy the code

The matrix contains a collection of plugins, which use hashSets to prevent repetition, and a pluginListener for the plugin state. Matrix uses a singleton pattern, with volatile sInstance ensuring thread visibility, double-checking initialization, assigning variables to constructors, iterating through plugins, and calling plugin.init() one by one. What is a plug-in plugin? Here is the code for the 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); }}Copy the code

The plugin is an abstract class, it inherits the IPlugin and IssuePublisher OnIssueDetectListener, IPlugin includes five plug-in states: CREATE, INITED, STARTED, STOPPED, and DESTROYED. When the plugin state changes, the callback is sent to the pluginListener. The OnIssueDetectListener interface is an internal interface to the IssuePublisher class. IssuePublisher does two things: logging problems and exposing problems. It does this by nullizing the implementation and exposing the interface. Plugin inherits the OnIssueDetectListener interface, but it also does not handle it itself, so it also leaves pluginListener to handle.

Summary of the first paragraph

1. Matrix is a singleton that maintains plugins as a collection of plug-ins and interfaces for handling different states and errors of plug-ins
2. Pluginlisteners, which are common to the plugins collection,
3. The init method of plugin is called one by one when the matrix is initialized.
4. Plugin Plugin is an abstract class, specific plug-ins need to be implemented, matrix framework built-in plug-ins haveTracePlugin,IOCanaryPlugin,SQLiteLintPlugin,ResourcePlugin. Each of these functions and implementations will be examined below

TracePlugin

FrameTracer, FPSTracer, EvilMethodTracer and StartUpTracer are used to analyze the app. The initialization method is as follows:

@Override public void init(Application app, PluginListener listener) { super.init(app, listener); MatrixLog.i(TAG, "trace plugin init, trace config: %s", mTraceConfig.toString()); // Earlier versions do not support 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); / / switch, can choose be unable to undo the if (mTraceConfig. IsMethodTraceEnable ()) {mStartUpTracer = new StartUpTracer (this, mTraceConfig); } if (mTraceConfig.isFPSEnable()) { mFPSTracer = new FPSTracer(this, mTraceConfig); } if (mTraceConfig.isMethodTraceEnable()) { mEvilMethodTracer = new EvilMethodTracer(this, mTraceConfig); }}Copy the code

ApplicationLifeObserver. Init (app) is the use of the application of ActivityLifecycleCallbacks can do to monitor each activity life cycle the observer pattern, OnActivityResumed and onActivityPaused are resumed after the onPause of the underlying activity. If onActivityPaused does not get to onActivityResumed 600ms later, the onActivityResumed is in the background. If an activity starts very slowly and exceeds 600ms, it is judged to have been in the background. However, this impact is relatively small, because the activity starts and resumes back to the normal foreground, even if misjudgment does not affect the detection, the specific implementation can see the source code.

When the TracePlugin is initialized, mStartUpTracer, mFPSTracer, mFrameTracer, and mEvilMethodTracer are created respectively. The parameter mTraceConfig is a simple configuration class. I just recorded the switch and it’s not going to unfold here. The entry to matrix demo is traceplugin.start (), and the code is as follows:

@Override public void start() { super.start(); if (! isSupported()) { return; } new Handler(looper.getMainLooper ()).post(new Runnable() {@override public void run() {// Ensure that the call is on the main thread FrameBeat.getInstance().onCreate(); }}); if (null ! = mFPSTracer) { mFPSTracer.onCreate(); } if (null ! = mEvilMethodTracer) { mEvilMethodTracer.onCreate(); } if (null ! = mFrameTracer) { mFrameTracer.onCreate(); } if (null ! = mStartUpTracer) { mStartUpTracer.onCreate(); }}Copy the code

Framebeat.getinstance ().onCreate() is called on the main thread when onstart is used for UI analysis. At present, there are two ways to do UI performance lag analysis:

Which is the main loop method in the search for the MSG. Target. DispatchMessage (MSG) respectively before and after the print a log, can make use of the contents of the log or log before and after different times recorded twice in the log time, In this way, it can be roughly considered as the time for the main thread to process MSG. If the time is too long, it is considered to be stuck.

The second is to use Choreographer, which is a message processor that calculates frames based on vsync signals, the current time at which callbacks can be received in the doFrame method, The normal time difference between drawing a doFrame is 1000/60=16.6666 ms (60 frames per second), but stalling or excessive redrawing can lead to a longer time.

The second method is adopted here, and its doFrame implementation is as follows:

@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; }}Copy the code

Log the time of the doFrame twice and hand it to mFrameListeners to perform the callback. MFPSTracer, mFrameTracer, mFrameTracer, mStartUpTracer, mFrameTracer, mStartUpTracer, mFPSTracer, mFrameTracer, mFrameTracer, mStartUpTracer

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); }}Copy the code

So this is a bit of core code, BaseTracer has a static hashMap, the class name is the key, the value is the concrete BaseTracer object, it’s static so there’s only one copy, OnCreate registers the ApplicationLifeObserver and FrameBeat listeners mentioned earlier, the callbacks that listen to the activity’s life cycle and the interface callbacks that Choreographer draws twice. The callbacks are up to you. In addition, the sendReport method is exposed, which calls onDetectIssue of the locally held TracePlugin object to process. This corresponds to plugins and pluginListeners in the Matrix above. OnDetectIssue in plugins is ultimately handled by pluginListener.

A preliminary summary of TracePlugin

TracePlugin is divided into four parts, mStartUpTracer, mFPSTracer, mFrameTracer, and mEvilMethodTracer, which all inherit from BaseTracer; BaseTracer listens for ApplicationLifeObserver, which is the life cycle and foreground and background state of each activity. BaseTracer monitors doFrame(long lastFrameNanos, long frameNanos) before and after refreshing each frame.

First latitude: mFrameTracer

Now let’s look at the key method doFrame which implements mFrameTracer

@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)); }}); }}}}Copy the code

In doFrame, according to the calculation of the time difference between interface drawing, if the time difference exceeds the normal drawing 16.67 seconds, the data will be called back in the listener. There are two callback methods doFrameSync and doFrameAsync, corresponding to synchronous call and asynchronous call. The asynchronous call is implemented by using the handler mechanism. Where getScene is the class name of the current activity or fragment.

Second latitude: EvilMethodTracer

EvilMethodTracer, as its name suggests, is about finding evil methods that take a lot of time. To implement this code, EvilMethodTracer inherits the LazyScheduler interface, The LazyScheduler interface is a timer implemented using handler. The code is as follows:

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); }}}Copy the code

This timer used the handler mechanism, the implementation of the handler which handlerThread thread to obtain directly from the parameters, the code is not complicated, just remember that one can, one is whether the timer support cycle, The execution is the onTimeExpire method that calls ILazyTask. EvilMethodTracer also overrides the timer’s onTimeExpire method. Here’s the code for EvilMethodTracer.

public EvilMethodTracer(TracePlugin plugin, TraceConfig config) {
    super(plugin);
    this.mTraceConfig = config;
    mLazyScheduler = new LazyScheduler(MatrixHandlerThread.getDefaultHandlerThread(), Constants.DEFAULT_ANR);
    mActivityCreatedInfoMap = new HashMap<>();
}
Copy the code

Initialization of mLazyScheduler and mActivityCreatedInfoMap, mLazyScheduler, where mLazyScheduler is a timer Constants.DEFAULT_ANR Defaults to 5 seconds, Used to record 5 seconds no response and ANR interface, there are other MatrixHandlerThread. Among getDefaultHandlerThread (), MatrixHandlerThread is a hadlerThread thread management class, It contains the Matrix default worker thread, the main thread, and a container for dynamically creating new threads. GetDefaultHandlerThread () gets the handlerThread of the default worker thread. MActivityCreatedInfoMap is used to record the time it takes to start an activity. How did you do that? Let’s take a step-by-step look at the code that starts 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); }}Copy the code

GetMethodBeat (). IsRealTrace (). MethodBeat is an important class that counts ANR and timeout methods. MAnalyseThread is a new thread that uses a MatrixHandlerThread to pass its looer to the mHandler. EvilMethodTracer reworks the doFrame method:

@override public void doFrame(long lastFrameNanos, long frameNanos) {//isIgnoreFrame is true. Second is the cache is full of the method of record is the if (isIgnoreFrame) {/ / clear the cache mActivityCreatedInfoMap. The clear (); // Change the identity setIgnoreFrame(false); // reset the number getMethodBeat().resetIndex(); return; } //index indicates the number of the currently executing method in the cache int index = getBeat ().getCurIndex(); //hasEntered indicates that the activity already exists; if (hasEntered && frameNanos - lastFrameNanos > mTraceConfig.getEvilThresholdNano()) { MatrixLog.e(TAG, "[doFrame] dropped frame too much! lastIndex:%s index:%s", 0, index); // The difference between two frames is more than one second, HandleBuffer (type.normal, 0, index-1, getBeat ().getBuffer(), (frameNanos - lastFrameNanos) / Constants.TIME_MILLIS_TO_NANO); } // reset the number getMethodBeat().resetIndex(); // Cancel mLazyScheduler, i.e., clear the corresponding messageQueue mlazyScheduler.cancel (); MLazyScheduler runnable mLazyScheduler. SetUp (this, false); }Copy the code

HandleBuffer will be executed if the doFrame interval exceeds 1 second, and onTimeExpire in mLazyScheduler will be executed if the doFrame interval exceeds 5 seconds. Let’s start with the onTimeExpire method:

Public void onTimeExpire() {// Doframe delay is 5 seconds, If (isBackground()) {matrixlog. w(TAG, "[onTimeExpire] pass this time, on Background!" ); return; } long happenedAnrTime = getMethodBeat().getCurrentDiffTime(); MatrixLog.w(TAG, "[onTimeExpire] maybe ANR!" ); // Pause Frame capture once setIgnoreFrame(true); GetMethodBeat ().lockBuffer(false); // Parse the cache, ANR handleBuffer(type.anr, 0, getMethodBeat().getCurIndex() -1, getMethodBeat().getBuffer(), null, Constants.DEFAULT_ANR, happenedAnrTime, -1); }Copy the code

When executing onTimeExpire, it is treated as ANR if it is in the foreground. By now, the capture of ANR is generally known. Parsing data is also handled handleBuffer like doFrame, and getMethodBeat() is mentioned again. GetMethodBeat returns a locally held object called sMethodBeat, and handleBuffer also uses sMethodBeat as a method for analyzing data, so let’s look at what this class does before we analyze it. After analyzing MethodBeat, let’s look at handleBuffer.

Episode – MethodBeat

The main thing the MethodBeat class does is keep an array of each method executed by the application and how long it took, using long[]. Bit-by-bit conversion using method IDS and how long it took takes a long value as an element. The cache default length is a million. MethodBeat starts with this code:

static {
    Hacker.hackSysHandlerCallback();
    sCurrentDiffTime = sLastDiffTime = System.nanoTime() / Constants.TIME_MILLIS_TO_NANO;
    sReleaseBufferHandler.sendEmptyMessageDelayed(RELEASE_BUFFER_MSG_ID, Constants.DEFAULT_RELEASE_BUFFER_DELAY);
}
Copy the code

Enter the 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()); }}Copy the code

} HackCallback is used to replace the mCallback in ActivityThread with HackCallback. The purpose of this method is to intercept the original message of mCallback. HackCallback then selects the message to process. The handleMessage implementation in HackCallback looks like this:

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); }Copy the code

The LAUNCH_ACTIVITY and ENTER_ANIMATION_COMPLETE messages are intercepted so that the current activity is created to completion.

MethodBeat again now, it inherits the IMethodBeat and ApplicationLifeObserver IObserver interface, IObserver is used for the activity life cycle before listening, IMethodBeat is used for method caching data. When I looked at the source code here, I had a question, which I’m sure most people have: how does it keep track of each method, and how does the execution time of those methods count? A cursory look at MethodBeat didn’t find a source for the data, but I did find the following two methods:

//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; }}}Copy the code

The comments for these two methods are worth noting: Hook method when it’s called in, hook method when it’s called out, hook method when it’s called out The method o() is called at the end of each method, recording the time difference between the method name and o-i. Both methods end with the mergeData method:

 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;
}
Copy the code

The sCurrentDiffTime here is the direct time difference between the two methods o() and I (), stored in long with methodId. The idea has, its realization way? MethodTracer () {hook: MethodTracer ();} hook: 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);Copy the code

}

This inner class in turn inherits AdviceAdapter. The AdviceAdapter implementation comes from the library referenced in org.wo2.asm. Asm is a Java bytecode manipulation framework. It can dynamically generate stub classes or other proxy classes directly in binary form, or modify classes dynamically at load time. ASM provides similar functionality to toolkits like BCEL and SERP, but is designed to be smaller and faster, making it suitable for real-time code instrumentation. For matrix, which means that you can use asm method of loading the framework, before the method perform “com/tencent/matrix/trace/core/MethodBeat” I () method in this class, in the final execution o each method () method. Suddenly feel up posture, want to know the details of their own piece of the source code.

Back to EvilMethodTracer

MethodBeat now has a source for the method cache, so let’s go back to EvilMethodTracer’s 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)); }}}Copy the code

* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * AnalyseTask has a long analysis method. The general idea is to find the time abnormal method according to the stored data, that is, each method ID and execution time, save the abnormal method information and some basic information in a JSONObject, and then call plugin’s sendReport method. Here is a direct intercept of the post-analysis published method:

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);
        }
Copy the code

The final format is as follows:

{ "machine": 2015, "detail": "ENTER", "cost": 3205, "viewInfo": { "viewDeep": 10, "viewCount": 6, "activity": "TestFpsActivity" }, "stack": "3195,1,10 \ n1, 33,1,58 \ n2, 206,1,21 \ n3, 161,1,16 \ n4 interchange, 180,1,16 \ n5, 169,1,16 \ n6, 96,1,10 \ n7, 98,1,10 \ n4 interchange, 183,2,5 \ n5, 211,6,0 \ n0, 30 , 1, 56 \ n ", "stackKey,30,1,56 \ n" : "0", "tag" : "Trace_EvilMethod", "process" is: "sample. Tencent. Matrix"}Copy the code

So much for EvilMethodTracer, let’s take a look at StartUpTracer

StartUpTracer

StartUpTracer is used to analyze the startup time of an activity. In MethodBeat, we used hook to log the activity at LAUNCH_ACTIVITY and ENTER_ANIMATION_COMPLETE. Two points in time are used here. The core implementation method is in 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; }Copy the code

So this is the first part of the method, and there are two hashMaps, mFirstActivityMap, which records when the activity is in onCreate, and mActivityEnteredMap, which records when the activity is in onActivityEntered, OnActivityEntered The onActivityEntered () method is called by hook in WindowFocusChange, and the OnActivityEnter() method follows:

long activityCost = activityEndTime - firstActivityStart; / / sApplicationCreateEndTime is methodBeat hook to get through the 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();Copy the code

This code counts the application startup time, SplashActivity (welcome page) time, and the time between the application and the activity. The statistical format is as follows:

{
"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
}
Copy the code

StartUpTracer stops here, leaving one last FPSTracer

FPSTracer

FPSTracer measures the frame rate and the frame drop level of corresponding activities and fragments. Also using Choreographer’s doFrame(), let’s go straight to its implementation:

@override public void doFrame(long lastFrameNanos, long frameNanos) {//isInvalid is used to draw if (! IsInvalid && isDrawing && isEnterAnimationComplete () && mTraceConfig. IsTargetScene (getScene ())) {/ / analysis handleDoFrame(lastFrameNanos, frameNanos, getScene()); } isDrawing = false; }Copy the code

After starting onDraw, handleDoFrame is called

private void handleDoFrame(long lastFrameNanos, long frameNanos, String scene) { int sceneId; if (mSceneToSceneIdMap.containsKey(scene)) { sceneId = mSceneToSceneIdMap.get(scene); } else {// Record the interface name and interface number 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); // If (offset >= 5 * 1000000000L) {matrixlog. w(TAG, "[handleDoFrame] WARNING Drop frame! offset:%s scene%s", offset, scene); } synchronized (this.getClass()) {// record mFrameDataList. Add (trueId); }}Copy the code

The internal timer mLazyScheduler is started on onCreate with a default interval of 120 seconds.

 public void onTimeExpire() {
    doReport();
}
Copy the code

Call doReport ()

private void doReport() { LinkedList<Integer> reportList; synchronized (this.getClass()) { if (mFrameDataList.isEmpty()) { return; } reportList = mFrameDataList; mFrameDataList = new LinkedList<>(); 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(); For (int I = 0; 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)); }}}Copy the code

The final parse is the activity corresponding frame time data, the data format is as follows:

{
"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"
}
Copy the code

At present, the content analysis of tracePlugin is finished, and some data calculation has not been expanded, you can check it yourself.

TracePlugin summary

This section focuses on the implementation of the TracePlugin, which includes ANR records, timeout function records, frame counts, and startup records. This is just one of the Plugins, and it is already a bit long. So I decided to separate the following IOCanaryPlugin, SQLiteLintPlugin, and ResourcePlugin into different articles.

Their talent and learning are shallow, there must be a lot of inadequacies, omissions or mistakes are welcome to point out.

Welcome to reprint, indicate the source, the following article is still in writing. Original address www.dahei.me