The opening

In the second article, we examined the LooperAnrTrace class in the TracePlugin. Today’s article continues by analyzing the source code for the FrameTrace class in TracePlugin.

When a FrameTrace is triggered

1.1 Traceplugin.start () method

Note that in the start() method of the TracePlugin class, all Trace onStartTrace() methods are called:

@Override public void start() { // ... Runnable = new Runnable() {@override public void run() {//... Omit / / 1, to join inputCallback event UIThreadMonitor addInputQueue the queue. The getMonitor (). OnStart (); if (traceConfig.isAnrTraceEnable()) { looperAnrTracer.onStartTrace(); } if (traceConfig.isIdleHandlerEnable()) { idleHandlerLagTracer = new IdleHandlerLagTracer(traceConfig); idleHandlerLagTracer.onStartTrace(); } if (traceConfig.isSignalAnrTraceEnable()) { if (! SignalAnrTracer.hasInstance) { signalAnrTracer = new SignalAnrTracer(traceConfig); signalAnrTracer.onStartTrace(); } } if (traceConfig.isMainThreadPriorityTraceEnable()) { threadPriorityTracer = new ThreadPriorityTracer(); threadPriorityTracer.onStartTrace(); If (traceconfig.isfpSenable ()) {frameTracer.onStartTrace(); } if (traceConfig.isEvilMethodTraceEnable()) { evilMethodTracer.onStartTrace(); } if (traceConfig.isStartupEnable()) { startupTracer.onStartTrace(); }}}; / /... Omit}Copy the code
  • Description:

Because the first startup analysis was done in detail, some of the irrelevant code was omitted. Let’s focus on two of them:

  1. UIThreadMonitor.getMonitor().onStart();
  2. frameTracer.onStartTrace();

Let’s look at the first one and see what we do.

1.1.1 UIThreadMonitor. OnStart ()

@Override public synchronized void onStart() { if (! isInit) { MatrixLog.e(TAG, "[onStart] is never init."); return; } if (! isAlive) { this.isAlive = true; synchronized (this) { MatrixLog.i(TAG, "[onStart] callbackExist:%s %s", Arrays.toString(callbackExist), Utils.getStack()); callbackExist = new boolean[CALLBACK_LAST + 1]; } //1, this int[] array is used to hold the start and end states of the three stages (input, animation, traversal) in a UI rendering frame. queueStatus = new int[CALLBACK_LAST + 1]; QueueCost = new Long [CALLBACK_LAST + 1]; queueCost = new Long [CALLBACK_LAST + 1]; // add an input stage callback to the input list. addFrameCallback(CALLBACK_INPUT, this, true); }}Copy the code
  • Description:

1,2 points are easier to understand, see the notes. Third point need detailed analysis, first look at addFrameCallback source code:

Private synchronized void addFrameCallback(int type, Runnable callback, Boolean isAddHeader) {// omit... Try {//1, remember that the lock objects in Choreographer were picked up by reflection from the start analysis in the first article. synchronized (callbackQueueLock) { Method method = null; switch (type) { case CALLBACK_INPUT: method = addInputQueue; break; case CALLBACK_ANIMATION: method = addAnimationQueue; break; case CALLBACK_TRAVERSAL: method = addTraversalQueue; break; } // 2, the final method is the addCallbackLocked method of CallbackQueue, callback is added to the list structure corresponding to type if (null! = method) { method.invoke(callbackQueues[type], ! isAddHeader ? SystemClock.uptimeMillis() : -1, callback, null); callbackExist[type] = true; } } } catch (Exception e) { MatrixLog.e(TAG, e.toString()); }}Copy the code

Conclusion:

The external listener needs to listen for different phases of each frame, so it registers different types of callback through the reflected method object.

As you can see, we registered an input callback in the onStart() method. I’m definitely going to use the run method. So let’s look at the run method for callback:

@Override public void run() { final long start = System.nanoTime(); try { doFrameBegin(token); doQueueBegin(CALLBACK_INPUT); addFrameCallback(CALLBACK_ANIMATION, new Runnable() { @Override public void run() { doQueueEnd(CALLBACK_INPUT); doQueueBegin(CALLBACK_ANIMATION); } }, true); addFrameCallback(CALLBACK_TRAVERSAL, new Runnable() { @Override public void run() { doQueueEnd(CALLBACK_ANIMATION); doQueueBegin(CALLBACK_TRAVERSAL); } }, true); } finally { if (config.isDevEnv()) { MatrixLog.d(TAG, "[UIThreadMonitor#run] inner cost:%sns", System.nanoTime() - start); }}}Copy the code
private void doQueueBegin(int type) { queueStatus[type] = DO_QUEUE_BEGIN; queueCost[type] = System.nanoTime(); } private void doQueueEnd(int type) { queueStatus[type] = DO_QUEUE_END; QueueCost [type] = system.nanotime () - queueCost[type]; synchronized (this) { callbackExist[type] = false; }}Copy the code
  • Description:

The logic is very clear. We start and end the three stages of input, animation and traversal in sequence, and then count the time consuming of each stage and save it for later reporting.

Alright, let’s move on to the second point: frameTracer.onStartTrace();

1.2 FrameTrace. OnStartTrace () method

@Override
final synchronized public void onStartTrace() {
    if (!isAlive) {
        this.isAlive = true;
        onAlive();
    }
}
Copy the code

The onStartTrace() method calls onAlive() :

@Override public void onAlive() { super.onAlive(); if (isFPSEnable) { UIThreadMonitor.getMonitor().addObserver(this); Matrix.with().getApplication().registerActivityLifecycleCallbacks(this); }}Copy the code
  • Description:

If isFPSEnable=true, register to listen for callbacks to the LooperObserver class. At this point, initialization of FrameTrace is complete. The back is to wait for the callback information to come over, after processing the data integration report. So let’s look at the parent of its superclass: LooperObserver.

1.3 LooperObserver class

public abstract class LooperObserver { private boolean isDispatchBegin = false; @CallSuper public void dispatchBegin(long beginNs, long cpuBeginNs, long token) { isDispatchBegin = true; } public void doFrame(String focusedActivity, long startNs, long endNs, boolean isVsyncFrame, long intendedFrameTimeNs, long inputCostNs, long animationCostNs, long traversalCostNs) { } @CallSuper public void dispatchEnd(long beginNs, long cpuBeginMs, long endNs, long cpuEndMs, long token, boolean isVsyncFrame) { isDispatchBegin = false; } public boolean isDispatchBegin() { return isDispatchBegin; }}Copy the code

LooperObserver is an abstract class that encapsulates the start and end callback of looper message processing. DispatchBegin and dispatchEnd are easy to understand, but what is doFrame? Let’s take a look at them one by one

1.3.1 dispatchBegin Method Parsing

dispatchBegin(long beginNs, long cpuBeginNs, long token)

  • BeginNs: indicates the time when messages start to be distributed, in nanoseconds. throughSystem.nanoTime()To obtain.
  • CpuBeginNs: indicates the thread time of the main thread when the message starts, in millisecondsSystemClock.currentThreadTimeMillis()To obtain.
  • Token: Same as beginNs.

1.3.2 dispatchEnd Method Parsing

dispatchEnd(long beginNs, long cpuBeginMs, long endNs, long cpuEndMs, long token, boolean isVsyncFrame)

  • BeginNs: indicates the time when messages start to be distributeddispatchBeginIn thebeginNsIt’s the same value.
  • CpuBeginMs: withdispatchBeginIn thecpuBeginMsIt’s the same value.
  • EndNs: indicates the point in time when the message ends distribution, in nanoseconds.
  • CpuEndMs: indicates the time of the main thread when the message ends and is distributed, in milliseconds.
  • Token: withdispatchBeginIn thetokenIt’s the same value.
  • IsVsyncFrame: Used to determinelooperWhether the message is a UI render frame. The default is false. Matrix throughUIThreadMonitorIn the class addFrameCallback(CALLBACK_INPUT, this, true);Start listening for input events inrunnableAt the start of the execution, the message in Looper is handling UI drawing.
@Override public synchronized void onStart() { if (! isInit) { MatrixLog.e(TAG, "[onStart] is never init."); return; } if (! isAlive) { this.isAlive = true; synchronized (this) { MatrixLog.i(TAG, "[onStart] callbackExist:%s %s", Arrays.toString(callbackExist), Utils.getStack()); callbackExist = new boolean[CALLBACK_LAST + 1]; } queueStatus = new int[CALLBACK_LAST + 1]; queueCost = new long[CALLBACK_LAST + 1]; // addFrameCallback(CALLBACK_INPUT, this, true); }}Copy the code

1.3.3 doFrame() method parsing

First, we want to know where the doFrame method is called? This is actually called in the dispatchEnd method of the UIThreadMonitor class:

Private void dispatchEnd() {// omit... synchronized (observers) { for (LooperObserver observer : observers) { if (observer.isDispatchBegin()) { observer.doFrame(AppMethodBeat.getVisibleScene(), startNs, endNs, isVsyncFrame, intendedFrameTimeNs, queueCost[CALLBACK_INPUT], queueCost[CALLBACK_ANIMATION], queueCost[CALLBACK_TRAVERSAL]); }}} // omit... }Copy the code

The meanings of method signatures are as follows:

doFrame(String focusedActivity, long startNs, long endNs, boolean isVsyncFrame, long intendedFrameTimeNs, long inputCostNs, long animationCostNs, long traversalCostNs)

FocusedActivity: The name of the current top-level activity

  • StartNs: indicates the time when messages start to be distributed in nanoseconds
  • EndNs: indicates the end time of message distribution in nanoseconds
  • IsVsyncFrame: Whether it is a UI render frame. As long as the input is triggeredcallbackCallbacks, that must be render messages.
  • IntendedFrameTimeNs: Indicates the current time, in nanoseconds. If the reflection retrieval fails, thestartNsAs the default. By reflectionChoreographerThe inner classFrameDisplayEventReceiverClass variables:mTimestampNanos.
  • InputCostNs: Input time. Now these three are pretty easy
  • AnimationCostNs: animation time.
  • TraversalCostNs: Traversal takes time.

Here’s a question:

DispatchEnd is the callback for every message in Looper that is processed, and some of those messages are definitely not UI renders. Then doFrame must call back every time, meaning that every message is rendered as a frame.

So isn’t that a problem? Will not cause false statistics? The answer will be given later

1.4 summarize

After analyzing for a long time, we finally understand the operation principle behind FrameTrace. We have done the following two things:

  1. Register callback reflectively into the Callback linked list of the Choreographer class. Calculate the time consuming of input, animation and traversal.
  2. toUIThreadMonitorRegister message callback, the main concern is each frame of message processingdoFrameMethods.

After getting these data, how did Matrix process and report them? Let’s move on.

FrameTrace data processing

After analysis, we only care about the doFrame method.

2.1 doFrame method

@Override public void doFrame(String focusedActivity, long startNs, long endNs, boolean isVsyncFrame, long intendedFrameTimeNs, long inputCostNs, long animationCostNs, long traversalCostNs) { if (isForeground()) { notifyListener(focusedActivity, startNs, endNs, isVsyncFrame, intendedFrameTimeNs, inputCostNs, animationCostNs, traversalCostNs); }}Copy the code

Only in the foreground will do the data collection and processing, the background will not process. Why is that? Because the app doesn’t do UI rendering when it’s not visible. This is controlled by the system to avoid wasting resources.

Then look at the notifyListener method:

private void notifyListener(final String focusedActivity, final long startNs, final long endNs, final boolean isVsyncFrame, final long intendedFrameTimeNs, final long inputCostNs, final long animationCostNs, final long traversalCostNs) { long traceBegin = System.currentTimeMillis(); try { final long jiter = endNs - intendedFrameTimeNs; // The number of frames in the entire drawing process: the actual time of a frame/the theoretical time of a frame. Final int dropFrame = (int) (jiter/frameIntervalNs); if (dropFrameListener ! = null) {// Trigger frame drop threshold, Is distributed out frames callback if (dropFrame > dropFrameListenerThreshold) {try {if (AppActiveMatrixDelegate. GetTopActivityName ()! = null) {// long lastResumeTime = lastResumeTimeMap.get(AppActiveMatrixDelegate.getTopActivityName()); dropFrameListener.dropFrame(dropFrame, AppActiveMatrixDelegate.getTopActivityName(), lastResumeTime); } } catch (Exception e) { MatrixLog.e(TAG, "dropFrameListener error e:" + e.getMessage()); } } } droppedSum += dropFrame; durationSum += Math.max(jiter, frameIntervalNs); synchronized (listeners) { for (final IDoFrameListener listener : listeners) { if (config.isDevEnv()) { listener.time = SystemClock.uptimeMillis(); } if (null ! = listener.getexecutor ()) {// The frame threshold >0 indicates the number of frames to collect. If not, then I don't have to analyze the replay. If (listener. GetIntervalFrameReplay () > 0) {/ / this is opened fpsmonitor switch will go here, Else Listener. collect(focusedActivity, startNs, endNs, dropFrame, isVsyncFrame, intendedFrameTimeNs, inputCostNs, animationCostNs, traversalCostNs); } else {listener.getexecutor ().execute(new Runnable() {@override public void run() {listener.getexecutor ().execute(new Runnable() {@override public void run() {listener.getexecutor ().  listener.doFrameAsync(focusedActivity, startNs, endNs, dropFrame, isVsyncFrame, intendedFrameTimeNs, inputCostNs, animationCostNs, traversalCostNs); }}); } } else { listener.doFrameSync(focusedActivity, startNs, endNs, dropFrame, isVsyncFrame, intendedFrameTimeNs, inputCostNs, animationCostNs, traversalCostNs); } 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() - traceBegin; if (config.isDebug() && cost > frameIntervalNs) { MatrixLog.w(TAG, "[notifyListener] warm! maybe do heavy work in doFrameSync! size:%s cost:%sms", listeners.size(), cost); }}}Copy the code

Description:

This method seems long and does two main things:

  1. Count the number of frames lost
  2. Data is collected and processed asynchronously

2.1.1 Calculation of lost frames

final long jiter = endNs - intendedFrameTimeNs; // The number of frames in the entire drawing process: the actual time of a frame/the theoretical time of a frame. Final int dropFrame = (int) (jiter/frameIntervalNs);Copy the code

How it works: Theoretically we require a render time of 16.66ms per frame. So you divide the actual time of a frame by the theoretical time to get the number of frames. Here’s an example:

  • Assuming that a frame actually takes time: <16.66ms, then dropFrame=0. It means no frames dropped, which is nice.
  • Assuming that a frame actually takes time: =16.66ms, then dropFrame=1. It means no frames dropped, which is nice.
  • Assuming that a frame actually takes time: 16.66ms< < about 32ms, then dropFrame=1. It’s not up to the theoretical value, but it’s basically nice.
  • Assuming that a frame actually takes time: =32ms, then dropFrame=2. I think I lost a frame, but I basically think nice.

According to this calculation, matrix determined such a standard to measure fluency according to the interval distribution of dropped frames:

If the number of frames dropped on a page ranges from 0 to 3, it is considered best. That is, the render time of each frame is basically maintained between 16ms and 48ms. To better understand:

What’s good about this definition? If you simply look at the average frame rate of the interface, you can’t see where the lag is. Moreover, even if each frame is 32ms, as long as the consecutive frames are 32ms, the human eye will not consider it to be stuck. Only the sudden appearance of a frame such as >300ms will make the user feel awkward.

Therefore, we judge an interface by collecting the number of frames dropped over a period of time (which Matrix puts at 200 frames). That is, every 200 frames). Website:

2.1.2 Data processing logic

If the FPS switch is on, start analyzing the data

// The fpsmonitor switch is on. Else Listener. collect(focusedActivity, startNs, endNs, dropFrame, isVsyncFrame, intendedFrameTimeNs, inputCostNs, animationCostNs, traversalCostNs);Copy the code

2.1.2.1 IDoFrameListener. Collect () method

FPSCollector inherits the IDoFrameListener class, so let’s look at the collect method first:

@CallSuper public void collect(String focusedActivity, long startNs, long endNs, int dropFrame, boolean isVsyncFrame, long intendedFrameTimeNs, long inputCostNs, long animationCostNs, FrameReplay = framereplay.create (); replay.focusedActivity = focusedActivity; replay.startNs = startNs; replay.endNs = endNs; replay.dropFrame = dropFrame; replay.isVsyncFrame = isVsyncFrame; replay.intendedFrameTimeNs = intendedFrameTimeNs; replay.inputCostNs = inputCostNs; replay.animationCostNs = animationCostNs; replay.traversalCostNs = traversalCostNs; list.add(replay); If (list.size() >= intervalFrame && getExecutor()! = null) {// intervalFrame is determined by FPSCollector, the inner class of FrameTrace. final List<FrameReplay> copy = new LinkedList<>(list); list.clear(); // Make a copy and start an analysis task based on the backup. getExecutor().execute(new Runnable() { @Override public void run() { doReplay(copy); For (FrameReplay Record: copy) {// Release record.recycle(); }}}); }}Copy the code

It’s very simple. It’s very clear in the notes. Then look at the doReplay method:

2.1.2.2 FPSCollector. DoReplay () method

@override public void doReplay(List<FrameReplay> List) {super.doreplay (List); for (FrameReplay replay : list) { doReplayInner(replay.focusedActivity, replay.startNs, replay.endNs, replay.dropFrame, replay.isVsyncFrame, replay.intendedFrameTimeNs, replay.inputCostNs, replay.animationCostNs, replay.traversalCostNs); }}Copy the code

Walk through the collection of frames and start analyzing each frame

public void doReplayInner(String visibleScene, long startNs, long endNs, int droppedFrames, boolean isVsyncFrame, long intendedFrameTimeNs, long inputCostNs, long animationCostNs, long traversalCostNs) { if (Utils.isEmpty(visibleScene)) return; // 1, if (! isVsyncFrame) return; FrameCollectItem item = map.get(visibleScene); // 2, from the page dimension, associate each frame with the current page. if (null == item) { item = new FrameCollectItem(visibleScene); map.put(visibleScene, item); } //3, start to collect the frame information of each page item.collect(droppedFrames); If (item.sumFrameCost >= timeSliceMs) {// report map.remove(visibleScene); // 5, start reporting item.report(); }}}Copy the code

We have done five things:

  1. Exclude invalid frames
  2. Collect for page dimensions
  3. Specific collection logic
  4. Report trigger logic
  5. To integrate
  • 1. Exclude invalid frames

This filters out non-UI draw messages (invalid frames). For example, if you send a normal message through handler in the main thread without refreshing the UI, the matrix will count it as a frame, but it won’t be analyzed here. Because there is no drawing process, there is no point.

This also answers the question raised before, so does not affect the statistics of the data!

And the matrix is throughlooperListen at the end of the message, not atchoreographertheonVsyncMethod to listen on. Why is that?

Because onVsync can only listen for freezes, not where. Matrix, on its own, postcallback externally to Choreographer’s queue, will definitely go to looper’s message interface whenever a UI drawing takes place, and then calculate the elapsed time for each stage and the current frame. Very clever ah!

  • 2. Collect data for page dimensions

There must be multiple frames that belong to the same page. Therefore, statistics are based on the dimension of the page. Instead of counting from the dimension of the frame. This makes it more difficult to fully reflect the distribution of page congestion.

  • 3. Specific collection logic
void collect(int droppedFrames) { float frameIntervalCost = 1f * UIThreadMonitor.getMonitor().getFrameIntervalNanos() / Constants.TIME_MILLIS_TO_NANO; // The total drawing time of this page. sumFrameCost += (droppedFrames + 1) * frameIntervalCost; SumDroppedFrames += droppedFrames; SumFrame++; // This is equivalent to a page of all statistics. // The number of frames dropped on a page is a distribution of good, bad, medium and high frames. Look at the proportions. Very nice! If (droppedFrames >= frozenThreshold) {// The number of frozen frames can be used to calculate the proportion. 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] += Math.max(droppedFrames, 0); }}Copy the code

The comments are very clear

  • 4. Reporting trigger logic

The total drawing time of a page is greater than a certain threshold. Matrix is 10s by default and can be configured externally.

It is equivalent to that a page is stuck, but if it is not frequently triggered and the accumulated conditions cannot be reported, it can be considered that the page is stuck or acceptable. If it is triggered, it means that the stackage is highly likely to exist in the online scene and is serious, so we need to pay attention to it.

  • 5. Report and integrate
Void report() {float FPS: number of frames per second float FPS = math.min (60.f, 1000.f * sumFrame/sumFrameCost); MatrixLog.i(TAG, "[report] FPS:%s %s", fps, toString()); try { TracePlugin plugin = Matrix.with().getPluginByClass(TracePlugin.class); if (null == plugin) { return; 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, plugin.getApplication()); Resultobject. put(shaRepluginInfo. ISSUE_SCENE, visibleScene); resultObject.put(SharePluginInfo.ISSUE_DROP_LEVEL, dropLevelObject); resultObject.put(SharePluginInfo.ISSUE_DROP_SUM, dropSumObject); resultObject.put(SharePluginInfo.ISSUE_FPS, fps); Issue issue = new Issue(); issue.setTag(SharePluginInfo.TAG_PLUGIN_FPS); issue.setContent(resultObject); plugin.onDetectIssue(issue); } catch (JSONException e) { MatrixLog.e(TAG, "json error", e); } finally { sumFrame = 0; sumDroppedFrames = 0; sumFrameCost = 0; }}Copy the code

Third, summary

FrameTrace does the following:

  1. Collect information for each frame: start and finish time of drawing, current page name, input, animation, traversal stage time, etc
  2. Triggered from the dimensions of the page, an overall evaluation of the render frames occurring on the current page: what percentage of the lag interval is. Is the page stalling due to continuous frame drop? Or is a frame seriously stalling?
  3. Of course, FPS related page presentation classes are also provided: FrameDecorator. In the test environment, the external can be used directly.

Well, the FrameTrace analysis is done, and further analysis continues!

As a result of the personal level is limited, if there is a problem still hope to comment correct, we progress together! If feel the article is helpful, also hope to help a little praise, thanks ~