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

Android ANR

Word count: 8.3kReading time: 38 min

 2025/02/08 

本文为 Android App ANR 系列的第二篇，主要分享 ANR 分析套路和关键 Log 介绍，系列文章目录如下

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)，提取有效的信息。
1. 发生 ANR 的时间
2. 打印 ANR 日志的进程
3. 发生 ANR 的进程
4. 发生 ANR 的原因
5. CPU 负载
6. Memory 负载
7. CPU 使用统计时间段
8. 各进程的 CPU 使用率
  1. 总的 CPU 使用率
  2. 缺页次数 fault
    1. xxx minor 表示高速缓存中的缺页次数，可以理解为进程在做内存访问
    2. xxx major 表示内存的缺页次数，可以理解为进程在做 IO 操作
9. CPU 使用汇总
配合 MainLog(Android Log) 和 EventLog 把 CPU 开始和结束的时间点内的所有有用信息提取出来到一个文件中.
1. 收集关键操作，比如解锁、安装应用、亮灭屏、应用启动等
2. 收集异常和系统关键 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 (是否过高)
3. 收集 ANR 进程的所有关键线程的运行情况、线程优先级等
4. 根据第四步提取出来的关键信息文件，进一步理出系统当时的情况、状态（（推荐 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+0xe4/0x198”}。
查看是否存在系统异常，比如自研功能导致系统繁忙，没有及时响应应用 Binder 之类的，这种需要分析 Log 中 SystemServer 的日志输出，查看是否有异常的 Log 输出。

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

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

ANR Log 分析

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

1	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 负载

1	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

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

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

IO 负载

1	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 操作负载比较高

进程负载

1	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 介绍

应用冻结

1	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，说明系统目前处于一个比较卡的状态，分析的时候就得考虑到系统的因素

1
2
3

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

1	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

1	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

1	ClockTag AlarmClockApplication: onTrimMemory: 80

dvm_lock_sample

当某个线程等待 lock 的时间 blocked 超过阈值（比如：500ms）,则输出当前的持锁状态.

1	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）时,则输出相应的目标调用信息.

1	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 通信都处于饥饿状态, 则饥饿状态超过一定阈值则输出信息.

1	E IPCThreadState: binder thread pool (31 threads) starved for 120 ms

am_kill

1	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

1	am_proc_died: [0,13210,com.xxx.gallery3d,935,19]

am_anr

1	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 中

1 2	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