ANR问题分析

ANR概念

ANR(Application Not responding)，是指应用程序未响应，Android系统对于一些事件需要在一定的时间范围内完成，如果超过预定时间未能得到有效响应或者响应时间过长，都会造成ANR

什么引发了ANR？

在Android里，应用程序的响应性是由Activity Manager和WindowManager系统服务监视的，当它检测到一下情况中的一个时，Android就会针对特定的应用程序显示ANR
在 5 秒内没有响应输入的事件(例如，按键按下，屏幕触摸) BroadcastReceiver 在 10 秒内没有执行完毕
一个 ANR 对话框显示给用户

如何避免 ANR？

考虑上面的 ANR 定义，让我们来研究一下为什么它会在 Android 应用程序里发生和如何最佳
构建应用程序来避免 ANR。

  • Android 应用程序通常是运行在一个单独的线程（例如，main）里。这意味着你的应用程序
    所做的事情如果在主线程里占用了太长的时间的话，就会引发 ANR 对话框，因为你的应用程
    序并没有给自己机会来处理输入事件或者 Intent 广播。

  • 因此，运行在主线程里的任何方法都尽可能少做事情。特别是，Activity 应该在它的关键
    生命周期方法（如 onCreate()和 onResume()）里尽可能少的去做创建操作。潜在的耗时操
    作，例如网络或数据库操作，或者高耗时的计算如改变位图尺寸，应该在子线程里（或者以
    数据 库操作为例，通过异步请求的方式）来完成。然而，不是说你的主线程阻塞在那里等
    待子线程的完成——也不是调用 Thread.wait()或是 Thread.sleep()。替代的方法是，主
    线程应该为子线程提供一个 Handler，以便完成时能够提交给主线程。以这种方式设计你的
    应用程序，将 能保证你的主线程保持对输入的响应性并能避免由于 5 秒输入事件的超时引
    发的 ANR 对话框。这种做法应该在其它显示 UI 的线程里效仿，因为它们都受相同的超 时影
    响。

  • IntentReceiver 执行时间的特殊限制意味着它应该做：在后台里做小的、琐碎的工作如保
    存设定或者注册一个 Notification。和在主线 程里调用的其它方法一样，应用程序应该避
    免在 BroadcastReceiver 里做耗时的操作或计算。但不再是在子线程里做这些任务（因为
    BroadcastReceiver 的生命周期短），替代的是，如果响应 Intent 广播需要执行一个耗时
    的动作的话，应用程序应该启动一个 Service。顺便提及一句，你也应该避免在IntentReceiver 里启动一个 Activity，因为它会创建一个新的画面，并从当前用户正在运行的程序上抢夺焦点。如果你的应用程序在响应 Intent 广播时需要向用户展示什么，你应该使用 Notification Manager 来实现。

  • 增强响应灵敏性
    一般来说，在应用程序里，100 到 200ms 是用户能感知阻滞的时间阈值。因此，这里有一些
    额外的技巧来避免 ANR，并有助于让你的应用程序看起来有响应性。
    如果你的应用程序为响应用户输入正在后台工作的话，可以显示工作的进度（ProgressBar
    和 ProgressDialog 对这种情况来说很有用）。
    特别是游戏，在子线程里做移动的计算。

如果你的应用程序有一个耗时的初始化过程的话，考虑可以显示一个 SplashScreen 或者快
速显示主画面并异步来填充这些信息。在这两种情况下，你都应该显示正在进行的进度，以
免用户认为应用程序被冻结了。
前台与后台ANR
前台ANR:用户能感知，比如拥有前台可见的activity的进程，或者拥有前台通知的fg-service的进程，此时发 生ANR对用户体验影响比较大，需要弹框让用户决定是否退出还是等待 后台ANR:，只抓取发生无响应进程的trace，也不会收集CPU信息，并且会在后台直接杀掉该无响应的进 程，不会弹框提示用户

ANR的常见类型

1:KeyDispatchTimeout(5 seconds) --主要类型
按键或触摸事件在特定时间内无响应
2:BroadcastTimeout(10 seconds)
BroadcastReceiver在特定时间内无法处理完成
3.ServiceTimeout(20 seconds)小概率类型
Service在特定的时间内无法处理完成
为什么会超时呢？
超时时间的计数一般是从按键分发给app开始，超时的原因一般有两种：
1）当前的事件没有机会得到处理(即UI线程正在处理一个事件，没有及时的完成或者looper被某种原因阻塞住了)
2)当前的事件正在处理，但没有及时完成

如何避免KeyDispatchTimeout

