Android 性能优化——ANR监控与解决_waited 5000ms for focusevent(2)

最新推荐文章于 2024-05-16 17:20:40 发布

原创最新推荐文章于 2024-05-16 17:20:40 发布 · 1.1k 阅读

13 ·

CC 4.0 BY-SA版权

文章标签：

#android #性能优化 #javascript

2024年程序员学习专栏收录该内容

249 篇文章

订阅专栏

沉默ANR（SilentAnr)，SilentANR 会直接kill进程，不会设置该标识。
闪退ANR，OPPO VIVO 的机型ANR之后，会直接闪退，也不会设置该标识。

应对方案：结合主线程的卡顿状态。

反射获取主线程MessageQueue 的 mMessages 对象，此对象的when变量时预期该消息被处理的时间，该变量和当前时间做差就能得到该消息等待的时间，被耽误的耗时，如果该耗过长，就说明主线程‘卡顿’了。

收到了SIGQUIT且当前主线程卡顿了，就认为发生了 ANR。

2.2.3 ANR 监控小结

通过监听系统SIGQUIT信号结合check 当前进程的 NOT_RESPONDING标识和主线程的卡顿状态，综合判定为该进程发生了ANR。

这只是我们知道发生了ANR，知道发生了ANR，进一步知道什么导致了ANR，采集ANR发生时的上下文环境信息，解决ANR更重要。

3 信息的采集监控

3.1 ANR问题定位难点

观察ANR信息采集的难点在于往往信息采集不准确、不全面，当ANR发生的当下采集的信息并不是ANR的真正诱因，因而采集的信息对排查问题的参考价值大折扣。

如上图所示，在主线程耗时的任务已经执行完毕，service启动任务在超过了规定的阈值产生了ANR，此时采集的信息是一个正常的任务调用信息。

总的来说，诱发ANR的原因分主线程执行耗时过大和系统负载过重。

主线程任务执行耗时过大又可大概分为一下几种

历史消息里有多个耗时较重，触发了ANR。
历史消息里有一个耗时极其重的消息。
极其多个耗时小消息执行综合起来耗时严重，触发ANR。

系统负载过重，包括系统内存不足，cpu负载，导致任务得不到执行。

如果能较完整记录过完一段时间段内主线程历史消息任务、当前执任务和将要执行的任务以及系统负载情况，对我们更为准确的诊断ANR问题有非常重要的意义。

3.2 消息调度监控

主线程中记录监控Looper消息执行方案，我们自然的把目光转移到了Looper的Printer方案上。关于这个在三板斧的前两篇文章都介绍过这里不展开。

Looper分发消息执行的时候，前后都打印消息信息，我们依此可以获取到消息任务的相关信息，包活Message的target、what、callback、消息执行的耗时等。

消息耗时，需要采集主线程的WallTime和ThreadTime。

WallTime：任务占用的时间，包括等待锁，线程休眠时间片流转的时间。
ThreadTime（CpuTime）时线程真实执行的时间，不包括等待锁等时间。依次我们可以在侧面推断系统负载情况。

大部分情况下，消息执行都耗时较短，Looper也会有Idel状态，即无消息执行的状态，我们需要对这些消息进行聚合处理。

此外，三板斧系列文章主线程耗时监控里有介绍主线程处理消息除了Looper正常的分发的消息需要监控外，IdleHandler、TouchEvent消息也要纳入到统计记录里才更为完整。

3.2.1 消息聚合以及分类

连续的耗时较小的消息聚合统计，连续小于50ms 的消息，聚合成一条记录，该记录里存储消息的数量，和总耗时信息等
超过阈值的消息单做一条记录统计。
系统调用消息统计（ActivityThread.H Activity 、Service、 ContentProvider），这些对我们分析ANR问题很重要。
IDLE状态消息单独统计。
IdleHandler 的统计。
TouchEvent 等native 层触发的主线程调度任务统计。

综合来说，把消息分类型，聚合类型（Agree），连续的耗时较少的消息。耗时类型（Huge）：超过50ms的消息。系统调用消息（SYSTEM）

3.2.2 消息堆栈采集

除了，统计记录Looper Messge的what、callback和耗时之外，每个消息内到底执行了什么哪些动作也需要采集，这就需要采集每个消息的执行的栈，频繁的采集执行栈对性能影响较大，要进行有策略的采集。

开启子线程采集主线程的堆栈。
耗时较少的消息任务不采集。
超过一定阈值还未执行完毕的消息任务进行一次采集，再隔一段时间如果本次消息任务还未执行完，再进行采集，间隔时间是依此线性增加。
【shoppe的非堵塞式高效抓栈】

