ANR

一原因分析

应用进程自身引起：主线程阻塞，挂起，死循环等。
其他线程间接引起
- 线程间通信，其他线程长时间没反馈
- 其他线程的CPU占用率高，使得主线程无法抢占到CPU时间片。
直接：
- 对输入事件(如按键、触摸屏事件)的响应超过5秒
- 对于Broadcast，如果BroadcastReceiver超过10秒钟仍未执行完成
基本方案：
1. 如访问网络和数据库;或者是开销很大的计算，如改变位图的大小，需要在一个单独的子线程中完成 (或者是使用异步请求，如数据库操作)。
2. 但这并不意味着你的主线程需要进入阻塞状态已等待子线程结束，也不需要调用Therad.wait()或者Thread.sleep()方法。
3. 取而代之的是，主线程为子线程提供一个句柄(Handler)，让子线程在即将结束的时候调用它。

二 log分析

1. ActivityManager

ANR in com.example.demo
PID: 21904
Reason: Broadcast of Intent { act=android.intent.action.TIME_TICK flg=0x50000014 (has extras) }
//CPU负载：一段时间内正在使用和等待使用CPU的进程的数量。
Load: 11.57 / 11.06 / 10.9
//在ANR之前一段时间的CPU的使用率
CPU usage from 15260ms to 0ms ago:
3.2% 1755/system_server: 1.9% user + 1.3% kernel / faults: 9 minor 1 major
1.9% 1917/RX_Thread: 0% user + 1.9% kernel
...
6% TOTAL: 1.9% user + 2.8% kernel + 0.3% iowait + 0.8% softirq   
//ANR之后CPU的使用率                                               
CPU usage from 3523ms to 4064ms later:
...
14% 1755/system_server: 5.3% user + 8.9% kernel / faults: 16 minor
8.9% 1821/ActivityManager: 1.7% user + 7.1% kernel
1.7% 1755/system_server: 0% user + 1.7% kernel
16% TOTAL: 4.5% user + 10% kernel + 0.9% softirq
...

Skipping duplicate ANR: 
ProcessRecord{222aea3 21904:com.example.demo/u0a218} Broadcast of Intent { act=android.intent.action.TIME_TICK flg=0x50000014 (has extras) }
05-29 14:33:42.513 1755-1822/? W/ActivityManager:   
Force finishing activity com.mobvoi.baiding/com.example.demo.ui.MainActivity
05-29 14:33:42.542 1755-1822/? I/ActivityManager: 
Killing 21904:com.example.demo/u0a218 (adj 0): user request after error

2. Process

对应的pid = u0a218，filter Process

3. dalvikvm

06-02 11:51:31.422    8857-8862/com.example.demo I/dalvikvm﹕ Wrote stack traces to '/data/anr/traces.txt'
06-02 11:51:31.422      743-748/? I/dalvikvm﹕ threadid=3: reacting to signal 3
06-02 11:51:32.243    1275-1280/? I/dalvikvm﹕ Wrote stack traces to '/data/anr/traces.txt'
06-02 11:51:32.253    1282-1287/? I/dalvikvm﹕ threadid=3: reacting to signal 3
06-02 11:51:32.283    1282-1287/? I/dalvikvm﹕ Wrote stack traces to '/data/anr/traces.txt'
06-02 11:51:32.283    1348-1353/? I/dalvikvm﹕ threadid=3: reacting to signal 3
06-02 11:51:32.283    1360-1365/? I/dalvikvm﹕ Wrote stack traces to '/data/anr/traces.txt'

三案例分析

案例一：等待binder调用返回

SYS_BINDER_INFO这个文件查找当前这个线程在和谁通信

案例二：主线程等待锁

主线程的CallStack DVM thread Status是Blocked

案例三：卡在IO上

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

案例四：主线程作耗时的动作

耗时操作造成主线程堵塞

案例五：binder线程被占满

