ANR（一）

https://www.jianshu.com/p/fa962a5fd939
http://gityuan.com/2016/07/02/android-anr/
https://developer.android.com/topic/performance/vitals/anr.html#java
https://developer.android.com/training/articles/perf-anr.html

控制台日志过滤 ActivityManager
命令行导出手机anr日志 adb pull data/anr/ .

• 获取anr 日志
  获取控制台log 过滤 关键TAG ActivityManager 或者、从log中搜索“ANR in”或“am_anr”，会找到ANR发生的log
  例如 过滤 ActivityManager

03-25 13:41:04.871 1614-1634/? E/ActivityManager: ANR in com.jpc.anr (com.jpc.anr/.developer.DeveloperActivity)
    PID: 17669
    Reason: 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.)
    Load: 0.0 / 0.0 / 0.0
    CPU usage from 0ms to 13555ms later (2019-03-25 13:40:51.258 to 2019-03-25 13:41:04.813):
      72% 17669/com.jpc.anr: 70% user + 1.9% kernel / faults: 3581 minor 191 major
      28% 1614/system_server: 16% user + 12% kernel / faults: 5253 minor 1612 major
      8.7% 123/kswapd0: 0% user + 8.7% kernel

获取手机上的日志：androidStudio Terminal 里输入,导出日志到工程目录中会自动生成 anr 文件夹加，手机上的anr日志会被覆盖，要及时导出。

adb pull data/anr/ .

• 什么情况下会出现ANR问题：
  ANR(Application Not responding)。Android中，主线程(UI线程)如果在规定时内没有处理完相应工作，就会出现ANR。
  具体来说，ANR会在以下几种情况中出现：

