ANR分析思路简析

Posted 2021-02-17 aspirs

1.ANR介绍

1.1 何为ANR

ANR全名Application Not Responding, 也就是"应用无响应". 当操作在一段时间内系统无法处理时, 系统层面会弹出上图那样的ANR对话框.

1.2 为什么会产生ANR
android里, App的响应能力是由Activity Manager和Window Manager系统服务来监控的. 通常在如下两种情况下会弹出ANR对话框:
1：KeyDispatchTimeout(谷歌default 5s，MTK平台上是8s) --主要类型
按键或触摸事件在特定时间内无响应
2：BroadcastTimeout(10s)
BroadcastReceiver在特定时间内无法处理完成
3：ServiceTimeout(20s) --小概率类型
Service在特定的时间内无法处理完成

1.3 如何避免ANR
知道了ANR产生的原因, 那么想要避免ANR, 也就很简单了, 就一条规则:不要在主线程(UI线程)里面做繁重的操作

 

2.ANR的分析

将基于MTK平台讨论ANR的一般解决思路，旨在通过了解本文后能够对ANR问题能够快速定位，减少排查的时间。

最好使用userdebug版本测试，因为ENG版本测试的话本身会加重CPU loading
获取日志还有一点需要注意，发生ANR后，不要选择结束进程，因为这样AMS会kill掉该进程，有些信息会打印不出来，最好是ANR发生后等两三分钟左右，再将mtklog收集起来（db.XX.ANR写入到aee_exp文件夹下需要时间）。这里的aee_exp文件夹一般都是需要的, 对DB进行dump解析，得到ANR发生时场景信息，比如主线程callstack，CPU，memory等，在分析问题根因时很关键。

 

日志分析一般步骤
Step1:
查看mobilelog文件夹下的events_log,搜索关键字"am_anr",这一步用于确认ANR时间点，可以搜索到类似如下信息
11-09 21:33:21.518: I/am_anr(1041): [0,1848,com.android.contacts,953728589,Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 1.)]
这个例子中的ANR类型为Input dispatching timed out, 这种anr的原因的是在viewrootimpl分发事件时，并没有找到focuswindow导致的。时间点:21:33:21,进程号:1848 注意这里的进程号比较重要，后面要去trace.txt或者db文件中去看这个process(1848)对应的backtrace

Step2:
查看mobilelog文件夹下的main_log,搜索关键字"Application is not responding",发生ANR的时间或DB(MTK工具GAT)解析的_exp_main.txt
Backtrace: 
Process: com.android.contacts
Flags: 0x38d8be4d
Package: com.android.contacts v24 (1.2)
Foreground: Yes
Activity: com.android.contacts/com.mediatek.contacts.list.ContactListMultiChoiceActivity
Subject: Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 1.)
Build: D-171117V33:user/release-keys

nullAndroid time :[2017-11-19 03:31:26.86] [107321.313]
ANR期间的 Cpu usage，前几个占用情况以及Total如下：
CPU usage from 74494ms to 0ms ago (2019-11-09 21:32:06.966 to 2019-11-09 21:33:21.460):
  104% 323/mobile_log_d: 17% user + 86% kernel / faults: 2622 minor
  56% 1041/system_server: 41% user + 14% kernel / faults: 30698 minor 36 major
  34% 1408/com.android.phone: 28% user + 6% kernel / faults: 17027 minor 35 major
  15% 5541/android.process.acore: 13% user + 2.3% kernel / faults: 10865 minor 49 major
  10% 248/servicemanager: 4.4% user + 6.5% kernel / faults: 63 minor
  10% 249/surfaceflinger: 5.1% user + 5.6% kernel / faults: 1645 minor 1 major
  8.6% 215/logd: 2.7% user + 5.8% kernel / faults: 310 minor 11 major
  5.6% 1848/com.android.contacts: 4.4% user + 1.1% kernel / faults: 9569 minor 677 major
  3.7% 1155/com.android.systemui: 2.9% user + 0.7% kernel / faults: 12145 minor 50 major
98% TOTAL: 54% user + 42% kernel + 0.1% iowait + 0% softirq

很多时候需要注意iowait的占有率，如果占比比较高，则排查的方向要倾向与读取文件操作有关的信息，可以看trace日志中有没有读取文件或者操作SD卡的动作
还有注意观察一下在出现“Application is not responding”信息往上看，注意主线程是不是有耗时的动作，可以搜索关键字"ActivityThread"且搜索到的片段含有ANR的进程名。
如果发现ANR时CPUloading并不高，再去检查memory的情况，以排查是否存在竞争memory的情况。aee_exp文件下的db文件解析后会有一个 SYS_MEMORY_INFO文件，这个文件会列出问题发生时的MemTotal,MemFree,MemAvailable等信息。

