TraceCanary module can only run on devices with API 16 or above. It is divided into four monitoring modules: ANR, frame rate, slow method and start. The core interface is LooperObserver. LooperObserver is an abstract class that, as its name suggests, acts as an observer of Looper, calling back when Looper dispatches messages and refreshes the UI. These callback methods are also the basis for ANR, slow methods, and other modules:
@callsuper public void dispatchBegin(long beginMs, long cpuBeginMs, Public void doFrame(String focusedActivityName, Long Start, Long End, long frameCostMs, long inputCostNs, long animationCostNs, } @callsuper public void dispatchEnd(long beginMs, long cpuBeginMs, long endMs, long cpuEndMs, long token, boolean isBelongFrame) { } }Copy the codeLooper is monitored by the class LooperMonitor. The principle is very simple. The main thread Looper can set a Printer. Avoid affecting Printer Settings of other users:
private synchronized void resetPrinter() { Printer originPrinter = ReflectUtils.get(looper.getClass(), "mLogging", looper);; looper.setMessageLogging(printer = new LooperPrinter(originPrinter)); } class LooperPrinter implements Printer { @Override public void println(String x) { if (null ! = origin) { origin.println(x); } dispatch(x.charat (0) == '>', x); // Start distribution, end distribution}}Copy the codeUI refresh monitoring is based on Choreographer’s implementation, and when TracePlugin is initialized, UIThreadMoniter adds callbacks to Choreographer by reflection:
Public class UIThreadMonitor implements BeatLifecycle, Runnable {// Choreographer an internal class method, Private static final String ADD_CALLBACK = "addCallbackLocked"; Public static final int CALLBACK_INPUT = 0; public static final int CALLBACK_ANIMATION = 1; public static final int CALLBACK_TRAVERSAL = 2; public void init(TraceConfig config) { choreographer = Choreographer.getInstance(); // callbackQueues = reflectObject(Choreographer, "mCallbackQueues"); / / reflection, Find the method of adding callback on the Choreographer addInputQueue = reflectChoreographerMethod (callbackQueues [CALLBACK_INPUT], ADD_CALLBACK, long.class, Object.class, Object.class); addAnimationQueue = reflectChoreographerMethod(callbackQueues[CALLBACK_ANIMATION], ADD_CALLBACK, long.class, Object.class, Object.class); addTraversalQueue = reflectChoreographerMethod(callbackQueues[CALLBACK_TRAVERSAL], ADD_CALLBACK, long.class, Object.class, Object.class); }}Copy the codeThe reason we do this through reflection rather than postCallback is to put our callback in the header so that we can calculate the time of input events, animations, View draws, and so on submitted by the system.
This way, when Choreographer listens to vsync signals, both UIThreadMonitor and system-added callbacks will be executed (for example, when drawing a View, The system will add a traversal callback to Choreographer) :
public final class Choreographer { private final class FrameDisplayEventReceiver extends DisplayEventReceiver implements Runnable { @Override public void run() { doFrame(mTimestampNanos, mFrame); } } void doFrame(long frameTimeNanos, int frame) { doCallbacks(Choreographer.CALLBACK_INPUT, frameTimeNanos); doCallbacks(Choreographer.CALLBACK_ANIMATION, frameTimeNanos); doCallbacks(Choreographer.CALLBACK_TRAVERSAL, frameTimeNanos); . }}Copy the codeSince the callbacks added by UIThreadMonitor are at the head of the queue and can be used to record the start time, and other system methods, such as the View’s postOnAnimation, add callbacks later, after all callbacks of the same type are executed, You can calculate the time of the corresponding events (input events, animation, View drawing, etc.).
ANR monitoring principle: During Looper message distribution, a delay task (executed after 5s) is inserted into the background thread and deleted after THE Looper message is distributed. If the task is not deleted after 5s, ANR is considered to have occurred.
Public class AnrTracer extends Tracer {// Initializes when onAlive and exits when onDead. Private Handler anrHandler; private volatile AnrHandleTask anrTask; Public void dispatchBegin(long beginMs, long cpuBeginMs, long token) { Begin from the node execution record collection methods anrTask = new AnrHandleTask (AppMethodBeat. GetInstance (). MaskIndex (" AnrTracer# dispatchBegin "), token); // Token is equal to beginMs, So the latter subtraction is used to subtract the time spent calling back the method anrHandler.postDelayed(anrTask, Constants.DEFAULT_ANR - (SystemClock.uptimeMillis() - token)); } @Override public void dispatchEnd(long beginMs, long cpuBeginMs, long endMs, long cpuEndMs, long token, boolean isBelongFrame) { if (null ! = anrTask) { anrTask.getBeginRecord().release(); anrHandler.removeCallbacks(anrTask); }}}Copy the codeIf the task is not deleted after 5 seconds, AnrTracer collects and reports information about processes, threads, memory, and stacks.
Application startup monitoring starts with the first method executed:
public class AppMethodBeat implements BeatLifecycle { private static volatile int status = STATUS_DEFAULT; Public static void I (int methodId) {if (status == STATUS_DEFAULT) {// If (status == STATUS_DEFAULT) { RealExecute (); realExecute(); status = STATUS_READY; }} private static void realExecute () {/ / record timestamp ActivityThreadHacker. HackSysHandlerCallback (); Looper loOperMonitor. register(looperMonitorListener); }}Copy the codeThe Matrix will also take over the Callback of the ActivityThread Handler by reflection after the first method is timestamp:
Public class ActivityThreadHacker {public static void hackSysHandlerCallback() { As the beginning of the application to enable sApplicationCreateBeginTime = SystemClock time. UptimeMillis (); // reflect ActivityThread, take over Handler Class<? > forName = Class.forName("android.app.ActivityThread"); . }}Copy the codeThis timestamp can be used as the end time when the Application starts:
private final static class HackCallback implements Handler.Callback { private static final int LAUNCH_ACTIVITY = 100; private static final int CREATE_SERVICE = 114; private static final int RECEIVER = 113; private static boolean isCreated = false; @Override public boolean handleMessage(Message msg) { boolean isLaunchActivity = isLaunchActivity(msg); // If the Activity or Service or Receiver is started first, this timestamp is used as the end time of Application start. isCreated) { if (isLaunchActivity || msg.what == CREATE_SERVICE || msg.what == RECEIVER) { // todo for provider ActivityThreadHacker.sApplicationCreateEndTime = SystemClock.uptimeMillis(); ActivityThreadHacker.sApplicationCreateScene = msg.what; isCreated = true; }}}}Copy the codeFinally, finish with the onWindowFocusChange method of the main Activity (the first Activity after the splash screen), Record the timestamp – The Activity’s startup time can be subtracted from the timestamp at the time of the onWindowFocusChange callback. The startup time can be calculated after the preceding information is collected:
firstMethod.i LAUNCH_ACTIVITY onWindowFocusChange LAUNCH_ACTIVITY onWindowFocusChange ^ ^ ^ ^ ^ | | | | | |---------app---------|---|---firstActivity---|---------... ---------|---careActivity---| |<--applicationCost-->| |<--------------firstScreenCost-------------->| |<---------------------------------------coldCost------------------------------------->| . |<-----warmCost---->|Copy the codeIf the cold and warm startup time exceeds a certain threshold (which can be set by IDynamicConfig and is 10s and 4s by default), method execution records during startup are collected from AppMethodBeat and reported; otherwise, the time information is simply reported.
The principle of slow method monitoring is that when Looper distributes messages, endms-beginms is calculated. If the distribution time exceeds the threshold (which can be set by IDynamicConfig and is 700ms by default), information is collected and reported.
ublic class EvilMethodTracer extends Tracer { @Override public void dispatchBegin(long beginMs, long cpuBeginMs, long token) { super.dispatchBegin(beginMs, cpuBeginMs, token); // Insert a method node. Begin from the node execution record collection methods indexRecord = AppMethodBeat. GetInstance () maskIndex (" EvilMethodTracer# dispatchBegin "); } @Override public void dispatchEnd(long beginMs, long cpuBeginMs, long endMs, long cpuEndMs, long token, boolean isBelongFrame) { long dispatchCost = endMs - beginMs; / / method time-consuming than slow threshold if (dispatchCost > = evilThresholdMs) {long [] data = AppMethodBeat. GetInstance (). CopyData (indexRecord); MatrixHandlerThread.getDefaultHandler().post(new AnalyseTask(...) ; }} private class AnalyseTask implements Runnable {void analyse() {int[] processStat = Utils.getProcessPriority(Process.myPid()); String usage = Utils.calculateCpuUsage(cpuCost, cost); Insert node / / start collecting and sorting method execution records TraceDataUtils. StructuredDataToStack (data, stack, true, endMs); TraceDataUtils.trimStack(stack, Constants.TARGET_EVIL_METHOD_STACK, new TraceDataUtils.IStructuredDataFilter() { ... Pluginbyclass = matrix.with ().getpluginbyclass (traceplugin.class); plugin.onDetectIssue(issue); }}}Copy the codeThe principle of framerate monitoring is to listen on Choreographer and count the total time currently taking after all callbacks have completed, thus counting the number of frames dropped and the amount of frames dropped. When the same Activity/Fragment drops more than a threshold, a problem is reported. Key source code is as follows:
private class FPSCollector extends IDoFrameListener { @Override public void doFrameAsync(String visibleScene, long taskCost, long frameCostMs, int droppedFrames, FrameCollectItem item = map.get(visibleScene); if (null == item) { item = new FrameCollectItem(visibleScene); map.put(visibleScene, item); } // Collect item.collect(droppedFrames, isContainsFrame); // If the number of frames dropped exceeds a certain threshold, the problem is reported and recalculated. // sumFrameCost = Number of frames dropped * 16.66ms The default is 10s if (item.sumframecost >= timeSliceMs) {// report map.remove(visibleScene); item.report(); }}}Copy the codeBut there is a problem here, that is, when Matrix calculates the UI refresh time, it adds 1 to the number of frames dropped each time:
Private class FrameCollectItem {void collect(int droppedFrames, Boolean isContainsFrame) { This value will also increase sumFrameCost += (droppedFrames + 1) * frameIntervalCost/Constants.TIME_MILLIS_TO_NANO; }}Copy the codeMoreover, the doFrame method does not just call back when the UI is refreshed, but every time Looper dispatches messages, which can be much more frequent than the frame rate, so that even though no frames are actually dropped, because Looper dispatches messages constantly, SumFrameCost values also accumulate, quickly breaking the reporting threshold and reporting frequently:
private void dispatchEnd() { ... synchronized (observers) { for (LooperObserver observer : observers) { if (observer.isDispatchBegin()) { observer.doFrame(...) ; }}}}Copy the codeThe solution is to manually filter in PluginListener, or modify the source code.
TraceCanary is divided into four modules: slow method, start, ANR, and frame rate. Each module functions through the listening interface LooperObserver, which monitors Looper and Choreographer on the main thread.
Looper monitoring is realized by Printer, each event distribution will call back LooperObserver dispatchBegin, dispatchEnd method, calculate the time of these two methods can detect slow method and ANR and other problems.
Monitoring Choreographer is achieved by adding input, animation, and traversal callbacks to the Choreographer header. After the vsync signal is triggered, each type of callback in Choreographer will be executed. The interval between the start time of the two types of callback is equivalent to the time of the first type of event (input.cost = animation.begin-input.begiin), and the traversal of the last event (traversal), Looper’s diaptchEnd method is also executed, so traversal. Cost = looper.dispatchend -traversal. Begin.
The realization principle of each module is as follows:
ANR: When Looper starts to distribute messages, a delayed task (executed after 5s) is inserted into the background thread. After the Looper message is distributed, the task is deleted. If the task is not deleted after 5s, ANR is considered to have occurred, information is collected and problems are reported
Slow method: when Looper distributes messages, endms-beginms is calculated. If the duration is greater than the threshold (set by IDynamicConfig and 700ms by default), information is collected and reported
Start: The time stamp is recorded starting with the first method executed, followed by the time when the first Activity or Service or Receiver is started, as the end time of Application start. Finally, record the timestamp with the onWindowFocusChange method of the main Activity (the first Activity after the splash screen) as the endpoint. The time it takes for an Activity to start can be subtracted from the timestamp at the time of the onWindowFocusChange callback. After collecting the preceding information, you can calculate the startup time.
Frame drop: Listen on Choreographer, doFrame callback counts the UI refresh time, counts the number of frames dropped and the number of frames dropped, and reports when the number of frames dropped for the same Activity/Fragment exceeds the threshold. However, there are problems in the calculation method of Matrix, which may be frequently reported and requires manual filtering.
Slow function detection
Purpose: To detect slow functions that affect main thread execution.
Like FrameTracer, EvilMethodTracer relies on the dispatchBegin, doFrame, and dispatchEnd methods in the LooperObserver interface that UIThreadMonitor flings.
In the dispatchBegin method, record the current index in AppMethodBeat as start; In dispatchEnd, read the current index in the current AppMethodBeat, called end. The data in between is the information about the methods executed during this period. When the Message execution time exceeds the specified threshold (700ms by default), a slow method is considered possible and further analysis is performed. As for the data recorded in doFrame, there is no specific use, it just prints the log at the end.
@Override public void dispatchBegin(long beginMs, long cpuBeginMs, long token) { super.dispatchBegin(beginMs, cpuBeginMs, token); / / record starting index indexRecord = AppMethodBeat. GetInstance () maskIndex (" EvilMethodTracer# dispatchBegin "); } @Override public void doFrame(String focusedActivityName, long start, long end, long frameCostMs, long inputCostNs, long animationCostNs, long traversalCostNs) { queueTypeCosts[0] = inputCostNs; queueTypeCosts[1] = animationCostNs; queueTypeCosts[2] = traversalCostNs; } @Override public void dispatchEnd(long beginMs, long cpuBeginMs, long endMs, long cpuEndMs, long token, boolean isBelongFrame) { super.dispatchEnd(beginMs, cpuBeginMs, endMs, cpuEndMs, token, isBelongFrame); long start = config.isDevEnv() ? System.currentTimeMillis() : 0; Try {// If Message execution time exceeds the threshold long dispatchCost = endMs -beginms; If (dispatchCost >= evilThresholdMs) {// If (dispatchCost >= evilThresholdMs) AppMethodBeat.getInstance().copyData(indexRecord); long[] queueCosts = new long[3]; System.arraycopy(queueTypeCosts, 0, queueCosts, 0, 3); String scene = AppMethodBeat.getVisibleScene(); . / / the child thread analysis report MatrixHandlerThread getDefaultHandler (), post (new AnalyseTask (isForeground (), scene, data, queueCosts, cpuEndMs - cpuBeginMs, endMs - beginMs, endMs)); }} finally {// Release indexRecord.release(); if (config.isDevEnv()) { String usage = Utils.calculateCpuUsage(cpuEndMs - cpuBeginMs, endMs - beginMs); MatrixLog.v(TAG, "[dispatchEnd] token:%s cost:%sms cpu:%sms usage:%s innerCost:%s", token, endMs - beginMs, cpuEndMs - cpuBeginMs, usage, System.currentTimeMillis() - start); }}}Copy the codeHere’s how AnalyseTask analyzed and reported:
private class AnalyseTask implements Runnable { ... Void analyse() {// process // get priority and nice of process, Int [] processStat = utils.getProcesspriority (process.mypid ()); String Usage = Utils. CalculateCpuUsage (cpuCost, cost); LinkedList<MethodItem> stack = new LinkedList(); If (data.length > 0) {// Merge the original long[] array into a List of type MethodItem // The 3rd argument (isStrict) is paired with the 4th argument (endTime), if isStrict is true, METHOD_ID_DISPATCH starts with the first METHOD_ID_DISPATCH. The endTime as o time merge into a List of TraceDataUtils. StructuredDataToStack (data, stack, true, endMs); TraceDataUtils.trimStack(stack, Constants.TARGET_EVIL_METHOD_STACK, New TraceDataUtils. IStructuredDataFilter () {/ / need to be discarded in the process of handling conditions @ Override public Boolean isFilter (long during, int filterCount) { return during < filterCount * Constants.TIME_UPDATE_CYCLE_MS; } @override public int getFilterMaxCount() {return Constants. } // If maxCount is exceeded, @override public void fallback(List<MethodItem> stack, int size) {matrixlog. w(TAG, matrixlog. w, matrixlog. w, matrixlog. w, matrixlog. w, matrixlog. w, matrixlog. w, matrixlog. w "[fallback] size:%s targetSize:%s stack:%s", size, Constants.TARGET_EVIL_METHOD_STACK, stack); Iterator iterator = stack.listIterator(Math.min(size, Constants.TARGET_EVIL_METHOD_STACK)); while (iterator.hasNext()) { iterator.next(); iterator.remove(); }}}); } StringBuilder reportBuilder = new StringBuilder(); StringBuilder logcatBuilder = new StringBuilder(); long stackCost = Math.max(cost, TraceDataUtils.stackToString(stack, reportBuilder, logcatBuilder)); String stackKey = TraceDataUtils.getTreeKey(stack, stackCost); MatrixLog.w(TAG, "%s", printEvil(scene, processStat, isForeground, logcatBuilder, stack.size(), stackKey, usage, queueCost[0], queueCost[1], queueCost[2], cost)); // for logcat // report try { ... } catch (JSONException e) { MatrixLog.e(TAG, "[JSONException error: %s", e); } } @Override public void run() { analyse(); } ... }Copy the codeThe brain-wasting part of AnalyseTask is how to integrate and cut the original data sBuffer, and how to generate a key that can represent the caton, which is convenient for aggregation. This section is also covered a little bit in matrix-Wiki. Excerpts:
Stack clustering problem: If the original data collected is reported, there is a large amount of data and it is difficult for the background to cluster the faulty stack. Therefore, the collected data should be simply integrated and clipped before the report, and a key that can represent the caton stack should be analyzed to facilitate the background aggregation. Through traversing the collected buffer, adjacent I and O are a complete function execution, a call tree and the execution time of each function are calculated, and some same execution functions in each level are aggregated. Finally, through a simple strategy, the one-level function with the main time consumption is analyzed as the key representing the caton stack.Copy the code
/** * hook method when it's called in. * * @param methodId */ public static void i(int methodId) { if (isBackground) { return; }... isRealTrace = true; if (isCreated && Thread.currentThread() == sMainThread) { ... } else if (! isCreated && Thread.currentThread() == sMainThread && sBuffer ! = null) { .. } } /** * hook method when it's called out. * * @param methodId */ public static void o(int methodId) { if (isBackground || null == sBuffer) { return; } if (isCreated && Thread.currentThread() == sMainThread) { ... } else if (! isCreated && Thread.currentThread() == sMainThread) { ... }}Copy the codeCounts the entry and exit of methods executed on the main thread while the application is in the foreground. This information is eventually stored in MethodBeat’s Buffer. When the main thread has a suspected slow function, the Buffer data is read, the possible slow function is analyzed, and the JSON data is reported to the back end (the back end converts methodId into a specific method declaration).
There are actually two suspected slow functions: one is a frame drop scenario, and the other is a scenario like ANR where the main thread blocks UI drawing for a long time.
The scene of dropping frames
The implementation of the FrameTracer relies on the LooperObserver#doFrame callback thrown from UIThreadMonitor. The method declaration for this callback is as follows:
public void doFrame(String focusedActivityName, long start, long end, long frameCostMs, long inputCostNs, long animationCostNs, long traversalCostNs)
Copy the codeThe parameters are described as follows:
- focusedActivityName
The name of the Activity being displayed
- start
The time before Message execution
- end
The time when LooperObserver#doFrame is called after Message completes execution
- frameCostMs
If UIThreadMonitor#run is executed when dispatchEnd is called, this value is the value of end-start above; Otherwise 0
- InputCostNs, animationCostNs, traversalCostNs
Duration of executing the three callbackqueues
Let’s look at how FrameTracer calculates frame rate information from these values, looking directly at Override’s doFrame method:
@Override public void doFrame(String focusedActivityName, long start, long end, long frameCostMs, long inputCostNs, long animationCostNs, long traversalCostNs) { if (isForeground()) { notifyListener(focusedActivityName, end - start, frameCostMs, frameCostMs >= 0); } } private void notifyListener(final String visibleScene, final long taskCostMs, final long frameCostMs, final boolean isContainsFrame) { long start = System.currentTimeMillis(); try { synchronized (listeners) { for (final IDoFrameListener listener : listeners) { if (config.isDevEnv()) { listener.time = SystemClock.uptimeMillis(); } final int dropFrame = (int) (taskCostMs / frameIntervalMs); listener.doFrameSync(visibleScene, taskCostMs, frameCostMs, dropFrame, isContainsFrame); if (null ! = listener.getExecutor()) { listener.getExecutor().execute(new Runnable() { @Override public void run() { listener.doFrameAsync(visibleScene, taskCostMs, frameCostMs, dropFrame, isContainsFrame); }}); } if (config.isDevEnv()) { listener.time = SystemClock.uptimeMillis() - listener.time; MatrixLog.d(TAG, "[notifyListener] cost:%sms listener:%s", listener.time, listener); } } } } finally { long cost = System.currentTimeMillis() - start; if (config.isDebug() && cost > frameIntervalMs) { MatrixLog.w(TAG, "[notifyListener] warm! maybe do heavy work in doFrameSync! size:%s cost:%sms", listeners.size(), cost); }}}Copy the codeOn the FrameTracer#doFrame, the notifyListener method is invoked when the App is in the foreground state. Note that the taskCostMs parameter value is end-start, which should be the same as the value of frameCostMs. In notifyListener, taskCostMs/frameIntervalMs is first used to calculate the number of frames lost in the execution, denoted as dropFrame. This means that a single Message execution takes no more than 16ms, and no frames are lost. Finally, IDoFrameListener#doFrameSync and IDoFrameListener#doFrameAsync are called to execute lisetner’s synchronous and asynchronous methods.
With the dropFrame calculated above, taskCostMs and frameCostMs are not much needed in the future. Let’s focus on the other parameters (visibleScene, dropFrame, isContainsFrame), and then we can report the frame rate and display it in real time.
Let’s take a look at some of the frame rate reporting code. When FrameTracer is constructed, the Matrix adds a FPSCollector class that implements the IDoFrameListener interface for frame rate collection and reporting.
private class FPSCollector extends IDoFrameListener { private Handler frameHandler = new Handler(MatrixHandlerThread.getDefaultHandlerThread().getLooper()); Executor executor = new Executor() { @Override public void execute(Runnable command) { frameHandler.post(command); }}; private HashMap<String, FrameCollectItem> map = new HashMap<>(); @Override public Executor getExecutor() { return executor; } @Override public void doFrameAsync(String visibleScene, long taskCost, long frameCostMs, int droppedFrames, boolean isContainsFrame) { super.doFrameAsync(visibleScene, taskCost, frameCostMs, droppedFrames, isContainsFrame); if (Utils.isEmpty(visibleScene)) { return; } FrameCollectItem item = map.get(visibleScene); if (null == item) { item = new FrameCollectItem(visibleScene); map.put(visibleScene, item); } item.collect(droppedFrames, isContainsFrame); if (item.sumFrameCost >= timeSliceMs) { // report map.remove(visibleScene); item.report(); }}}Copy the codeThe FPSCollector records frames for each page with the page as the key. First call framecollectitem. collect to collect frame rate information. Then, when the page sumFrameCost exceeds a certain threshold (10 seconds by default), the page is reported.
Then let’s look at the key framecollectite #collect method:
void collect(int droppedFrames, boolean isContainsFrame) {
long frameIntervalCost = UIThreadMonitor.getMonitor().getFrameIntervalNanos();
sumFrameCost += (droppedFrames + 1) * frameIntervalCost / Constants.TIME_MILLIS_TO_NANO;
sumDroppedFrames += droppedFrames;
sumFrame++;
if (!isContainsFrame) {
sumTaskFrame++;
}
if (droppedFrames >= frozenThreshold) {
dropLevel[DropStatus.DROPPED_FROZEN.index]++;
dropSum[DropStatus.DROPPED_FROZEN.index] += droppedFrames;
} else if (droppedFrames >= highThreshold) {
dropLevel[DropStatus.DROPPED_HIGH.index]++;
dropSum[DropStatus.DROPPED_HIGH.index] += droppedFrames;
} else if (droppedFrames >= middleThreshold) {
dropLevel[DropStatus.DROPPED_MIDDLE.index]++;
dropSum[DropStatus.DROPPED_MIDDLE.index] += droppedFrames;
} else if (droppedFrames >= normalThreshold) {
dropLevel[DropStatus.DROPPED_NORMAL.index]++;
dropSum[DropStatus.DROPPED_NORMAL.index] += droppedFrames;
} else {
dropLevel[DropStatus.DROPPED_BEST.index]++;
dropSum[DropStatus.DROPPED_BEST.index] += (droppedFrames < 0 ? 0 : droppedFrames);
}
}
Copy the codeSumFrameCost records the cumulative frame time. SumDroppedFrames records the total number of lost frames. SumFrame is the cumulative number of frames. After recording these numbers, according to the value of the lost frame, it is recorded into the corresponding lost frame state array. After recording, the report method will be called at an appropriate time to report, and the reported code is not important.
Matrix-trace-canary has a FrameDecorator class that displays live frame rates in a floating window, right out of the box, without writing your own logic. The underlying implementation is similar to FrameTracer.
Internal FrameBeat class implements the Choreographer FrameCallback, can sense of each frame drawing time. Determine whether a slow function occurs by the time difference between the two frames.
@Override public void doFrame(long lastFrameNanos, long frameNanos) { if (isIgnoreFrame) { mActivityCreatedInfoMap.clear(); setIgnoreFrame(false); getMethodBeat().resetIndex(); return; } int index = getMethodBeat().getCurIndex(); / / determine whether there is a slow function if (hasEntered && frameNanos - lastFrameNanos > mTraceConfig. GetEvilThresholdNano ()) {MatrixLog. E (the 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.cancel(); mLazyScheduler.setUp(this, false); }Copy the codeThe main thread blocks UI drawing for a long time
In ANR monitoring, if ANR occurs, the call stack needs to be parsed for that time period. This part of the logic is basically the same as the slow method monitoring EvilMethodTracer above.
Now let’s think about how ANR makes the decision. We throw a timed task at the beginning of Message execution, and if the task executes, ANR can be considered to have occurred. If the task is actively cleared after Message execution, no ANR has occurred. This idea is similar to the determination of system ANR.
@Override public void dispatchBegin(long beginMs, long cpuBeginMs, long token) { super.dispatchBegin(beginMs, cpuBeginMs, token); anrTask = new AnrHandleTask(AppMethodBeat.getInstance().maskIndex("AnrTracer#dispatchBegin"), token); if (traceConfig.isDevEnv()) { MatrixLog.v(TAG, "* [dispatchBegin] token:%s index:%s", token, anrTask.beginRecord.index); } // Bombshell anrHandler.postdelayed (anrTask, Constants.DEFAULT_ANR - (SystemClock.uptimemillis () -token)); } @Override public void doFrame(String focusedActivityName, long start, long end, long frameCostMs, long inputCost, long animationCost, long traversalCost) { if (traceConfig.isDevEnv()) { MatrixLog.v(TAG, "--> [doFrame] activityName:%s frameCost:%sms [%s:%s:%s]ns", focusedActivityName, frameCostMs, inputCost, animationCost, traversalCost); } } @Override public void dispatchEnd(long beginMs, long cpuBeginMs, long endMs, long cpuEndMs, long token, boolean isBelongFrame) { super.dispatchEnd(beginMs, cpuBeginMs, endMs, cpuEndMs, token, isBelongFrame); if (traceConfig.isDevEnv()) { MatrixLog.v(TAG, "[dispatchEnd] token:%s cost:%sms cpu:%sms usage:%s", token, endMs - beginMs, cpuEndMs - cpuBeginMs, Utils.calculateCpuUsage(cpuEndMs - cpuBeginMs, endMs - beginMs)); } // If (null! = anrTask) { anrTask.getBeginRecord().release(); anrHandler.removeCallbacks(anrTask); }}Copy the codeThere is a HandlerThread in LazyScheduler, and calling the lazyScheduler.setup method sends a 5s delay message to the HandlerThread’s MQ. If anR-like scenarios do not occur, cancel this message in the doFrame callback of each frame and send a new message with a delay of 5s (normally messages are not executed); If an ANR-like situation occurs and doFrame is not called back, the 5s delayed message is executed and will be called back to the onTimeExpire method
@Override public void onTimeExpire() { // maybe ANR if (isBackground()) { MatrixLog.w(TAG, "[onTimeExpire] pass this time, on Background!" ); return; } long happenedAnrTime = getMethodBeat().getCurrentDiffTime(); MatrixLog.w(TAG, "[onTimeExpire] maybe ANR!" ); setIgnoreFrame(true); getMethodBeat().lockBuffer(false); // There are slow functions handleBuffer(type.anr, 0, getMethodBeat().getCurIndex() -1, getMethodBeat().getBuffer(), null, Constants.DEFAULT_ANR, happenedAnrTime, -1); }Copy the codeWhen a slow function is detected, the analysis of the slow function is completed in the background thread
private final class AnalyseTask implements Runnable { private final long[] buffer; private final AnalyseExtraInfo analyseExtraInfo; private AnalyseTask(long[] buffer, AnalyseExtraInfo analyseExtraInfo) { this.buffer = buffer; this.analyseExtraInfo = analyseExtraInfo; } private long getTime(long trueId) { return trueId & 0x7FFFFFFFFFFL; } private int getMethodId(long trueId) { return (int) ((trueId >> 43) & 0xFFFFFL); } private boolean isIn(long trueId) { return ((trueId >> 63) & 0x1) == 1; } @Override public void run() { analyse(buffer); } private void analyse(long[] buffer) { ... // Analyzing logic is mainly to find the most time-consuming method.Copy the codeFPS testing
Objective: To detect the number of FPS during drawing.
Get the ViewTreeObserver of the DectorView to sense the start of the UI drawing
private void addDrawListener(final Activity activity) { activity.getWindow().getDecorView().post(new Runnable() { @Override public void run() { activity.getWindow().getDecorView().getViewTreeObserver().removeOnDrawListener(FPSTracer.this); activity.getWindow().getDecorView().getViewTreeObserver().addOnDrawListener(FPSTracer.this); }}); } @Override public void onDraw() { isDrawing = true; }Copy the codeThrough the Choreographer FrameCallback, perceive the UI end of drawing
@Override public void doFrame(long lastFrameNanos, long frameNanos) { if (! isInvalid && isDrawing && isEnterAnimationComplete() && mTraceConfig.isTargetScene(getScene())) { handleDoFrame(lastFrameNanos, frameNanos, getScene()); } isDrawing = false; }Copy the codeTheoretically, the user is more concerned about the lag caused by the low FPS during the drawing process (when the UI is still, the user will not feel the low FPS).
In the doFrame method, the data for each frame is recorded, with the scene field identifying a page
@Override
public void onChange(final Activity activity, final Fragment fragment) {
this.mScene = TraceConfig.getSceneForString(activity, fragment);
}
Copy the codeOnChange default implementation is through the Application of ActivityLifecycleCallbacks callback perceive the change of the Activity
@Override
public void onActivityResumed(final Activity activity) {
...
if (!activityHash.equals(mCurActivityHash)) {
for (IObserver listener : mObservers) {
listener.onChange(activity, null);
}
mCurActivityHash = activityHash;
}
...
}
Copy the codeBy default, FPS data is analyzed every 2 minutes (in the foreground case). The background polling thread stops when the background is cut.
/** * report FPS */ private void doReport() { ... // Data analysis logic can be read}Copy the codeCaton detection
Objective: To detect the lag in UI drawing.
Stall detection is similar to FPS detection. It determines whether stall occurs in the ‘doFrame callback’ of each frame, and sends data to the background analysis thread for processing if stall occurs.
@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 codeStart the test
Objective: Check startup time
firstMethod.i LAUNCH_ACTIVITY onWindowFocusChange LAUNCH_ACTIVITY onWindowFocusChange ^ ^ ^ ^ ^ | | | | | |---------app---------|---|---firstActivity---|---------... ---------|---careActivity---| |<--applicationCost-->| |<--------------firstScreenCost-------------->| |<---------------------------------------coldCost------------------------------------->| . |<-----warmCost---->|Copy the codePreviously, the plugin had woven the AppMethodBeat.at method into the compiler for Activity#onWindowFocusChanged to get the onWindowFocusChanged callback time for each Activity. Then, on the first appMethodBeat. I method call, the time is recorded as the time after the process zygote; The Callback in the mH of the Hook ActivityThread checks what of the first Activity or Service or Receiver as the end time of Application creation. The difference between this time and the above time is denoted as the Application creation time. In the onWindowFocusChange callback of the first Activity, the time minus zygote time is the first screen startup time. When the onWindowFocusChange callback for the second Activity is performed, the time minus zygote is the total cold start time.
Let’s take a look at the code along the line above, starting with the code in the appMethBeat. I method.
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; }}}... }Copy the codeStatus defaults to STATUS_DEFAULT, so the first time you execute AppMethodBeat# I will definitely execute to realExecute(), which basically initializes AppMethodBeat and does some other stuff.
private static void realExecute() { MatrixLog.i(TAG, "[realExecute] timestamp:%s", System.currentTimeMillis()); sCurrentDiffTime = SystemClock.uptimeMillis() - sDiffTime; sHandler.removeCallbacksAndMessages(null); sHandler.postDelayed(sUpdateDiffTimeRunnable, Constants.TIME_UPDATE_CYCLE_MS); 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); / / hook mH, provide support for StartUpTracer ActivityThreadHacker. HackSysHandlerCallback (); LooperMonitor.register(looperMonitorListener); }Copy the codeWe focus on ActivityThreadHacker. HackSysHandlerCallback () this method, the hook inside the mH mCallback, such can end Application initialization time.
public class ActivityThreadHacker { private static final String TAG = "Matrix.ActivityThreadHacker"; / / process startup time private static long sApplicationCreateBeginTime = 0 l; / / implementation of four major components for the first time to the time of private static long sApplicationCreateEndTime = 0 l; // Last launch time private static long sLastLaunchActivityTime = 0L; public static AppMethodBeat.IndexRecord sLastLaunchActivityMethodIndex = new AppMethodBeat.IndexRecord(); public static AppMethodBeat.IndexRecord sApplicationCreateBeginMethodIndex = new AppMethodBeat.IndexRecord(); public static int sApplicationCreateScene = -100; 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(); 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()); } } public static long getApplicationCost() { return ActivityThreadHacker.sApplicationCreateEndTime - ActivityThreadHacker.sApplicationCreateBeginTime; } public static long getEggBrokenTime() { return ActivityThreadHacker.sApplicationCreateBeginTime; } public static long getLastLaunchActivityTime() { return ActivityThreadHacker.sLastLaunchActivityTime; } private final static class HackCallback implements Handler.Callback { private static final int LAUNCH_ACTIVITY = 100; private static final int CREATE_SERVICE = 114; private static final int RECEIVER = 113; public static final int EXECUTE_TRANSACTION = 159; // For Android 9.0 private static Boolean isCreated = false; private static int hasPrint = 10; private final Handler.Callback mOriginalCallback; HackCallback(Handler.Callback callback) { this.mOriginalCallback = callback; } @Override public boolean handleMessage(Message msg) { if (! AppMethodBeat.isRealTrace()) { return null ! = mOriginalCallback && mOriginalCallback.handleMessage(msg); } boolean isLaunchActivity = isLaunchActivity(msg); if (hasPrint > 0) { MatrixLog.i(TAG, "[handleMessage] msg.what:%s begin:%s isLaunchActivity:%s", msg.what, SystemClock.uptimeMillis(), isLaunchActivity); hasPrint--; } if (isLaunchActivity) { ActivityThreadHacker.sLastLaunchActivityTime = SystemClock.uptimeMillis(); ActivityThreadHacker.sLastLaunchActivityMethodIndex = AppMethodBeat.getInstance().maskIndex("LastLaunchActivityMethodIndex"); } if (! isCreated) { if (isLaunchActivity || msg.what == CREATE_SERVICE || msg.what == RECEIVER) { // todo for provider ActivityThreadHacker.sApplicationCreateEndTime = SystemClock.uptimeMillis(); ActivityThreadHacker.sApplicationCreateScene = msg.what; isCreated = true; } } return null ! = mOriginalCallback && mOriginalCallback.handleMessage(msg); } private Method method = null; private boolean isLaunchActivity(Message msg) { if (Build.VERSION.SDK_INT > Build.VERSION_CODES.O_MR1) { if (msg.what == EXECUTE_TRANSACTION && msg.obj ! = null) { try { if (null == method) { Class clazz = Class.forName("android.app.servertransaction.ClientTransaction"); method = clazz.getDeclaredMethod("getCallbacks"); method.setAccessible(true); } List list = (List) method.invoke(msg.obj); if (! list.isEmpty()) { return list.get(0).getClass().getName().endsWith(".LaunchActivityItem"); } } catch (Exception e) { MatrixLog.e(TAG, "[isLaunchActivity] %s", e); } } return msg.what == LAUNCH_ACTIVITY; } else { return msg.what == LAUNCH_ACTIVITY; }}}}Copy the codeThe code in the above class is relatively simple and does not need to be overanalyzed. Startuptracer-related code is highlighted. After calculating the start point of Application initialization, let’s move on to the code in StartUpTracer#onActivityFocused:
@override public void onActivityFocused(String activity) {// If coldCost is 0, the code is not running. If (isColdStartup()) {// If firstScreenCost is 0, this is the first Activity to get focus. If (firstScreenCost == 0) {this.firstScreenCost = uptimeMillis() - ActivityThreadHacker.getEggBrokenTime(); } // If the first screen Activity has already been displayed, the Activity is a true MainActivity, Record the shift for cold start time consuming if (hasShowSplashActivity) {coldCost = uptimeMillis () - ActivityThreadHacker. GetEggBrokenTime (); } else {/ / if it has not yet been demonstrated first screen Activity if (splashActivities. The contains (Activity)) {/ / and declare the first screen of the Activity list included in this Activity, HasShowSplashActivity = true; } else if (splashActivities.isempty ()) {// Declare the first screen of activities to be empty, Matrixlog. I (TAG, "default Splash Activity [%s]", activity); coldCost = firstScreenCost; } else { MatrixLog.w(TAG, "pass this activity[%s] at duration of start up! splashActivities=%s", activity, splashActivities); Cold start time consuming if}} / / analysis (coldCost > 0) {analyse (ActivityThreadHacker. GetApplicationCost (), firstScreenCost, coldCost, false); }} else if (isWarmStartUp ()) {/ / whether the temperature start, here isWarmStartUp symbol also depends on the monitor ActivityLifecycleCallbacks, // The warmStartup time is the current time minus the last launch Activity time isWarmStartUp = false; long warmCost = uptimeMillis() - ActivityThreadHacker.getLastLaunchActivityTime(); if (warmCost > 0) { analyse(ActivityThreadHacker.getApplicationCost(), firstScreenCost, warmCost, true); } } } private boolean isColdStartup() { return coldCost == 0; } private boolean isWarmStartUp() { return isWarmStartUp; }Copy the codeThe analyse logic part of the analyse logic is to copy the function call stack and analyze the process when the start time reaches a threshold.
When the application starts, it hooks the ActivityThread class directly
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 { Considered the whole App launch time 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 codeCallback, the agent’s original handler. Callback, senses when Application onCreate ends
public class HackCallback implements Handler.Callback { private static final String TAG = "Matrix.HackCallback"; private static final int LAUNCH_ACTIVITY = 100; private static final int ENTER_ANIMATION_COMPLETE = 149; private static final int CREATE_SERVICE = 114; private static final int RECEIVER = 113; private static boolean isCreated = false; private final Handler.Callback mOriginalCallback; public HackCallback(Handler.Callback callback) { this.mOriginalCallback = callback; } @Override public boolean handleMessage(Message msg) { // MatrixLog.i(TAG, "[handleMessage] msg.what:%s begin:%s", msg.what, System.currentTimeMillis()); 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) {/ / send to start the Activity such as news, Considered the Application onCreate the end time of the 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 codeRecord the onCreate time of the first Activity
@Override public void onActivityCreated(Activity activity) { super.onActivityCreated(activity); if (isFirstActivityCreate && mFirstActivityMap.isEmpty()) { String activityName = activity.getComponentName().getClassName(); mFirstActivityIndex = getMethodBeat().getCurIndex(); mFirstActivityName = activityName; mFirstActivityMap.put(activityName, System.currentTimeMillis()); MatrixLog.i(TAG, "[onActivityCreated] first activity:%s index:%s", mFirstActivityName, mFirstActivityIndex); getMethodBeat().lockBuffer(true); }}Copy the codeRecord when the Activity gets focus (at compile time, insert methodbeat.at in the Activity subclass’s onWindowFocusChange method)
public static void at(Activity activity, boolean isFocus) { MatrixLog.i(TAG, "[AT] activity: %s, isCreated: Listeners size: %d, isFocus: %b", activity.getClass().getSimplename (), isCreated, sListeners size(), isFocus); if (isCreated && Thread.currentThread() == sMainThread) { for (IMethodBeatListener listener : sListeners) { listener.onActivityEntered(activity, isFocus, sIndex - 1, sBuffer); }}}Copy the codeThe startup phase is considered to end when the Activity gains focus (if there is a SplashActivity, record the time when the Activity gains focus)
@Override public void onActivityEntered(Activity activity, boolean isFocus, int nowIndex, long[] buffer) { ... Start data analysis}Copy the code