1. 输入事件(按键和触摸事件)5s内没被处理: Input event dispatching timed out
2. BroadcastReceiver的事件(onRecieve方法)在规定时间内没处理完(前台广播为10s，后台广播为60s)：Timeout of broadcast BroadcastRecord
3. service 前台20s后台200s未完成启动 Timeout executing service
4. ContentProvider的publish在10s内没进行完：timeout publishing content providers
   在android文档([https://developer.android.com/training/articles/perf-anr.html]中，只写了第一种和第二种情况，而根据源码和实际的实验，我们能发现service的启动和provider的publish同样会造成anr问题。
   这里需要注意的是，在后三种情况，以BroadcastReviever为例，在onRecieve()方法执行10秒内没发生第一种ANR(也就是在这个过程中没有输入事件或输入事件还没到5s)才会发生Receiver timeout，否则将先发生事件无相应ANR，所以onRecieve()是有可能执行不到10s就发生ANR的，所以不要在onRecieve()方法里面干活，service的onCreate()和ContentProvider的onCreate()也一样，他们都是主线程的，不要在这些方法里干活

• 如何分析ANR问题：
  从前文可以明确，ANR问题是由于主线程的任务在规定时间内没处理完任务，而造成这种情况的原因大致会有一下几点：

主线程在做一些耗时的工作
主线程被其他线程锁
cpu被其他进程占用，该进程没被分配到足够的cpu资源。

判断一个ANR属于哪种情况便是分析ANR问题的关键。那么拿到一个anr的日志，应该如何分析呢？
在发生ANR的时候，系统会收集ANR相关的信息提供给开发者：首先在Log中有ANR相关的信息，其次会收集ANR时的CPU使用情况，还会收集trace信息，也就是当时各个线程的执行情况。trace文件保存到了/data/anr/traces.txt中，此外，ANR前后该进程打印出的log也有一定价值。一般来说可以按一下思路来分析：

从log中找到ANR反生的信息：可以从log中搜索“ANR in”或“am_anr”，会找到ANR发生的log，该行会包含了ANR的时间、进程、是何种ANR等信息，如果是BroadcastReceiver的ANR可以怀疑BroadCastReceiver.onRecieve()的问题，如果的Service或Provider就怀疑是否其onCreate()的问题。
在该条log之后会有CPU usage的信息，表明了CPU在ANR前后的用量（log会表明截取ANR的时间），从各种CPU Usage信息中大概可以分析如下几点：
(1). 如果某些进程的CPU占用百分比较高，几乎占用了所有CPU资源，而发生ANR的进程CPU占用为0%或非常低，则认为CPU资源被占用，进程没有被分配足够的资源，从而发生了ANR。这种情况多数可以认为是系统状态的问题，并不是由本应用造成的。
(2). 如果发生ANR的进程CPU占用较高，如到了80%或90%以上，则可以怀疑应用内一些代码不合理消耗掉了CPU资源，如出现了死循环或者后台有许多线程执行任务等等原因，这就要结合trace和ANR前后的log进一步分析了。
(3). 如果CPU总用量不高，该进程和其他进程的占用过高，这有一定概率是由于某些主线程的操作就是耗时过长，或者是由于主进程被锁造成的。
除了上述的情况(1)以外，分析CPU usage之后，确定问题需要我们进一步分析trace文件。trace文件记录了发生ANR前后该进程的各个线程的stack。对我们分析ANR问题最有价值的就是其中主线程的stack，一般主线程的trace可能有如下几种情况：
(1). 主线程是running或者native而对应的栈对应了我们应用中的函数，则很有可能就是执行该函数时候发生了超时。
(2). 主线程被block:非常明显的线程被锁，这时候可以看是被哪个线程锁了，可以考虑优化代码。如果是死锁问题，就更需要及时解决了。
(3). 由于抓trace的时刻很有可能耗时操作已经执行完了（ANR -> 耗时操作执行完毕 ->系统抓trace），这时候的trace就没有什么用了，主线程的stack就是这样的：

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x757855c8 self=0xb4d76500
  | sysTid=3276 nice=0 cgrp=default sched=0/0 handle=0xb6ff5b34
  | state=S schedstat=( 50540218363 186568972172 209049 ) utm=3290 stm=1764 core=3 HZ=100
  | stack=0xbe307000-0xbe309000 stackSize=8MB
  | held mutexes=
  kernel: (couldn't read /proc/self/task/3276/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 00086abd  /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 android.app.ActivityThread.main(ActivityThread.java:5528)
  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)

当然这种情况很有可能是由于该进程的其他线程消耗掉了CPU资源，这就需要分析其他线程的trace以及ANR前后该进程自己输出的log了。

• 如何降低ANR的概率：

有一些操作是很危险的，非常容易发生ANR，在写代码时候一定要避免：

1. 主线程读取数据：在Android中主线程去读取数据是非常不好的，Android是不允许主线程从网络读数据的，但系统允许主线程从数据库或者其他地方获取数据，但这种操作ANR风险很大，也会造成掉帧等，影响用户体验。
   （1）. 避免在主线程query provider，首先这会比较耗时，另外这个操作provider那一方的进程如果挂掉了或者正在启动，我们应用的query就会很长时间不会返回，我们应该在其他线程中执行数据库query、provider的query等获取数据的操作。
   （2）. sharePreference的调用：针对sharePreference的优化点有很多，文章http://weishu.me/2016/10/13/sharedpreference-advices/ 详细介绍了几点sharepreference使用时候的注意事项。首先sharePreference的commit()方法是同步的，apply()方法一般是异步执行的。所以在主线程不要用其commit()，用apply()替换。其次sharePreference的写是全量写而非增量写，所以尽量都修改完同一apply，避免改一点apply一次(apply()方法在Activity stop的时候主线程会等待写入完成，提交多次就很容易卡)。并且存储文本也不宜过大，这样会很慢。另外，如果写入的是json或者xml，由于需要加和删转义符号，速度会比较慢。
2. 不要在broadcastReciever的onRecieve()方法中干活，这一点很容易被忽略，尤其应用在后台的时候。为避免这种情况，一种解决方案是直接开的异步线程执行，但此时应用可能在后台，系统优先级较低，进程很容易被系统杀死，所以可以选择开个IntentService去执行相应操作，即使是后台Service也会提高进程优先级，降低被杀可能性。
3. 各个组件的生命周期函数都不应该有太耗时的操作，即使对于后台Service或者ContentProvider来讲，应用在后台运行时候其onCreate()时候不会有用户输入引起事件无响应ANR，但其执行时间过长也会引起Service的ANR和ContentProvider的ANR。
4. 尽量避免主线程的被锁的情况，在一些同步的操作主线程有可能被锁，需要等待其他线程释放相应锁才能继续执行，这样会有一定的ANR风险，对于这种情况有时也可以用异步线程来执行相应的逻辑。另外， 我们要避免死锁的发生(主线程被死锁基本就等于要发生ANR了)

• anr 工程

• anr 超时时间
  https://blog.csdn.net/wxlinwzl/article/details/77851643

ANR超时时间在ActivityManagerService.Java文件中进行了定义    
// How long we allow a receiver to run before giving up on it.  
static final int BROADCAST_FG_TIMEOUT = 10*1000;  
static final int BROADCAST_BG_TIMEOUT = 60*1000;  
// How long we wait until we timeout on key dispatching.  
static final int KEY_DISPATCHING_TIMEOUT = 5*1000;  
// How long we wait until we timeout on key dispatching during instrumentation.  
static final int INSTRUMENTATION_KEY_DISPATCHING_TIMEOUT = 60*1000;  
service ANR超时的定义在ActiveServices.java中
// How long we wait for a service to finish executing.  
static final int SERVICE_TIMEOUT = 20*1000;  
// How long we wait for a service to finish executing.  
static final int SERVICE_BACKGROUND_TIMEOUT = SERVICE_TIMEOUT * 10;  

• anr 日志分析
  从LOG可以看出ANR的类型，CPU的使用情况，如果CPU使用量接近100%，说明当前设备很忙，有可能是CPU饥饿导致了ANR
  如果CPU使用量很少，说明主线程被BLOCK了
  如果IOwait很高，说明ANR有可能是主线程在进行I/O操作造成的
  主线程等待子线程释放锁 的控制台 anr日志 log_develop_3_1.txt

03-25 17:30:19.379 1614-1634/? E/ActivityManager: ANR in com.jpc.anr (com.jpc.anr/.developer.DeveloperActivity)
    PID: 25121
    Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length: 2.  Wait queue head age: 28285.5ms.)
    Load: 0.0 / 0.11 / 0.1
    CPU usage from 164ms to -12075ms ago (2019-03-25 17:30:07.083 to 2019-03-25 17:30:19.322):
      100% 25121/com.jpc.anr: 99% user + 0.4% kernel / faults: 1429 minor 111 major
      57% 1614/system_server: 32% user + 25% kernel / faults: 30845 minor 19010 major
      ...

主线程等待子线程释放锁 手机端日志 traces_develop_anr_3_1.txt

----- pid 25121 at 2019-03-25 17:30:07 -----
Cmd line: com.jpc.anr
...

suspend all histogram:  Sum: 2.395s 99% C.I. 0.006ms-19.618ms Avg: 1.257ms Max: 63.326ms
DALVIK THREADS (23):
"AsyncTask #1" prio=5 tid=23 Runnable
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x15e80028 self=0x7224df7800
  | sysTid=28220 nice=10 cgrp=default sched=0/0 handle=0x7222b824f0
  | state=R schedstat=( 32246677889 21909686 174 ) utm=3224 stm=0 core=4 HZ=100
  | stack=0x7222a80000-0x7222a82000 stackSize=1037KB
  | held mutexes= "mutator lock"(shared held)
  at com.jpc.anr.developer.BubbleSort.sortData(BubbleSort.java:26)


"Signal Catcher" daemon prio=5 tid=3 Runnable
  | group="system" sCount=0 dsCount=0 flags=0 obj=0x15e80e38 self=0x72416c4400
  | sysTid=25127 nice=0 cgrp=default sched=0/0 handle=0x72368fe4f0


"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x731f8120 self=0x72416c3a00
  | sysTid=25121 nice=-10 cgrp=default sched=0/0 handle=0x72468ee9c8
  | state=S schedstat=( 1306069289 83794736 729 ) utm=102 stm=28 core=6 HZ=100
  | stack=0x7fce8a2000-0x7fce8a4000 stackSize=8MB
  | held mutexes=
  at com.jpc.anr.developer.DeveloperActivity$1.onClick(DeveloperActivity.java:92)
  - waiting to lock <0x0f2ca04d> (a java.lang.Object) held by thread 23
  at android.view.View.performClick(View.java:6891)

从控制台日志里知道anr的包名和pid = A，在手机的日志里搜索 “"main" prio=5” 同时pid = A的线程，这个是发生ANR 应用的主线程，【"main" prio=5 tid=1 Blocked】看线程状态 推测一些信息；一般手机日志的和第一个线程相关的记录和发生anr有关【"AsyncTask #1" prio=5 tid=23 Runnable】。

线程状态 线程状态.png

相关anr日志分析帖子
https://blog.csdn.net/fanxudonggreat/article/details/81840791
https://www.jianshu.com/p/545e5e7bbf94
https://blog.csdn.net/tinderliang/article/details/77717872
https://blog.csdn.net/tjy1985/article/details/6777983

其他
https://www.jianshu.com/p/388166988cef