3ANRAnalysisRootCause

Anr信息解释

"Signal Catcher" daemon prio=5 tid=6 Runnable
  | group="system" sCount=0 dsCount=0 flags=0 obj=0x15b802d8 self=0x756d5cc2e000
  | sysTid=7781 nice=0 cgrp=default sched=0/0 handle=0x756d5c9ffd50
  | state=R schedstat=( 9996973 11775302 9 ) utm=0 stm=0 core=3 HZ=100
  | stack=0x756d5c909000-0x756d5c90b000 stackSize=991KB
  | held mutexes= "mutator lock"(shared held)
  native: #00 pc 000000000048df0e  /apex/com.android.runtime/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+126)
  native: #01 pc 00000000005a77b3  /apex/com.android.runtime/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+675)
  native: #02 pc 00000000005c49bb  /apex/com.android.runtime/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+859)
  native: #03 pc 00000000005bcf18  /apex/com.android.runtime/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+456)
  native: #04 pc 00000000005bc2d1  /apex/com.android.runtime/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool)+1601)
  native: #05 pc 00000000005bbb88  /apex/com.android.runtime/lib64/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+840)
  native: #06 pc 00000000005621f9  /apex/com.android.runtime/lib64/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+201)
  native: #07 pc 00000000005763a2  /apex/com.android.runtime/lib64/libart.so (art::SignalCatcher::HandleSigQuit()+1618)
  native: #08 pc 00000000005752b4  /apex/com.android.runtime/lib64/libart.so (art::SignalCatcher::Run(void*)+244)
  native: #09 pc 0000000000100fce  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+30)
  native: #10 pc 0000000000098fe7  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+55)
  (no managed stack frames)

第1行：“Signal Catcher”：线程名称，daemon：是否是daemon线程（如果不是，则不打印“daemon”），prio=5：java线程Thread对象中的优先级，tid=3：vm中对应的 threadid，Runnable：线程在虚拟机中的状态；（如果当前线程没有attach，则第一行显示： “name” prio=num (not attached)）；

第2行：group: ThreadGroup，sCount: Suspend count， dsCount: debugger suspend count（小于等于sCount），obj：对应java线程 java.lang.Thread对象，self：native 对应的 thread 指针；

第3行：sysTid：对应linux线程 tid， nice：线程调度执行优先级，-20 ~ 20 之间，越小，优先级越高， -1代表获取优先级失败，cgrp:cgroup,cpu调度group，sched：调度策略和调度优先级，handle：当前线程对应的pthread_t

第4行：state：linux线程的状态，schedstat：线程调度情况，utm=15：线程在用户态运行的时间， stm=6：线程在内核态运行的时间， core=4：线程最后运行在哪个cpu上， HZ=100：系统时钟频率。

utm,stm 单位是jiffies，时钟中断次数;频率是周期的倒数，一般是一秒钟中断产生的次数，所以 1/100 = 0.01s = 10ms, 每10ms产生一次中断；

第5行：stack=0x7fa1f14000-0x7fa1f16000 stackSize=1005KB。线程栈的start 和 end，以及 stack size；

第6行：held mutexes= “mutator lock”(shared held)

分析思路

在上面我们对各类日志的关键信息进行了基本释义，下面就来介绍一下，当我们日常遇到 ANR 问题时，是如何分析的，总结思路如下：

  • 分析堆栈，看看是否存在明显业务问题(如死锁，业务严重耗时等等)，如果无上述明显问题，则进一步通过 ANR Info 观察系统负载是否过高，进而导致整体性能较差，如 CPU，Mem，IO。然后再进一步分析是本进程还是其它进程导致，最后再分析进程内部分析对比各个线程 CPU 占比，找出可疑线程。
  • 综合上述信息，利用监控工具收集的信息，观察和找出 ANR 发生前一段时间内，主线程耗时较长的消息都有哪些，并查看这些耗时较长的消息执行过程中采样堆栈，根据堆栈聚合展示，进一步的对比当前耗时严重的接口或业务逻辑。

