卡頓監測之真正輕量級的卡頓監測工具BlockDetectUtil（僅一個類）

_yph發表於2018-03-01
BloC

一、背景

    一直以來，應用的流暢度都關乎著使用者的體驗性，而體驗性好的產品自然而然會受到更多使用者的歡迎，所以對於廣大的工程師來說，介面的卡頓優化一直是Android應用效能優化的重要一環。而當前應用卡頓監控的主要切入點有兩個：

1，利用UI執行緒的Looper

UI執行緒的Looper的loop()方法中會一直從訊息佇列中取出msg，然後交給這個msg對應handler的dispatchMessage處理，而Android是通過訊息機制來驅動UI更新的，也就是說主執行緒發生了卡頓，那麼也就是在dispatchMessage方法裡發生了耗時操作。

public static void loop() {
    final Looper me = myLooper();
    if (me == null) {
        throw new RuntimeException("No Looper; Looper.prepare() wasn't called on this thread.");
    }
    final MessageQueue queue = me.mQueue;

    // Make sure the identity of this thread is that of the local process,
    // and keep track of what that identity token actually is.
    Binder.clearCallingIdentity();
    final long ident = Binder.clearCallingIdentity();

    for (;;) {
        Message msg = queue.next(); // might block
        if (msg == null) {
            // No message indicates that the message queue is quitting.
            return;
        }

        // This must be in a local variable, in case a UI event sets the logger
        final Printer logging = me.mLogging;
        if (logging != null) {
            logging.println(">>>>> Dispatching to " + msg.target + " " +
                    msg.callback + ": " + msg.what);
        }

        final long traceTag = me.mTraceTag;
        if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {
            Trace.traceBegin(traceTag, msg.target.getTraceName(msg));
        }
        try {
            msg.target.dispatchMessage(msg);
        } finally {
            if (traceTag != 0) {
                Trace.traceEnd(traceTag);
            }
        }

        if (logging != null) {
            logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
        }

        // Make sure that during the course of dispatching the
        // identity of the thread wasn't corrupted.
        final long newIdent = Binder.clearCallingIdentity();
        if (ident != newIdent) {
            Log.wtf(TAG, "Thread identity changed from 0x"
                    + Long.toHexString(ident) + " to 0x"
                    + Long.toHexString(newIdent) + " while dispatching to "
                    + msg.target.getClass().getName() + " "
                    + msg.callback + " what=" + msg.what);
        }

        msg.recycleUnchecked();
    }
}

那麼怎麼來監測dispatchMessage方法的執行時間呢？注意到這個方法的前後有兩個logging.println函式，那麼我們可以自己實現一個Printer來替換系統的logging，在通過setMessageLogging()方法傳入，最後通過這兩個函式列印的差值即可算出dispatchMessage方法的耗時。得到的時間跟預定的閾值時間對比可確定是否發生了卡頓。BlockCanary就是採用了此方案。


2，利用Choreographer.FrameCallback監控卡頓

Android系統每隔16.6ms發出VSYNC訊號，來通知介面進行重繪、渲染。SDK中包含了一個相關類Choreographer，當每一幀被渲染時會觸發回撥FrameCallback的doFrame (long frameTimeNanos)方法。由於主執行緒的執行耗時會造成兩次doFrame的間隔大於16.6ms，這裡我們設定一個閾值，如果兩次doFrame之間的間隔大於這個閾值時間，說明就發生了卡頓。

主執行緒耗時操作導致了兩次doFrame的間隔大於16.6ms，那具體到底是哪裡導致的呢，我們從原始碼的角度來看看，

        Choreographer.getInstance().postFrameCallback(new Choreographer.FrameCallback() {
            @Override
            public void doFrame(long frameTimeNanos) {
                Choreographer.getInstance().postFrameCallback(this);
            }
        });

通常我們是用上面的程式碼來監控卡頓，主要就是獲取Choreographer的例項，然後呼叫postFrameCallback方法，傳入一個介面，然後實現介面方法，那我們直接看postFrameCallback方法

public void postFrameCallback(FrameCallback callback) {
    postFrameCallbackDelayed(callback, 0);
}

接著看postFrameCallbackDelayed方法，此處的第一個引數為CALLBACK_ANIMATION為1

public static final int CALLBACK_ANIMATION = 1;

public void postFrameCallbackDelayed(FrameCallback callback, long delayMillis) {
    if (callback == null) {
        throw new IllegalArgumentException("callback must not be null");
    }
    postCallbackDelayedInternal(CALLBACK_ANIMATION,
            callback, FRAME_CALLBACK_TOKEN, delayMillis);
}

