Android教你如何发现APP卡顿的实现

Android教你如何发现APP卡顿的实现
最近部门打算优化下 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 源码的深⼊研究，也有了其他两种⽐较⽅便的⽅式，并且这两种⽅式侵⼊性⼩，占⽤内存低，能够更好的⽤在实际场景中：
利⽤UI线程的Looper打印的⽇志匹配；
使⽤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:
ng.Thread.sleep(Native Method)
ng.Thread.sleep(Thread.java:443)
ng.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)
ng.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监控卡顿
我们知道， 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(yout.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: ng.Thread.sleep(Native Method)
ng.Thread.sleep(Thread.java:443)
ng.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)
ng.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教你如何发现APP卡顿的实现的⽂章就介绍到这了,更多相关Android APP卡顿内容请搜索以前的⽂章或继续浏览下⾯的相关⽂章希望⼤家以后多多⽀持！。