Android 教你如何發現 APP 卡頓

huansky發表於2020-11-01
AndroidAPP

最近部門打算優化下 APP 在低端機上的卡頓情況，既然想優化，就必須獲取卡頓情況，那麼如何獲取卡頓情況就是本文目的。

一般主執行緒過多的 UI 繪製、大量的 IO 操作或是大量的計算操作佔用 CPU，導致 App 介面卡頓。只要我們能在發生卡頓的時候，捕捉到主執行緒的堆疊資訊和系統的資源使用資訊，即可準確分析卡頓發生在什麼函式，資源佔用情況如何。那麼問題就是如何有效檢測 Android 主執行緒的卡頓發生？

用 adb 系統工具觀察 App 的卡頓資料情況，試圖重現場景來定位問題。

常用的方式是使用 adb SurfaceFlinger 服務和 adb gfxinfo 功能，在自動化操作 app 的過程中，使用 adb 獲取資料來監控 app 的流暢情況，發現出現出現卡頓的時間段，尋找出現卡頓的場景和操作。

方式1：adb shell dumpsysSurfaceFlinger

使用 ‘adb shell dumpsysSurfaceFlinger’ 命令即可獲取最近 127 幀的資料，通過定期執行 adb 命令，獲取幀數來計算出幀率 FPS。

方式2：adb shell dumpsys gfxinfo

使用 ‘adb shell dumpsys gfxinfo’ 命令即可獲取最新 128 幀的繪製資訊，詳細包括每一幀繪製的 Draw，Process，Execute 三個過程的耗時，如果這三個時間總和超過 16.6ms 即認為是發生了卡頓。

已有的兩種方案比較適合衡量回歸卡頓問題的修復效果和判斷某些特定場景下是否有卡頓情況，然而，這樣的方式有幾個明顯的不足：

  • 一般很難構造實際使用者卡頓的環境來重現；

  • 這種方式操作起來比較麻煩，需編寫自動化用例，無法覆蓋大量的可疑場景，測試重現耗時耗人力；

  • 無法衡量靜態頁面的卡頓情況；

  • 出現卡頓的時候app無法及時獲取執行狀態和資訊，開發定位困難。

隨著對Android 原始碼的深入研究，也有了其他兩種比較方便的方式，並且這兩種方式侵入性小，佔用記憶體低，能夠更好的用在實際場景中：

  1. 利用UI執行緒的Looper列印的日誌匹配；

  2. 使用Choreographer.FrameCallback

利用 UI 執行緒的 Looper 列印的日誌匹配

Android 主執行緒更新 UI。如果介面1秒鐘重新整理少於 60 次，即 FPS 小於 60，使用者就會產生卡頓感覺。簡單來說，Android 使用訊息機制進行 UI 更新，UI 執行緒有個 Looper，在其 loop方法中會不斷取出 message，呼叫其繫結的 Handler 在 UI 執行緒執行。如果在 handler 的 dispatchMesaage 方法裡有耗時操作，就會發生卡頓。

下面來看下 Looper.loop( ) 的原始碼

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();

        // Allow overriding a threshold with a system prop. e.g.
        // adb shell 'setprop log.looper.1000.main.slow 1 && stop && start'
        final int thresholdOverride =
                SystemProperties.getInt("log.looper."
                        + Process.myUid() + "."
                        + Thread.currentThread().getName()
                        + ".slow", 0);

        boolean slowDeliveryDetected = false;

        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);
            }
            // Make sure the observer won't change while processing a transaction.
            final Observer observer = sObserver;

            final long traceTag = me.mTraceTag;
            long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;
            long slowDeliveryThresholdMs = me.mSlowDeliveryThresholdMs;
            if (thresholdOverride > 0) {
                slowDispatchThresholdMs = thresholdOverride;
                slowDeliveryThresholdMs = thresholdOverride;
            }
            final boolean logSlowDelivery = (slowDeliveryThresholdMs > 0) && (msg.when > 0);
            final boolean logSlowDispatch = (slowDispatchThresholdMs > 0);

            final boolean needStartTime = logSlowDelivery || logSlowDispatch;
            final boolean needEndTime = logSlowDispatch;

            if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {
                Trace.traceBegin(traceTag, msg.target.getTraceName(msg));
            }

            final long dispatchStart = needStartTime ? SystemClock.uptimeMillis() : 0;
            final long dispatchEnd;
            Object token = null;
            if (observer != null) {
                token = observer.messageDispatchStarting();
            }
            long origWorkSource = ThreadLocalWorkSource.setUid(msg.workSourceUid);
            try {
                msg.target.dispatchMessage(msg);
                if (observer != null) {
                    observer.messageDispatched(token, msg);
                }
                dispatchEnd = needEndTime ? SystemClock.uptimeMillis() : 0;
            } catch (Exception exception) {
                if (observer != null) {
                    observer.dispatchingThrewException(token, msg, exception);
                }
                throw exception;
            } finally {
                ThreadLocalWorkSource.restore(origWorkSource);
                if (traceTag != 0) {
                    Trace.traceEnd(traceTag);
                }
            }
            if (logSlowDelivery) {
                if (slowDeliveryDetected) {
                    if ((dispatchStart - msg.when) <= 10) {
                        Slog.w(TAG, "Drained");
                        slowDeliveryDetected = false;
                    }
                } else {
                    if (showSlowLog(slowDeliveryThresholdMs, msg.when, dispatchStart, "delivery",
                            msg)) {
                        // Once we write a slow delivery log, suppress until the queue drains.
                        slowDeliveryDetected = true;
                    }
                }
            }
            if (logSlowDispatch) {
                showSlowLog(slowDispatchThresholdMs, dispatchStart, dispatchEnd, "dispatch", msg);
            }

            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();
        }
    }