以上分析思路，进一步细分的话，可以分为以下几个步骤：

  • 一看 Trace：

    • 死锁堆栈： 观察 Trace 堆栈，确认是否有明显问题，如主线程是否与其他线程发生死锁，如果是进程内部发生了死锁，那么恭喜，这类问题就清晰多了，只需找到与当前线程死锁的线程，问题即可解决；
    • 业务堆栈： 观察通过 Trace 堆栈，发现当前主线程堆栈正在执行业务逻辑，你找到对应的业务同学，他承认该业务逻辑确实存在性能问题，那么恭喜，你很有可能解决了该问题，为什么只是有可能解决该问题呢？因为有些问题取决于技术栈或框架设计，无法在短时间内解决。如果业务同学反馈当前业务很简单，基本不怎么耗时，而这种场景也是日常经常遇到的一类问题，那么就可能需要借助我们的监控工具，追溯历史消息耗时情况了；
    • IPC Block 堆栈： 观察通过 Trace 堆栈，发现主线程堆栈是在跨进程(Binder)通信，那么这个情况并不能当即下定论就是 IPC block 导致，实际情况也有可能是刚发送 Binder 请求不久，以及想要进一步的分析定位，这时也需要借助我们的自研监控工具了；
    • 系统堆栈： 通过观察 Trace，发现当前堆栈只是简单的系统堆栈，想要搞清楚是否发生严重耗时，以及进一步的分析定位，如我们常见的 NativePollOnce 场景，那么也需要借助我们的自研监控工具进一步确认了。

  • 二看关键字：Load，CPU，Slow Operation，Kswapd，Mmcqd，Kwork，Lowmemkiller 等等

刚才我们介绍到，上面这些关键字是反应系统 CPU，Mem，IO 负载的关键信息，在分析完主线程堆栈信息之后，还需要进一步在 ANRInfo，logcat 或 Kernel 日志中搜索这些关键字，并根据这些关键字当前数值，判断当前系统是否存在资源(CPU，Mem，IO)紧张的情况；

  • 三看系统负载分布：观察系统整体负载：User,Sys,IOWait

通过观察系统负载，则可以进一步明确是 CPU 资源紧张，还是 IO 资源紧张；如果系统负载过高，一定是有某个进程或多个进程引起的。反之系统负载过高又会影响到所有进程调度性能。通过观察 User，Sys 的 CPU 占比，可以进一步发分析当前负载过高是发生在应用空间，还是系统空间，如大量调用逻辑(如文件读写，内存紧张导致系统不断回收内存等等)，知道这些之后，排查方向又会进一步缩小范围。

  • 四看进程 CPU：观察 Top 进程的 CPU 占比

从上面分析，在我们知道当前系统负载过高，是发生在用户空间还是内核空间之后，那么我们就要通过 Anrinfo 的提供的进程 CPU 列表，进一步锁定是哪个(些)进程导致的，这时则要进一步的观察每个进程的 CPU 占比，以及进程内部 user，sys 占比。

  • 在分析进程 CPU 占比过程，有一个关键的信息，要看统计这些进程 CPU 过高的场景是发生在 ANR 之前的一段时间还是之后一段时间，如下图表示 ANR 之前 4339ms 到 22895ms 时间内进程的 CPU 使用率。

  • 五看 CPU 占比定线程 ：对比各线程 CPU 占比，以及线程内部 user 和 kernel 占比

在通过系统负载(user,sys,iowait)锁定方向之后，又通过进程列表锁定目标进程，那么接下来我们就可以从目标进程内部分析各个线程的(utm,stm)，进一步分析是哪个线程有问题了。

在 Trace 日志的线程信息里可以清晰的看到每个线程的 utm，stm 耗时。至此我们就完成了从系统到进程，再到进程内部线程方向的负载分析和排查。当然，有时候可能导致系统高负载的不是当前进程，而是其他进程导致，这时同样会影响其他进程，进而导致 ANR。

  • 六看消息调度锁定细节 ：

    • 在分析和明确系统负载是否正常，以及负载过高是哪个进程引起的结论之后，接下来便要通过我们的监控工具，进一步排查是当前消息调度耗时导致，历史消息调度耗时导致，还是消息过于频繁导致。同时通过我们的线程 CheckTime 调度情况分析当前进程的 CPU 调度是否及时以及影响程度，在锁定上述场景之后，再进一步分析耗时消息的采样堆栈，才算找到解决问题的终极之钥。当然耗时消息内部可能存在一个或多个耗时较长的函数接口，或者会有多个消息存在耗时较长的函数接口，这就是我们前文中提到的：“发生 ANR 时，没有一个消息是无辜的”

更多信息：

除了上面的一些信息，我们还可以结合 logcat 日志分析 ANR 之前的一些信息，查看是否存在业务侧或系统侧的异常输出，如搜索“Slow operation”，“Slow delivery"等关键字。也可以观察当前进程和系统进程是否存在频繁 GC 等等，以帮忙我们更全面的分析系统状态。