直接上干货
Android ANR日志分析指南
当你的项目越做越复杂,或者你的用户达到某个数量级的时候,你的代码不小心出现细小的问题,你会收到各种各样的bug,其中ANR的问题你一定不会陌生。本文将详细讲解ANR的类型、出现的原因、ANR案例详细分析、经典的案例。
定义
ANR(Application Not Responding)
应用程序无响应。如果你应用程序在UI线程被阻塞太长时间,就会出现ANR,通常出现ANR,系统会弹出一个提示提示框,让用户知道,该程序正在被阻塞,是否继续等待还是关闭。
ANR类型
出现ANR的一般有以下几种类型:
1:KeyDispatchTimeout(常见)
input事件在5S
内没有处理完成发生了ANR。
logcat日志关键字:Input event dispatching timed out
2:BroadcastTimeout
前台Broadcast:onReceiver在10S
内没有处理完成发生ANR。
后台Broadcast:onReceiver在60s
内没有处理完成发生ANR。
logcat日志关键字:Timeout of broadcast BroadcastRecord
3:ServiceTimeout
前台Service:onCreate
,onStart
,onBind
等生命周期在20s
内没有处理完成发生ANR。
后台Service:onCreate
,onStart
,onBind
等生命周期在200s
内没有处理完成发生ANR
logcat日志关键字:Timeout executing service
4:ContentProviderTimeout
ContentProvider 在10S
内没有处理完成发生ANR。 logcat日志关键字:timeout publishing content providers
ANR出现的原因
1:主线程频繁进行耗时的IO操作:如数据库读写
2:多线程操作的死锁,主线程被block;
3:主线程被Binder 对端block;
4:System Server
中WatchDog出现ANR;
5:service binder
的连接达到上线和无法和System Server通信
6:系统资源已耗尽(管道、CPU、IO)
场景
- Service Timeout
- BroadcastQueue Timeout
- ContentProvider Timeout
- InputDispatching Timeout
Timeout时长
-
对于前台服务,则超时为SERVICE_TIMEOUT = 20s;
-
对于后台服务,则超时为SERVICE_BACKGROUND_TIMEOUT = 200s
-
对于前台广播,则超时为BROADCAST_FG_TIMEOUT = 10s;
-
对于后台广播,则超时为BROADCAST_BG_TIMEOUT = 60s;
-
ContentProvider超时为CONTENT_PROVIDER_PUBLISH_TIMEOUT = 10s;
-
InputDispatching Timeout: 输入事件分发超时5s,包括按键和触摸事件。
注意事项: Input的超时机制与其他的不同,对于input来说即便某次事件执行时间超过timeout时长,只要用户后续在没有再生成输入事件,则不会触发ANR
超时检测机制
-
Service超时检测机制:
- 超过一定时间没有执行完相应操作来触发移除延时消息,则会触发anr;
-
BroadcastReceiver超时检测机制:
- 有序广播的总执行时间超过 2* receiver个数 * timeout时长,则会触发anr;
有序广播的某一个receiver执行过程超过 timeout时长,则会触发anr;
- 有序广播的总执行时间超过 2* receiver个数 * timeout时长,则会触发anr;
-
另外:
- 对于Service, Broadcast, Input发生ANR之后,最终都会调用AMS.appNotResponding;
- 对于provider,在其进程启动时publish过程可能会出现ANR, 则会直接杀进程以及清理相应信息,而不会弹出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分析
- 前台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则直接杀掉
- 分析步骤
- 定位发生ANR时间点
- 查看trace信息
- 分析是否有耗时的message,binder调用,锁的竞争,CPU资源的抢占
- 结合具体的业务场景的上下文来分析
如何避免ANR发生
- 主线程尽量只做UI相关的操作,避免耗时操作,比如过度复杂的UI绘制,网络操作,文件IO操作;
- 避免主线程跟工作线程发生锁的竞争,减少系统耗时binder的调用,谨慎使用sharePreference,注意主线程执行provider query操作
总之,尽可能减少主线程的负载,让其空闲待命,以期可随时响应用户的操作
trace.txt文件解读
- 人为的收集trace.txt的命令
adb shell kill -3 888 //可指定进程pid
执行完该命令后traces信息的结果保存到文件/data/anr/traces.txt - 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个线程.
- 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案例分析过程
我们将一步一步分析ANR,这个过程更加理解如何找到问题、分析问题以及解决问题。
一、 查看events_log
查看mobilelog文件夹下的events_log,从日志中搜索关键字:am_anr
,找到出现ANR的时间点、进程PID、ANR类型。
如日志:
07-20 15:36:36.472 1000 1520 1597 I am_anr : [0,1480,com.xxxx.moblie,952680005,Input dispatching timed out (AppWindowToken{da8f666 token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.moblie/.ui.MainActivity t3862}}}, Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]
从上面的log我们可以看出: 应用com.xxxx.moblie
在07-20 15:36:36.472
时间,发生了一次KeyDispatchTimeout
类型的ANR,它的进程号是1480
. 把关键的信息整理一下:
ANR时间:07-20 15:36:36.472
进程pid:1480
进程名:com.xxxx.moblie
ANR类型:KeyDispatchTimeout
我们已经知道了发生KeyDispatchTimeout
的ANR是因为 input事件在5秒内没有处理完成
。那么在这个时间07-20 15:36:36.472
的前5秒,也就是(15:36:30 ~15:36:31
)时间段左右程序到底做了什么事情?这个简单,因为我们已经知道pid了,再搜索一下pid = 1480
的日志.这些日志表示该进程所运行的轨迹,关键的日志如下:
07-20 15:36:29.749 10102 1480 1737 D moblie-Application: [Thread:17329] receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE
07-20 15:36:30.136 10102 1480 1737 D moblie-Application: receiving an empty message, drop
07-20 15:36:35.791 10102 1480 1766 I Adreno : QUALCOMM build : 9c9b012, I92eb381bc9
07-20 15:36:35.791 10102 1480 1766 I Adreno : Build Date : 12/31/17
07-20 15:36:35.791 10102 1480 1766 I Adreno : OpenGL ES Shader Compiler Version: EV031.22.00.01
07-20 15:36:35.791 10102 1480 1766 I Adreno : Local Branch :
07-20 15:36:35.791 10102 1480 1766 I Adreno : Remote Branch : refs/tags/AU_LINUX_ANDROID_LA.UM.6.4.R1.08.00.00.309.049
07-20 15:36:35.791 10102 1480 1766 I Adreno : Remote Branch : NONE
07-20 15:36:35.791 10102 1480 1766 I Adreno : Reconstruct Branch : NOTHING
07-20 15:36:35.826 10102 1480 1766 I vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/hw/gralloc.msm8998.so from the current namespace instead.
07-20 15:36:36.682 10102 1480 1480 W ViewRootImpl[MainActivity]: Cancelling event due to no window focus: KeyEvent { action=ACTION_UP, keyCode=KEYCODE_PERIOD, scanCode=0, metaState=0, flags=0x28, repeatCount=0, eventTime=16099429, downTime=16099429, deviceId=-1, source=0x101 }
从上面我们可以知道,在时间 07-20 15:36:29.749 程序收到了一个action消息。
07-20 15:36:29.749 10102 1480 1737 D moblie-Application: [Thread:17329] receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE。
原来是应用com.xxxx.moblie
收到了一个推送消息(com.ttt.push.RECEIVE_MESSAGE
)导致了阻塞,我们再串联一下目前所获取到的信息:在时间07-20 15:36:29.749
应用com.xxxx.moblie
收到了一下推送信息action=com.ttt.push.RECEIVE_MESSAGE
发生阻塞,5秒后发生了KeyDispatchTimeout的ANR
。
虽然知道了是怎么开始的,但是具体原因还没有找到,是不是当时CPU很紧张、各路APP再抢占资源? 我们再看看CPU的信息,。搜索关键字关键字: ANR IN
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: ANR in com.xxxx.moblie (com.xxxx.moblie/.ui.MainActivity) (进程名)
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: PID: 1480 (进程pid)
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: Reason: Input dispatching timed out (AppWindowToken{da8f666 token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.moblie/.ui.MainActivity t3862}}}, Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: Load: 0.0 / 0.0 / 0.0 (Load表明是1分钟,5分钟,15分钟CPU的负载)
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: CPU usage from 20ms to 20286ms later (2018-07-20 15:36:36.170 to 2018-07-20 15:36:56.436):
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 42% 6774/pressure: 41% user + 1.4% kernel / faults: 168 minor
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 34% 142/kswapd0: 0% user + 34% kernel
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 31% 1520/system_server: 13% user + 18% kernel / faults: 58724 minor 1585 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 13% 29901/com.ss.android.article.news: 7.7% user + 6% kernel / faults: 56007 minor 2446 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 13% 32638/com.android.quicksearchbox: 9.4% user + 3.8% kernel / faults: 48999 minor 1540 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 11% (CPU的使用率)1480/com.xxxx.moblie: 5.2%(用户态的使用率) user + (内核态的使用率) 6.3% kernel / faults: 76401 minor 2422 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 8.2% 21000/kworker/u16:12: 0% user + 8.2% kernel
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 0.8% 724/mtd: 0% user + 0.8% kernel / faults: 1561 minor 9 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 8% 29704/kworker/u16:8: 0% user + 8% kernel
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 7.9% 24391/kworker/u16:18: 0% user + 7.9% kernel
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 7.1% 30656/kworker/u16:14: 0% user + 7.1% kernel
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 7.1% 9998/kworker/u16:4: 0% user + 7.1% kernel
我已经在log 中标志了相关的含义。com.xxxx.moblie
占用了11%的CPU,其实这并不算多。现在的手机基本都是多核CPU。假如你的CPU是4核,那么上限是400%,以此类推。
既然不是CPU负载的原因,那么到底是什么原因呢? 这时就要看我们的终极大杀器——traces.txt
。
二、 traces.txt 日志分析
当APP不响应、响应慢了、或者WatchDog的监视没有得到回应时,系统就会dump出一个traces.txt
文件,存放在文件目录:/data/anr/traces.txt
,通过traces文件,我们可以拿到线程名、堆栈信息、线程当前状态、binder call等信息。
通过adb命令拿到该文件:adb pull /data/anr/traces.txt
trace: Cmd line:com.xxxx.moblie
"main" prio=5 tid=1 Runnable
| group="main" sCount=0 dsCount=0 obj=0x73bcc7d0 self=0x7f20814c00
| sysTid=20176 nice=-10 cgrp=default sched=0/0 handle=0x7f251349b0
| state=R schedstat=( 0 0 0 ) utm=12 stm=3 core=5 HZ=100
| stack=0x7fdb75e000-0x7fdb760000 stackSize=8MB
| held mutexes= "mutator lock"(shared held)
// java 堆栈调用信息,可以查看调用的关系,定位到具体位置
at ttt.push.InterceptorProxy.addMiuiApplication(InterceptorProxy.java:77)
at ttt.push.InterceptorProxy.create(InterceptorProxy.java:59)
at android.app.Activity.onCreate(Activity.java:1041)
at miui.app.Activity.onCreate(SourceFile:47)
at com.xxxx.moblie.ui.b.onCreate(SourceFile:172)
at com.xxxx.moblie.ui.MainActivity.onCreate(SourceFile:68)
at android.app.Activity.performCreate(Activity.java:7050)
at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1214)
at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2807)
at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2929)
at android.app.ActivityThread.-wrap11(ActivityThread.java:-1)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1618)
at android.os.Handler.dispatchMessage(Handler.java:105)
at android.os.Looper.loop(Looper.java:171)
at android.app.ActivityThread.main(ActivityThread.java:6699)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:246)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:783)
我详细解析一下traces.txt
里面的一些字段,看看它到底能给我们提供什么信息.
main:main标识是主线程,如果是线程,那么命名成“Thread-X”的格式,x表示线程id,逐步递增。
prio:线程优先级,默认是5
tid:tid不是线程的id,是线程唯一标识ID
group:是线程组名称
sCount:该线程被挂起的次数
dsCount:是线程被调试器挂起的次数
obj:对象地址
self:该线程Native的地址
sysTid:是线程号(主线程的线程号和进程号相同)
nice:是线程的调度优先级
sched:分别标志了线程的调度策略和优先级
cgrp:调度归属组
handle:线程处理函数的地址。
state:是调度状态
schedstat:从 /proc/[pid]/task/[tid]/schedstat
读出,三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度,不支持这项信息的三个值都是0;
utm:是线程用户态下使用的时间值(单位是jiffies)
stm:是内核态下的调度时间值
core:是最后执行这个线程的cpu核的序号。
Java的堆栈信息是我们最关心的,它能够定位到具体位置。从上面的traces,我们可以判断ttt.push.InterceptorProxy.addMiuiApplicationInterceptorProxy.java:77
导致了com.xxxx.moblie
发生了ANR。这时候可以对着源码查看,找到出问题,并且解决它。
总结一下这分析流程:首先我们搜索am_anr
,找到出现ANR的时间点、进程PID、ANR类型、然后再找搜索PID
,找前5秒左右的日志。过滤ANR IN 查看CPU信息,接着查看traces.txt
,找到java的堆栈信息定位代码位置,最后查看源码,分析与解决问题。这个过程基本能找到发生ANR的来龙去脉。
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/-22, size 348-0 line 2916