程式碼中兩處標紅的地方，就是 msg.target.dispatchMessage(msg) 的執行前後索列印的 log。通過測量處理時間就能檢測到部分UI執行緒是否有耗時的操作。注意到這行執行程式碼的前後，有兩個 logging.println 函式，如果設定了logging，會分別列印出 ”>>>>> Dispatching to “ 和 ”<<<<< Finished to “ 這樣的日誌，這樣我們就可以通過兩次log的時間差值，來計算 dispatchMessage 的執行時間，從而設定閾值判斷是否發生了卡頓。

那麼如何設定 logging 呢？

我們看下面的程式碼：

/**
     * Control logging of messages as they are processed by this Looper.  If
     * enabled, a log message will be written to <var>printer</var>
     * at the beginning and ending of each message dispatch, identifying the
     * target Handler and message contents.
     *
     * @param printer A Printer object that will receive log messages, or
     * null to disable message logging.
     */
public final class Looper {  
    private Printer mLogging;  
    public void setMessageLogging(@Nullable Printer printer) {  
        mLogging = printer;  
    }  
}  

public interface Printer {  
    void println(String x);  
}

Looper 的 mLogging 是私有的，並且提供了 setMessageLogging(@Nullable Printer printer) 方法，所以我們可以自己實現一個 Printer，在通過 setMessageLogging() 方法傳入即可，程式碼如下： 

public class BlockDetectByPrinter {
    
    public static void start() {
        Looper.getMainLooper().setMessageLogging(new Printer() {
            private static final String START = ">>>>> Dispatching";
            private static final String END = "<<<<< Finished";

            @Override
            public void println(String x) {
                if (x.startsWith(START)) {
                    LogMonitor.getInstance().startMonitor();
                }
                if (x.startsWith(END)) {
                    LogMonitor.getInstance().removeMonitor();
                }
            }
        });
    }
}

設定了logging後，loop方法會回撥 logging.println 列印出每次訊息執行的時間日誌：”>>>>> Dispatching to “和”<<<<< Finished to “。BlockDetectByPrinter 的使用則在Application 的 onCreate 方法中呼叫 BlockDetectByPrinter.start() 即可。

我們可以簡單實現一個 LogMonitor 來記錄卡頓時候主執行緒的堆疊資訊。當匹配到 >>>>> Dispatching 時，執行 startMonitor，會在 200ms（設定的卡頓閾值）後執行任務，這個任務負責在子執行緒（非UI執行緒）列印UI執行緒的堆疊資訊。如果訊息低於 200ms 內執行完成，就可以匹配到 <<<<< Finished 日誌，那麼在列印堆疊任務啟動前執行 removeMonitor 取消了這個任務，則認為沒有卡頓的發生；如果訊息超過 200ms 才執行完畢，此時認為發生了卡頓，並列印 UI 執行緒的堆疊資訊。

LogMonitor如何實現？

public class LogMonitor {
    private static final String TAG = "LogMonitor";
    private static LogMonitor sInstance = new LogMonitor();
    private HandlerThread mLogThread = new HandlerThread("log");
    private Handler mIoHandler;
    private static final long TIME_BLOCK = 200L;