系统对每个process最多分配15个binder线程，这个是google的设计（/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的完整日志，一般步骤如下：
find ANR time,PID,ANR type
check CPU usage and Memory
check trace.txt,mapping process ID and time stamp
find more information about main thread through main log and event log

三 trace.txt分析

1. main

"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 obj=0x747ec5c8 self=0xb4d36500
| sysTid=1755 nice=-2 cgrp=default sched=0/0 handle=0xb6fa8b34
| state=S schedstat=( 1057136282054 1036064987970 2171062 ) utm=63487 stm=42226 core=0 HZ=100
| stack=0xbe0e7000-0xbe0e9000 stackSize=8MB
| held mutexes=kernel: (couldn't read /proc/self/task/1755/stack)
native: #00 pc 0004099c  /system/lib/libc.so (__epoll_pwait+20)
native: #01 pc 00019f63  /system/lib/libc.so (epoll_pwait+26)
native: #02 pc 00019f71  /system/lib/libc.so (epoll_wait+6)
native: #03 pc 00012ce7  /system/lib/libutils.so (_ZN7android6Looper9pollInnerEi+102)
native: #04 pc 00012f63  /system/lib/libutils.so (_ZN7android6Looper8pollOnceEiPiS1_PPv+130)
native: #05 pc 00086a31  /system/lib/libandroid_runtime.so (_ZN7android18NativeMessageQueue8pollOnceEP7_JNIEnvP8_jobjecti+22)
native: #06 pc 0000055d  /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_os_MessageQueue_nativePollOnce__JI+96)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:323)
at android.os.Looper.loop(Looper.java:138)
at com.android.server.SystemServer.run(SystemServer.java:292)
at com.android.server.SystemServer.main(SystemServer.java:172)
at java.lang.reflect.Method.invoke!(Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:740)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:630)

2. 作用

trace是分析死机的非常重要的手段，我们可以快速的知道，对应的process/thread 在当时正在执行哪些动作，卡住哪里等。可以非常直观的分析死机现场。
如果现场有问题机的话，我们还可以通过一些客观的执行环境来分析，通常包括如CPU 利用率，Memory 使用情况， Storage 剩余情况等。这些资料也非常重要，比如可以快速的知道，当时是否有Process 在疯狂的执行，当时是不是处于严重的low memory 情况， Storage 是否有耗尽的情况发生等。
执行adb pull data/anr我们都可以获取一些比较完整的trace信息。【当时用的手表，但手机都有不能这么取了】
替换第3步：执行 adb bugreport > bugreport.txt 可以取trace文件。

3. trace每一行的意义

代表 PID at time
然后接着Cmd line: process name
固定头，指明下面都是当前运行的dvm thread ，“DALVIK THREADS:” 及所包含的线程数 106
“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）
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)
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
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标识
stack=0x7f7dc93000-0x7f7dc95000 stackSize=1020KB
- 代表堆栈地址区域及size
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
剩余的就是一些 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

参考文章

ANR分析思路简析

其他案例

一、主线程被其他线程lock，导致死锁

waiting on <0x1cd570> (a android.os.MessageQueue)
DALVIK THREADS:
"main" prio=5 tid=3 TIMED_WAIT
  | group="main" sCount=1 dsCount=0 s=0 obj=0x400143a8
  | sysTid=691 nice=0 sched=0/0 handle=-1091117924
  at java.lang.Object.wait(Native Method)
  - waiting on <0x1cd570> (a android.os.MessageQueue)
  at java.lang.Object.wait(Object.java:195)
  at android.os.MessageQueue.next(MessageQueue.java:144)
  at android.os.Looper.loop(Looper.java:110)
  at android.app.ActivityThread.main(ActivityThread.java:3742)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:515)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:739)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:497)
  at dalvik.system.NativeStart.main(Native Method)