1:UI线程尽量只做跟UI相关的工作
2:耗时的工作(比如数据库操作，I/O，连接网络或者别的有可能阻碍UI线程的操作)把它放入单独的线程处理
3:尽量用Handler来处理UIthread和别的thread之间的交互
UI线程
UI线程主要包括如下：
1.Activity:onCreate(),onResume(),onDestory(),onKeyDown(),onClick()
2.Mainthread handler:handlerMessage(),post*(runnable r)

如何避免ANR发生

1.主线程尽量只做UI相关的操作，避免耗时操作，比如过度复杂的UI绘制，网络操作，文件IO操作；
2.避免主线程跟工作线程发生锁的竞争，减少系统耗时binder的调用，谨慎使用sharePreference,注意主线程执行provider query操作
总之，尽可能减少主线程的负载，让其空闲待命，以期可随时响应用户的操作

如何去分析 ANR

先看个 LOG:
04-01 13:12:11.572 I/InputDispatcher( 220): Application is not responding:Window{2b263310com.android.email/com.android.email.activity.SplitScreenActivit ypaused=false}. 5009.8ms since event, 5009.5ms since waitstarted
04-0113:12:11.572 I/WindowManager( 220): Input event dispatching timedout sending tocom.android.email/com.android.email.activity.SplitScreenActivity
04-01 13:12:14.123 I/Process( 220): Sending signal. PID: 21404 SIG: 3---发生 ANR 的时间 和生成 trace.txt 的时间
04-0113:12:15.872 E/ActivityManager:CPUusage from 4361ms to 699ms ago----CPU 在ANR 发生前的使用情况
04-0113:12:15.872 E/ActivityManager(220): 100%TOTAL: 4.8% user + 7.6% kernel + 87%iowait
04-0113:12:15.872 E/ActivityManager(220):CPUusage from 3697ms to 4223ms later:-- ANR后 CPU 的使用量

从 LOG 可以看出 ANR 的类型，CPU 的使用情况，如果 CPU 使用量接近 100%，说明当前 设备很忙，有可能是 CPU 饥饿导致了 ANR
如果 CPU 使用量很少，说明主线程被 BLOCK 了
如果 IOwait 很高，说明 ANR 有可能是主线程在进行 I/O 操作造成的
除了看 LOG，解决 ANR 还得需要 trace.txt 文件， 如何获取呢?可以用如下命令获取

  1. $chmod 777 /data/anr
  2. $rm /data/anr/traces.txt
  3. $ps
  4. $kill -3PID
  5. adbpull data/anr/traces.txt ./mytraces.txt
    从 trace.txt 文件，看到最多的是如下的信息: -----pid 21404 at 2011-04-0113:12:14 -----
    Cmdline: com.android.email
    DALVIK THREADS:
    (mutexes: tll=0tsl=0 tscl=0 ghl=0 hwl=0 hwll=0) "main" prio=5 tid=1NATIVE
    | group="main" sCount=1 dsCount=0obj=0x2aad2248 self=0xcf70
    | sysTid=21404 nice=0 sched=0/0cgrp=[fopen-error:2] handle=1876218976 atandroid.os.MessageQueue.nativePollOnce(Native Method) atandroid.os.MessageQueue.next(MessageQueue.java:119) atandroid.os.Looper.loop(Looper.java:110)
    at android.app.ActivityThread.main(ActivityThread.java:3688) at java.lang.reflect.Method.invokeNative(Native Method)
    atjava.lang.reflect.Method.invoke(Method.java:507)
    atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:624)
    at dalvik.system.NativeStart.main(Native Method)
    说明主线程在等待下条消息进入消息队列
    Thread 状态
    ThreadState (defined at “dalvik/vm/thread.h “)
    THREAD_UNDEFINED = -1, /* makes enum compatible with int32_t / THREAD_ZOMBIE = 0, / TERMINATED /
    THREAD_RUNNING = 1, /     RUNNABLE or running now /
    THREAD_TIMED_WAIT = 2, /     TIMED_WAITING in Object.wait() /
    THREAD_MONITOR = 3, /     BLOCKED on a monitor /
    THREAD_WAIT = 4, /     WAITING in Object.wait() /
    THREAD_INITIALIZING= 5, /     allocated, not yet running /
    THREAD_STARTING = 6, /     started, not yet on thread list /
    THREAD_NATIVE = 7, /     off in a JNI native method /
    THREAD_VMWAIT = 8, /     waiting on a VM resource /
    THREAD_SUSPENDED = 9, /     suspended, usually by GC or debugger */