繼續postCallbackDelayedInternal方法，這裡做了兩步操作，將傳進來的介面FrameCallback在addCallbackLocked方法裡封裝成CallbackRecord後新增進佇列mCallbackQueues，然後定義了一個message傳送給mHandler處理。這裡mCallbackQueues是一個儲存CallbackRecord的陣列，而CallbackRecord是一個單連結串列結構，其action可能是Runnable或者FrameCallback，也就是說當我們post多個FrameCallback的時候，它們是以連結串列的形式存在CallbackRecord裡。

private static final class CallbackRecord {
    public CallbackRecord next;
    public long dueTime;
    public Object action; // Runnable or FrameCallback
    public Object token;

    public void run(long frameTimeNanos) {
        if (token == FRAME_CALLBACK_TOKEN) {
            ((FrameCallback)action).doFrame(frameTimeNanos);
        } else {
            ((Runnable)action).run();
        }
    }
}

private void postCallbackDelayedInternal(int callbackType,
        Object action, Object token, long delayMillis) {
    ...
    synchronized (mLock) {
        final long now = SystemClock.uptimeMillis();
        final long dueTime = now + delayMillis;
        //此處callbackType即CALLBACK_ANIMATION = 1，而mCallbackQueues[1]儲存的是CALLBACK_ANIMATION佇列
        mCallbackQueues[callbackType].addCallbackLocked(dueTime, action, token);//新增進佇列

        if (dueTime <= now) {
            scheduleFrameLocked(now);
        } else {
            Message msg = mHandler.obtainMessage(MSG_DO_SCHEDULE_CALLBACK, action);
            msg.arg1 = callbackType;
            msg.setAsynchronous(true);
            mHandler.sendMessageAtTime(msg, dueTime);
        }
    }
}

繼續跟mssage，經過一系列的跳轉，最終程式碼來到DisplayEventReceiver的nativeScheduleVsync，這是一個native方法，這裡我們就沒必要跟下去了，從它的註釋來看可以知道它的功能是接收下一次顯示幀訊號

/**
 * Schedules a single vertical sync pulse to be delivered when the next
 * display frame begins.
 */
public void scheduleVsync() {
    if (mReceiverPtr == 0) {
        Log.w(TAG, "Attempted to schedule a vertical sync pulse but the display event "
                + "receiver has already been disposed.");
    } else {
        nativeScheduleVsync(mReceiverPtr);
    }
}

那麼哪裡接收下一次的幀訊號呢，在Choreographer找到繼承自DisplayEventReceiver的FrameDisplayEventReceiver，它的onVsync即是回撥下一次幀訊號的方法。

private final class FrameDisplayEventReceiver extends DisplayEventReceiver
        implements Runnable {
    private boolean mHavePendingVsync;
    private long mTimestampNanos;
    private int mFrame;

    public FrameDisplayEventReceiver(Looper looper) {
        super(looper);
    }
    @Override
    public void onVsync(long timestampNanos, int builtInDisplayId, int frame) {
        ...
        Message msg = Message.obtain(mHandler, this);
        msg.setAsynchronous(true);
        mHandler.sendMessageAtTime(msg, timestampNanos / TimeUtils.NANOS_PER_MS);
    }
    @Override
    public void run() {
        mHavePendingVsync = false;
        doFrame(mTimestampNanos, mFrame);
    }
}

onVsync是非同步操作，所以接收到訊號後通過handler把執行緒切換為主執行緒然後再執行doFrame，那麼到這裡我們已經知道為什麼主執行緒耗時會造成卡頓了，因為當如果主執行緒在執行耗時操作時，會來不及從訊息佇列裡取出上面程式碼的Runnable來執行，那麼也就來不及執行doFrame方法，而doFrame方法裡執行了從儲存FrameCallback介面的佇列裡取出介面執行其回撥方法的操作，還有介面的繪製方法，這裡我們再跟跟doFrame方法就一目瞭然。

void doFrame(long frameTimeNanos, int frame) {
    ...
    try {
        Trace.traceBegin(Trace.TRACE_TAG_VIEW, "Choreographer#doFrame");

        mFrameInfo.markInputHandlingStart();
        doCallbacks(Choreographer.CALLBACK_INPUT, frameTimeNanos);

        mFrameInfo.markAnimationsStart();
        doCallbacks(Choreographer.CALLBACK_ANIMATION, frameTimeNanos);//執行我們設定進去的FrameCallback

        mFrameInfo.markPerformTraversalsStart();
        doCallbacks(Choreographer.CALLBACK_TRAVERSAL, frameTimeNanos);//執行繪製介面操作doTraversal

        doCallbacks(Choreographer.CALLBACK_COMMIT, frameTimeNanos);
    } finally {
        Trace.traceEnd(Trace.TRACE_TAG_VIEW);
    }
    ...
}