Step3:
查看时间段内对应线程的 call stack
----- pid 1848 at 2019-11-09 21:33:21 -----
Cmd line: com.android.contacts
Build fingerprint: ‘TECNO/H3721A1/TECNO-IN5:7.0/NRD90M/A-171108V56:user/release-keys‘
ABI: ‘arm64‘
Build type: optimized
Zygote loaded classes=4375 post zygote classes=1641
Intern table: 50890 strong; 232 weak
JNI: CheckJNI is off; globals=848 (plus 2739 weak)
Libraries: /system/lib64/libandroid.so /system/lib64/libcompiler_rt.so /system/lib64/libdcfdecoderjni.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libwebviewchromium_loader.so libjavacore.so libopenjdk.so (9)
Heap: 6% free, 35MB/37MB; 294645 objects
Dumping cumulative Gc timings

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x75740b50 self=0x7128096a00
  | sysTid=1848 nice=0 cgrp=default sched=0/0 handle=0x712c693a98
  | state=S schedstat=( 343191137004 166931064193 540669 ) utm=28155 stm=6164 core=0 HZ=100
  | stack=0x7fdc4ca000-0x7fdc4cc000 stackSize=8MB
  | held mutexes=
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(Binder.java:622)
  at android.database.BulkCursorProxy.getWindow(BulkCursorNative.java:163)
  at android.database.BulkCursorToCursorAdaptor.onMove(BulkCursorToCursorAdaptor.java:82)
  at android.database.AbstractCursor.moveToPosition(AbstractCursor.java:236)
  at android.database.CursorWrapper.moveToPosition(CursorWrapper.java:197)
  at com.android.common.widget.CompositeCursorAdapter.getItem(CompositeCursorAdapter.java:436)
  at com.mediatek.contacts.list.MultiPhoneAndEmailsPickerAdapter.getDataId(MultiPhoneAndEmailsPickerAdapter.java:230)
  at com.mediatek.contacts.list.DataKindPickerBaseAdapter.getItemId(DataKindPickerBaseAdapter.java:249)
  at android.widget.HeaderViewListAdapter.getItemId(HeaderViewListAdapter.java:194)
  at android.widget.AdapterView.rememberSyncState(AdapterView.java:1255)
  at android.widget.AbsListView.setItemChecked(AbsListView.java:1142)
  at com.mediatek.contacts.list.AbstractPickerFragment.updateCheckBoxState(AbstractPickerFragment.java:742)
  at com.mediatek.contacts.list.AbstractPickerFragment.onSelectAll(AbstractPickerFragment.java:261)
  at com.mediatek.contacts.list.ContactListMultiChoiceActivity$1.onClick(ContactListMultiChoiceActivity.java:383)
  at android.view.View.performClick(View.java:6076)
  at android.widget.CompoundButton.performClick(CompoundButton.java:122)
  at android.view.View$PerformClick.run(View.java:23138)
  at android.os.Handler.handleCallback(Handler.java:836)
  at android.os.Handler.dispatchMessage(Handler.java:103)
  at android.os.Looper.loop(Looper.java:203)
  at android.app.ActivityThread.main(ActivityThread.java:6292)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1094)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:955)
可以看到在等待binder返回

Step4:
binder分析 binder_analysis
[Info]: Start parse executing & pending transactions for 1848!
    incoming transaction 118494543: 0000000000000000 from 1848:1848 to 5541:5554 code 1 flags 10 pri 0 r1 node 118458515 size 68:0 data 0000000000000000
[Analysis]: This binder call is waiting for 5541:5554 to executing complete.

    outgoing transaction 118494543: 0000000000000000 from 1848:1848 to 5541:5554 code 1 flags 10 pri 0 r1 node 118458515 size 68:0 data 0000000000000000
[Analysis]: This binder call is waiting for 5541:5554 to executing complete.

    pending transaction 118494731: 0000000000000000 from 0:0 to 1041:3702 code 0 flags 0 pri 0 r0 size 8:0 data 0000000000000000
[Analysis]: This binder call is waiting for 1041:3702 to executing complete.