ANR分析
  1. 前台ANR发生后，系统会马上去抓取现场的信息，用于调试分析，收集的信息如下:
    • 将am_anr信息输出到EventLog，也就是说ANR触发的时间点最接近的就是EventLog中输出的am_anr信息
    • 收集以下重要进程的各个线程调用栈trace信息，保存在data/anr/traces.txt文件
      • 当前发生ANR的进程，system_server进程以及所有persistent进程
      • audioserver, cameraserver, mediaserver, surfaceflinger等重要的native进程
      • CPU使用率排名前5的进程
    • 将发生ANR的reason以及CPU使用情况信息输出到main log
    • 将traces文件和CPU使用情况信息保存到dropbox，即data/system/dropbox目录
    • 对用户可感知的进程则弹出ANR对话框告知用户，对用户不可感知的进程发生ANR则直接杀掉
  2. 分析步骤
    1. 定位发生ANR时间点
    2. 查看trace信息
    3. 分析是否有耗时的message,binder调用，锁的竞争，CPU资源的抢占
    4. 结合具体的业务场景的上下文来分析
trace.txt文件解读 【重点要看的】
  1. 人为的收集trace.txt的命令
    adb shell kill -3 888 //可指定进程pid
    执行完该命令后traces信息的结果保存到文件/data/anr/traces.txt
  2. trace文件解读
----- pid 888 at 2016-11-11 22:22:22 -----
Cmd line: system_server
ABI: arm
Build type: optimized
Zygote loaded classes=4113 post zygote classes=3239
Intern table: 57550 strong; 9315 weak
JNI: CheckJNI is off; globals=2418 (plus 115 weak)
Libraries: /system/lib/libandroid.so /system/lib/libandroid_servers.so /system/lib/libaudioeffect_jni.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/librs_jni.so /system/lib/libsechook.so /system/lib/libshell_jni.so /system/lib/libsoundpool.so /system/lib/libwebviewchromium_loader.so /system/lib/libwifi-service.so /vendor/lib/libalarmservice_jni.so /vendor/lib/liblocationservice.so libjavacore.so (16)
//已分配堆内存大小40MB，其中29M已用，总分配207772个对象 
Heap: 27% free, 29MB/40MB; 307772 objects
... //省略GC相关信息

//当前进程总99个线程
DALVIK THREADS (99):
//主线程调用栈
"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x75bd9fb0 self=0x5573d4f770
  | sysTid=12078 nice=-2 cgrp=default sched=0/0 handle=0x7fa75fafe8
  | state=S schedstat=( 5907843636 827600677 5112 ) utm=453 stm=137 core=0 HZ=100
  | stack=0x7fd64ef000-0x7fd64f1000 stackSize=8MB
  | held mutexes=
  //内核栈
  kernel: __switch_to+0x70/0x7c
  kernel: SyS_epoll_wait+0x2a0/0x324
  kernel: SyS_epoll_pwait+0xa4/0x120
  kernel: cpu_switch_to+0x48/0x4c
  native: #00 pc 0000000000069be4 /system/lib64/libc.so (__epoll_pwait+8)
  native: #01 pc 000000000001cca4 /system/lib64/libc.so (epoll_pwait+32)
  native: #02 pc 000000000001ad74 /system/lib64/libutils.so (_ZN7android6Looper9pollInnerEi+144)
  native: #03 pc 000000000001b154 /system/lib64/libutils.so (_ZN7android6Looper8pollOnceEiPiS1_PPv+80)
  native: #04 pc 00000000000d4bc0 /system/lib64/libandroid_runtime.so (_ZN7android18NativeMessageQueue8pollOnceEP7_JNIEnvP8_jobjecti+48)
  native: #05 pc 000000000000082c /data/dalvik-cache/arm64/system@framework@boot.oat (Java_android_os_MessageQueue_nativePollOnce__JI+144)
  at android.os.MessageQueue.nativePollOnce(Native method)
  at android.os.MessageQueue.next(MessageQueue.java:323)
  at android.os.Looper.loop(Looper.java:135)
  at com.android.server.SystemServer.run(SystemServer.java:290)
  at com.android.server.SystemServer.main(SystemServer.java:175)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:738)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:628)
  
