本文为稀土掘金技术社区首发签约文章,30 天内禁止转载,30 天后未获授权禁止转载,侵权必究!
本文为 Android App ANR 系列的第二篇,主要分享 ANR 分析套路和关键 Log 介绍,系列文章目录如下
- Android App ANR 系列 1 :深入理解 Android ANR 机制 (已完成,代码示例更新中)
- Android App ANR 系列 2 :ANR 分析套路和关键 Log 介绍
- Android App ANR 系列 3 :ANR 案例分享
ANR(Application Not Responding),应用程序无响应,简单一个定义,却涵盖了很多 Android 系统的设计思想
首先,ANR 属于应用程序的范畴。这不同于 SNR(System Not Respoding),SNR 反映的问题是系统进程(system_server)失去了响应能力,而 ANR 明确将问题圈定在应用程序。SNR 由 Watchdog 机制保证,具体可以查阅 Watchdog 机制以及问题分析; ANR 由消息处理机制保证,Android 在系统层实现了一套精密的机制来发现 ANR,核心原理是消息调度和超时处理
其次,ANR 机制主体实现在系统层。所有与 ANR 相关的消息,都会经过系统进程(system_server)调度,然后派发到应用进程完成对消息的实际处理,同时,系统进程设计了不同的超时限制来跟踪消息的处理。 一旦应用程序处理消息不当,超时限制就起作用了,它收集一些系统状态,譬如 CPU/IO 使用情况、进程函数调用栈,并且报告用户有进程无响应了(ANR 对话框,部分 Rom 不显示 ANR 对话框,而是直接闪退到主界面)
然后,ANR 问题本质是一个性能问题。ANR 机制实际上对应用程序主线程的限制,要求主线程在限定的时间内处理完一些最常见的操作(启动服务、处理广播、处理输入), 如果处理超时,则认为主线程已经失去了响应其他操作的能力。主线程中的耗时操作,譬如密集 CPU 运算、大量 IO、复杂界面布局等,都会降低应用程序的响应能力
最后,部分 ANR 问题是很难分析的。有时候由于系统底层的一些影响,导致消息调度失败,出现问题的场景又难以复现。 这类 ANR 问题往往需要花费大量的时间去了解系统的一些行为,超出了 ANR 机制本身的范畴。有一些 ANR 问题很难调查清楚,因为整个系统不稳定的因素很多,例如 Linux Kernel 本身的 Bug 引起的内存碎片过多、硬件损坏等。这类比较底层的原因引起的 ANR 问题往往无从查起,并且这根本不是应用程序的问题,浪费了应用开发人员很多时间,如果你从事过整个系统的开发和维护工作的话会深有体会。所以我不能保证了解了本章的所有内容后能够解决一切 ANR 问题,如果出现了很疑难的 ANR 问题,我建议最好去和做 Framework、驱动和内核的朋友聊聊,或者,如果问题只是个十万分之一的偶然现象,不影响程序的正常运行,我倒是建议不去理它
-- From duanqz
ANR 分析套路
ANR 问题主要有两种原因:应用自身的问题 和 系统异常导致的问题。在分析 ANR 问题的时候,最主要的就是要确定是哪个原因导致的(当然也有一些中间地带,比如代码写的不好,在正常情况下不会暴露,在系统出问题的时候很快就暴露出来)。
ANR 问题一般的分析步骤如下:
- EventLog 看具体的 ANR 时间(搜索 am_anr),看看是否跟 ANR log 能够对上,以确定 ANR Log 是否有效,如果 ANR Log 有效,分析 ANR Log,提取有用信息:pid、tid、死锁等,遇到 ANR 问题,摆在我们面前的 trace 是不是第一案发现场,如果 ANR 发生的输出的信息很多,当时的 CPU 和 I/O 资源比较紧张,那么这段日志输出的时间点可能会延迟 10 秒到 20 秒都有可能,所以我们有时候需要提高警惕。不过正常情况下,EventLog 中的 am_anr 的输出时间是最早的,也是最接近 ANR 时间的。
- 看 MainLog(Android Log) 或者 SystemLog 查看 ANR 详细信息(搜索 ANR in),提取有效的信息。
- 发生 ANR 的时间
- 打印 ANR 日志的进程
- 发生 ANR 的进程
- 发生 ANR 的原因
- CPU 负载
- Memory 负载
- CPU 使用统计时间段
- 各进程的 CPU 使用率
- 总的 CPU 使用率
- 缺页次数 fault
- xxx minor 表示高速缓存中的缺页次数,可以理解为进程在做内存访问
- xxx major 表示内存的缺页次数,可以理解为进程在做 IO 操作
- CPU 使用汇总
- 配合 MainLog(Android Log) 和 EventLog 把 CPU 开始和结束的时间点内的所有有用信息提取出来到一个文件中.
- 收集关键操作,比如解锁、安装应用、亮灭屏、应用启动等
- 收集异常和系统关键 Log
- 系统变慢 :比如 Slow operation、Slow dispatch、Slow delivery、dvm_lock_sample
- 进程变化 :am_kill、am_proc_died、lowmemorykiller、ANR、应用启动关系等
- 系统信息 :cpu info、meminfo、binder info(是否满了) 、iowait (是否过高)
- 收集 ANR 进程的所有关键线程的运行情况、线程优先级等
- 根据第四步提取出来的关键信息文件,进一步理出系统当时的情况、状态((推荐 vscode 或者 notepad ++ ,有 线索就全局搜索)),比如
- 是处于低内存频繁杀进程?
- 重启第一次解锁系统繁忙
- 还是短时间内多个应用启动系统繁忙
- 还是应用自己的逻辑等待?
- 不行就加 Log 复现.
区分是应用的问题还是系统的问题
首先应该分析是否是应用的问题
分析应用的问题的关键是需要理清当时用户的操作是什么,应用在用户这个操作的过程中扮演了什么角色,然后再进行进一步的分析
- 分析应用是否关键组件中的生命周期中有耗时操作,可能平时没有暴露出来,一旦系统负载上来,就会暴露问题(建议在关键生命周期函数中加上对应的 Log,方便 Debug)。
- 分析是否出现极端情况,导致应用的逻辑耗时,比如大量的数据处理或者导入,同时运行线程过多等(看应用的 cpu \ io 使用情况)。
- 分析是否存在死锁。
- 分析是否是在等待 binder 返回。
- 分析 Trace 文件中 MainThread 和 RenderThread 是否存在异常。
- 分析 Trace 文件中 MainThread 跟 WorkerThread 是否存在等待关系。
分析系统的状态
- 查看 CPU 使用情况(cpu 使用率和 cpu 负载),看看 SystemServer、lowmemorykiller、HeapTaskDeamon、Audio、SurfaceFlinger 这些系统相关的进程或者线程是否占用高
- 查看是否存在大量 IO 的情况,看 io 负载
- faults: 118172 minor(高速缓存的缺页次数)。
- major(内存的缺页次数)。
- 查看系统是否是低内存
- 看 dumpsys meminfo 的结果,看看是否处于低内存。
- kernel log 是否有频繁的 lowmemorykiller。
- event log 是否有频繁的应用被系统低内存策略杀掉。
- kswapd0 。
- 应用是否被冻结:应用处于 D 状态,发生 ANR,如果最后的操作是 refriger,那么是应用被冻结了,正常情况下是功耗优化引起的,可以找一下前后是否有 xxxHansManager : unfreeze 这样的 Log;或者在 Systrace 中的 Kernel Callstack 显示 :{kernel callsite when blocked:: "__refrigerator+0xe4/0x198"}。
- 查看是否存在系统异常,比如自研功能导致系统繁忙,没有及时响应应用 Binder 之类的,这种需要分析 Log 中 SystemServer 的日志输出,查看是否有异常的 Log 输出。
继续分析:应用可以解决还是系统可以解决
- ANR 问题如果转给系统,大概率是无解的。
- 如果应用的代码是正常的,也没有极端的使用场景和数据处理,纯粹是由于系统或者其他的 App 造成的,那么可以转给系统处理。
- 如果应用代码本身有一定的问题,在非极端场景或者非系统异常的不会暴露出来,那么需要应用这边想一想规避方案。
ANR Log 分析
Log 可由测试使用 Log 工具抓取,可由线上平台获取,也可以自己抓取:
adb bugreport log.zip1
ANR Trace Log 所包含的内容如下
线程详细数据
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 flags=1 obj=0x72c8bbf8 self=0xb400007b0ec10800
| sysTid=5991 nice=-10 cgrp=default sched=0/0 handle=0x7b95f61500
| state=S schedstat=( 807053249 267562324 1494 ) utm=63 stm=17 core=3 HZ=100
| stack=0x7fcccd9000-0x7fcccdb000 stackSize=8192KB
| held mutexes=
native: #00 pc 00000000000c6418 /apex/com.android.runtime/lib64/bionic/libc.so (__epoll_pwait+8)
native: #01 pc 0000000000019a9c /system/lib64/libutils.so (android::Looper::pollInner(int)+184)
native: #02 pc 000000000001997c /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+112)
native: #03 pc 0000000000114310 /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:339)
at android.os.Looper.loop(Looper.java:198)
at android.app.ActivityThread.main(ActivityThread.java:8142)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1006)
上面 Trace 中 部分字段的含义
线程堆栈
下面是该线程对应的调用堆栈
native: #00 pc 00000000000c6418 /apex/com.android.runtime/lib64/bionic/libc.so (__epoll_pwait+8)
native: #01 pc 0000000000019a9c /system/lib64/libutils.so (android::Looper::pollInner(int)+184)
native: #02 pc 000000000001997c /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+112)
native: #03 pc 0000000000114310 /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:339)
at android.os.Looper.loop(Looper.java:198)
at android.app.ActivityThread.main(ActivityThread.java:8142)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1006)
分为 Java 和 Native,一般来说,nativePollOnce 是在等待 Message,这是正常的
线程状态
Thread.java 中的状态和 Thread.cpp 中的状态是有对应关系的。可以看到前者更加概括,也比较容易理解,面向 Java 的使用者;而后者更详细,面向虚拟机内部的环境。traces.txt 中显示的线程状态都是 Thread.cpp 中定义的,完整的对应关系如下
art/runtime/thread_state.h
// State stored in our C++ class Thread.
// When we refer to "a suspended state", or when function names mention "ToSuspended" or
// "FromSuspended", we mean any state other than kRunnable, i.e. any state in which the thread is
// guaranteed not to access the Java heap. The kSuspended state is merely one of these.
enum ThreadState {
// Java
// Thread.State JDWP state
kTerminated = 66, // TERMINATED TS_ZOMBIE Thread.run has returned, but Thread* still around
kRunnable, // RUNNABLE TS_RUNNING runnable
kTimedWaiting, // TIMED_WAITING TS_WAIT in Object.wait() with a timeout
kSleeping, // TIMED_WAITING TS_SLEEPING in Thread.sleep()
kBlocked, // BLOCKED TS_MONITOR blocked on a monitor
kWaiting, // WAITING TS_WAIT in Object.wait()
kWaitingForLockInflation, // WAITING TS_WAIT blocked inflating a thin-lock
kWaitingForTaskProcessor, // WAITING TS_WAIT blocked waiting for taskProcessor
kWaitingForGcToComplete, // WAITING TS_WAIT blocked waiting for GC
kWaitingForCheckPointsToRun, // WAITING TS_WAIT GC waiting for checkpoints to run
kWaitingPerformingGc, // WAITING TS_WAIT performing GC
kWaitingForDebuggerSend, // WAITING TS_WAIT blocked waiting for events to be sent
kWaitingForDebuggerToAttach, // WAITING TS_WAIT blocked waiting for debugger to attach
kWaitingInMainDebuggerLoop, // WAITING TS_WAIT blocking/reading/processing debugger events
kWaitingForDebuggerSuspension, // WAITING TS_WAIT waiting for debugger suspend all
kWaitingForJniOnLoad, // WAITING TS_WAIT waiting for execution of dlopen and JNI on load code
kWaitingForSignalCatcherOutput, // WAITING TS_WAIT waiting for signal catcher IO to complete
kWaitingInMainSignalCatcherLoop, // WAITING TS_WAIT blocking/reading/processing signals
kWaitingForDeoptimization, // WAITING TS_WAIT waiting for deoptimization suspend all
kWaitingForMethodTracingStart, // WAITING TS_WAIT waiting for method tracing to start
kWaitingForVisitObjects, // WAITING TS_WAIT waiting for visiting objects
kWaitingForGetObjectsAllocated, // WAITING TS_WAIT waiting for getting the number of allocated objects
kWaitingWeakGcRootRead, // WAITING TS_WAIT waiting on the GC to read a weak root
kWaitingForGcThreadFlip, // WAITING TS_WAIT waiting on the GC thread flip (CC collector) to finish
kNativeForAbort, // WAITING TS_WAIT checking other threads are not run on abort.
kStarting, // NEW TS_WAIT native thread started, not yet ready to run managed code
kNative, // RUNNABLE TS_RUNNING running in a JNI native method
kSuspended, // RUNNABLE TS_RUNNING suspended by GC or debugger
};
Trace 文件中,线程名的最后一行标识的就是当前线程的状态
正常主线程 Trace
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 flags=1 obj=0x72c8bbf8 self=0xb400007b0ec10800
| sysTid=5991 nice=-10 cgrp=default sched=0/0 handle=0x7b95f61500
| state=S schedstat=( 807053249 267562324 1494 ) utm=63 stm=17 core=3 HZ=100
| stack=0x7fcccd9000-0x7fcccdb000 stackSize=8192KB
| held mutexes=
native: #00 pc 00000000000c6418 /apex/com.android.runtime/lib64/bionic/libc.so (__epoll_pwait+8)
native: #01 pc 0000000000019a9c /system/lib64/libutils.so (android::Looper::pollInner(int)+184)
native: #02 pc 000000000001997c /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+112)
native: #03 pc 0000000000114310 /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:339)
at android.os.Looper.loop(Looper.java:198)
at android.app.ActivityThread.main(ActivityThread.java:8142)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1006)
异常主线程 Trace
"main" prio=5 tid=1 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x70f65400 self=0xe28dae00
| sysTid=22002 nice=-10 cgrp=default sched=0/0 handle=0xe9674474
| state=S schedstat=( 1943159901 290647362 1661 ) utm=159 stm=34 core=7 HZ=100
| stack=0xff041000-0xff043000 stackSize=8192KB
| held mutexes=
at com.facebook.cache.disk.DiskStorageCache.e(DiskStorageCache.java:3)
- waiting to lock <0x0e57c91f> (a java.lang.Object) held by thread 89
at com.xxx.community.util.imageloader.FrescoImageLoader.a(FrescoImageLoader.java:18)
at com.xxx.community.util.imageloader.FrescoImageLoader$2$1.run(FrescoImageLoader.java:2)
at android.os.Handler.handleCallback(Handler.java:938)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loop(Looper.java:254)
at android.app.ActivityThread.main(ActivityThread.java:8142)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1006)
CPU 使用率分析
搜索 ANR in 关键字可以看到 ANR 前一段时间内的 CPU 使用情况,其解析如下
ActivityManager: ANR in com.xxx.launcher (com.xxx.launcher/.Launcher)(进程名)
ActivityManager: PID: 5991(进程 pid)
ActivityManager: Reason: Input dispatching timed out (6a6083a com.xxx.launcher/com.xxx.launcher.Launcher (server) is not responding. Waited 5001ms for FocusEvent(hasFocus=true))(原因)
ActivityManager: Parent: com.xxx.launcher/.Launcher
ActivityManager: Load: 15.29 / 5.19 / 1.87(Load 表明是 1 分钟,5 分钟,15 分钟 CPU 的负载)
ActivityManager: ----- Output from /proc/pressure/memory -----(内存压力)
ActivityManager: somavg10=1.35 avg60=0.31 avg300=0.06 total=346727
ActivityManager: full avg10=0.00 avg60=0.00 avg300=0.00 total=34803
ActivityManager: ----- End output from /proc/pressure/memory -----
// 13s 内的 cpu 使用情况
ActivityManager: CPU usage from 0ms to 13135ms later (2020-09-09 02:09:54.942 to 2020-09-09 02:10:08.077):
ActivityManager: 191%(CPU 的使用率) 1948/system_server: 72%(用户态的使用率) user + 119%(内核态的使用率) kernel / faults: 78816 minor 9 major
ActivityManager: 10% 2218/android.bg: 3.6% user + 6.6% kernel
ActivityManager: 30% 5991/com.xxx.launcher: 23% user + 6.4% kernel / faults: 118172 minor(高速缓存的缺页次数) 2 major(内存的缺页次数)
ActivityManager: 16% 6174/launcher-loader: 13% user + 2.8% kernel
ActivityManager: 3.9% 5991/m.xxx.launcher: 3.1% user + 0.8% kernel
ActivityManager: 20% 6549/com.xxx.xxx: 16% user + 3.7% kernel / faults: 3541 minor
ActivityManager: 10% 6889/DBCacheManager: 8.7% user + 1.2% kernel
ActivityManager: 9.4% 6942/DefaultDispatch: 7.1% user + 2.2% kernel
// 1s 内的 各个进程各个线程的 cpu 使用情况
ActivityManager: CPU usage from 246ms to 1271ms later (2020-09-09 02:09:55.188 to 2020-09-09 02:09:56.213):
ActivityManager: 290% 1948/system_server: 114% user + 176% kernel / faults: 9353 minor
ActivityManager: 32% 5159/LockSettingsSer: 29% user + 2.9% kernel
ActivityManager: 25% 8661/AnrConsumer: 8.8% user + 16% kernel
ActivityManager: 44% 5991/com.xxx.launcher: 37% user + 7.4% kernel / faults: 5756 minor
ActivityManager: 16% 6174/launcher-loader: 13% user + 3.7% kernel
ActivityManager: 14% 5991/m.xxx.launcher: 14% user + 0% kernel
ActivityManager: 37% 6549/com.xxx.xxx: 28% user + 9.3% kernel / faults: 153 minor
ActivityManager: 37% 6942/DefaultDispatch: 28% user + 9.3% kernel
ActivityManager: 20% 5962/com.android.phone: 14% user + 5.5% kernel / faults: 1345 minor
ActivityManager: 11% 5962/m.android.phone: 7.4% user + 3.7% kernel
CPU 负载
ActivityManager: Load: 15.29 / 5.19 / 1.871
Load 后面的三个数字的意思分别是 1 分钟、5 分钟、15 分钟内系统的平均负荷。当 CPU 完全空闲的时候,平均负荷为 0;当 CPU 工作量饱和的时候,平均负荷为 1,通过 Load 可以判断系统负荷是否过重
有一个形象的比喻:个= CPU 想象成一座大桥,桥上只有一根车道,所有车辆都必须从这根车道上通过,系统负荷为 0,意味着大桥上一辆车也没有,系统负荷为 0.5,意味着大桥一半的路段有车,系统负荷为 1.0,意味着大桥的所有路段都有车,也就是说大桥已经"满"了,系统负荷为 2.0,意味着车辆太多了,大桥已经被占满了 (100%),后面等着上桥的车辆还有一倍。大桥的通行能力,就是 CPU 的最大工作量;桥梁上的车辆,就是一个个等待 CPU 处理的进程(process)
经验法则是这样的
- 1.当系统负荷持续大于 0.7,你必须开始调查了,问题出在哪里,防止情况恶化
- 2.当系统负荷持续大于 1.0,你必须动手寻找解决办法,把这个值降下来
- 3.当系统负荷达到 5.0,就表明你的系统有很严重的问题
现在的手机是多核 CPU 架构,八核的多的是,意味着 Cpu 处理的能力就乘以了8,每个核运行的时间可以从下面的文件中得到,/sys/devices/system/cpu/cpu%d/cpufreq/stats/time_in_state 中读取的,%d 代表是 CPU 的核。文件中记录了 CPU 从开机到读取文件时,在各个频率下的运行时间,单位:10 ms
Memory 负载
ActivityManager: ----- Output from /proc/pressure/memory -----(内存压力)
ActivityManager: somavg10=1.35 avg60=0.31 avg300=0.06 total=346727
ActivityManager: full avg10=0.00 avg60=0.00 avg300=0.00 total=34803
ActivityManager: ----- End output from /proc/pressure/memory -----
Memory 负载是从 /proc/pressure/memory 中获取的
avg10、avg60、avg300 分别代表 10s、60s、300s 的时间周期内的阻塞时间百分比。total 是总累计时间,以毫秒为单位
some 这一行,代表至少有一个任务在某个资源上阻塞的时间占比,full 这一行,代表所有的非 idle 任务同时被阻塞的时间占比,这期间 cpu 被完全浪费,会带来严重的性能问题。我们以 IO 的 some 和 full 来举例说明,假设在 60 秒的时间段内,系统有两个 task,在 60 秒的周期内的运行情况如下图所示:
红色阴影部分表示任务由于等待 IO 资源而进入阻塞状态。Task A 和 Task B 同时阻塞的部分为 full,占比 16.66%;至少有一个任务阻塞(仅 Task B 阻塞的部分也计算入内)的部分为 some,占比 50%。
some 和 full 都是在某一时间段内阻塞时间占比的总和,阻塞时间不一定连续,如下图所示:
具体内容可以参考内核工匠的文章: blog.csdn.net/feelabclihu…
IO 负载
ActivityManager: 30% 5991/com.xxx.launcher: 23% user + 6.4% kernel / faults: 118172 minor(高速缓存的缺页次数) 2 major(内存的缺页次数)
- Minor,高速缓存的缺页次数,指的是 Minor Page Fault(次要页错误,简称 MnPF),磁盘数据被加载到内存后,内核再次读取时,会发出一个 MnPF 信息。 一个文件第一次被读写时会有很多的 MPF,被缓存到内存后再次访问 MPF 就会很少,MnPF 反而变多,这是内核为减少效率低下的磁盘 I/O 操作采用的缓存技术的结果可以理解为进程在做内存访问
- Major,内存的缺页次数,指 Major Page Fault(主要页错误,简称 MPF),内核在读取数据时会先后查找 CPU 的高速缓存和物理内存,如果找不到会发出一个 MPF 信息,请求将数据加载到内存可以理解为进程在做 IO 操作
如果有大量的 major,那么说明当时 IO 操作负载比较高
进程负载
ActivityManager: 30% 5991/com.xxx.launcher: 23% user + 6.4% kernel / faults: 118172 minor(高速缓存的缺页次数) 2 major(内存的缺页次数)
- 1.23% user:用户态的 cpu 占用
- 2.6.4% kernel:内核态的 cpu 占用
CPU 异常进程
- SystemServer cpu 占用偏高,系统整体运行会缓慢
- kswapd0 cpu 占用率偏高,系统整体运行会缓慢,从而引起各种 ANR。把问题转给"内存优化",请他们进行优化
- logd CPU 占用率偏高,也会引起系统卡顿和 ANR,因为各个进程输出 LOG 的操作被阻塞从而执行的极为缓慢。
- Vold 占用 CPU 过高,会引起系统卡顿和 ANR,请负责存储的同学先调查
- 应用自身 CPU 占用率较高,高概率应用自身问题
- 应用处于 D 状态,发生 ANR,如果最后的操作是 refriger,那么是应用被冻结了,正常情况下是功耗优化引起的,可以找一下前后是否有 xxxHansManager : unfreeze 这样的 Log;或者在 Systrace 中的 Kernel Callstack 显示 :{kernel callsite when blocked:: "__refrigerator+0xe4/0x198"}
- CPU 使用率前面的 “+”。部分进程的 CPU 使用率前面有 “+” 号,譬如 cat 和 zygote64,表示在上一次 CPU 统计的时间片段内,还没有这些进程,而这一次 CPU 统计的时间片段内,运行了这些进程。 类似的还有 “-” 号,表示两次 CPU 统计时间片段时,这些进程消亡了
系统关键 Log 介绍
应用冻结
xxxHansManager : freeze uid: 10245 package: com.tencent.mm reason: LcdOff
如果冻结逻辑有 Bug,也会导致应用产生 ANR,这一行 Log 比较简单,主要是被冻结的进程信息和被冻结的原因
ActivityManager : Slow operation
AMS 在执行关键任务的时候,如果任务耗时超过 50 ms,则会打印对应的 Log
frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
void checkTime(long startTime, String where) {
long now = SystemClock.uptimeMillis();
if ((now-startTime) > 50) {
// If we are taking more than 50ms, log about it.
Slog.w(TAG, "Slow operation: " + (now-startTime) + "ms so far, now at " + where);
}
}
对应的 Log 如下,如果系统中频繁打印这种 Log,说明系统目前处于一个比较卡的状态,分析的时候就得考虑到系统的因素
ActivityManager: Slow operation: 138ms so far, now at startProcess: done updating battery stats
ActivityManager: Slow operation: 138ms so far, now at startProcess: building log message
ActivityManager: Slow operation: 138ms so far, now at startProcess: starting to update pids map
Looper : Slow dispatch
Looper : Slow dispatch took 418ms main h=android.app.ActivityThread$H c=android.app.-$$Lambda$LoadedApk$ReceiverDispatcher$Args$_BumDX2UKsnxLVrE6UJsJZkotuA@e68bdc4 m=0
Looper : Slow delivery
Looper : Slow delivery took 361ms android.ui h=com.android.server.am.ActivityManagerService$UiHandler c=null m=53
Looper:Slow Looper
W/Looper: Slow Looper main: Activity com.androidperformance.memoryfix/.MainActivity is 439ms late (wall=0ms running=0ms ClientTransaction{ callbacks=[android.app.servertransaction.TopResumedActivityChangeItem] }) because of 3 msg, msg 2 took 268ms (seq=2 running=207ms runnable=15ms late=1ms h=android.app.ActivityThread$H w=110), msg 3 took 171ms (seq=3 running=140ms runnable=5ms io=1ms late=268ms h=android.app.ActivityThread$H w=159)
onTrimMemory
ClockTag AlarmClockApplication: onTrimMemory: 80
dvm_lock_sample
当某个线程等待 lock 的时间 blocked 超过阈值(比如:500ms),则输出当前的持锁状态.
dvm_lock_sample:[system_server,1,Binder_9,1500,ActivityManagerService.java,6403,-,1448,0]
- system_server: Binder_9 执行到 ActivityManagerService.java 的 6403 行代码,一直在等待 AMS 锁
- "-"代表持锁的是同一个文件,即该锁被同一文件的 1448 行代码所持有, 从而导致 Binder_9 线程被阻塞 1500ms.
binder_sample
binder_sample: 监控每个进程的主线程的 binder transaction 的耗时情况, 当超过阈值(比如:500ms)时,则输出相应的目标调用信息.
6628 6628 I binder_sample: [android.view.accessibility.IAccessibilityManager,6,2010,com.xxx.community,100]
- 进程是 6628,主线程 6628
- 执行 android.view.accessibility.IAccessibilityManager 接口
- 所对应方法 code = 6 ( 即 TRANSACTION_addAccessibilityInteractionConnection )
- 所花费时间为 2010 ms
- 该 block 所在 package 为 com.xxx.community
- 最后一个参数是 sample 比例
查找对应的接口函数,比如上面例子里面 IAccessibilityManager 中 Code = 6 是对应的哪个函数,可以在 cs.android.com 里面 搜索 FIRST_CALL_TRANSACTION ,点击调用,然后查看 out 目录里面的对应的 IAccessibilityManager 文件(一直往下滑,直到可以搜索到 IAccessibilityManager )
其中对应的 static final int TRANSACTION_addAccessibilityInteractionConnection = (android.os.IBinder.FIRST_CALL_TRANSACTION + 5)
Long monitor contention
16809 14216 W system_server: Long monitor contention with owner InputDispatcher (17039) at android.content.res.Configuration com.android.server.wm.ActivityTaskManagerService.getGlobalConfigurationForPid(int)(ActivityTaskManagerService.java:1066) waiters=0 in boolean com.android.server.wm.WindowProcessController.hasActivities() for 141ms
art/runtime/monitor.cc
std::string Monitor::PrettyContentionInfo(const std::string& owner_name,
pid_t owner_tid,
ArtMethod* owners_method,
uint32_t owners_dex_pc,
size_t num_waiters) {
Locks::mutator_lock_->AssertSharedHeld(Thread::Current());
const char* owners_filename;
int32_t owners_line_number = 0;
if (owners_method != nullptr) {
TranslateLocation(owners_method, owners_dex_pc, &owners_filename, &owners_line_number);
}
std::ostringstream oss;
oss << "monitor contention with owner " << owner_name << " (" << owner_tid << ")";
if (owners_method != nullptr) {
oss << " at " << owners_method->PrettyMethod();
oss << "(" << owners_filename << ":" << owners_line_number << ")";
}
oss << " waiters=" << num_waiters;
return oss.str();
}
Binder Thread
当 system_server 等进程的线程池使用完, 无空闲线程时, 则 binder 通信都处于饥饿状态, 则饥饿状态超过一定阈值则输出信息.
E IPCThreadState: binder thread pool (31 threads) starved for 120 ms
am_kill
am_kill : [0,18555,com.sina.weibo.image,945,remove task]1
上面这句话里面,remove task 指的是这个应用被杀的原因
下面是各种被杀的情况所对应的 Reason,有时候我们需要看应用被杀的原因,来判断系统是否正常或者用户的操作步骤:
force-stop
异常杀进程
主动杀进程
调度杀进程
其他杀进程
以上介绍的所有杀进程都是调用 ProcessRecord.kill()方法, 必然会输出相应的 EventLog.那么还有哪些场景的杀进程不会输出 log 呢:
- Process.killProcess(int pid) //可杀任何指定进程,或者直接发 signal
- adb shell kill -9 pid //可杀任何指定的进程
- 直接 lmk 杀进程
也就是说进程被杀而无 log 输出,那么可能是通过直接调用 kill 或者发信号, 再或许是 lmk 所杀.
am_proc_died
am_proc_died: [0,13210,com.xxx.gallery3d,935,19]
am_anr
am_anr : [0,8769,com.android.updater,952680005,Broadcast of Intent { act=android.intent.action.BOOT_COMPLETED flg=0x9000010 cmp=com.android.updater/.BootCompletedReceiver (has extras) }]
- 进程 pid:8769
- 进程名:com.android.updater
- 发生 ANR 的类型是:BroadcastTimeout 的具体类或者原因:{ act=android.intent.action.BOOT_COMPLETED flg=0x9000010 cmp=com.android.updater/.BootCompletedReceiver (has extras) }
Lowmemorykiller
lowmemorykiller 的 log 在 kernel log 中
lowmemorykiller: Kill 'com.heytap.themestore' (15545), uid 10136, oom_adj 995 to free 105068kB
lowmemorykiller: Reclaimed 105068kB at oom_adj 606
通过 lowmemorykiller 机制杀应用:
- com.heytap.themestore 进程名
- 15545:PID
- 10136:UID
- 995:oom_adj
- 105068kB: 释放的内存
- 606:min_adj
Blocked msg
内部 加的 Log,当 Message 执行时间超过 1.5s 的时候,就会打印下面的 Log,从下面的 Log 可以看到:
- 执行超时的 Message,和这个 Message 执行耗时
- 被这个 Message 阻塞的 Message
可以从这个 Log 里面观察是自己的 Message 执行阻塞了别的 Message 还是自己的 Message 被其他的 Message 阻塞
E ANR_LOG : >>> msg's executing time is too long
E ANR_LOG : Blocked msg = { when=-32s683ms what=110 target=android.app.ActivityThread$H obj=AppBindData{appInfo=ApplicationInfo{bd8d51e com.android.contacts}} } , cost = 32436 ms
E ANR_LOG : >>>Current msg List is:
E ANR_LOG : Current msg <1> = { when=-32s672ms what=140 target=android.app.ActivityThread$H arg1=5 }
E ANR_LOG : Current msg <2> = { when=-32s671ms what=114 target=android.app.ActivityThread$H obj=CreateServiceData{token=android.os.BinderProxy@f7611ff className=com.android.contacts.xxxAppServicesManagerClient packageName=com.android.contacts intent=null} }
E ANR_LOG : Current msg <3> = { when=-32s671ms what=121 target=android.app.ActivityThread$H obj=BindServiceData{token=android.os.BinderProxy@f7611ff intent=Intent { cmp=com.android.contacts/.xxxAppServicesManagerClient }} }
E ANR_LOG : Current msg <4> = { when=-31s658ms what=1 target=android.os.AsyncTask$InternalHandler obj=android.os.AsyncTask$AsyncTaskResult@75e517c }
E ANR_LOG : Current msg <5> = { when=-29s750ms what=140 target=android.app.ActivityThread$H arg1=10 }
E ANR_LOG : Current msg <6> = { when=-29s103ms what=118 target=android.app.ActivityThread$H obj={1.0 460mcc3mnc [zh_CN] ldltr sw360dp w360dp h622dp 480dpi nrml long port finger -keyb/v/h -nav/h appBounds=Rect(0, 0 - 1080, 1920) s.10mThemeChanged = 0mThemeChangedFlags = 0mFlipFont = 0}
E ANR_LOG : Current msg <7> = { when=-28s370ms what=118 target=android.app.ActivityThread$H obj={1.0 460mcc11mnc [zh_CN] ldltr sw360dp w360dp h622dp 480dpi nrml long port finger -keyb/v/h -nav/h appBounds=Rect(0, 0 - 1080, 1920) s.11mThemeChanged = 0mThemeChangedFlags = 0mFlipFont = 0} }
E ANR_LOG : Current msg <8> = { when=-27s821ms what=122 target=android.app.ActivityThread$H obj=BindServiceData{token=android.os.BinderProxy@f7611ff intent=Intent { cmp=com.android.contacts/.xxxAppServicesManagerClient }} }
E ANR_LOG : Current msg <9> = { when=-27s821ms what=116 target=android.app.ActivityThread$H obj=android.os.BinderProxy@f7611ff }
E ANR_LOG : Current msg <10> = { when=-27s654ms what=114 target=android.app.ActivityThread$H obj=CreateServiceData{token=android.os.BinderProxy@e23cf1b className=com.android.contacts.xxxAppServicesManagerClient packageName=com.android.contacts intent=null} }
E ANR_LOG : >>>CURRENT MSG DUMP OVER<<<
通用场景 Log 介绍
灭屏 Log
关键是 power_screen_broadcast_done、screen_toggled 和 power_screen_state
1810 2470 I intercept_power: [ACTION_DOWN,1,0]
1810 2470 I intercept_power: [ACTION_UP,0,0]
1810 2470 I power_sleep_requested: 0
1810 1810 I power_screen_state: [0,2,0,0,1254]
1810 1810 I screen_toggled: 0 // 0 代表灭屏,1 代表亮屏
1810 1810 I power_screen_broadcast_send: 1
1810 1825 I wm_set_keyguard_shown: [1,0,0,setKeyguardShown] // (keyguardShowing|1),(aodShowing|1),(keyguardGoingAway|1),(Reason|3)
2768 2768 I sysui_status_bar_state: [1,1,0,0,0,1]
1810 1810 I power_screen_broadcast_done: [0,611,1] // 0 代表灭屏,611 是灭屏时间
亮屏 Log
关键是 power_screen_broadcast_done、screen_toggled 和 power_screen_state
其中 power_screen_state
- 1.offOrOn|1|5
- 2.becauseOfUser|1|5
- 3.totalTouchDownTime|2|3
- 4.touchCycles|1|1
- 5.latency|1|3
1810 2470 I intercept_power: [ACTION_DOWN,1,0]
1810 2470 I intercept_power: [ACTION_UP,1,0]
1810 1810 I screen_toggled: 1 // 1 代表亮屏
1810 1810 I power_screen_broadcast_send: 1
1810 1810 I power_screen_state: [1,0,0,0,319]
1810 1810 I power_screen_broadcast_done: [1,633,1] // 1 代表亮屏,633 是亮屏时间
解锁完整 Log
wm_set_keyguard_shown 的值
- (keyguardShowing|1) :Keyguard 是否在显示
- (aodShowing|1) :aodShowing 是否在显示
- (keyguardGoingAway|1) :Keyguard 消失
- (Reason|3) :原因
1810 5711 I wm_set_keyguard_shown: [1,0,1,keyguardGoingAway]
// 桌面 Resume
1810 5711 I wm_set_resumed_activity: [0,com.xxx.launcher/.Launcher,resumeTopActivityInnerLocked]
1810 5711 I wm_resume_activity: [0,93093883,63,com.xxx.launcher/.Launcher]
20615 20615 I wm_on_restart_called: [93093883,com.xxx.launcher.Launcher,performRestartActivity]
20615 20615 I wm_on_start_called: [93093883,com.xxx.launcher.Launcher,handleStartActivity]
20615 20615 I wm_on_resume_called: [93093883,com.xxx.launcher.Launcher,RESUME_ACTIVITY]
20615 20615 I wm_on_top_resumed_gained_called: [93093883,com.xxx.launcher.Launcher,topWhenResuming]
1810 5711 I wm_set_keyguard_shown: [0,0,1,setKeyguardShown] // keyguard 不显示,aod 不显示,keyguardGoingAway,原因是调用了 setKeyguardShown 显示桌面
通知栏下拉完整 Log
2768 2768 I sysui_multi_action: [757,803,799,panel_open,802,1]
2768 2768 I sysui_multi_action: [757,1328,758,4,1326,29,1327,0,1329,0]
1810 3004 I notification_visibility: [-1|android|55|null|1000,1,457483196,457483196,0,4]
1810 3004 I notification_visibility: [0|com.android.systemui|10005|null|10132,1,97168545,97168545,0,2]
1810 3004 I notification_visibility: [0|com.android.systemui|2147483647|ranker_group|10132|ranker_group,1,97168236,97168236,0,1]
1810 3004 I notification_visibility: [-1|com.android.systemui|10006|null|10132,1,82586063,82586063,0,0]
通知栏折叠完整 Log
2768 2768 I sysui_multi_action: [757,111,758,2]
1810 5473 I notification_visibility: [-1|android|55|null|1000,0,457546516,457546516,0,4]
1810 5473 I notification_visibility: [0|com.android.systemui|10005|null|10132,0,97231865,97231865,0,2]
1810 5473 I notification_visibility: [0|com.android.systemui|2147483647|ranker_group|10132|ranker_group,0,97231557,97231557,0,1]
1810 5473 I notification_visibility: [-1|com.android.systemui|10006|null|10132,0,82649384,82649384,0,0]
应用启动完整 Log
// 创建 Task
1810 5473 I wm_task_created: [100,-1]
1810 5473 I wm_stack_created: 100
1810 5473 I wm_create_task: [0,100]
// 创建 Activity
1810 5473 I wm_create_activity: [0,231348670,100,com.androidperformance.memoryfix/.MainActivity,android.intent.action.MAIN,NULL,NULL,270532608]
// 桌面走 pause 流程
1810 5473 I wm_pause_activity: [0,93093883,com.xxx.launcher/.Launcher,userLeaving=true]
0615 20615 I wm_on_top_resumed_lost_called: [93093883,com.xxx.launcher.Launcher,topStateChangedWhenResumed]
0615 20615 I wm_on_paused_called: [93093883,com.xxx.launcher.Launcher,performPause]
1810 3720 I wm_add_to_stopping: [0,93093883,com.xxx.launcher/.Launcher,makeInvisible]
//启动 Activity
1810 2045 I am_proc_start: [0,18803,10263,com.androidperformance.memoryfix,pre-top-activity,{com.androidperformance.memoryfix/com.androidperformance.memoryfix.MainActivity}]
1810 3428 I am_proc_bound: [0,18803,com.androidperformance.memoryfix]
1810 3428 I wm_restart_activity: [0,231348670,100,com.androidperformance.memoryfix/.MainActivity]
1810 3428 I wm_set_resumed_activity: [0,com.androidperformance.memoryfix/.MainActivity,minimalResumeActivityLocked]
8803 18803 I wm_on_create_called: [231348670,com.androidperformance.memoryfix.MainActivity,performCreate]
8803 18803 I wm_on_start_called: [231348670,com.androidperformance.memoryfix.MainActivity,handleStartActivity]
8803 18803 I wm_on_resume_called: [231348670,com.androidperformance.memoryfix.MainActivity,RESUME_ACTIVITY]
8803 18803 I wm_on_top_resumed_gained_called: [231348670,com.androidperformance.memoryfix.MainActivity,topStateChangedWhenResumed]
1810 2034 I wm_activity_launch_time: [0,231348670,com.androidperformance.memoryfix/.MainActivity,471]
// 桌面走 stop 流程
1810 1978 I wm_stop_activity: [0,93093883,com.xxx.launcher/.Launcher]
0615 20615 I wm_on_stop_called: [93093883,com.xxx.launcher.Launcher,STOP_ACTIVITY_ITEM]
Window Focus 相关的流程
// 从桌面启动 App,focus 变化 :Launcher => null => App
WindowManager: Changing focus from Window{b0416d7 u0 com.xxx.launcher/com.xxx.launcher.Launcher} to null,diplayid=0
WindowManager: Changing focus from null to Window{10f5145 u0 com.android.settings/com.android.settings.Settings},diplayid=0
// 从 App 返回桌面,focus 变化 :App => null => Launcher
WindowManager: Changing focus from Window{10f5145 u0 com.android.settings/com.android.settings.Settings} to null,diplayid=0
WindowManager: Changing focus from null to Window{b0416d7 u0 com.xxx.launcher/com.xxx.launcher.Launcher},diplayid=0
// 从 App 界面进入锁屏:focus 变化 :App => null => 锁屏
WindowManager: Changing focus from Window{10f5145 u0 com.android.settings/com.android.settings.Settings} to null,diplayid=0
WindowManager: Changing focus from null to Window{82e5f30 u0 NotificationShade},diplayid=0
// 从锁屏界面解锁进入 App,focus 变化 :锁屏 => App
WindowManager: Changing focus from Window{82e5f30 u0 NotificationShade} to Window{10f5145 u0 com.android.settings/com.android.settings.Settings},diplayid=0
ANR 相关资料分享
- 西瓜视频稳定性治理体系建设一:Tailor 原理及实践
- 西瓜视频稳定性治理体系建设二:Raphael 原理及实践
- 西瓜视频稳定性治理体系建设三:Sliver 原理及实践
- 西瓜卡顿 & ANR 优化治理及监控体系建设
- 今日头条 ANR 优化实践系列 - 设计原理及影响因素
- 今日头条 ANR 优化实践系列 - 监控工具与分析思路
- 今日头条 ANR 优化实践系列分享 - 实例剖析集锦
- 今日头条 ANR 优化实践系列 - Barrier 导致主线程假死
- 今日头条 ANR 优化实践系列 - 告别 SharedPreference 等待
- Android ANR|原理解析及常见案例