查看SYS_PROCESSES_AND_THREADS 线程的信息
对端1041(system_server):3702(1041_D)
"Binder:1041_D" prio=5 tid=61 Native
  | group="main" sCount=1 dsCount=0 obj=0x14b0c160 self=0x7110f02200
  | sysTid=3702 nice=0 cgrp=default sched=0/0 handle=0x71078e1450
  | state=S schedstat=( 775971117390 490089600857 2178398 ) utm=57038 stm=20559 core=2 HZ=100
  | stack=0x71077e7000-0x71077e9000 stackSize=1005KB
  | held mutexes=
  kernel: (couldn‘t read /proc/self/task/3702/stack)
  native: #00 pc 000000000001bcec  /system/lib64/libc.so (syscall+28)
  native: #01 pc 00000000000e77c8  /system/lib64/libart.so (_ZN3art17ConditionVariable16WaitHoldingLocksEPNS_6ThreadE+156)
  native: #02 pc 000000000054aaac  /system/lib64/libart.so (_ZN3artL12GoToRunnableEPNS_6ThreadE+328)
  native: #03 pc 000000000054a920  /system/lib64/libart.so (_ZN3art12JniMethodEndEjPNS_6ThreadE+28)
  native: #04 pc 000000000088b6a0  /system/framework/arm64/boot-framework.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+220)
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(Binder.java:622)
  at android.os.ServiceManagerProxy.getService(ServiceManagerNative.java:123)
  at android.os.ServiceManager.getService(ServiceManager.java:55)
  at android.telephony.SubscriptionManager.getPhoneId(SubscriptionManager.java:1020)
  at com.android.server.TelephonyRegistry.idMatch(TelephonyRegistry.java:1983)
  at com.android.server.TelephonyRegistry.notifySignalStrengthForPhoneId(TelephonyRegistry.java:901)
  - locked <0x0bb31bba> (a java.util.ArrayList)
  at com.android.internal.telephony.ITelephonyRegistry$Stub.onTransact(ITelephonyRegistry.java:174)
  at android.os.Binder.execTransact(Binder.java:570)

案例一：等待binder调用返回
SYS_BINDER_INFO这个文件查找当前这个线程在和谁通信

案例二：主线程等待锁
主线程的CallStack DVM thread Status是Blocked

案例三：卡在IO上
这种情况一般是和文件操作相关，判断是否是这种情况。IO占比很高，这个时候就需要查看trace日志看当时的callstack，着重看有没有file相关的动作。

案例四：主线程作耗时的动作
耗时操作造成主线程堵塞

案例五：binder线程被占满
系统对每个process最多分配15个binder线程，这个是谷歌的设计（/frameworks/native/libs/binder/ProcessState.cpp)
如果另一个process发送太多重复binder请求，那么就会导致接收端binder线程被占满，从而处理不了其它的binder请求
这本身就是系统的一个限制，如果应用未按照系统的要求来实现对应逻辑，那么就会造成问题。
而系统端是不会（也不建议）通过修改系统行为来兼容应用逻辑，否则更容易造成其它根据系统需求正常编写的应用反而出现不可预料的问题。
判断Binder是否用完，可以在trace中搜索关键字"binder_f"，如果搜索到则表示已经用完，然后就要找log其他地方看是谁一直在消耗binder或者是有死锁发生，对于binder用完的前期思路大致如此。

案例六：JE或者NE导致ANR

案例七：只存在于Monkey测试下
只在Monkey环境下才能跑出来，而user版本是不会出现的，这种问题没有改动的意义。另外SAT
由于STK应用的特殊性，跑monkey会引发一些问题，如下为MTK的解释：
[DESCRIPTION]
Monkey测试时，测试SAT会经常发生 ANR 或者phone进程挂掉的问题。有时虽然没有跑到SAT中做测试，仍会因SAT应用导致许多异常现象。
[SOLUTION]
因为monkey测试时根本不适合跑SAT应用。主要是SAT应用涉及到卡跟手机或者卡跟网络的交互，这些交互过程并无固定的时间长短，且都是需要耗费一定时间。
因此，monkey测试时如果包含或者跑SAT应用就很容易发生问题(比如很常见的ANR和一些其他问题)。
建议: 不同于其他 APP，不建议monkey测试包含 SAT 应用和测试SAT应用。

小结：
总的说来，拿到一份eng的完整日志，一般步骤如下：
1.find ANR time,PID,ANR type
2.check CPU usage and Memory
3.check trace.txt,mapping process ID and time stamp
4.find more information about main thread through main log and event log

