ANR分析

发表于 2020/02/23

作者 Hacket Zeng

31 分钟阅读

ANR分析

ANR 问题分析

ANR 分析套路

ANR 问题主要有两种原因：应用自身的问题 和 系统异常导致的问题。在分析 ANR 问题的时候，最主要的就是要确定是哪个原因导致的（当然也有一些中间地带，比如代码写的不好，在正常情况下不会暴露，在系统出问题的时候很快就暴露出来）

ANR 问题一般的分析步骤如下

分析 Log

从 EventLog 看具体的 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)

看 MainLog(Android Log) 或者 SystemLog 查看 ANR 详细信息 (搜索 ANR in)，提取有效的信息。

发生 ANR 的时间
打印 ANR 日志的进程
发生 ANR 的进程
发生 ANR 的原因
CPU 负载
Memory 负载
CPU 使用统计时间段
各进程的 CPU 使用率
1. 总的 CPU 使用率
2. 缺页次数 fault
  1. xxx minor 表示高速缓存中的缺页次数，可以理解为进程在做内存访问
  2. xxx major 表示内存的缺页次数，可以理解为进程在做 IO 操作
CPU 使用汇总

配合 MainLog(Android Log) 和 EventLog 看 CPU

配合 MainLog(Android Log) 和 EventLog 把 CPU 开始和结束的时间点内的所有有用信息提取出来到一个文件中.

收集关键操作，比如解锁、安装应用、亮灭屏、应用启动等
收集异常和系统关键 Log
1. 系统变慢：比如 Slow operation、Slow dispatch、Slow delivery、dvm_lock_sample
2. 进程变化：am_kill、am_proc_died、lowmemorykiller、ANR、应用启动关系等
3. 系统信息：cpu info、meminfo、binder info（是否满了）、iowait (是否过高)
收集 ANR 进程的所有关键线程的运行情况、线程优先级 等
根据第四步提取出来的关键信息文件，进一步理出系统当时的情况、状态（（推荐 vscode 或者 notepad ++ ，有线索就全局搜索）），比如
1. 是处于低内存频繁杀进程？
2. 重启第一次解锁系统繁忙
3. 还是短时间内多个应用启动系统繁忙
4. 还是应用自己的逻辑等待？

加 Log 复现

区分是应用的问题还是系统的问题

首先应该分析是否是应用的问题

分析应用的问题的关键是需要理清当时用户的操作是什么，应用在用户这个操作的过程中扮演了什么角色，然后再进行进一步的分析：

分析应用是否关键组件中的生命周期中有耗时操作，可能平时没有暴露出来，一旦系统负载上来，就会暴露问题（建议在关键生命周期函数中加上对应的 Log，方便 Debug）。
分析是否出现极端情况，导致应用的逻辑耗时，比如大量的数据处理或者导入，同时运行线程过多等（看应用的 cpu \ io 使用情况）。
分析是否存在死锁。
分析是否是在等待 binder 返回。
分析 Trace 文件中 MainThread 和 RenderThread 是否存在异常。
分析 Trace 文件中 MainThread 跟 WorkerThread 是否存在等待关系。

分析系统的状态

查看 CPU 使用情况 (cpu 使用率和 cpu 负载)，看看 SystemServer、lowmemorykiller、HeapTaskDeamon、Audio、SurfaceFlinger 这些系统相关的进程或者线程是否占用高
查看是否存在大量 IO 的情况，看 io 负载
1. faults: 118172 minor(高速缓存的缺页次数)。
2. major(内存的缺页次数)。
查看系统是否是低内存
1. 看 dumpsys meminfo 的结果，看看是否处于低内存。
2. kernel log 是否有频繁的 lowmemorykiller。
3. event log 是否有频繁的应用被系统低内存策略杀掉。
4. kswapd0 。
应用是否被冻结：应用处于 D 状态，发生 ANR，如果最后的操作是 refriger，那么是应用被冻结了，正常情况下是功耗优化引起的，可以找一下前后是否有 xxxHansManager : unfreeze 这样的 Log；或者在 Systrace 中的 Kernel Callstack 显示：{kernel callsite when blocked:: “__refrigerator+0 xe 4/0 x 198”}。
查看是否存在系统异常，比如自研功能导致系统繁忙，没有及时响应应用 Binder 之类的，这种需要分析 Log 中 SystemServer 的日志输出，查看是否有异常的 Log 输出。

继续分析：应用可以解决还是系统可以解决

ANR 问题如果转给系统，大概率是无解的。
如果应用的代码是正常的，也没有极端的使用场景和数据处理，纯粹是由于系统或者其他的 App 造成的，那么可以转给系统处理。
如果应用代码本身有一定的问题，在非极端场景或者非系统异常的不会暴露出来，那么需要应用这边想一想规避方案。

ANR Log 分析（ANR Trace）

Log 可由测试使用 Log 工具抓取，可由线上平台获取，也可以自己抓取：

adb bugreport log.zip1

线程信息

线程详细数据

  
"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

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)) // (ANR原因)  
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 处理的能力就乘以了８，每个核运行的时间可以从下面的文件中得到，/sys/devices/system/cpu/cpu%d/cpufreq/stats/time_in_state 中读取的，%d 代表是 CPU 的核。文件中记录了 CPU 从开机到读取文件时，在各个频率下的运行时间，单位：10 ms

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 统计时间片段时，这些进程消亡了

Memory

Memory 负载

Memory 负载是从 /proc/pressure/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 -----

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 都是在某一时间段内阻塞时间占比的总和，阻塞时间不一定连续，如下图所示：

具体内容可以参考内核工匠的文章： https://blog.csdn.net/feelabclihu/article/details/105534140

IO

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(内存的缺页次数)

23% user：用户态的 cpu 占用
6.4% kernel：内核态的 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

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.xxx.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.xxx.themestore' (15545), uid 10136, oom_adj 995 to free 105068kB  
lowmemorykiller: Reclaimed 105068kB at oom_adj 606

通过 lowmemorykiller 机制杀应用：

com. xxx.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

Ref

Android ANR 系列 2 ：ANR 分析套路和关键 Log 介绍 · Android Performance

性能优化, 卡顿

卡顿性能优化 ANR

本文由作者按照 CC BY 4.0 进行授权