"Binder Thread #3" prio=5 tid=15 NATIVE
  | group="main" sCount=1 dsCount=0 s=0 obj=0x434e7758
  | sysTid=734 nice=0 sched=0/0 handle=1733632
  at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #2" prio=5 tid=13 NATIVE
  | group="main" sCount=1 dsCount=0 s=0 obj=0x1cd570
  | sysTid=696 nice=0 sched=0/0 handle=1369840
  at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #1" prio=5 tid=11 NATIVE
  | group="main" sCount=1 dsCount=0 s=0 obj=0x433aca10
  | sysTid=695 nice=0 sched=0/0 handle=1367448
  at dalvik.system.NativeStart.run(Native Method)

----- end 691 -----

二、主线程做耗时的操作：比如数据库读写。

"main" prio=5 tid=1 Native
held mutexes=
kernel: (couldn't read /proc/self/task/11003/stack)
native: #00 pc 000492a4 /system/lib/libc.so (nanosleep+12)
native: #01 pc 0002dc21 /system/lib/libc.so (usleep+52)
native: #02 pc 00009cab /system/lib/libsqlite.so (???)
native: #03 pc 00011119 /system/lib/libsqlite.so (???)
native: #04 pc 00016455 /system/lib/libsqlite.so (???)
native: #16 pc 0000fa29 /system/lib/libsqlite.so (???)
native: #17 pc 0000fad7 /system/lib/libsqlite.so (sqlite3_prepare16_v2+14)
native: #18 pc 0007f671 /system/lib/libandroid_runtime.so (???)
native: #19 pc 002b4721 /system/framework/arm/boot-framework.oat (Java_android_database_sqlite_SQLiteConnection_nativePrepareStatement__JLjava_lang_String_2+116)
at android.database.sqlite.SQLiteConnection.setWalModeFromConfiguration(SQLiteConnection.java:294)
at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:215)
at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:193)
at android.database.sqlite.SQLiteConnectionPool.openConnectionLocked(SQLiteConnectionPool.java:463)
at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:185)
at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:177)
at android.database.sqlite.SQLiteDatabase.openInner(SQLiteDatabase.java:808)
locked <0x0db193bf> (a java.lang.Object)
at android.database.sqlite.SQLiteDatabase.open(SQLiteDatabase.java:793)
at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:696)
at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:690)
at android.content.ContextWrapper.openOrCreateDatabase(ContextWrapper.java:299)
at android.database.sqlite.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:223)
at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:163)
locked <0x045a4a8c> (a com.xxxx.video.common.data.DataBaseHelper)
at com.xxxx.video.common.data.DataBaseORM.<init>(DataBaseORM.java:46)
at com.xxxx.video.common.data.DataBaseORM.getInstance(DataBaseORM.java:53)
locked <0x017095d5> (a java.lang.Class<com.xxxx.video.common.data.DataBaseORM>)

三、binder数据量过大

07-21 04:43:21.573  1000  1488 12756 E Binder  : Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 388568 (data: 1, 32, 7274595)
07-21 04:43:21.573  1000  1488 12756 E Binder  : android.util.Log$TerribleFailure: Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 388568 (data: 1, 32, 7274595)
07-21 04:43:21.607  1000  1488  2951 E Binder  : Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 211848 (data: 1, 23, 7274595)
07-21 04:43:21.607  1000  1488  2951 E Binder  : android.util.Log$TerribleFailure: Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 211848 (data: 1, 23, 7274595)
07-21 04:43:21.662  1000  1488  6258 E Binder  : Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 259300 (data: 1, 33, 7274595)

四、binder 通信失败

07-21 06:04:35.580 <6>[32837.690321] binder: 1698:2362 transaction failed 29189/-3, size 100-0 line 3042
07-21 06:04:35.594 <6>[32837.704042] binder: 1765:4071 transaction failed 29189/-3, size 76-0 line 3042
07-21 06:04:35.899 <6>[32838.009132] binder: 1765:4067 transaction failed 29189/-3, size 224-8 line 3042
07-21 06:04:36.018 <6>[32838.128903] binder: 1765:2397 transaction failed 29189

ANR

ANR

一 原因分析