什么是ANR？
ANR(Application Not responding)，是指应用程序未响应，Android系统对于一些事件需要在一定的时间范围内完成，如果超过预定时间能未能得到有效响应或者响应时间过长，都会造成ANR。一般地，这时往往会弹出一个提示框，告知用户当前xxx未响应，用户可选择继续等待或者Force Close。
那么哪些场景会造成ANR呢？
Service Timeout：前台服务在20s内未执行完成；
BroadcastQueue Timeout：前台广播在10s内未执行完成
ContentProvider Timeout：内容提供者在publish过超时10s;
InputDispatching Timeout：输入事件分发超时5s，包括按键和触摸事件。
ANR的原理通俗的说 在以上事件触发后会预先埋一个ANR弹框的炸弹，类似于handler发一个延迟消息，在单位时间内我们会拆除这个炸弹，但如果由于这期间的操作太过耗时导致没有在规定时间内拆除，炸弹就会引爆。ANR最终表现就是卡顿，我们的目的只是为了知道是否卡顿，ANR的知识暂时不深入开展。因为ANR的触发是在底层C C++做的，需要监控SIGQUIT信号并作相关兼容才能实现，难度复杂性都很高。
那有没有容易的小白也可以很容易实现的呢？有！ 那就是利用Handler.
比如WatchDog 通过不断向UI线程发送Message，每隔一段时间检查一次刚刚发送的Message是否被处理，如果没有被处理，则说明这段时间主线程被卡住了 这种方法的轮询的时间间隔选择很重要，又让人左右为难，轮询的时间间隔越小，对性能的负面影响就越大，而时间间隔选择的越大，漏报的可能性也就越大
替换主线程Looper的Printer，从而监控dispatchMessage的执行时间。这方案也比较常见，微信本身（Matrix）也在线上也使用了这种方案。
在Android源码中，主线程Looper也会根据执行dispatchMessage的时间来判断是否有卡顿，有则会打印一些日志
无论是通过反射替换Looper的mLogging还是通过setMessageLogging设置printer，我们只需要替换主线程Looper的printer对象，通过计算执行dispatchMessage方法之后和之前打印字符串的时间的差值，就可以拿到到dispatchMessage方法执行的时间。而大部分的主线程的操作最终都会执行到这个dispatchMessage方法中。
注意我说的是大部分哟！先卖个关子后续会展开讲，做了这么多铺垫，下面开始手撕源码了
根据前文可知，我们需要在 Matrix init 之后手动调用插件的 start() 方法：
public void start() {
super.start();
if (!isSupported()) {
MatrixLog.w(TAG, "[start] Plugin is unSupported!");
return;
}
MatrixLog.w(TAG, "start!");
Runnable runnable = new Runnable() {
@Override
public void run() {
if (willUiThreadMonitorRunning(traceConfig)) {
if (!UIThreadMonitor.getMonitor().isInit()) {
try {
UIThreadMonitor.getMonitor().init(traceConfig, supportFrameMetrics);
} catch (java.lang.RuntimeException e) {
MatrixLog.e(TAG, "[start] RuntimeException:%s", e);
return;
}
}
}
if (traceConfig.isAppMethodBeatEnable()) {
AppMethodBeat.getInstance().onStart();
} else {
AppMethodBeat.getInstance().forceStop();
}
UIThreadMonitor.getMonitor().onStart();
if (traceConfig.isAnrTraceEnable()) {
looperAnrTracer.onStartTrace();
}
if (traceConfig.isIdleHandlerTraceEnable()) {
idleHandlerLagTracer = new IdleHandlerLagTracer(traceConfig);
idleHandlerLagTracer.onStartTrace();
}
if (traceConfig.isTouchEventTraceEnable()) {
touchEventLagTracer = new TouchEventLagTracer(traceConfig);
touchEventLagTracer.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();
}
}
};
if (Thread.currentThread() == Looper.getMainLooper().getThread()) {
runnable.run();
} else {
MatrixLog.w(TAG, "start TracePlugin in Thread[%s] but not in mainThread!", Thread.currentThread().getId());
MatrixHandlerThread.getDefaultMainHandler().post(runnable);
}
}
上述代码做了三件事
- UIThreadMonitor：一个监听 UI 线程的监视器，监听什么内容？怎么监听？后面会给出答案。
- 追踪器开始工作：TracePlugin 包含的四大追踪器，是实际的工作者。
- 线程检查：监视器和追踪器等需要在主线程进行初始化，所以分为两种情况：当前在主线程下：直接调用 Runnable 对象的 run() 方法执行初始化；当前不在主线程：使用 MatrixHandlerThread 中的主线程 Handler post 任务，切换到主线程执行初始化。
UIThreadMonitor
UIThreadMonitor 顾名思义一个监听UI 线程的监视器，它实现了 Runnable 所以是一个线程。 为了监听UI线程，所以专门控制在UI线程中运行。
我们看UIThreadMonitor init逻辑
public void init(TraceConfig config, boolean supportFrameMetrics) {
this.config = config;
useFrameMetrics = supportFrameMetrics;
if (Thread.currentThread() != Looper.getMainLooper().getThread()) {
throw new AssertionError("must be init in main thread!");
}
boolean historyMsgRecorder = config.historyMsgRecorder;
boolean denseMsgTracer = config.denseMsgTracer;
LooperMonitor.register(new LooperMonitor.LooperDispatchListener(historyMsgRecorder, denseMsgTracer) {
@Override
public boolean isValid() {
return isAlive;
}
@Override
public void dispatchStart() {
super.dispatchStart();
UIThreadMonitor.this.dispatchBegin();
}
@Override
public void dispatchEnd() {
super.dispatchEnd();
UIThreadMonitor.this.dispatchEnd();
}
});
this.isInit = true;
frameIntervalNanos = ReflectUtils.reflectObject(choreographer, "mFrameIntervalNanos", Constants.DEFAULT_FRAME_DURATION);
if (!useFrameMetrics) {
choreographer = Choreographer.getInstance();
callbackQueueLock = ReflectUtils.reflectObject(choreographer, "mLock", new Object());
callbackQueues = ReflectUtils.reflectObject(choreographer, "mCallbackQueues", null);
if (null != callbackQueues) {
addInputQueue = ReflectUtils.reflectMethod(callbackQueues[CALLBACK_INPUT], ADD_CALLBACK, long.class, Object.class, Object.class);
addAnimationQueue = ReflectUtils.reflectMethod(callbackQueues[CALLBACK_ANIMATION], ADD_CALLBACK, long.class, Object.class, Object.class);
addTraversalQueue = ReflectUtils.reflectMethod(callbackQueues[CALLBACK_TRAVERSAL], ADD_CALLBACK, long.class, Object.class, Object.class);
}
vsyncReceiver = ReflectUtils.reflectObject(choreographer, "mDisplayEventReceiver", null);
MatrixLog.i(TAG, "[UIThreadMonitor] %s %s %s %s %s %s frameIntervalNanos:%s", callbackQueueLock == null, callbackQueues == null,
addInputQueue == null, addTraversalQueue == null, addAnimationQueue == null, vsyncReceiver == null, frameIntervalNanos);
if (config.isDevEnv()) {
addObserver(new LooperObserver() {
@Override
public void doFrame(String focusedActivity, long startNs, long endNs, boolean isVsyncFrame, long intendedFrameTimeNs, long inputCostNs, long animationCostNs, long traversalCostNs) {
MatrixLog.i(TAG, "focusedActivity[%s] frame cost:%sms isVsyncFrame=%s intendedFrameTimeNs=%s [%s|%s|%s]ns",
focusedActivity, (endNs - startNs) / Constants.TIME_MILLIS_TO_NANO, isVsyncFrame, intendedFrameTimeNs, inputCostNs, animationCostNs, traversalCostNs);
}
});
}
}
}
可以看到主要初始化了两个核心
- Choreographer 可以简单理解为帧率监听器；
- LooperMonitor Looper 监听。
所以 UIThreadMonitor 是依靠上述两个核心来实现的帧率和主线程 Looper 的监听，本节先LooperMonitor。 LooperMonitor 顾名思义，监听Looper消息，那么如何监听呢？
根据上文我们知道在系统Looper 中有一个打印日志的类 Printer，会在处理 Message 的前后输出 log。所以可以通过重新设置 Printer 监听到每一个消息处理前后的信息。
- 事件处理前会打印
">>>>> Dispatching to ..."，处理后会打印"<<<<< Finished to...； - 如果能够拿到这个 Printer 对象，获取到打印日志的信息，就能实现类似监听事件开始前后的功能了。
如何实现？这就要依靠强大的反射，把Printer替换成我们自己的
LooperMonitor 初始化的时候传入了主线程的 Looper。
//饿汉模式提前默认初始化
private static final LooperMonitor sMainMonitor = LooperMonitor.of(Looper.getMainLooper());
//内部维护了一个map支持不同的looper监控
public static LooperMonitor of(@NonNull Looper looper) {
LooperMonitor looperMonitor = sLooperMonitorMap.get(looper);
if (looperMonitor == null) {
looperMonitor = new LooperMonitor(looper);
sLooperMonitorMap.put(looper, looperMonitor);
}
return looperMonitor;
}
在构造方法中通过resetPrinter我们替换了自己的Printer
private LooperMonitor(Looper looper) {
Objects.requireNonNull(looper);
this.looper = looper;
resetPrinter();
addIdleHandler(looper);
}
private synchronized void resetPrinter() {
Printer originPrinter = null;
try {
if (!isReflectLoggingError) {
//通过反射拿到Looper中的mLogging对象
originPrinter = ReflectUtils.get(looper.getClass(), "mLogging", looper);
if (originPrinter == printer && null != printer) {
return;
}
// Fix issues that printer loaded by different classloader
if (originPrinter != null && printer != null) {
if (originPrinter.getClass().getName().equals(printer.getClass().getName())) {
MatrixLog.w(TAG, "LooperPrinter might be loaded by different classloader"
+ ", my = " + printer.getClass().getClassLoader()
+ ", other = " + originPrinter.getClass().getClassLoader());
return;
}
}
}
} catch (Exception e) {
isReflectLoggingError = true;
Log.e(TAG, "[resetPrinter] %s", e);
}
if (null != printer) {
MatrixLog.w(TAG, "maybe thread:%s printer[%s] was replace other[%s]!",
looper.getThread().getName(), printer, originPrinter);
}
//重新设置looper，装饰者模式，在原有功能的基础上增加了我们的监控
looper.setMessageLogging(printer = new LooperPrinter(originPrinter));
if (null != originPrinter) {
MatrixLog.i(TAG, "reset printer, originPrinter[%s] in %s", originPrinter, looper.getThread().getName());
}
}
需要注意的是，上文传来的 Looper 对象是主线程的，所以以下操作都是针对主线程 Looper 的。
首先会尝试反射获取 Looper 的 mLogging 对象，这个 mLogging 就是一个 Printer 类型的对象。可以看到 LooperPrinter 包裹了一个 Looper 中的 Printer 对象，同时自己也是一个 Printer。通过 setMessageLogging() 替换 Looper 中的 mLogging 对象为 LooperPrinter，等到 Looper 需要打印日志的时候，就会调用 LooperPrinter 的 println() 方法。
class LooperPrinter implements Printer {
public Printer origin;
boolean isHasChecked = false;
boolean isValid = false;
LooperPrinter(Printer printer) {
this.origin = printer;
}
@Override
public void println(String x) {
if (null != origin) {
origin.println(x);
if (origin == this) {
throw new RuntimeException(TAG + " origin == this");
}
}
if (!isHasChecked) {
isValid = x.charAt(0) == '>' || x.charAt(0) == '<';
isHasChecked = true;
if (!isValid) {
MatrixLog.e(TAG, "[println] Printer is inValid! x:%s", x);
}
}
if (isValid) {
dispatch(x.charAt(0) == '>', x);
}
}
}
该方法先是调用原 Printer 对象的 println() 方法打印日志，再进行获取日志前后事件的处理。
这样做既不影响原 Printer 打印日志的逻辑，又可以拦截到 println() 方法（妙啊）
那么拦截到事件了，怎么区分前后呢？就是通过打印日志的内容。
回到 Looper 中的 loop() 方法，事件开始处理打印的是 ">>>>> Dispatching to..."，结束打印的是 "<<<<< Finished to..."，所以可以根据第一个符号来区分是开始还是结束。
dispatch(x.charAt(0) == '>', x);
向右的 > 表示事件开始处理，回调事件开始的方法，反之回调事件结束。
private void dispatch(boolean isBegin, String log) {
synchronized (listeners) {
//监听looper的观察者不止一个，所以这里是HashSet
for (LooperDispatchListener listener : listeners) {
if (listener.isValid()) {
if (isBegin) {
if (!listener.isHasDispatchStart) {
if (listener.historyMsgRecorder) {
messageStartTime = System.currentTimeMillis();
latestMsgLog = log;
recentMCount++;
}
//begin事件
listener.onDispatchStart(log);
}
} else {
if (listener.isHasDispatchStart) {
//如果开启了历史记录，通过ConcurrentLinkedQueue还留存了一套过去的日志据
if (listener.historyMsgRecorder) {
recordMsg(log, System.currentTimeMillis() - messageStartTime, listener.denseMsgTracer);
}
//end 事件
listener.onDispatchEnd(log);
}
// 特殊情况，listener 不可用但是接收到了开始状态
// 说明 listener 在设置生效前先设置了监听
// 此时又收到了事件结束的信息，回调结束即可
} else if (!isBegin && listener.isHasDispatchStart) {
listener.dispatchEnd();
}
}
}
}
private static void recordMsg(final String log, final long duration, boolean denseMsgTracer) {
historyMsgHandler.post(new Runnable() {
@Override
public void run() {
enqueueHistoryMQ(new M(log, duration));
}
});
if (denseMsgTracer) {
historyMsgHandler.post(new Runnable() {
@Override
public void run() {
enqueueRecentMQ(new M(log, duration));
}
});
}
}
private static final Queue<M> anrHistoryMQ = new ConcurrentLinkedQueue<>();
private static void enqueueHistoryMQ(M m) {
if (anrHistoryMQ.size() == HISTORY_QUEUE_MAX_SIZE) {
anrHistoryMQ.poll();
}
anrHistoryMQ.offer(m);
}
总结
说了那么多其实就一句话： 通过重新设置主线程 Looper 中的 Printer 对象，达到监听主线程每条消息处理前后的信息。
为啥通过 Printer 就能知道呢？ 因为Looper 每次处理消息前后会使用 Printer 打印 log。
怎么区分前后呢？ 处理前打印的是 “>>>” 开头的，处理后是 “>>>” 开头的。所以拿到打印的内容后，">" 开头的是处理前，反之是处理后。
什么时候注册的监听？ UIThreadMonitor init的时候提前注入监听
LooperMonitor.register(new LooperDispatchListener(historyMsgRecorder, denseMsgTracer) {
public boolean isValid() {
return UIThreadMonitor.this.isAlive;
}
public void dispatchStart() {
super.dispatchStart();
UIThreadMonitor.this.dispatchBegin();
}
public void dispatchEnd() {
super.dispatchEnd();
UIThreadMonitor.this.dispatchEnd();
}
});
拿到回调以后UIThreadMonitor自身又做了什么呢？ 计算时间戳，再进一步通知到跟下层的观察者
private void dispatchBegin() {
token = dispatchTimeMs[0] = System.nanoTime();
dispatchTimeMs[2] = SystemClock.currentThreadTimeMillis();
if (config.isAppMethodBeatEnable()) {
AppMethodBeat.i(AppMethodBeat.METHOD_ID_DISPATCH);
}
synchronized (observers) {
for (LooperObserver observer : observers) {
if (!observer.isDispatchBegin()) {
observer.dispatchBegin(dispatchTimeMs[0], dispatchTimeMs[2], token);
}
}
}
if (config.isDevEnv()) {
MatrixLog.d(TAG, "[dispatchBegin#run] inner cost:%sns", System.nanoTime() - token);
}
}
此外还有AppMethodBeat 帧率doFrame回调 篇幅有限后序展开分析
private void dispatchEnd() {
long traceBegin = 0;
if (config.isDevEnv()) {
traceBegin = System.nanoTime();
}
if (config.isFPSEnable() && !useFrameMetrics) {
long startNs = token;
long intendedFrameTimeNs = startNs;
if (isVsyncFrame) {
doFrameEnd(token);
intendedFrameTimeNs = getIntendedFrameTimeNs(startNs);
}
long endNs = System.nanoTime();
synchronized (observers) {
for (LooperObserver observer : observers) {
if (observer.isDispatchBegin()) {
observer.doFrame(AppActiveMatrixDelegate.INSTANCE.getVisibleScene(), startNs, endNs, isVsyncFrame, intendedFrameTimeNs, queueCost[CALLBACK_INPUT], queueCost[CALLBACK_ANIMATION], queueCost[CALLBACK_TRAVERSAL]);
}
}
}
}
if (config.isEvilMethodTraceEnable() || config.isDevEnv()) {
dispatchTimeMs[3] = SystemClock.currentThreadTimeMillis();
dispatchTimeMs[1] = System.nanoTime();
}
AppMethodBeat.o(AppMethodBeat.METHOD_ID_DISPATCH);
synchronized (observers) {
for (LooperObserver observer : observers) {
if (observer.isDispatchBegin()) {
observer.dispatchEnd(dispatchTimeMs[0], dispatchTimeMs[2], dispatchTimeMs[1], dispatchTimeMs[3], token, isVsyncFrame);
}
}
}
this.isVsyncFrame = false;
if (config.isDevEnv()) {
MatrixLog.d(TAG, "[dispatchEnd#run] inner cost:%sns", System.nanoTime() - traceBegin);
}
}
最终又回到了我们LooperAnrTracer注册的地方，每一层的逻辑层层隔离，从LooperMonitor到UIThreadMonitor再到LooperAnrTracer 精妙啊！！！
@Override
public void onAlive() {
super.onAlive();
if (isAnrTraceEnable) {
UIThreadMonitor.getMonitor().addObserver(this);
this.anrHandler = new Handler(MatrixHandlerThread.getDefaultHandler().getLooper());
this.lagHandler = new Handler(MatrixHandlerThread.getDefaultHandler().getLooper());
}
}
我们再看看真正的下层LooperAnrTracer具体做了什么？
@Override
public void dispatchBegin(long beginNs, long cpuBeginMs, long token) {
super.dispatchBegin(beginNs, cpuBeginMs, token);
anrTask.beginRecord = AppMethodBeat.getInstance().maskIndex("AnrTracer#dispatchBegin");
anrTask.token = token;
if (traceConfig.isDevEnv()) {
MatrixLog.v(TAG, "* [dispatchBegin] token:%s index:%s", token, anrTask.beginRecord.index);
}
long cost = (System.nanoTime() - token) / Constants.TIME_MILLIS_TO_NANO;
anrHandler.postDelayed(anrTask, Constants.DEFAULT_ANR - cost);
lagHandler.postDelayed(lagTask, Constants.DEFAULT_NORMAL_LAG - cost);
}
@Override
public void dispatchEnd(long beginNs, long cpuBeginMs, long endNs, long cpuEndMs, long token, boolean isBelongFrame) {
super.dispatchEnd(beginNs, cpuBeginMs, endNs, cpuEndMs, token, isBelongFrame);
if (traceConfig.isDevEnv()) {
long cost = (endNs - beginNs) / Constants.TIME_MILLIS_TO_NANO;
MatrixLog.v(TAG, "[dispatchEnd] token:%s cost:%sms cpu:%sms usage:%s",
token, cost,
cpuEndMs - cpuBeginMs, Utils.calculateCpuUsage(cpuEndMs - cpuBeginMs, cost));
}
anrTask.getBeginRecord().release();
anrHandler.removeCallbacks(anrTask);
lagHandler.removeCallbacks(lagTask);
}
主要在消息开始的时候通过Hander发送了延迟Runable,在结束的时候清空Runable，是不是感觉跟开篇讲的系统ANR监控原理非常相似？？？没错！！！这也是一个埋炸弹的过程，在消息处理完炸弹Runaable一旦没被拆掉就会引爆，执行runaable 记录卡顿信息。
public static final int DEFAULT_ANR = 5 * 1000;
public static final int DEFAULT_NORMAL_LAG = 2 * 1000;
这里埋了一个2s和5s炸弹 我们简单看下
2s的卡顿监控，其实就是获取当前环境信息 通过onDetectIssue抛出去交给下层处理
class LagHandleTask implements Runnable {
@Override
public void run() {
String scene = AppActiveMatrixDelegate.INSTANCE.getVisibleScene();
boolean isForeground = isForeground();
try {
TracePlugin plugin = Matrix.with().getPluginByClass(TracePlugin.class);
if (null == plugin) {
return;
}
StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();
String dumpStack = Utils.getWholeStack(stackTrace);
JSONObject jsonObject = new JSONObject();
jsonObject = DeviceUtil.getDeviceInfo(jsonObject, Matrix.with().getApplication());
jsonObject.put(SharePluginInfo.ISSUE_STACK_TYPE, Constants.Type.LAG);
jsonObject.put(SharePluginInfo.ISSUE_SCENE, scene);
jsonObject.put(SharePluginInfo.ISSUE_THREAD_STACK, dumpStack);
jsonObject.put(SharePluginInfo.ISSUE_PROCESS_FOREGROUND, isForeground);
Issue issue = new Issue();
issue.setTag(SharePluginInfo.TAG_PLUGIN_EVIL_METHOD);
issue.setContent(jsonObject);
plugin.onDetectIssue(issue);
MatrixLog.e(TAG, "happens lag : %s, scene : %s ", dumpStack, scene);
} catch (JSONException e) {
MatrixLog.e(TAG, "[JSONException error: %s", e);
}
}
}
5s的ANR卡顿监控回调，这里涉及到帧率信息的收集组装以及真是的堆栈信息如何采集请听下回分享
class AnrHandleTask implements Runnable {
AppMethodBeat.IndexRecord beginRecord;
long token;
public AppMethodBeat.IndexRecord getBeginRecord() {
return beginRecord;
}
AnrHandleTask() {
}
AnrHandleTask(AppMethodBeat.IndexRecord record, long token) {
this.beginRecord = record;
this.token = token;
}
@Override
public void run() {
long curTime = SystemClock.uptimeMillis();
boolean isForeground = isForeground();
// process
int[] processStat = Utils.getProcessPriority(Process.myPid());
long[] data = AppMethodBeat.getInstance().copyData(beginRecord);
beginRecord.release();
String scene = AppActiveMatrixDelegate.INSTANCE.getVisibleScene();
// memory
long[] memoryInfo = dumpMemory();
// Thread state
Thread.State status = Looper.getMainLooper().getThread().getState();
StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();
String dumpStack;
if (traceConfig.getLooperPrinterStackStyle() == TraceConfig.STACK_STYLE_WHOLE) {
dumpStack = Utils.getWholeStack(stackTrace, "|*\t\t");
} else {
dumpStack = Utils.getStack(stackTrace, "|*\t\t", 12);
}
// frame
UIThreadMonitor monitor = UIThreadMonitor.getMonitor();
long inputCost = monitor.getQueueCost(UIThreadMonitor.CALLBACK_INPUT, token);
long animationCost = monitor.getQueueCost(UIThreadMonitor.CALLBACK_ANIMATION, token);
long traversalCost = monitor.getQueueCost(UIThreadMonitor.CALLBACK_TRAVERSAL, token);
// trace
LinkedList<MethodItem> stack = new LinkedList();
if (data.length > 0) {
TraceDataUtils.structuredDataToStack(data, stack, true, curTime);
TraceDataUtils.trimStack(stack, Constants.TARGET_EVIL_METHOD_STACK, new TraceDataUtils.IStructuredDataFilter() {
@Override
public boolean isFilter(long during, int filterCount) {
return during < filterCount * Constants.TIME_UPDATE_CYCLE_MS;
}
@Override
public int getFilterMaxCount() {
return Constants.FILTER_STACK_MAX_COUNT;
}
@Override
public void fallback(List<MethodItem> stack, int size) {
MatrixLog.w(TAG, "[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(Constants.DEFAULT_ANR, TraceDataUtils.stackToString(stack, reportBuilder, logcatBuilder));
// stackKey
String stackKey = TraceDataUtils.getTreeKey(stack, stackCost);
MatrixLog.w(TAG, "%s \npostTime:%s curTime:%s",
printAnr(scene, processStat, memoryInfo, status, logcatBuilder, isForeground, stack.size(),
stackKey, dumpStack, inputCost, animationCost, traversalCost, stackCost),
token / Constants.TIME_MILLIS_TO_NANO, curTime); // for logcat
if (stackCost >= Constants.DEFAULT_ANR_INVALID) {
MatrixLog.w(TAG, "The checked anr task was not executed on time. "
+ "The possible reason is that the current process has a low priority. just pass this report");
return;
}
// report
try {
TracePlugin plugin = Matrix.with().getPluginByClass(TracePlugin.class);
if (null == plugin) {
return;
}
JSONObject jsonObject = new JSONObject();
jsonObject = DeviceUtil.getDeviceInfo(jsonObject, Matrix.with().getApplication());
jsonObject.put(SharePluginInfo.ISSUE_STACK_TYPE, Constants.Type.ANR);
jsonObject.put(SharePluginInfo.ISSUE_COST, stackCost);
jsonObject.put(SharePluginInfo.ISSUE_STACK_KEY, stackKey);
jsonObject.put(SharePluginInfo.ISSUE_SCENE, scene);
jsonObject.put(SharePluginInfo.ISSUE_TRACE_STACK, reportBuilder.toString());
if (traceConfig.getLooperPrinterStackStyle() == TraceConfig.STACK_STYLE_WHOLE) {
jsonObject.put(SharePluginInfo.ISSUE_THREAD_STACK, Utils.getWholeStack(stackTrace));
} else {
jsonObject.put(SharePluginInfo.ISSUE_THREAD_STACK, Utils.getStack(stackTrace));
}
jsonObject.put(SharePluginInfo.ISSUE_PROCESS_PRIORITY, processStat[0]);
jsonObject.put(SharePluginInfo.ISSUE_PROCESS_NICE, processStat[1]);
jsonObject.put(SharePluginInfo.ISSUE_PROCESS_FOREGROUND, isForeground);
// memory info
JSONObject memJsonObject = new JSONObject();
memJsonObject.put(SharePluginInfo.ISSUE_MEMORY_DALVIK, memoryInfo[0]);
memJsonObject.put(SharePluginInfo.ISSUE_MEMORY_NATIVE, memoryInfo[1]);
memJsonObject.put(SharePluginInfo.ISSUE_MEMORY_VM_SIZE, memoryInfo[2]);
jsonObject.put(SharePluginInfo.ISSUE_MEMORY, memJsonObject);
Issue issue = new Issue();
issue.setKey(token + "");
issue.setTag(SharePluginInfo.TAG_PLUGIN_EVIL_METHOD);
issue.setContent(jsonObject);
plugin.onDetectIssue(issue);
} catch (JSONException e) {
MatrixLog.e(TAG, "[JSONException error: %s", e);
}
}
最后留个彩蛋问题 LoopMonior初始化的时候为什么要添加一个idleHandler?
private LooperMonitor(Looper looper) {
Objects.requireNonNull(looper);
this.looper = looper;
resetPrinter();
addIdleHandler(looper);
}
为避免 LooperPrinter 失效，Matrix 添加了一个空闲时 Handler 每分钟重新设置一次。
依旧是通过反射添加 IdleHandler，在主线程空闲时（也就是 Looper 没有 Message 可以拿出来使用时）会调用这些 IdleHandler 的 queueIdle() 方法。
private synchronized void addIdleHandler(Looper looper) {
if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.M) {
looper.getQueue().addIdleHandler(this);
} else {
try {
MessageQueue queue = ReflectUtils.get(looper.getClass(), "mQueue", looper);
queue.addIdleHandler(this);
} catch (Exception e) {
Log.e(TAG, "[removeIdleHandler] %s", e);
}
}
}
设置这样的 Handler 不会占用主线程资源，queueIdle() 返回 true 表示会保留该 IdleHandler 供下次空闲时调用，也就是 queueIdle() 会在主线程空闲时不断回调。
这样就实现了不占用资源，又保证了 LooperPrinter 的有效性
@Override
public boolean queueIdle() {
if (SystemClock.uptimeMillis() - lastCheckPrinterTime >= CHECK_TIME) {
resetPrinter();
lastCheckPrinterTime = SystemClock.uptimeMillis();
}
return true;
}
通过以上逻辑可以holder大部分卡顿？为什么是大部分呢？
因为有些情况的卡顿，这种方案从原理上就无法监控到。看到上面的queue.next() ，这里给了注释：might block，直接跟你说这里是可能会卡住的，这时候再计算dispatchMessage方法的耗时显然就没有意义了。有的同学可能会想，那我改成计算相邻两次dispatchMessage执行之前打印字符串的时间差值不就好了？这样就可以把next方法的耗时也计算在内。不幸的是，主线程空闲时，也会阻塞在MessageQueue的next方法中，我们很难区分究竟是发生了卡顿还是主线程空闲。
如果排除主线程空闲的情况，究竟会是什么原因会卡在MessageQueue的next方法中呢？下图是next方法简化过后的源码，frameworks/base/core/java/android/os/MessageQueue.java:
for (;;) {
if (nextPollTimeoutMillis != 0) {
Binder.flushPendingCommands();
}
nativePollOnce(ptr, nextPollTimeoutMillis);
//......
// Run the idle handlers.
// We only ever reach this code block during the first iteration.
for (int i = 0; i < pendingIdleHandlerCount; i++) {
final IdleHandler idler = mPendingIdleHandlers[i];
mPendingIdleHandlers[i] = null; // release the reference to the handler
boolean keep = false;
try {
keep = idler.queueIdle();
} catch (Throwable t) {
Log.wtf(TAG, "IdleHandler threw exception", t);
}
if (!keep) {
synchronized (this) {
mIdleHandlers.remove(idler);
}
}
}
//......
}
除了主线程空闲时就是阻塞在nativePollOnce之外，非常重要的是，应用的Touch事件也是在这里被处理的。这就意味着，View的TouchEvent中的卡顿这种方案是无法监控的。然而，对于我们来说，微信中有大量的自定义View，这些View中充满了各种各样很多的onTouch回调，卡在这里面的情况非常普遍，这种情况的卡顿监控不到是很难接受的。
另外一种常见的情况是IdleHandler 的queueIdle() 回调方法也是无法被监控的，这个方法会在主线程空闲的时候被调用。然而实际上，很多开发同学都先入为主的认为这个时候反正主线程空闲，做一些耗时操作也没所谓。其实主线程MessageQueue的queueIdle默认当然也是执行在主线程中，所以这里的耗时操作其实是很容易引起卡顿和ANR的。例如微信之前就使用IdleHandler在进入微信的主界面后，做一些读写文件的IO操作，就造成了一些卡顿和ANR问题。
还有一类相对少见的问题是SyncBarrier（同步屏障）的泄漏同样无法被监控到，当我们每次通过invalidate来刷新UI时，最终都会调用到ViewRootImpl中的scheduleTraversals方法，会向主线程的Looper中post一个SyncBarrier，其目的是为了在刷新UI时，主线程的同步消息都被跳过，此时渲染UI的异步消息就可以得到优先处理。但是我们注意到这个方法是线程不安全的，如果在非主线程中调用到了这里，就有可能会同时post多个SyncBarrier，但只能remove掉最后一个，从而有一个SyncBarrier就永远无法被remove，就导致了主线程Looper无法处理同步消息（Message默认就是同步消息），导致卡死，参考源码frameworks/base/core/java/android/view/ViewRootImpl.java:
void scheduleTraversals() {
if (!mTraversalScheduled) {
mTraversalScheduled = true;
mTraversalBarrier = mHandler.getLooper().getQueue().postSyncBarrier();
mChoreographer.postCallback(
Choreographer.CALLBACK_TRAVERSAL, mTraversalRunnable, null);
notifyRendererOfFramePending();
pokeDrawLockIfNeeded();
}
}
void unscheduleTraversals() {
if (mTraversalScheduled) {
mTraversalScheduled = false;
mHandler.getLooper().getQueue().removeSyncBarrier(mTraversalBarrier);
mChoreographer.removeCallbacks(
Choreographer.CALLBACK_TRAVERSAL, mTraversalRunnable, null);
}
}
我们认为Looper Printer方案总体还是比较理想的，那么，既然该方案监控不到这三种卡顿的情况，我们想能不能通过其他的一些手段，专门监控这些卡顿的case呢？关注我，听我娓娓道来。