"Binder_1" prio=5 tid=8 Native
  | group="main" sCount=1 dsCount=0 obj=0x12c610a0 self=0x5573e5c750
  | sysTid=12092 nice=0 cgrp=default sched=0/0 handle=0x7fa2743450
  | state=S schedstat=( 796240075 863170759 3586 ) utm=50 stm=29 core=1 HZ=100
  | stack=0x7fa2647000-0x7fa2649000 stackSize=1013KB
  | held mutexes=
  kernel: __switch_to+0x70/0x7c
  kernel: binder_thread_read+0xd78/0xeb0
  kernel: binder_ioctl_write_read+0x178/0x24c
  kernel: binder_ioctl+0x2b0/0x5e0
  kernel: do_vfs_ioctl+0x4a4/0x578
  kernel: SyS_ioctl+0x5c/0x88
  kernel: cpu_switch_to+0x48/0x4c
  native: #00 pc 0000000000069cd0 /system/lib64/libc.so (__ioctl+4)
  native: #01 pc 0000000000073cf4 /system/lib64/libc.so (ioctl+100)
  native: #02 pc 000000000002d6e8 /system/lib64/libbinder.so (_ZN7android14IPCThreadState14talkWithDriverEb+164)
  native: #03 pc 000000000002df3c /system/lib64/libbinder.so (_ZN7android14IPCThreadState20getAndExecuteCommandEv+24)
  native: #04 pc 000000000002e114 /system/lib64/libbinder.so (_ZN7android14IPCThreadState14joinThreadPoolEb+124)
  native: #05 pc 0000000000036c38 /system/lib64/libbinder.so (???)
  native: #06 pc 000000000001579c /system/lib64/libutils.so (_ZN7android6Thread11_threadLoopEPv+208)
  native: #07 pc 0000000000090598 /system/lib64/libandroid_runtime.so (_ZN7android14AndroidRuntime15javaThreadShellEPv+96)
  native: #08 pc 0000000000014fec /system/lib64/libutils.so (???)
  native: #09 pc 0000000000067754 /system/lib64/libc.so (_ZL15__pthread_startPv+52)
  native: #10 pc 000000000001c644 /system/lib64/libc.so (__start_thread+16)
  (no managed stack frames)
... //此处省略剩余的N个线程.
  1. trace参数解读
"Binder_1" prio=5 tid=8 Native
  | group="main" sCount=1 dsCount=0 obj=0x12c610a0 self=0x5573e5c750
  | sysTid=12092 nice=0 cgrp=default sched=0/0 handle=0x7fa2743450
  | state=S schedstat=( 796240075 863170759 3586 ) utm=50 stm=29 core=1 HZ=100
  | stack=0x7fa2647000-0x7fa2649000 stackSize=1013KB
  | held mutexes=
  • 第0行:
    • 线程名: Binder_1（如有daemon则代表守护线程)
    • prio: 线程优先级
    • tid: 线程内部id
    • 线程状态: NATIVE
  • 第1行:
    • group: 线程所属的线程组
    • sCount: 线程挂起次数
    • dsCount: 用于调试的线程挂起次数
    • obj: 当前线程关联的java线程对象
    • self: 当前线程地址
  • 第2行：
    • sysTid：线程真正意义上的tid
    • nice: 调度有优先级
    • cgrp: 进程所属的进程调度组
    • sched: 调度策略
    • handle: 函数处理地址
  • 第3行：
    • state: 线程状态
    • schedstat: CPU调度时间统计
    • utm/stm: 用户态/内核态的CPU时间(单位是jiffies)
    • core: 该线程的最后运行所在核
    • HZ: 时钟频率
  • 第4行：
    • stack：线程栈的地址区间
    • stackSize：栈的大小
  • 第5行：
    • mutex: 所持有mutex类型，有独占锁exclusive和共享锁shared两类
  • schedstat含义说明：

    • nice值越小则优先级越高。此处nice=-2, 可见优先级还是比较高的;

    • schedstat括号中的3个数字依次是Running、Runable、Switch，紧接着的是utm和stm

      • Running时间：CPU运行的时间，单位ns
      • Runable时间：RQ队列的等待时间，单位ns
      • Switch次数：CPU调度切换次数
      • utm: 该线程在用户态所执行的时间，单位是jiffies，jiffies定义为sysconf(_SC_CLK_TCK)，默认等于10ms
      • stm: 该线程在内核态所执行的时间，单位是jiffies，默认等于10ms
  • 可见，该线程Running=186667489018ns,也约等于186667ms。在CPU运行时间包括用户态(utm)和内核态(stm)。 utm + stm = (12112 + 6554) ×10 ms = 186666ms。
  • 结论：utm + stm = schedstat第一个参数值。

当然最主要的学习参考是官网的关于ANR
https://developer.android.google.cn/topic/performance/vitals/anr?hl=zh_cn#java

©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 212,332评论 6赞 493
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 90,508评论 3赞 385
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 157,812评论 0赞 348
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 56,607评论 1赞 284
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 65,728评论 6赞 386
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 49,919评论 1赞 290
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 39,071评论 3赞 410
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 37,802评论 0赞 268
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 44,256评论 1赞 303
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,576评论 2赞 327
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,712评论 1赞 341
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 34,389评论 4赞 332
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 40,032评论 3赞 316
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,798评论 0赞 21
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,026评论 1赞 266
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 46,473评论 2赞 360
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 43,606评论 2赞 350

推荐阅读更多精彩内容