附录：
trace解析
该文档我们主要说明trace的解析和一些客观数据的如何获取。
trace它是分析死机的非常重要的手段，我们可以快速的知道，对应的process/thread 在当时正在执行哪些动作，卡住哪里等。可以非常直观的分析死机现场。
如果现场有问题机的话，我们还可以通过一些客观的执行环境来分析，通常包括如CPU 利用率，Memory 使用情况， Storage 剩余情况等。这些资料也非常重要，比如可以快速的知道，当时是否有Process 在疯狂的执行，当时是不是处于严重的low memory 情况， Storage 是否有耗尽的情况发生等。
我们知道出现问题java bt会在data/anr 保存相关的bt 信息，所以data/anr 里面的数据针对分析问题是很关键的，正常执行adb pull data/anr 我们都可以获取一些比较完整的trace信息。下面是一小段system server 的java trace的开始，从第一行开始我们来按每一行解析其所代表的含义。
1，代表 PID at time
2，然后接着Cmd line: process name
3，固定头，指明下面都是当前运行的dvm thread ，“DALVIK THREADS:” 及所包含的线程数 106
4，"main" prio=5 tid=1 Native
分别代表thread name, java thread Priority, DVM thread id, DVM thread status
"main" -> main thread -> activity thread
prio :java thread priority default is 5, （正常区域是1-10）
tid:是DVM thread id, 不是 linux thread id（下一行的sysTid才是）
Native:DVM thread Status 正常有这些状态（ZOMBIE, RUNNABLE, TIMED_WAIT, MONITOR, WAIT, INITALIZING,STARTING, NATIVE, VMWAIT, SUSPENDED,UNKNOWN）
5，group="main" sCount=1 dsCount=0 obj=0x75720fb8 self=0x7f7e8af800
代表 DVM thread status。
group:是线程所处的线程组  default is “main”
sCount: 线程被正常挂起的次数 1 (thread suspend count)
dsCount: 线程因调试而挂起次数 0 (thread dbg suspend count)
obj: 当前线程所关联的java线程对象 0x75720fb8 (thread obj address)
Sef: 该线程本身的地址 0x7f7e8af800 (thread point address)
6，sysTid=775 nice=-2 cgrp=default sched=0/0 handle=0x7f827d5e58
代表Linux thread status显示线程调度信息
sysTId: linux系统下得本地线程id linux thread tid 
Nice:线程的调度有优先级 linux thread nice value 
cgrp: 优先组属 c group
sched: 调度策略 cgroup policy/gourp id 
handle: 处理函数地址 handle address
7，state=S schedstat=( 225588889412 17277569839 97525 ) utm=20901 stm=1657 core=3 HZ=100
代表CPU Sched stat 显示更多该线程当前上下文
State:调度状态 process/thread state （正常有 "R (running)", "S (sleeping)", "D (disk sleep)", "T (stopped)", "t (tracing stop)", "Z (zombie)", "X (dead)", "x (dead)", "K (wakekill)", "W (waking)",），通常一般的Process 处于的状态都是S (sleeping), 而如果一旦发现处于如D (disk sleep), T (stopped), Z (zombie) 等就要认真审查.
Schedstat (Run CPU Clock/ns, Wait CPU Clock/ns, Slice times) 该线程运行信息
utm: utime, user space time 线程用户态下使用的时间值(单位是jiffies）
stm: stime, kernel space time 内核态下得调度时间值
core: now running in cpu. 最后运行改线程的cup标识
8，stack=0x7f7dc93000-0x7f7dc95000 stackSize=1020KB
代表堆栈地址区域及size
9，held mutexes=
代表是否被锁住，正常有四个属性(mutexes: tll=0 tsl=0 tscl=0 ghl=0)，0表示unlock，其它值都代表被lock，
tll: thread List Lock, 
tsl: thread Suspend Lock, 
tscl: thread Suspend Count Lock 
ghl: gc Heap Lock
10，剩余的就是一些 Call Stack

CPU Usage
追查CPU 利用率可大体的知道，当时机器是否有Process 在疯狂的运行, 当时系统运行是否繁忙。通常死机分析，只需要抓取基本的使用情况即可。通常使用的命令如 top
top 可以简单的查询Cpu 的基本使用情况，注意的是top 的CPU% 是按全部CPU 来计算的，如果以单线程来计算，比如当时有开启4个核心，那么最多吃到25%.

Memory Usage 
我们通常会审查，系统当时memory 是否足够, 是否处于low memory 状态, 是否可能出现因无法申请到memory 而卡死的情况. 常见的一些基本信息如下: 
* meminfo: basic memory status 
adb shell cat proc/meminfo 
adb shell cat proc/pid/maps 
adb shell cat proc/pid/smaps 
* procrank info: all process memory status 
adb shell procrank 
adb shell procmem pid 
adb shell dumpsys meminfo pid 
adb shell cat proc
adb shell cat /proc/buddyinfo

Storage Usage
查看Storage 的情况，通常主要是查询data 分区是否已经刷满, sdcard 是否已经刷满, 剩余的空间是否足够。以及是否有产生超大文件等。 通常使用的命令如 df

from: https://blog.csdn.net/sinat_34157462/java/article/details/78651870