3.2.3 正在执行的消息和pending消息统计

除了监控 ANR 发生之前主线程历史消息调度及耗时之外，也需要知道 ANR 发生时正在调度的消息及其耗时，以便于在看到 ANR 的 Trace 堆栈时，可以清晰的知道当前 Trace 逻辑到底执行了多长时间

MessageQueue中等待执行的消息也很有必要统计

对我们知道什么组件诱发了ANR的产生
可以统计等待执行的消息等待了多久。判断消息队列繁忙程度。

3.3 更全面的信息采集

以上我们比较全面的监控统计主线程调度任务的耗时，

3.3.1 获取ANRInfo

应用层可通过AcivityManager获取ANRInfo

val am = application.getSystemService(Context.ACTIVITY_SERVICE) as ActivityManager
val processesInErrorStates = am.processesInErrorState

ProcessesInErrorState中可获取到

shortMsg: ANR Inputdispatching timed out …

shortMessage：ANR 产生的直接原因，TouchEvent超时，Servcie启动超时等。

Reason: Input dispatching timed out
xxx is not responding. Waited 5003ms for FocusEvent(hasFocus=false))
Load: 3.19 / 2.46 / 2.42

----- Output from /proc/pressure/memory -----
some avg10=0.00 avg60=0.00 avg300=0.00 total=144741615
full avg10=0.00 avg60=0.00 avg300=0.00 total=29370150
----- End output from /proc/pressure/memory -----

CPU usage from 0ms to xxx ms later with 99% awake:

TOTAL: 6.4% user + 8.2% kernel + 0% iowait + 0.6% irq + 0.1% softirq

CPU usage from 0ms to xxx ms later with 99% awake:

27% TOTAL: 10% user + 14% kernel + 0.3% iowait + 0.9% irq + 0.3% softirq

longMessage：包括系统负载，cup使用情况，IO情况等系统情况。

3.3.2 Logcat 日志

应用运行时采集logcat日志，注意需要控制量有相应的策略，定时清理。

String cmd = "logcat -f " + file.getAbsolutePath();
Runtime.getRuntime().exec(cmd);

3.3.3 当前进程其他线程的堆栈信息

从 Java 层获取各线程堆栈，或通过反射方式获取到虚拟机内部 Dump 线程堆栈的接口，在内存映射的函数地址，强制调用该接口，并将数据重定向输出到本地。

这样当ANR发生时我们就有丰富的信息供我们参考，包括主线程过去现在和未来的调度信息，系统的信息，线程信息，Logcat信息。

4 问题分析定位和解决

4.1 分析主线程调度情况

查看我们主线程任务调度，是否有明显的耗时任务执行，诱发ANR产生。

分析我们记录的消息调度的wallTime和cputime
定位记录的耗时消息堆栈定位出问题
注意有可能出现连续的非常多的耗时小的消息也会造成ANR

4.2 ANR Info解读

4.2.1 系统负载情况

Load: xx/xx/xx

ANR发生的前1分钟 5分钟和15分钟时间段内的CPU负载，数值代表着等待系统调度的任务数，数值过高，意味着系统有CPU和IO竞争激烈，我们的应用进程可能收到影响

4.2.2 CPU占用情况

CPU usage from 0ms to xxx ms later with xx% awake:

14% 1673/system_server: 8% user + 6.7% kernel / faults: 12746 minor
13% 30829/tv.danmaku.bili: 7.3% user + 6.2% kernel / faults: 24286 minor
6.6% 31147/tv.danmaku.bili:ijkservice: 3.7% user + 2.8% kernel / faults: 11880 minor
6% 574/logd: 2.1% user + 3.8% kernel / faults: 64 minor
…
TOTAL: 6.4% user + 8.2% kernel + 0% iowait + 0.6% irq + 0.1% softirq

CPU usage from xxms to xxxms later
73% 1673/system_server: 49% user + 24% kernel / faults: 1695 minor
33% 2330/AnrConsumer: 12% user + 21% kernel
15% 1683/HeapTaskDaemon: 15% user + 0% kernel
9.2% 7013/Binder:1673_12: 6.1% user + 3% kernel
6.1% 1685/ReferenceQueueD: 6.1% user + 0% kernel
6.1% 2715/HwBinder:1673_5: 6.1% user + 0% kernel
3% 2529/PhotonicModulat: 0% user + 3% kernel
25% 30829/tv.danmaku.bili: 4.2% user + 21% kernel / faults: 423 minor
25% 31050/thread_ad: 4.2% user + 21% kernel
…
…
27% TOTAL: 10% user + 14% kernel + 0.3% iowait + 0.9% irq + 0.3% softirq