    private LogMonitor() {
        mLogThread.start();
        mIoHandler = new Handler(mLogThread.getLooper());
    }

    private static Runnable mLogRunnable = new Runnable() {
        @Override
        public void run() {
            StringBuilder sb = new StringBuilder();
            StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();
            for (StackTraceElement s : stackTrace) {
                sb.append(s.toString() + "\n");
            }
            Log.e(TAG, sb.toString());
        }
    };

    public static LogMonitor getInstance() {
        return sInstance;
    }

    public boolean isMonitor() {
        return mIoHandler.hasCallbacks(mLogRunnable);
    }

    public void startMonitor() {
        mIoHandler.postDelayed(mLogRunnable, TIME_BLOCK);
    }

    public void removeMonitor() {
        mIoHandler.removeCallbacks(mLogRunnable);
    }
}

這裡我們使用 HandlerThread 來構造一個 Handler，HandlerThread 繼承自 Thread，實際上就一個 Thread，只不過比普通的 Thread 多了一個 Looper，對外提供自己這個 Looper 物件的 getLooper 方法，然後建立 Handler 時將 HandlerThread 中的 looper 物件傳入。這樣我們的 mIoHandler 物件就是與 HandlerThread 這個非 UI 執行緒繫結的了，它處理耗時操作將不會阻塞UI。如果UI執行緒阻塞超過 200ms，就會在子執行緒中執行 mLogRunnable，列印出 UI 執行緒當前的堆疊資訊，如果處理訊息沒有超過 1000ms，則會實時的 remove 掉這個mLogRunnable 任務。

發生卡頓時列印出堆疊資訊的大致內容如下，開發可以通過 log 定位耗時的地方。

2020-10-30 14:26:13.823 30359-30415/com.example.myproxyplugin E/LogMonitor: java.lang.Thread.sleep(Native Method)
    java.lang.Thread.sleep(Thread.java:443)
    java.lang.Thread.sleep(Thread.java:359)
    com.example.myproxyplugin.MainActivity$1.run(MainActivity.java:22)
    android.os.Handler.handleCallback(Handler.java:900)
    android.os.Handler.dispatchMessage(Handler.java:103)
    android.os.Looper.loop(Looper.java:219)
    android.app.ActivityThread.main(ActivityThread.java:8347)
    java.lang.reflect.Method.invoke(Native Method)
    com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:513)
    com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1055)

優點：使用者使用 app 或者測試過程中都能從app層面來監控卡頓情況，一旦出現卡頓能記錄 app 狀態和資訊， 只要dispatchMesaage執行耗時過大都會記錄下來，不再有前面兩種adb方式面臨的問題與不足。

缺點：需另開子執行緒獲取堆疊資訊，會消耗少量系統資源。

在實際實現中，不同手機不同 Android  系統甚至是不同的 ROM 版本，Loop 函式不一定都能列印出 ”>>>>> Dispatching to “ 和 ”<<<<< Finished to “ 這樣的日誌，導致該方式無法進行。

優化的策略：我們知道 Loop 函式開始和結束必會執行 println 列印日誌，所以優化版本將卡頓的判斷改為，Loop輸出第一句 log 時當作 startMonitor，輸出下一句log時當作end時刻來解決這個問題。

其實 Looper 中有個 Observer 介面可以很好的完成這個任務，只是因為被標記為 hide 了，所以我們不能使用，不過可以知道下。

Observer 介面提供了三個方法，分別是監聽任務開始，結束，發生錯誤的回撥。

    /** {@hide} */
    public interface Observer {
        /**
         * Called right before a message is dispatched.
         *
         * <p> The token type is not specified to allow the implementation to specify its own type.
         *
         * @return a token used for collecting telemetry when dispatching a single message.
         *         The token token must be passed back exactly once to either
         *         {@link Observer#messageDispatched} or {@link Observer#dispatchingThrewException}
         *         and must not be reused again.
         *
         */
        Object messageDispatchStarting();

        /**
         * Called when a message was processed by a Handler.
         *
         * @param token Token obtained by previously calling
         *              {@link Observer#messageDispatchStarting} on the same Observer instance.
         * @param msg The message that was dispatched.
         */
        void messageDispatched(Object token, Message msg);

        /**
         * Called when an exception was thrown while processing a message.
         *
         * @param token Token obtained by previously calling
         *              {@link Observer#messageDispatchStarting} on the same Observer instance.
         * @param msg The message that was dispatched and caused an exception.
         * @param exception The exception that was thrown.
         */
        void dispatchingThrewException(Object token, Message msg, Exception exception);
    }