繼續看doCallbacks方法，顯然根據type取出陣列的CallbackRecord連結串列，然後遍歷CallbackRecord執行其run方法，從上面貼的CallbackRecord結構可以看到，它的run方法其實就是要麼執行FrameCallback的doFrame方法，要麼就是Runnable的run方法。

void doCallbacks(int callbackType, long frameTimeNanos) {
    CallbackRecord callbacks;
    synchronized (mLock) {
        callbacks = mCallbackQueues[callbackType].extractDueCallbacksLocked(
                now / TimeUtils.NANOS_PER_MS);
        if (callbacks == null) {
            return;
        }
        ...
    try {
        Trace.traceBegin(Trace.TRACE_TAG_VIEW, CALLBACK_TRACE_TITLES[callbackType]);
        for (CallbackRecord c = callbacks; c != null; c = c.next) {
            c.run(frameTimeNanos);
        }
    } finally {
        ...
    }
}

那麼到這裡也就可以得出答案了，當主執行緒在執行耗時操作時，會來不及從訊息佇列裡取出FrameDisplayEventReceiver 來執行，那麼也就來不及執行doFrame方法，那麼最終導致來不及執行FrameCallback的doFrame方法。而對UI造成的影響在這裡可能還是不那麼明顯，還存留著一些問題：

    上面可以看到doFrame除了執行FrameCallback的doFrame回撥，還執行了介面的繪製操作，即下面這句

        doCallbacks(Choreographer.CALLBACK_TRAVERSAL, frameTimeNanos);//執行繪製介面操作doTraversal

而這個方法主要是執行佇列裡Runnable，那麼說明Runnable裡封裝了UI繪製相關方法，那麼這個Runnable是封裝了什麼方法？它是在哪裡被放入佇列的？

    我們可以找請求介面重繪的方法來進行跟蹤，比如View的invalidate方法或者requestLayout都可以，這兩個方法的執行流程都是通過呼叫父容器相應方法來層層向上呼叫的，最終跑到ViewRootImpl來實現，接下來我們看看這兩個方法在ViewRootImpl裡的實現：

void invalidate() {
    mDirty.set(0, 0, mWidth, mHeight);
    if (!mWillDrawSoon) {
        scheduleTraversals();
    }
}
public void requestLayout() {
    if (!mHandlingLayoutInLayoutRequest) {
        checkThread();
        mLayoutRequested = true;
        scheduleTraversals();
    }
}

都不約而同的呼叫了scheduleTraversals，那我們看看這個方法幹了啥

void scheduleTraversals() {
    if (!mTraversalScheduled) {
        mTraversalScheduled = true;
        mTraversalBarrier = mHandler.getLooper().getQueue().postSyncBarrier();
        mChoreographer.postCallback(
                Choreographer.CALLBACK_TRAVERSAL, mTraversalRunnable, null);
        if (!mUnbufferedInputDispatch) {
            scheduleConsumeBatchedInput();
        }
        notifyRendererOfFramePending();
        pokeDrawLockIfNeeded();
    }
}

看到了我們熟悉的方法mChoreographer.postCallback，說明這個封裝了UI繪製的Runnable是在這裡被加入到佇列中，那麼接下來看看這個mTraversalRunnable是不是真的是做了UI繪製的工作

final class TraversalRunnable implements Runnable {
    @Override
    public void run() {
        doTraversal();
    }
}

在看看doTraversal

void doTraversal() {
    if (mTraversalScheduled) {
        mTraversalScheduled = false;
        mHandler.getLooper().getQueue().removeSyncBarrier(mTraversalBarrier);
        if (mProfile) {
            Debug.startMethodTracing("ViewAncestor");
        }
        performTraversals();
        if (mProfile) {
            Debug.stopMethodTracing();
            mProfile = false;
        }
    }
}
裡面執行了performTraversals，這說明這個mTraversalRunnable確實是做了UI繪製的工作。那麼到這裡我們就明白了主執行緒耗時操作對UI的影響了。結合前面分析的結果，當主執行緒耗時操作，會來不及從訊息佇列裡取出FrameDisplayEventReceiver 來執行，那麼也就來不及執行doFrame方法，也就來不及去處理封裝了doTraversal的Runnable，而doTraversal方法裡執行了performTraversal，而作為View繪製的根方法performTraversal來不及執行，就導致了最終的卡頓現象。 


二、利用Choreographer.FrameCallback實現監控卡頓

首先我們設定一個閾值時間，在這個時間內可能有多個耗時方法，為了能準確地獲取耗時方法堆疊，還需要設定一個取樣頻率f，表示在這個閾值時間裡取樣f次，然後選取出現次數兩次以上相同的堆疊，那這些堆疊對應的方法就是造成卡頓的方法。
大體流程：
①，開啟堆疊列印執行緒，迴圈獲取堆疊f次，取出重複次數兩次以上的堆疊；
②，如果下次doFrame執行時間跟第一次間隔小於閾值，則在下次doFrame到來之時，移除本次的執行緒，然後重新執行①；
      如果下次doFrame執行時間跟第一次間隔大於閾值，則在下次doFrame到來之前，執行緒會把①中取出來的堆疊進行列印，此時的堆疊資訊就是主執行緒造成卡頓的方法所處的堆疊。

然後還得考慮兩點的就是：

1，debug的時候不列印，因為debug操作本來就是要卡在斷點處除錯的；

2，在一個閾值時間內取樣f次，可能得到多個相同堆疊，需要去重後才能列印。

綜上，實現的程式碼如下：

public class BlockDetectUtil {

    private static final int TIME_BLOCK = 600;//閾值
    private static final int FREQUENCY = 6;//取樣頻率
    private static Handler mIoHandler;
    public static void start() {
        HandlerThread mLogThread = new HandlerThread("yph");
        mLogThread.start();
        mIoHandler = new Handler(mLogThread.getLooper());
        mIoHandler.postDelayed(mLogRunnable, TIME_BLOCK/FREQUENCY);
        Choreographer.getInstance().postFrameCallback(new Choreographer.FrameCallback() {
            @Override
            public void doFrame(long frameTimeNanos) {
                mIoHandler.removeCallbacks(mLogRunnable);
                mIoHandler.postDelayed(mLogRunnable, TIME_BLOCK/FREQUENCY);
                Choreographer.getInstance().postFrameCallback(this);
            }
        });
    }
    private static Runnable mLogRunnable = new Runnable() {

        int time = FREQUENCY;
        List<String> list = new ArrayList();
        @Override
        public void run() {
            if(Debug.isDebuggerConnected())return;
            StringBuilder sb = new StringBuilder();
            StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();
            for (StackTraceElement s : stackTrace) {
                sb.append(s.toString() + "\n");
            }
            list.add(sb.toString());
            time -- ;
            if(time == 0) {
                time = FREQUENCY;
                reList(list);
                for(String s : list) {
                    Log.e("BlockDetectUtil", s);
                }
                list.clear();
            }else
                mIoHandler.postDelayed(mLogRunnable, TIME_BLOCK/FREQUENCY);
        }
    };
    private static void reList(List<String> list){
        List<String> reList = new ArrayList<>();
        String lastLog = "";
        for(String s : list){
            if(s.equals(lastLog) && !reList.contains(s)) {
                reList.add(s);
            }
            lastLog = s;
        }
        list.clear();
        list.addAll(reList);
    }
}

使用方法：在Application的onCreate方法裡新增一句 BlockDetectUtil.start();

三，驗證

這裡我們用執行緒的sleep方法來代替主執行緒耗時方法，直接在主執行緒執行：


頁面開啟後，再點選tv，監測的堆疊如下：


當一個耗時方法（35行），其他不耗時的情況：


堆疊如下，可以看到準確地找到了第35行耗時方法：


多個耗時方法的情況：


堆疊如下，可以看到準確的找到這兩個耗時方法：


當然，程式碼中更常見的是迴圈執行一個不耗時方法所造成的耗時卡頓現象，如下程式碼：


堆疊如下，所以當堆疊中找到的方法不耗時的情況下，說明它被迴圈呼叫了：


顯然，這些情況都是可以準確的找出具體耗時方法所對應的堆疊的。

四、總結

    本文介紹了Android卡頓優化的重要性及優化的兩種方案，分享了BlockDetectUtil這個真正輕量級的卡頓監測工具類，同時講解了它的實現思路。程式碼裡的閾值和取樣頻率都是我簡單測試後的經驗值，可能不太準確，大家可以自己接入這個工具自行測試。

    系列文章第二篇，歡迎繼續關注 卡頓監測之遠端收集log（潛入Bugly這趟順風車）

相關文章