利用Choreographer.FrameCallback監控卡頓

Choreographer.FrameCallback 官方文件連結（https://developer.android.com/reference/android/view/Choreographer.FrameCallback.html）

我們知道， Android 系統每隔 16ms 發出 VSYNC 訊號，來通知介面進行重繪、渲染，每一次同步的週期為16.6ms，代表一幀的重新整理頻率。SDK 中包含了一個相關類，以及相關回撥。理論上來說兩次回撥的時間週期應該在 16ms，如果超過了 16ms 我們則認為發生了卡頓，利用兩次回撥間的時間週期來判斷是否發生卡頓（這個方案是 Android 4.1 API 16 以上才支援）。

這個方案的原理主要是通過 Choreographer 類設定它的 FrameCallback 函式，當每一幀被渲染時會觸發回撥 FrameCallback， FrameCallback 回撥 void doFrame (long frameTimeNanos) 函式。一次介面渲染會回撥 doFrame 方法，如果兩次 doFrame 之間的間隔大於 16.6ms 說明發生了卡頓。 

public class FPSFrameCallback implements Choreographer.FrameCallback {

    private static final String TAG = "FPS_TEST";
    private long mLastFrameTimeNanos = 0;
    private long mFrameIntervalNanos;

    public FPSFrameCallback(long lastFrameTimeNanos) {
        mLastFrameTimeNanos = lastFrameTimeNanos;
        // 1s 60 幀
        mFrameIntervalNanos = (long) (1000000000 / 60.0);
    }

    @Override
    public void doFrame(long frameTimeNanos) {

        //初始化時間
        if (mLastFrameTimeNanos == 0) {
            mLastFrameTimeNanos = frameTimeNanos;
        }
        final long jitterNanos = frameTimeNanos - mLastFrameTimeNanos;
        if (jitterNanos >= mFrameIntervalNanos) {
            final long skippedFrames = jitterNanos / mFrameIntervalNanos;
            if (skippedFrames > 30) {
                Log.i(TAG, "Skipped " + skippedFrames + " frames!  "
                        + "The application may be doing too much work on its main thread.");
            }
        }
        mLastFrameTimeNanos = frameTimeNanos;
        //註冊下一幀回撥
        Choreographer.getInstance().postFrameCallback(this);
    }
}

本質和 log 沒太多區別，但是這個更加通用些，不會因為機型系統原因出現不可用的問題。 

示例

下面進入實戰，看看程式碼層面是如何實現的。 

MainActivity 程式碼如下：

public class MainActivity extends AppCompatActivity {
    Handler handler = new Handler(Looper.getMainLooper());

    private final Runnable runnable = new Runnable() {
        @Override
        public void run() {
            try {
                Thread.sleep(600);
                handler.postDelayed(runnable, 500);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    };

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);
        Choreographer.getInstance().postFrameCallback(new FPSFrameCallback(System.nanoTime()));
        BlockDetectByPrinter.start();
    }

    @Override
    protected void onResume() {
        super.onResume();
        handler.postDelayed(runnable, 500);
    }

}

收集到的堆疊資訊如下：

2020-10-30 14:26:13.823 30359-30415/com.example.myproxyplugin E/LogMonitor: java.lang.Thread.sleep(Native Method)
    java.lang.Thread.sleep(Thread.java:443)
    java.lang.Thread.sleep(Thread.java:359)
    com.example.myproxyplugin.MainActivity$1.run(MainActivity.java:22)
    android.os.Handler.handleCallback(Handler.java:900)
    android.os.Handler.dispatchMessage(Handler.java:103)
    android.os.Looper.loop(Looper.java:219)
    android.app.ActivityThread.main(ActivityThread.java:8347)
    java.lang.reflect.Method.invoke(Native Method)
    com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:513)
    com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1055)

對於 FPS log 可以看到如下資訊：

     I/Choreographer: Skipped 64 frames!  The application may be doing too much work on its main thread.
     I/FPS_TEST: Skipped 65 frames!  The application may be doing too much work on its main thread.

如果你要把上面的方法用到自己的APP 中，那麼還需要很多操作，具體可以閱讀參考文獻的內容。

 

參考文章

廣研Android卡頓監控系統

相關文章