weijunfeng
11/22/2019 - 7:04 AM
anr文件提取
新版Android 系统的anr 文件 如果需要直接pull 需要root 权限
如果不是root 机 可以通过 adb bugreport 导出对应的bug信息包，然后在其中会有相关数据。
然而 部分手机进行了定制 如华为， 其中导出的zip 并没有anr 的文件夹。
不过在执行了adb bugreport指令之后，华为会在原有的/data/anr/ 目录下生成两个权限为all 的可导出的dump 文件，这个时候直接adb pull 也可以了
作者：Zcclucky
链接：https://www.jianshu.com/p/5efbc1603a4a
来源：简书
著作权归作者所有。商业转载请联系作者获得授权，非商业转载请注明出处。Android手机在没有/data/anr目录权限的情况下如何分析ANR
2019-07-31 20:47:28 奋斗中的年轻人 阅读数 157更多
分类专栏： android
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
本文链接：https://blog.csdn.net/xjz696/article/details/97958441
背景：ANR一直以来都是一个比较头疼的问题，当开发中碰到ANR的时候我们该如何分析呢？常规的方案都是去手机的/data/anr目录下拿trace文件，然后再分析trace文件。那问题来了，现在好多研发、测试的开发机都是没有root而且又没有/data/anr目录权限的，在这种情况下我们该怎么定位呢？今天我们就主要聊下这个问题
解决方案：做Android研发的大家应该都知道adb有个命令叫bugreport，至于这个命令是干嘛的大家可以自己去百度去Google，今天主要讲怎么用这个命令去拿到ANR的trace信息。
Step1: 将发生ANR的手机打开"开发者选项"并启动"调试模式"（不会的自行百度）
Step2:将手机连接到电脑上
Step3:在电脑的命令行里面执行命令 "adb bugreport anrlog.zip" (anrlog.zip是生成文件的名字，自己可以随便写)，这里有个前提是你的电脑装了adb，没装的自行百度如何安装。
Step4:解压生成好的anrlog.zip文件，大概是下图的结构，打开第一个文件，也就是体积最大的那个文件。
Step5:文件打开一看乱七八糟啥都有，其实这就对了，那么我们开始分析这个文件，找出trace信息。
我的经验搜索关键字： "VM TRACES AT LAST ANR"，一般就能定位到下图的位置，你看看进程名和时间跟你的进程对上不，对上那就OK了，顺着往下翻就是这次ANR的trace信息了。
Step6：至于分析ANR到底是啥原因引起，那就学问大了去了，我一般也就是分析下主线程卡在哪里了，就跟下图一样。如果一眼看不出来，那就继续去搜索前人的经验吧，怎么根据trace信息分析ANR。
android ANR文件的导出不需要root权限
2017-10-18 12:12:41 乐活青年 阅读数 3975
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
本文链接：https://blog.csdn.net/u011016373/article/details/78271423
$:adb shell
$:cd data/anr(此处不要直接cd data，因为有些目录没有权限，会报permission deny)
$:ls
查看当前目录下的所有文件，并找到你想导出的那个（traces.txt，traces_1.txt，native1_1.txt，....）
$:ctrl+d或exit退出
$:adb pull data/anr/traces.txt
1.adb进入到/data/anr即可看到ANR日志
02.png
2.将ANR日志拿出
命令：adb pull /data/anr C:\log
03.png
3.查看ANR日志
04.png
0人点赞
抓包
"小礼物走一走
作者：安小龙
链接：https://www.jianshu.com/p/e11892fd26e2
来源：简书
著作权归作者所有。商业转载请联系作者获得授权，非商业转载请注明出处。ANR问题简析
2017-12-07 10:05:29 周一的早上 阅读数 5328
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
本文链接：https://blog.csdn.net/qzh123456/article/details/78737791
ANR问题，相信是每位开发日常都会遇到的问题，对于这类问题的分析，按照官方的推荐，或网络博客的总结思路能解决一定的问题，但是多数时候大家的困惑就是应用本逻辑很简单，耗时很短或应用堆栈完全正常，或者或处于空闲状态，可系统为什么就认为接收者发生ANR了呢？下面将之前公司的一次内部分享开放出来，用几个实例从不同角度分析导致ANR产生的Root Case。也希望对大家以后分析该类问题有一定参考，不对的地方欢迎大家拍砖。
一 ANR分类，含如下几种类型：
广播ANR
Service ANR
ContentProvider ANR
Input ANR
面向系统：WatchDog
二 产生ANR原因，如下几种：
主线程耗时操作
主线程被其它线程Block
系统级响应阻塞
系统或进程自身可用内存紧张
CPU资源被抢占
对于这些ANR，先给大家的推荐一下大致分析思路和相关日志，通常发生ANR时，首先去查找对应Trace日志，看看主线程是否在处理该广播或被阻塞，如果发现上述现象，那么恭喜你，已经很接近答案了。但如果发现堆栈完全处于空闲状态，那么很不幸，就需要扩大参考面了，需要结合log日志进行分析，日志包括logcat, kernel日志，cpuinfo以及meminfo等，参考顺序从前向后。
1分析logcat思路：首先在日志中搜索（“anr in”，“low_memory”, “slow_operation”）等关键字，通过该类关键字主要是查看系统Cpu负载，如果是发现应用进程CPU明显过高，那么很有可能是该进程抢占CPU过多导致，系统调度不及时,误认为应用发生了超时行为。
2分析kernel思路：在此类日志中直接搜索lowmemorykiller, 如果存在则查看发生时间和ANR时间是否大致对应，相差无几的话，可以从该日志中看到操作系统层面当前内存情况，Free Memory说明的是空闲物理内存，File Free说明的则是文件Cache，也就是应用或系统从硬盘读取文件，使用结束后，kernel并没有这正释放这类内存，加以缓存，目的是为了下次读写过程加快速度。当然，发现Free和Other整体数值都偏低时，Kernel会进行一定程度的内存交换，导致整个系统卡顿。同时这类现象也会体现在log日志“slow_operation”中，即系统进程的调度也会收到影响。
3分析cpuinfo思路：这类日志一目了然，可以清晰的看到哪类进程CPU偏高，如果存在明显偏高进程，那么ANR和此进程抢占CPU有一定关系。当然，如发现Kswapd，emmc进程在top中，则说明遇到系统内存压力或文件IO开销。
4分析meminfo思路：分析该类日志，主要是看哪类应用或系统占用内存偏高，如果应用内存占用比较正常，系统也没有发生过度内存使用，那么则说明系统中缓存了大量进程，并没有及时释放导致系统整体内存偏低。
5综合分析当时系统环境，例如电量（低电可能会引起手机限频，限核等等），手机温度（温度过高也可能会引起限频），以及操作频率（例如执行monkey测试）等等；
上面说了这么多，下面结合实例进行分析：
实例一：主线程进行耗时操作，或被进程内其它线程阻塞，示例：
第一步，观察Trace 主线程堆栈，发现主线程在申请内存过程中被block，等待GC结束，但通过堆栈进一步发现其GC并没有发生在该线程，也就是说在其他线程在执行GC动作，而主线程在申请内存过程中需要等待GC完成，再进一步申请内存。
"main" prio=5 tid=1 WaitingForGcToComplete
native: #00 pc 0000000000019980 /system/lib64/libc.so (syscall+28)
native: #01 pc 000000000013a62c /system/lib64/libart.so (_ZN3art17ConditionVariable4WaitEPNS_6ThreadE+136)
native: #02 pc 0000000000237f14 /system/lib64/libart.so (_ZN3art2gc4Heap19WaitForGcToCompleteENS0_7GcCauseEPNS_6ThreadE+1376)
native: #03 pc 000000000024798c /system/lib64/libart.so (_ZN3art2gc4Heap22AllocateInternalWithGcEPNS_6ThreadENS0_13AllocatorTypeEmPmS5_S5_PPNS_6mirror5ClassE+168)
native: #04 pc 000000000050394c /system/lib64/libart.so (artAllocObjectFromCodeRosAlloc+1412)
native: #05 pc 00000000001215d0 /system/lib64/libart.so (art_quick_alloc_object_rosalloc+64)
native: #06 pc 00000000018e72f0 /system/framework/arm64/boot.oat (Java_android_widget_TextView__0003cinit_0003e__Landroid_content_Context_2Landroid_util_AttributeSet_2II+1156)
at android.widget.TextView.<init>(TextView.java:727)
at android.widget.TextView.<init>(TextView.java:682)
at android.widget.TextView.<init>(TextView.java:678)
at java.lang.reflect.Constructor.newInstance!(Native method)
第二步，再看看其它线程状态，进一步查找发现，下面任务正在执行GC
"LeuiRunningState:Background" prio=5 tid=28 WaitingPerformingGc
"AsyncTask #6" prio=5 tid=20 WaitingPerformingGc
综上可以得出大致结论，Tid=28,20线程执行GC,导致主线程申请内存被Block. 但是进一步思考，应用GC是常有的事，但是为何这次需要这么长时间呢，带着疑问我们看看进程的内存使用情况：
Total number of allocations 9887486
Total bytes allocated 732MB
Total bytes freed 476MB
Free memory 5KB
Free memory until GC 5KB
Free memory until OOME 5KB
Total memory 256MB
Max memory 256MB
上面发现，应用已使用256Mb, 距离OOM只有5K，内存对象超过998万个，也就是说GC过程需要扫描这些对象的巨大部分，导致耗时很久，另外内存距离OOM只有5kb，说明有内存泄漏，或内存使用不合理。
综上，对于这个问题得出结论，应用进程内存存在泄漏或使用不当，导致GC时间过程，产生ANR.
实例二：应用内部线程逻辑依赖关系导致超时，触发ANR，示例：
第一步，观察Trace 主线程堆栈，发现主线程在Binder通信过程被Block.
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 obj=0x75f0eaa8 self=0x7fad046a00
| sysTid=4298 nice=-6 cgrp=default sched=0/0 handle=0x7fb1d18fe8
| state=S schedstat=( 79488910537 19985244611 169915 ) utm=6564 stm=1384 core=0 HZ=100
| stack=0x7fc237c000-0x7fc237e000 stackSize=8MB
| held mutexes=
kernel: (couldn't read /proc/self/task/4298/stack)
native: #00 pc 00000000000683d0 /system/lib64/libc.so (__ioctl+4)
native: #01 pc 00000000000723f8 /system/lib64/libc.so (ioctl+100)
native: #02 pc 000000000002d584 /system/lib64/libbinder.so (_ZN7android14IPCThreadState14talkWithDriverEb+164)
native: #03 pc 000000000002e050 /system/lib64/libbinder.so (_ZN7android14IPCThreadState15waitForResponseEPNS_6ParcelEPi+104)
native: #04 pc 000000000002e2c4 /system/lib64/libbinder.so (_ZN7android14IPCThreadState8transactEijRKNS_6ParcelEPS1_j+176)
native: #05 pc 0000000000025654 /system/lib64/libbinder.so (_ZN7android8BpBinder8transactEjRKNS_6ParcelEPS1_j+64)
native: #06 pc 00000000000e0928 /system/lib64/libandroid_runtime.so (???)
native: #07 pc 000000000139ba24 /system/framework/arm64/boot.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+200)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(Binder.java:503)
at android.nfc.INfcAdapter$Stub$Proxy.setAppCallback(INfcAdapter.java:529)
at android.nfc.NfcActivityManager.requestNfcServiceCallback(NfcActivityManager.java:339)
at android.nfc.NfcActivityManager.setNdefPushMessageCallback(NfcActivityManager.java:309)
第二步，进一步查找此线程在和哪个进程进行通信，搜索关键字“setAppCallback”（Android命名习惯，客户端和服务端函数命名基本相同），在Nfc的Binder_3线程响应了客户端请求，但在处理过程中被线程1阻塞，顺着再看看线程1状态
"Binder_3" prio=5 tid=17 Blocked
| group="main" sCount=1 dsCount=0 obj=0x12ddf0a0 self=0x7fa670f000
| sysTid=3183 nice=-6 cgrp=default sched=0/0 handle=0x7f93c30440
| state=S schedstat=( 3041465858 2637156615 16961 ) utm=168 stm=136 core=3 HZ=100
| stack=0x7f93b34000-0x7f93b36000 stackSize=1013KB
| held mutexes=
at com.android.nfc.P2pLinkManager.setNdefCallback(P2pLinkManager.java:420)
- waiting to lock <0x0bed0520> (a com.android.nfc.P2pLinkManager) held by thread 1
at com.android.nfc.NfcService$NfcAdapterService.setAppCallback(NfcService.java:1679)
at android.nfc.INfcAdapter$Stub.onTransact(INfcAdapter.java:178)
at android.os.Binder.execTransact(Binder.java:453)
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 obj=0x75f0eaa8 self=0x7fad046a00
| sysTid=2706 nice=0 cgrp=default sched=0/0 handle=0x7fb1d18fe8
| state=S schedstat=( 115355173189 36125520701 224819 ) utm=8594 stm=2941 core=0 HZ=100
| stack=0x7fc237c000-0x7fc237e000 stackSize=8MB
| held mutexes=
kernel: (couldn't read /proc/self/task/2706/stack)
native: #00 pc 00000000000683d0 /system/lib64/libc.so (__ioctl+4)
native: #01 pc 00000000000723f8 /system/lib64/libc.so (ioctl+100)
native: #02 pc 000000000002d584 /system/lib64/libbinder.so (_ZN7android14IPCThreadState14talkWithDriverEb+164)
native: #03 pc 000000000002e050 /system/lib64/libbinder.so (_ZN7android14IPCThreadState15waitForResponseEPNS_6ParcelEPi+104)
native: #04 pc 000000000002e2c4 /system/lib64/libbinder.so (_ZN7android14IPCThreadState8transactEijRKNS_6ParcelEPS1_j+176)
native: #05 pc 0000000000025654 /system/lib64/libbinder.so (_ZN7android8BpBinder8transactEjRKNS_6ParcelEPS1_j+64)
native: #06 pc 00000000000e0928 /system/lib64/libandroid_runtime.so (???)
native: #07 pc 000000000139ba24 /system/framework/arm64/boot.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+200)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(Binder.java:503)
at android.nfc.IAppCallback$Stub$Proxy.createBeamShareData(IAppCallback.java:113)
at com.android.nfc.P2pLinkManager.prepareMessageToSend(P2pLinkManager.java:558)
- locked <0x0bed0520> (a com.android.nfc.P2pLinkManager)
通过主线程，又发现正进程Binder通信，同时被block,搜索关键字“createBeamShareData”，发现又回到浏览器线程，Binder_6线程响应此请求，同时也处于Waiting状态
"Binder_6" prio=5 tid=12 Waiting
| group="main" sCount=1 dsCount=0 obj=0x12c13a00 self=0x7f52850e00
| sysTid=23857 nice=0 cgrp=default sched=0/0 handle=0x7f694ff440
| state=S schedstat=( 705897380 828401158 3677 ) utm=45 stm=25 core=1 HZ=100
| stack=0x7f69403000-0x7f69405000 stackSize=1013KB
| held mutexes=
at java.lang.Object.wait!(Native method)
- waiting on <0x08a80433> (a java.lang.Object)
at java.lang.Thread.parkFor$(Thread.java:1220)
- locked <0x08a80433> (a java.lang.Object)
at sun.misc.Unsafe.park(Unsafe.java:299)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:810)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:970)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1278)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:203)
at com.android.browser.NfcHandler.createNdefMessage(NfcHandler.java:92)
at android.nfc.NfcActivityManager.createBeamShareData(NfcActivityManager.java:377)
at android.nfc.IAppCallback$Stub.onTransact(IAppCallback.java:53)
at android.os.Binder.execTransact(Binder.java:453)
为什么Binder_6处于Waiting状态？这就需要大家结合Read the Fuck Code的精神研究逻辑了，事后发现此线程的事件放在了主线程执行，当执行完毕后接收通知，停止waiting.
至此，我们找到了一条完整的链路，（浏览器主线程---->NFC Binder_3---->NFC主线程---->浏览器 Binder_6---->浏览器主线程），大家到此看到了根本原因，死锁！！！
综上，对于这个问题得出结论，应用通信过程中发生死锁导致ANR，后面只需解锁即可。
上面两类问题，相对简单，大家遇到时也多半能自行分析解决，下面两类涉及到较多系统或其它因素，问题比较隐晦，但是按照一定分析思路，静下来分析，多数时候还是能找到原因或给出优化方案的。
实例三：系统内存过低，kernel进行内存交换过程会引起整个系统运行缓慢(卡顿)，示例：
第一步，观察Trace 主线程堆栈，发现主线程处于Suspend状态；发生此类问题一般是两种情况，一种是进程自身过于繁忙，每次分配时间片都不够用，调度器强制把它置换成休眠了，另一种是系统比较繁忙，低优先级集成得不到时间片；带着这样的疑问，继续看：
"main" prio=5 tid=1 Suspended
| group="main" sCount=1 dsCount=0 obj=0x745518a0 self=0x7f86254a00
| sysTid=21916 nice=0 cgrp=default sched=0/0 handle=0x7f8b30efc8
| state=S schedstat=( 311762801762 96254728754 409881 ) utm=25610 stm=5566 core=0 HZ=100
| stack=0x7fd023c000-0x7fd023e000 stackSize=8MB
| held mutexes=
at java.util.regex.Splitter.fastSplit(Splitter.java:73)
at java.lang.String.split(String.java:1410)
at java.lang.String.split(String.java:1392)
at android.content.res.theme.LeResourceHelper.getResName(LeResourceHelper.java:193)
at android.content.res.Resources.loadDrawable(Resources.java:2624)
at android.content.res.Resources.getDrawable(Resources.java:862)
at android.content.Context.getDrawable(Context.java:458)
at android.widget.ImageView.resolveUri(ImageView.java:813)
这个时候可以看看应用逻辑是否会存在繁忙操作不停抢占时间片，另一方面可以看看对应日志，通过logcat发现如下信息，
11-17 09:49:41.392 1532 1574 E ActivityManager: ANR in com.android.systemui
11-17 09:49:41.392 1532 1574 E ActivityManager: PID: 21916
11-17 09:49:41.392 1532 1574 E ActivityManager: Reason: Broadcast of Intent { act=android.intent.action.TIME_TICK flg=0x50000014 mCallingUid=1000 (has extras) }
11-17 09:49:41.392 1532 1574 E ActivityManager: Load: 22.72 / 20.06 / 15.54 /分别对应1分钟/5分钟/15分钟/
11-17 09:49:41.392 1532 1574 E ActivityManager: CPU usage from 3ms to 24033ms later:
11-17 09:49:41.392 1532 1574 E ActivityManager: 60% 134/kswapd0: 0% user + 60% kernel
11-17 09:49:41.392 1532 1574 E ActivityManager: 32% 1532/system_server: 7.4% user + 25% kernel / faults: 31214 minor 423 major
系统整体负载很重，常规下负载在10左右；另外发现kswapdCPU占用率极高，通过这两项可以得到系统内存偏低，不停kill进程并发生内存交换，是不是这样的呢？我们再搜索一下其它关键字Slow operation：
11-17 09:42:25.292 1532 1572 W ActivityManager: Slow operation: 2440ms so far, now at startProcess: returned from zygote!
11-17 09:42:25.357 1532 1572 W ActivityManager: Slow operation: 2505ms so far, now at startProcess: done updating battery stats
11-17 09:42:25.357 1532 1572 I am_proc_start: [0,30188,10088,com.letv.android.usagestats,service,com.letv.android.usagestats/.UsageStatsReportService]
11-17 09:42:25.357 1532 1572 W ActivityManager: Slow operation: 2505ms so far, now at startProcess: building log message
11-17 09:42:25.357 1532 1572 I ActivityManager: Start proc 30188:com.letv.android.usagestats/u0a88 for service com.letv.android.usagestats/.UsageStatsReportService
11-17 09:42:25.357 1532 1572 W ActivityManager: Slow operation: 2505ms so far, now at startProcess: starting to update pids map
11-17 09:42:25.357 1532 1572 W ActivityManager: Slow operation: 2505ms so far, now at startProcess: done updating pids map
11-17 09:42:25.385 1532 1572 W ActivityManager: Slow operation: 2534ms so far, now at startProcess: done starting proc!
发现普通系统函数执行一次就耗费了2S以上，足见系统卡顿。现在我们继续延着内存方向确认，看看meminfo日志吧
Total PSS by process:
3441530 kB: com.android.mms (pid 2518 / activities)
229272 kB: mediaserver (pid 763)
通过PSS发现，SMS进程内存占用超过3G！对，第一反应就是内存泄漏，普通应用甚至系统内存占用根本不可能达到这么多。如果大家有时间可以看看kernel日志，搜索lowmemoryKiller，发生问题时间内一定有大量的进程被kill.
综上，对于这个问题得出结论，应用在Native层发生内存泄漏(不要问我为什么不是Java层发生这么多内存泄漏@@)。导致系统整体内存吃紧，又因为其本身Persist属性，具有很高优先级（-12），LMK不会将其Kill.只能不停Kill其它应用，并进程内存交换，类似问题参见XIIIM-8358
实例四：Binder资源耗尽，导致通信请求难以及时响应，示例：
该类问题和内存过低相似，查看主线程堆栈基本正常
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 obj=0x76261710 self=0x7f82646a00
| sysTid=3084 nice=0 cgrp=default sched=0/0 handle=0x7f874adfe8
| state=S schedstat=( 83808100322 29188718104 264083 ) utm=5716 stm=2664 core=1 HZ=100
| stack=0x7ff0f87000-0x7ff0f89000 stackSize=8MB
| held mutexes=
kernel: (couldn't read /proc/self/task/3084/stack)
native: #00 pc 00000000000682e4 /system/lib64/libc.so (__epoll_pwait+8)
native: #01 pc 000000000001f3a4 /system/lib64/libc.so (epoll_pwait+32)
native: #02 pc 000000000001be88 /system/lib64/libutils.so (_ZN7android6Looper9pollInnerEi+144)
native: #03 pc 000000000001c268 /system/lib64/libutils.so (_ZN7android6Looper8pollOnceEiPiS1_PPv+80)
native: #04 pc 00000000000d3088 /system/lib64/libandroid_runtime.so (_ZN7android18NativeMessageQueue8pollOnceEP7_JNIEnvP8_jobjecti+48)
native: #05 pc 000000000000554c /system/framework/arm64/boot.oat (Java_android_os_MessageQueue_nativePollOnce__JI+144)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:324)
at android.os.Looper.loop(Looper.java:135)
当处于这种状态时，我们直奔主题，分析log日志，按照logcat, kernel, cpuinfo, meminfo等依次分析：
11-08 23:51:44.088 1514 1554 E ActivityManager: ANR in com.android.phone
11-08 23:51:44.088 1514 1554 E ActivityManager: PID: 3084
11-08 23:51:44.088 1514 1554 E ActivityManager: Reason: Broadcast of Intent { act=com.android.internal.telephony.data-restart-trysetup.default flg=0x10000014 mCallingUid=1001 (has extras) }
11-08 23:51:44.088 1514 1554 E ActivityManager: Load: 9.92 / 9.81 / 10.02
11-08 23:51:44.088 1514 1554 E ActivityManager: CPU usage from 0ms to 6497ms later:
11-08 23:51:44.088 1514 1554 E ActivityManager: 108% 3084/com.android.phone: 101% user + 6.7% kernel / faults: 12120 minor 179 major
11-08 23:51:44.088 1514 1554 E ActivityManager: 66% 1514/system_server: 16% user + 49% kernel / faults: 20836 minor 88 major
11-08 23:51:44.088 1514 1554 E ActivityManager: 13% 13013/ca.bellmedia.cp24: 5.3% user + 8.4% kernel / faults: 3216 minor 39 major
通过上面的log日志，发现发生ANR进程本身CPU占用比较高，再搜索"slow operation"，“low_memory” 等关键字，都没有出现在log日志中，而lowmemorykiller也以较合理的频率出现在dmesg日志中，所以基本排除是内存过低导致；所以下面延着CPU方向继续分析
log日志无法找到更多线索，同时思考既然主线程状态正常，那么高cpu一定是其它线程引起的，那就反馈trace继续分析，查看phone进程的其它线程发现，几乎所有binder线程都处于waiting状态，只有Binder_2在工作：
"Binder_1" prio=5 tid=40 TimedWaiting
"Binder_3" prio=5 tid=40 TimedWaiting
"Binder_4" prio=5 tid=40 TimedWaiting
"Binder_5" prio=5 tid=39 TimedWaiting
"Binder_6" prio=5 tid=40 TimedWaiting
"Binder_7" prio=5 tid=40 TimedWaiting
"Binder_8" prio=5 tid=40 TimedWaiting
。。。。
"Binder_2" prio=5 tid=8 Native
| group="main" sCount=1 dsCount=0 obj=0x12c9b0a0 self=0x7f7be14400
| sysTid=3107 nice=0 cgrp=default sched=0/0 handle=0x7f8131d440
| state=R schedstat=( 515275891171 40426859698 234033 ) utm=49200 stm=2327 core=2 HZ=100
| stack=0x7f81221000-0x7f81223000 stackSize=1013KB
| held mutexes=
kernel: (couldn't read /proc/self/task/3107/stack)
native: #00 pc 0000000000070f20 /system/lib64/libsqlite.so (???)
native: #01 pc 000000000007420c /system/lib64/libsqlite.so (sqlite3_step+652)
native: #02 pc 00000000000ba4a4 /system/lib64/libandroid_runtime.so (???)
native: #03 pc 00000000000ba514 /system/lib64/libandroid_runtime.so (???)
native: #04 pc 00000000003bc578 /system/framework/arm64/boot.oat (Java_android_database_sqlite_SQLiteConnection_nativeExecuteForChangedRowCount__JJ+140)
at android.database.sqlite.SQLiteConnection.nativeExecuteForChangedRowCount(Native method)
at android.database.sqlite.SQLiteConnection.executeForChangedRowCount(SQLiteConnection.java:732)
at android.database.sqlite.SQLiteSession.executeForChangedRowCount(SQLiteSession.java:754)
at android.database.sqlite.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:64)
at android.database.sqlite.SQLiteDatabase.delete(SQLiteDatabase.java:1499)
at com.android.providers.telephony.SmsProvider.delete(SmsProvider.java:899)
at android.content.ContentProvider$Transport.delete(ContentProvider.java:339)
at android.content.ContentProviderNative.onTransact(ContentProviderNative.java:206)
at android.os.Binder.execTransact(Binder.java:453)
进一步分析该线程状态：state=R 说明其处于工作态。通过查看线程堆栈逻辑，发现正常情况下有log打印，借此再次返回到log日志，发现如下信息：
11-08 23:51:14.512 3084 3289 W SQLiteConnectionPool: The connection pool for database '/data/user/0/com.android.providers.telephony/databases/mmssms.db' has been unable to grant a connection to thread 111 (Binder_3) with flags 0x1 for 30.000002 seconds.
11-08 23:51:14.512 3084 3289 W SQLiteConnectionPool: Connections: 1 active, 0 idle, 0 available.
11-08 23:51:14.512 3084 3289 W SQLiteConnectionPool:
11-08 23:51:14.512 3084 3289 W SQLiteConnectionPool: Requests in progress:
11-08 23:51:14.512 3084 3289 W SQLiteConnectionPool: executeForChangedRowCount started 30008ms ago - running, sql="DELETE FROM sms WHERE (thread_id=2) AND (locked=0 AND date<1452658564000)"
11-08 23:51:14.513 3084 3613 W SQLiteConnectionPool: The connection pool for database '/data/user/0/com.android.providers.telephony/databases/mmssms.db' has been unable to grant a connection to thread 141 (Binder_5) with flags 0x1 for 30.009 seconds.
11-08 23:51:14.513 3084 3613 W SQLiteConnectionPool: Connections: 1 active, 0 idle, 0 available.
说明在Binder_3和Binder_6线程执行Sql之前，已经有其它线程执行时间超过30S仍未结束。继续搜集log发现，有15个Binder线程处于Waiting状态，而那个正在执行的则为Binder-2，耗时30S以上。
综上了该进程高CPU的原因：Binder_2线程执行Sql操作时间过长，进一步引起其它所有Binder线程被block，导致系统广播发送无法及时通过Binder传递给主线程，误触发系统认为Phone进程处理广播超时。
实例五：高CPU过度抢占时间片，导致其它应用或任务难以及时调度，示例：
该类问题主线程多半是处于空闲或Suspend状态，后者表示系统分配的CPU时间片无法满足当前需要便被强行切换，而引起该类现象的要么是底层系统动作，要么是其它任务高优先级任务抢占CPU行为；
"main" prio=5 tid=1 Suspended
| group="main" sCount=2 dsCount=0 obj=0x75285af8 self=0x7f87a46a00
| sysTid=9251 nice=-6 cgrp=default sched=0/0 handle=0x7f8c5f7fe8
| state=S schedstat=( 50580737351 8433337317 81975 ) utm=4561 stm=497 core=1 HZ=100
| stack=0x7ff8105000-0x7ff8107000 stackSize=8MB
| held mutexes=
at java.util.Arrays.checkOffsetAndCount(Arrays.java:1722)
at java.nio.CharBuffer.wrap(CharBuffer.java:90)
at java.nio.CharBuffer.wrap(CharBuffer.java:68)
at android.text.TextDirectionHeuristics$TextDirectionHeuristicImpl.isRtl(TextDirectionHeuristics.java:149)
at android.text.BoringLayout.isBoring(BoringLayout.java:477)
at android.widget.TextView.onMeasure(TextView.java:7096)
at android.view.View.measure(View.java:19138)
at android.view.ViewGroup.measureChildWithMargins(ViewGroup.java:6064)
at android.widget.LinearLayout.measureChildBeforeLayout(LinearLayout.java:1465)
at android.widget.LinearLayout.measureHorizontal(LinearLayout.java:1112)
at android.widget.LinearLayout.onMeasure(LinearLayout.java:632)
at android.view.View.measure(View.java:19138)
当Trace上无法继续分析时，便需要分析日志了，搜索关键字“anr in”，发现
11-26 11:47:16.514 1457 1490 E ActivityManager: ANR in com.android.browser (com.android.browser/.MainActivity)
11-26 11:47:16.514 1457 1490 E ActivityManager: PID: 9251
11-26 11:47:16.514 1457 1490 E ActivityManager: 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: 10. Wait queue head age: 8974.9ms.)
11-26 11:47:16.514 1457 1490 E ActivityManager: Load: 10.97 / 10.71 / 10.0
11-26 11:47:16.514 1457 1490 E ActivityManager: CPU usage from 0ms to 10480ms later:
11-26 11:47:16.514 1457 1490 E ActivityManager: 114% 9251/com.android.browser: 65% user + 48% kernel / faults: 10870 minor 11 major
11-26 11:47:16.514 1457 1490 E ActivityManager: 108% 1457/system_server: 33% user + 74% kernel / faults: 9584 minor 11 major
浏览器自身CPU占用较高，至于System_server占用比较多，尤其是当大家看到“ CPU usage from 0ms to 10480ms later”已经kernel部分（74% kernel /）占用较多的情况下，不要再轻易怀疑是system_server高CPU导致，其高CPU的真正原因是需要dump各进程信息而已。
顺着"ANR in"之前的日志，我们继续向上看，发现该应该进行了大量且频繁的GC操作
11-26 11:47:05.204 1457 1467 I art : Background partial concurrent mark sweep GC freed 842(578KB) AllocSpace objects, 455(85MB) LOS objects, 8% free, 169MB/185MB, paused 2.140ms total 245.072ms
11-26 11:47:10.493 9251 31938 W art : Suspending all threads took: 131.446ms
11-26 11:47:10.598 9251 31938 W art : Suspending all threads took: 88.134ms
11-26 11:47:10.699 9251 31938 W art : Suspending all threads took: 93.939ms
11-26 11:47:10.795 9251 31938 W art : Suspending all threads took: 75.051ms
11-26 11:47:10.821 9251 31938 W art : Suspending all threads took: 14.536ms
11-26 11:47:10.956 9251 31938 W art : Suspending all threads took: 114.243ms
11-26 11:47:11.101 9251 31938 W art : Suspending all threads took: 121.775ms
11-26 11:47:11.254 9251 31938 W art : Suspending all threads took: 93.763ms
.....
而根据GC类型（Background partial concurrent）来看，应该是有任务在不停的申请和使用大量内存，带着这样的想法，需要再此返回到Trace日志，分析相关线程状态，在大量的对比分析筛选之后，很幸运的发现了如下线程（该线程只有采集TraceView才会出现），并且处于R状态。对TraceView了解的同事都知道，该任务会引起关联进程非常大CPU消耗，并且异常卡顿（主线程得不到及时响应）。
"Sampling Profiler" daemon prio=9 tid=162 Native
| group="system" sCount=1 dsCount=0 obj=0x13102220 self=0x7f5a82f800
| sysTid=31938 nice=-6 cgrp=default sched=0/0 handle=0x7f643ff440
| state=R schedstat=( 22112458218 4449717737 10001 ) utm=2021 stm=190 core=0 HZ=100
综上找到了该进程高CPU的原因：采集TraceView线程需要申请大量内存不断触发进程内部GC，并且自身任务属于高耗时操作，从未导致主线程得不到及时调度和响应，触发ANR。
实例六：日志不全，缺少Trace或其它日志，示例：
遇到这类问题是比较郁闷的，这个时候智能拿现有的信息进行分析，尝试找出问题或改进方向，例如缺少Trace.但是其它日志相对齐全
例如在event日志中找到了应用ANR的大概时间点：10-14 00:40:26.010650
10-14 00:40:26.010650 1132 1172 I am_anr : [0,19746,android.process.media,952680005,Broadcast of Intent { act=android.intent.action.MEDIA_SCANNER_SCAN_FILE dat=file:///sdcard/AutoSmoke_UI30/testSwitchLetvView_20161014_003533/1476376700108.png 在flg=0x10 cmp=com.android.providers.media/.MediaScannerReceiver }]
在sys_log中发现ANR时进程CPU信息
10-14 00:40:57.052274 1132 1172 E ANRManager: ANR in android.process.media, time=304722739
10-14 00:40:57.052274 1132 1172 E ANRManager: Reason: Broadcast of Intent { act=android.intent.action.MEDIA_SCANNER_SCAN_FILE dat=file:///sdcard/AutoSmoke_UI30/testSwitchLetvView_20161014_003533/1476376700108.png flg=0x10 cmp=com.android.providers.media/.MediaScannerReceiver }
10-14 00:40:57.052274 1132 1172 E ANRManager: Load: 37.88 / 25.54 / 20.22
10-14 00:40:57.052274 1132 1172 E ANRManager: Android time :[2016-10-14 00:40:56.95] [304754.500]
10-14 00:40:57.052274 1132 1172 E ANRManager: CPU usage from 17448ms to 0ms ago:
10-14 00:40:57.052274 1132 1172 E ANRManager: 117% 19252/com.letv.android.letvlive: 80% user + 36% kernel / faults: 684 minor
10-14 00:40:57.052274 1132 1172 E ANRManager: 110% 11620/mediaserver: 64% user + 45% kernel / faults: 23 minor
10-14 00:40:57.052274 1132 1172 E ANRManager: 41% 378/logd: 19% user + 21% kernel / faults: 17 minor
10-14 00:40:57.052274 1132 1172 E ANRManager: 22% 573/mobile_log_d: 17% user + 5.3% kernel / faults: 1123 minor
10-14 00:40:57.052274 1132 1172 E ANRManager: 18% 19286/com.letv.android.letvlive:cde: 11% user + 6.9% kernel / faults: 6029 minor
10-14 00:40:57.052274 1132 1172 E ANRManager: 18% 422/adbd: 2.1% user + 15% kernel / faults: 1722 minor
10-14 00:40:57.052274 1132 1172 E ANRManager: 17% 18392/logcat: 7.4% user + 10% kernel
从上面日志可以看到有两个进程CPU占用率偏高，且系统长时间CPU负载很重（Load: 37.88 / 25.54 / 20.22），尤其是ANR之前1分钟的负载达到37；由此我们可以大概率的猜测这次ANR事故是由CPU过高导致其它任务调度不及时导致，到底是不是呢？还是如其他同事认为的内存原因引起呢？下面我们继续看对应时间点的Kernel日志，关键字”lowmemorykiller“，得到如下信息：
<6>[302600.931727] (4)[10628:Cam@AuxSensorCo]lowmemorykiller: Killing 'android.browser' (28649), adj 18, score_adj 1000,
<6>[302600.931727] to free 72464kB on behalf of 'Cam@AuxSensorCo' (10628) because
<6>[302600.931727] cache 1000628kB is below limit 322560kB for oom_score_adj 0
<6>[302600.931727] Free memory is 235708kB above reserved
<6>[303901.663086] (6)[16560:Cam@AuxSensorCo]lowmemorykiller: Killing 'roid.emojistore' (15854), adj 18, score_adj 1000,
<6>[303901.663086] to free 75636kB on behalf of 'Cam@AuxSensorCo' (16560) because
<6>[303901.663086] cache 1292884kB is below limit 322560kB for oom_score_adj 0
<6>[303901.663086] Free memory is 285336kB above reserved
<6>[302623.705248] (2)[10970:Cam@AuxSensorCo]lowmemorykiller: Killing 'ews:pushservice' (6186), adj 13, score_adj 764,
<6>[302623.705248] to free 62140kB on behalf of 'Cam@AuxSensorCo' (10970) because
<6>[302623.705248] cache 992668kB is below limit 322560kB for oom_score_adj 0
<6>[302623.705248] Free memory is 81320kB above reserved
cache项 ：为kernel端的文件缓存cache，为了提高IO访问速度，底层系统会有选择的缓存一些文件；
limit： 内存（文件缓存）的最低内存限制322560kB，当内存和文件缓存同时低于这个阀值，LMK变开始寻找低优先级进程查杀。
score_adj：从上层设置到kernel经过转换后的进程优先级，adj--> score_adj; score_adj为1000，则说明被查杀的进程优先级很低。
Free memory：当前空闲物理内存。
[302623.705248]：Kernel开机时间戳
通过以上日志分析可以得出结论：系统可用内存（Free+Cache）整体维持在1G左右，属于良好。查杀进程间隔时间较长，不会对系统负载带来太多开销。
分析完以上日志，基本排除了内存问题引起的ANR，接下来再回到log日志，分析ANR高CPU进程的相关日志，看看能否有进一步挖掘。在log日志中，高亮进程PID(11620)，结果发现在很长一段时间内存，该进程有几十万的日志输出，此时心里或许有了希望，这么频繁的输出，且含有很多相同日志，那就说明该进程产生了大量循环，而大量循环也是高CPU的常见起因。
10-14 00:40:46.035707 11620 19687 D MtkOmxVdecEx: [0xe1eb7800] RemoveInputBuf frm=0xe1eb8d70, omx=0xa3b9dfe0, i=5
10-14 00:40:46.035791 11620 19687 D MtkOmxVdecEx: [0xe1eb7800] FB in (0xA3B9DFE0)
10-14 00:40:46.036599 11620 11620 D MtkOmxMVAMgr: [0xb3cca9f0] [ION][FreeBuffer] entry=0xa3bcf3c0, va=0xd30d7000, pa=0x47600000,size=0x180000, srcFd=0xFFFFFFFF, fd=0xFFFFFFFF, bufHdr=0xA3B9CAE0
10-14 00:40:46.037036 11620 11620 D MtkOmxVdecEx: [0xe1eb7800] RemoveInputBuf frm=0xe1eb8d28, omx=0xa3b9cae0, i=4
10-14 00:40:46.037125 11620 11620 D MtkOmxVdecEx: [0xe1eb7800] FB in (0xA3B9CAE0)
10-14 00:40:46.037907 11620 11655 D MtkOmxMVAMgr: [0xb3cca9f0] [ION][FreeBuffer] entry=0xabbfc4e0, va=0xd3557000, pa=0x47000000,size=0x180000, srcFd=0xFFFFFFFF, fd=0xFFFFFFFF, bufHdr=0xA3B9C0C0
10-14 00:40:46.038281 11620 11655 D MtkOmxVdecEx: [0xe1eb7800] RemoveInputBuf frm=0xe1eb8ce0, omx=0xa3b9c0c0, i=3
10-14 00:40:46.038364 11620 11655 D MtkOmxVdecEx: [0xe1eb7800] FB in (0xA3B9C0C0)
10-14 00:40:46.039097 11620 11657 D MtkOmxMVAMgr: [0xb3cca9f0] [ION][FreeBuffer] entry=0xa3bcf240, va=0xd3f80000, pa=0x46c00000,size=0x180000, srcFd=0xFFFFFFFF, fd=0xFFFFFFFF, bufHdr=0xA3B9C120
10-14 00:40:46.039734 11620 11657 D MtkOmxVdecEx: [0xe1eb7800] RemoveInputBuf frm=0xe1eb8c98, omx=0xa3b9c120, i=2
10-14 00:40:46.039829 11620 11657 D MtkOmxVdecEx: [0xe1eb7800] FB in (0xA3B9C120)
10-14 00:40:46.041510 11620 11653 D MtkOmxMVAMgr: [0xb3cca9f0] [ION][FreeBuffer] entry=0xa3bcf6f0, va=0xdb528000, pa=0x46600000,size=0x180000, srcFd=0xFFFFFFFF, fd=0xFFFFFFFF, bufHdr=0xA3B9DF20
10-14 00:40:46.041966 11620 11653 D MtkOmxVdecEx: [0xe1eb7800] RemoveInputBuf frm=0xe1eb8c50, omx=0xa3b9df20, i=1
10-14 00:40:46.042057 11620 11653 D MtkOmxVdecEx: [0xe1eb7800] FB in (0xA3B9DF20)
10-14 00:40:46.043345 11620 11654 D MtkOmxMVAMgr: [0xb3cca9f0] [ION][FreeBuffer] entry=0xa3bcf120, va=0xdb828000, pa=0x43200000,size=0x180000, srcFd=0xFFFFFFFF, fd=0xFFFFFFFF, bufHdr=0xABBC4420
10-14 00:40:46.043756 11620 11654 D MtkOmxVdecEx: [0xe1eb7800] RemoveInputBuf frm=0xe1eb8c08, omx=0xabbc4420, i=0
10-14 00:40:46.043841 11620 11654 D MtkOmxVdecEx: [0xe1eb7800] FB in (0xABBC4420)
10-14 00:40:46.044026 11620 11654 D MtkOmxVdecEx: [0xe1eb7800] MtkOmxVdec::FreeBuffer all input buffers have been freed!!! signal mInPortFreeDoneSem(1)
至此，导出进一步结论，应用发生ANR主要是上面两个进程高CPU引起调度不及时。至于进程高CPU的进一步原因，则需要相关模块Owner结合日志进一步分析，论证。
通过以上6类ANR实例剖析，可以看出，除了正常Receiver处理耗时操作引起的ANR之外，也会有其它因素引发此类问题，例如总体内存偏低导致交换（kswap），CPU过高导致调度不及时，Binder资源被耗尽无法及时通讯等等，发生此类问题线索较为隐晦，需要大家汇总多个日志反复对比；但是好在这类问题发生时，系统都有关键log日志输出，可以利用关键字多角度深入分析，综合对比，这类问题多数时候是可以得出有效结论，并给出优化(解决)方案；对应日志确实不足的，只能借助于测试帮忙复现，并提供更多有效日志了。除此之外，也需要对相关系统知识有更多了解，例如LMK, 进程调能，Binder通信机制。方能在分析，解决此类问题过程中，有更多的参考和衡量。Android ANR分析
2015-11-28 21:42:48 大雀儿飞飞 阅读数 29529更多
分类专栏： android
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
本文链接：https://blog.csdn.net/yxz329130952/article/details/50087731
前言
ANR即Application Not Responding，顾名思义就是应用程序无响应。在Android中，一般情况下，四大组件均是工作在主线程中的，Android中的Activity Manager和Window Manager会随时监控应用程序的响应情况，如果因为一些耗时操作（网络请求或者IO操作）造成主线程阻塞一定时间（例如造成5s内不能响应用户事件或者BroadcastReceiver的onReceive方法执行时间超过10s），那么系统就会显示ANR对话框提示用户对应的应用处于无响应状态。
虽然每个程序员都不想ANR发生在自己的头上，因此，你需要严格遵守Google提供的一系列建议（看这里），简单总结就是以下两点：
1. 不要让主线程干耗时的工作
2. 不要让其他线程阻塞主线程的执行
1
2
因此，要尽量保证主线程执行工作干净利落，一个消息循环执行时间最好不超过100ms到200ms，对于一些脏活累活可以交给AsyncTask、HandlerThread、IntentService或者另外起的新线程来完成，这样应用程序就能够及时响应用户的操作而不会给用户带来卡顿的感觉。
ANR分析
一般应用程序在发布之前最好对新增的功能通过Systrace+TraceView进行性能测试，这样能够及时发现程序当中的耗时操作，对于一些可能引起ANR的风险做到提前规避。如果你是一个完美主义者，你也可以使用StrictMode来发现并干掉在你主线程中存在的一些磁盘IO、网络操作或者数据库读写等耗时代码，但是我个人觉得要完全避免在主线程进行这些操作还是不太现实，即使做到了也可能会造成应用程序的代码结构比较糟糕。
即使程序员在自己的环境中对代码进过了一系列的性能测试，到用户手中还是有中招的风险，毕竟再高效率的代码还是要时间来执行，而且不同手机性能差距还是很明显。如果你不幸中招，那么可以采用以下的方法来进行简单的分析。
导出trace文件
如果ANR发生，对应的应用会收到SIGQUIT异常终止信号，dalvik虚拟机就会自动在/data/anr/目录下生成trace.txt文件，这个文件记录了在发生ANR时刻系统各个线程的执行状态，获取这个文件是不需要root权限的，因此首先需要做的就是通过adb pull命令将这个文件导出并等待分析。
trace文件格式解析
导出trace文件后，可以看到类似于如下的文件内容：
----- pid 901 at 2015-11-28 14:38:34 -----
Cmd line: system_server
JNI: CheckJNI is off; workarounds are off; pins=6; globals=2154 (plus 409 weak)
DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
"main" prio=5 tid=1 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x415a4e88 self=0x414c48d8
| sysTid=901 nice=-2 sched=0/0 cgrp=apps handle=1073926484
| state=S schedstat=( 303590361913 618664734427 651535 ) utm=19466 stm=10893 core=0
#00 pc 00021914 /system/lib/libc.so (epoll_wait+12)
#01 pc 0001065f /system/lib/libutils.so (android::Looper::pollInner(int)+98)
#02 pc 00010889 /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)
#03 pc 0006b771 /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
#04 pc 0002034c /system/lib/libdvm.so (dvmPlatformInvoke+112)
#05 pc 00050fcf /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
#06 pc 00000214 /dev/ashmem/dalvik-jit-code-cache (deleted)
at android.os.MessageQueue.nativePollOnce(Native Method)
at android.os.MessageQueue.next(MessageQueue.java:138)
at android.os.Looper.loop(Looper.java:196)
at com.android.server.ServerThread.initAndLoop(SystemServer.java:1174)
at com.android.server.SystemServer.main(SystemServer.java:1271)
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:878)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:694)
at dalvik.system.NativeStart.main(Native Method)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
首先需要了解这些参数表示的意义，我们挑其中关键的几个说明：
第一二行
----- pid 901 at 2015-11-28 14:38:34 -----
Cmd line: system_server
1
2
说明了发生ANR的进程id、时间和进程名称。
后面三行是线程的基本信息
JNI: CheckJNI is off; workarounds are off; pins=6; globals=2154 (plus 409 weak)
DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
1
2
3
4
其中tll、tsl、tscl、ghl、hwl、hwll分别对应：thread list lock, thread suspend lock, thread suspend count lock, gc heap lock, heap worker lock和heap worker list lock。
main prio=5 tid=1 NATIVE说明了线程名称、线程的优先级、线程锁id和线程状态。线程名称是启动线程的时候手动指明的，这里的main标识是主线程，是Android自动设定的一个线程名称，如果是自己手动创建的线程，一般会被命名成“Thread-xx”的格式，其中xx是线程id，它只增不减不会被复用；注意这其中的tid不是线程的id,它是一个在Java虚拟机中用来实现线程锁的变量，随着线程的增减，这个变量的值是可能被复用的；最后线程的状态还分为如下几种
状态 值 说明
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_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
特别说明一下MONITOR状态和SUSPEND状态，MONITOR状态一般是类的同步块或者同步方法造成的，SUSPENDED状态在debugger的时候会出现，可以用来区别是不是真的是用户正常操作跑出了ANR。
后面一行
| group="main" sCount=1 dsCount=0 obj=0x415a4e88 self=0x414c48d8
1
group是线程组名称。sCount是此线程被挂起的次数，dsCount是线程被调试器挂起的次数，当一个进程被调试后，sCount会重置为0，调试完毕后sCount会根据是否被正常挂起增长，但是dsCount不会被重置为0，所以dsCount也可以用来判断这个线程是否被调试过。obj表示这个线程的Java对象的地址，self表示这个线程本身的地址。
此后是线程的调度信息
sysTid=901 nice=-2 sched=0/0 cgrp=apps handle=1073926484
1
sysTid是Linux下的内核线程id，nice是线程的调度优先级，sched分别标志了线程的调度策略和优先级，cgrp是调度属组，handle是线程的处理函数地址。
然后是线程当前上下文信息
state=S schedstat=( 303590361913 618664734427 651535 ) utm=19466 stm=10893 core=0
1
state是调度状态；schedstat从 /proc/[pid]/task/[tid]/schedstat读出，三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度，有的android内核版本不支持这项信息，得到的三个值都是0；utm是线程用户态下使用的时间值(单位是jiffies）;stm是内核态下的调度时间值；core是最后执行这个线程的cpu核的序号。
最后就是这个线程的调用栈信息。
通过分析trace文件得到ANR信息
通过上面分析，可以看到trace文件的头部就包含了很多与该线程相关的信息，但是并不是每个信息我们都必须弄懂，排查ANR的时候只需要找到其中关键的几个信息即可。一般可以通过以下几个简单的方法来判断。
trace文件顶部的线程一般是ANR的元凶
这是一个简单的方法，但是大部分情况下都适用，可以通过这个方法来快速判断是否是自己的应用造成了本次ANR。说明以下，并不是trace文件包含的应用就一定是造成ANR的帮凶，应用出现在trace文件中，只能说明出现ANR的时候这个应用进程还活着，trace文件的顶部则是触发ANR的应用信息。因此，如果你的应用出现在了trace文件的顶部，那么很有可能是因为你的应用造成了ANR，否则是你的应用造成ANR的可能性不大，但是具体是不是还需要进一步分析。例如：
----- pid 1182 at 2015-11-26 01:53:34 -----
Cmd line: system_server
JNI: CheckJNI is off; workarounds are off; pins=5; globals=2982 (plus 135 weak)
DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
"main" prio=5 tid=1 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x420a0e58 self=0x4208f918
| sysTid=1182 nice=-2 sched=0/0 cgrp=apps handle=1074594132
| state=S schedstat=( 211672310629 149959255867 472114 ) utm=13047 stm=8120 core=1
#00 pc 000218b8 /system/lib/libc.so (epoll_wait+12)
...
at android.os.MessageQueue.nativePollOnce(Native Method)
at android.os.MessageQueue.next(MessageQueue.java:138)
at android.os.Looper.loop(Looper.java:123)
at com.android.server.ServerThread.initAndLoop(SystemServer.java:1213)
at com.android.server.SystemServer.main(SystemServer.java:1317)
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:793)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:609)
at dalvik.system.NativeStart.main(Native Method)
...
----- end 1182 -----
----- pid 18927 at 2015-11-26 01:53:34 -----
Cmd line: com.android.example
JNI: CheckJNI is off; workarounds are off; pins=0; globals=465 (plus 984 weak)
DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
"main" prio=5 tid=1 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x420a0e58 self=0x4208f918
| sysTid=18927 nice=-6 sched=0/0 cgrp=apps handle=1074594132
| state=S schedstat=( 7748840431407 1615931922290 9994018 ) utm=712375 stm=62509 core=1
#00 pc 00020704 /system/lib/libc.so (__ioctl+8)
#01 pc 0002cfa3 /system/lib/libc.so (ioctl+14)
#02 pc 0001d3ed /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
#03 pc 0001d8d7 /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+42)
#04 pc 0001dadf /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+118)
#05 pc 00019791 /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+30)
...
#23 pc 00000d80 /system/bin/app_process
at android.os.BinderProxy.transact(Native Method)
at android.app.IAlarmManager$Stub$Proxy.set(IAlarmManager.java:154)
at android.app.AlarmManager.setImpl(AlarmManager.java:369)
at android.app.AlarmManager.setRepeating(AlarmManager.java:258)
at android.os.Handler.handleCallback(Handler.java:733)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5072)
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:793)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:609)
at dalvik.system.NativeStart.main(Native Method)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
虽然应用com.android.example出现在了trace文件中，但是在ANR的时候它在通过IPCThread在进行进程间通信，而此次ANR发生于system_server获取用户事件的native方法里面，并不是我们的应用造成了ANR。又例如下面的trace文件顶部内容为：
----- pid 13406 at 2015-11-27 11:46:14 -----
Cmd line: com.android.example
JNI: CheckJNI is off; workarounds are off; pins=0; globals=536 (plus 102 weak)
DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
"main" prio=5 tid=1 SUSPENDED
| group="main" sCount=1 dsCount=0 obj=0x41795e58 self=0x416b58b0
| sysTid=13406 nice=-6 sched=0/0 cgrp=apps handle=1074557268
| state=S schedstat=( 2352435524847 736727917292 2633566 ) utm=213075 stm=22168 core=1
at java.lang.String.<init>(String.java:~261)
at java.util.zip.ZipEntry.<init>(ZipEntry.java:392)
at java.util.zip.ZipFile.readCentralDir(ZipFile.java:414)
at java.util.zip.ZipFile.<init>(ZipFile.java:151)
at java.util.zip.ZipFile.<init>(ZipFile.java:123)
at com.android.example.Utility.isValideFile(Utility.java:2700)
at com.android.example.Test.getPath(Test.java:243)
at com.android.example.Test$1.run(Test.java:531)
at android.os.Handler.handleCallback(Handler.java:733)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5050)
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:807)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:623)
at dalvik.system.NativeStart.main(Native Method)
...
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
这种情况说明ANR发生于com.android.example应用中，而且指明了ANR发生时代码的执行位置，这种情况十有八九就是我们应用程序的问题，之后就需要通过这个trace文件指明的路径来对代码进行排查。
注意死锁和等待
虽然说ANR一般情况是由于让主线程做了很多耗时的操作，但是死锁或者主线程等待也是ANR高发的原因，例如如下的trace:
----- pid 9436 at 2015-11-28 21:30:41 -----
Cmd line: com.example.yxz.myapplication
JNI: CheckJNI is off; workarounds are off; pins=0; globals=277
DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
"main" prio=5 tid=1 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x415a4e88 self=0x414c48d8
| sysTid=9436 nice=0 sched=0/0 cgrp=apps handle=1073926484
| state=S schedstat=( 671264662 337280259 1005 ) utm=53 stm=14 core=0
at com.example.yxz.myapplication.performancetest.WaitANR$InnerMonitorClass.TimeConsumeFunc(WaitANR.java:~48)
- waiting to lock <0x447a5670> held by tid=11 (Thread-14208)
at com.example.yxz.myapplication.performancetest.WaitANR$2.run(WaitANR.java:32)
at android.os.Handler.handleCallback(Handler.java:733)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:212)
at android.app.ActivityThread.main(ActivityThread.java:5135)
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:878)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:694)
at dalvik.system.NativeStart.main(Native Method)
....
"Thread-14208" prio=10 tid=11 TIMED_WAIT
| group="main" sCount=1 dsCount=0 obj=0x447a4b98 self=0x78296bb8
| sysTid=9955 nice=-8 sched=0/0 cgrp=apps handle=2015978016
| state=S schedstat=( 946045 640869 1 ) utm=0 stm=0 core=2
at java.lang.VMThread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:1013)
at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:331)
at com.example.yxz.myapplication.performancetest.WaitANR$InnerMonitorClass.TimeConsumeFunc(WaitANR.java:48)
at com.example.yxz.myapplication.performancetest.WaitANR$1.run(WaitANR.java:20)
at java.lang.Thread.run(Thread.java:841)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
从trace文件可以看出，发生ANR的主线程正处于monitor状态，也就是它在等待一个synchronized块或者方法，但是目前这个monitor正在被tid=11的线程持有，所以造成了主线程被阻塞，从而发生了ANR。死锁的分析也是类似，发生死锁的线程一般处于MONITOR状态或者WAIT状态，等待其他进程的锁或者monitor，而其他进程又在等待另外线程的锁或者monitor，一直这样依赖下去，直到形成一个环。
结束
以上都是自己总结，欢迎提出意见和拍砖！
参考：
Android 信号处理面面观 之 trace 文件含义
How to read Dalvik SIGNQUIT output如何分析解决Android ANR
2012-12-07 16:44:02 Dartagnan 阅读数 85089更多
分类专栏： Android
来自：
http://blog.csdn.net/tjy1985/article/details/6777346
http://blog.csdn.net/tjy1985/article/details/6777355
http://blog.csdn.net/tjy1985/article/details/6777983
http://www.eoeandroid.com/forum.php?mod=viewthread&tid=165974
=================================================================
一：什么是ANR
ANR:Application Not Responding，即应用无响应
二：ANR的类型
ANR一般有三种类型：
1：KeyDispatchTimeout(5 seconds) --主要类型
按键或触摸事件在特定时间内无响应
2：BroadcastTimeout(10 seconds)
BroadcastReceiver在特定时间内无法处理完成
3：ServiceTimeout(20 seconds) --小概率类型
Service在特定的时间内无法处理完成
三：KeyDispatchTimeout
Akey or touch event was not dispatched within the specified time（按键或触摸事件在特定时间内无响应）
具体的超时时间的定义在framework下的
ActivityManagerService.java
//How long we wait until we timeout on key dispatching.
staticfinal int KEY_DISPATCHING_TIMEOUT = 5*1000
四：为什么会超时呢？
超时时间的计数一般是从按键分发给app开始。超时的原因一般有两种：
(1)当前的事件没有机会得到处理（即UI线程正在处理前一个事件，没有及时的完成或者looper被某种原因阻塞住了）
(2)当前的事件正在处理，但没有及时完成
五：如何避免KeyDispatchTimeout
1：UI线程尽量只做跟UI相关的工作
2：耗时的工作（比如数据库操作，I/O，连接网络或者别的有可能阻碍UI线程的操作）把它放入单独的线程处理
3：尽量用Handler来处理UIthread和别的thread之间的交互
六：UI线程
说了那么多的UI线程，那么哪些属于UI线程呢？
UI线程主要包括如下：
Activity:onCreate(), onResume(), onDestroy(), onKeyDown(), onClick(),etc
AsyncTask: onPreExecute(), onProgressUpdate(), onPostExecute(), onCancel,etc
Mainthread handler: handleMessage(), post*(runnable r), etc
other
七:如何去分析ANR
先看个LOG:
04-01 13:12:11.572 I/InputDispatcher( 220): Application is not responding:Window{2b263310com.android.email/com.android.email.activity.SplitScreenActivitypaused=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-01 13:12:14.123 I/dalvikvm(21404):threadid=4: reacting to signal 3
……
04-0113:12:15.872 E/ActivityManager( 220): ANR in com.android.email(com.android.email/.activity.SplitScreenActivity)
04-0113:12:15.872 E/ActivityManager( 220): Reason:keyDispatchingTimedOut
04-0113:12:15.872 E/ActivityManager( 220): Load: 8.68 / 8.37 / 8.53
04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 4361ms to 699ms ago ----CPU在ANR发生前的使用情况
04-0113:12:15.872 E/ActivityManager( 220): 5.5%21404/com.android.email: 1.3% user + 4.1% kernel / faults: 10 minor
04-0113:12:15.872 E/ActivityManager( 220): 4.3%220/system_server: 2.7% user + 1.5% kernel / faults: 11 minor 2 major
04-0113:12:15.872 E/ActivityManager( 220): 0.9%52/spi_qsd.0: 0% user + 0.9% kernel
04-0113:12:15.872 E/ActivityManager( 220): 0.5%65/irq/170-cyttsp-: 0% user + 0.5% kernel
04-0113:12:15.872 E/ActivityManager( 220): 0.5%296/com.android.systemui: 0.5% user + 0% kernel
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的使用量
04-0113:12:15.872 E/ActivityManager( 220): 25%21404/com.android.email: 25% user + 0% kernel / faults: 191 minor
04-0113:12:15.872 E/ActivityManager( 220): 16% 21603/__eas(par.hakan: 16% user + 0% kernel
04-0113:12:15.872 E/ActivityManager( 220): 7.2% 21406/GC: 7.2% user + 0% kernel
04-0113:12:15.872 E/ActivityManager( 220): 1.8% 21409/Compiler: 1.8% user + 0% kernel
04-0113:12:15.872 E/ActivityManager( 220): 5.5%220/system_server: 0% user + 5.5% kernel / faults: 1 minor
04-0113:12:15.872 E/ActivityManager( 220): 5.5% 263/InputDispatcher: 0% user + 5.5% kernel
04-0113:12:15.872 E/ActivityManager( 220): 32%TOTAL: 28% user + 3.7% kernel
从LOG可以看出ANR的类型，CPU的使用情况，如果CPU使用量接近100%，说明当前设备很忙，有可能是CPU饥饿导致了ANR
如果CPU使用量很少，说明主线程被BLOCK了
如果IOwait很高，说明ANR有可能是主线程在进行I/O操作造成的
除了看LOG，解决ANR还得需要trace.txt文件，
如何获取呢？可以用如下命令获取
$chmod 777 /data/anr
$rm /data/anr/traces.txt
$ps
$kill -3 PID
adbpull data/anr/traces.txt ./mytraces.txt
从trace.txt文件，看到最多的是如下的信息：
-----pid 21404 at 2011-04-01 13: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：首先分析log
2: 从trace.txt文件查看调用stack.
3: 看代码
4：仔细查看ANR的成因（iowait?block?memoryleak?）
十：案例
案例1：关键词:ContentResolver in AsyncTask onPostExecute, high iowait
Process:com.android.email
Activity:com.android.email/.activity.MessageView
Subject:keyDispatchingTimedOut
CPU usage from 2550ms to -2814ms ago:
5%187/system_server: 3.5% user + 1.4% kernel / faults: 86 minor 20major
4.4% 1134/com.android.email: 0.7% user + 3.7% kernel /faults: 38 minor 19 major
4% 372/com.android.eventstream: 0.7%user + 3.3% kernel / faults: 6 minor
1.1% 272/com.android.phone:0.9% user + 0.1% kernel / faults: 33 minor
0.9%252/com.android.systemui: 0.9% user + 0% kernel
0%409/com.android.eventstream.telephonyplugin: 0% user + 0% kernel /faults: 2 minor
0.1% 632/com.android.devicemonitor: 0.1% user + 0%kernel
100%TOTAL: 6.9% user + 8.2% kernel +84%iowait
-----pid 1134 at 2010-12-17 17:46:51 -----
Cmd line:com.android.email
DALVIK THREADS:
(mutexes: tll=0 tsl=0tscl=0 ghl=0 hwl=0 hwll=0)
"main" prio=5 tid=1 WAIT
|group="main" sCount=1 dsCount=0 obj=0x2aaca180self=0xcf20
| sysTid=1134 nice=0 sched=0/0 cgrp=[fopen-error:2]handle=1876218976
at java.lang.Object.wait(Native Method)
-waiting on <0x2aaca218> (a java.lang.VMThread)
atjava.lang.Thread.parkFor(Thread.java:1424)
atjava.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
atsun.misc.Unsafe.park(Unsafe.java:337)
atjava.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
atjava.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:808)
atjava.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:841)
atjava.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1171)
atjava.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:200)
atjava.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261)
atandroid.database.sqlite.SQLiteDatabase.lock(SQLiteDatabase.java:378)
atandroid.database.sqlite.SQLiteCursor.<init>(SQLiteCursor.java:222)
atandroid.database.sqlite.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:53)
atandroid.database.sqlite.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1356)
atandroid.database.sqlite.SQLiteDatabase.queryWithFactory(SQLiteDatabase.java:1235)
atandroid.database.sqlite.SQLiteDatabase.query(SQLiteDatabase.java:1189)
atandroid.database.sqlite.SQLiteDatabase.query(SQLiteDatabase.java:1271)
atcom.android.email.provider.EmailProvider.query(EmailProvider.java:1098)
atandroid.content.ContentProvider$Transport.query(ContentProvider.java:187)
atandroid.content.ContentResolver.query(ContentResolver.java:268)
atcom.android.email.provider.EmailContent$Message.restoreMessageWithId(EmailContent.java:648)
atcom.android.email.Controller.setMessageRead(Controller.java:658)
atcom.android.email.activity.MessageView.onMarkAsRead(MessageView.java:700)
atcom.android.email.activity.MessageView.access$2500(MessageView.java:98)
atcom.android.email.activity.MessageView$LoadBodyTask.onPostExecute(MessageView.java:1290)
atcom.android.email.activity.MessageView$LoadBodyTask.onPostExecute(MessageView.java:1255)
atandroid.os.AsyncTask.finish(AsyncTask.java:417)
atandroid.os.AsyncTask.access$300(AsyncTask.java:127)
atandroid.os.AsyncTask$InternalHandler.handleMessage(AsyncTask.java:429)
atandroid.os.Handler.dispatchMessage(Handler.java:99)
atandroid.os.Looper.loop(Looper.java:123)
atandroid.app.ActivityThread.main(ActivityThread.java:3652)
atjava.lang.reflect.Method.invokeNative(Native Method)
atjava.lang.reflect.Method.invoke(Method.java:507)
atcom.android.internal.os.ZygoteIn
原因：IOWait很高，说明当前系统在忙于I/O，因此数据库操作被阻塞
原来：
finalMessagemessage=Message.restoreMessageWithId(mProviderContext,messageId);
if(message==null){
return;
}
Accountaccount=Account.restoreAccountWithId(mProviderContext,message.mAccountKey);
if(account==null){
return;//isMessagingController returns false for null, but let's make itclear.
}
if(isMessagingController(account)){
newThread(){
@Override
publicvoidrun(){
mLegacyController.processPendingActions(message.mAccountKey);
}
}.start();
}
解决后：
newThread() {
finalMessagemessage=Message.restoreMessageWithId(mProviderContext,messageId);
if(message==null){
return;
}
Accountaccount=Account.restoreAccountWithId(mProviderContext,message.mAccountKey);
if(account==null){
return;//isMessagingController returns false for null, but let's make itclear.
}
if(isMessagingController(account)) {
mLegacyController.processPendingActions(message.mAccountKey);
}
}.start();
关于AsyncTask:http://developer.android.com/reference/android/os/AsyncTask.html
案例2：关键词:在UI线程进行网络数据的读写
ANRin process: com.android.mediascape:PhotoViewer (last incom.android.mediascape:PhotoViewer)
Annotation:keyDispatchingTimedOut
CPU usage:
Load: 6.74 / 6.89 / 6.12
CPUusage from 8254ms to 3224ms ago:
ovider.webmedia: 4% = 4% user +0% kernel / faults: 68 minor
system_server: 2% = 1% user + 0%kernel / faults: 18 minor
re-initialized>: 0% = 0% user + 0%kernel / faults: 50 minor
events/0: 0% = 0% user + 0%kernel
TOTAL:7% = 6% user + 1% kernel
DALVIKTHREADS:
""main"" prio=5 tid=3 NATIVE
|group=""main"" sCount=1 dsCount=0 s=Yobj=0x4001b240 self=0xbda8
| sysTid=2579 nice=0 sched=0/0cgrp=unknown handle=-1343993184
atorg.apache.harmony.luni.platform.OSNetworkSystem.receiveStreamImpl(NativeMethod)
atorg.apache.harmony.luni.platform.OSNetworkSystem.receiveStream(OSNetworkSystem.java:478)
atorg.apache.harmony.luni.net.PlainSocketImpl.read(PlainSocketImpl.java:565)
atorg.apache.harmony.luni.net.SocketInputStream.read(SocketInputStream.java:87)
atorg.apache.harmony.luni.internal.net.www.protocol.http.HttpURLConnection$LimitedInputStream.read(HttpURLConnection.java:303)
atjava.io.InputStream.read(InputStream.java:133)
atjava.io.BufferedInputStream.fillbuf(BufferedInputStream.java:157)
atjava.io.BufferedInputStream.read(BufferedInputStream.java:346)
atandroid.graphics.BitmapFactory.nativeDecodeStream(Native Method)
atandroid.graphics.BitmapFactory.decodeStream(BitmapFactory.java:459)
atcom.android.mediascape.activity.PhotoViewerActivity.getPreviewImage(PhotoViewerActivity.java:4465)
atcom.android.mediascape.activity.PhotoViewerActivity.dispPreview(PhotoViewerActivity.java:4406)
atcom.android.mediascape.activity.PhotoViewerActivity.access$6500(PhotoViewerActivity.java:125)
atcom.android.mediascape.activity.PhotoViewerActivity$33$1.run(PhotoViewerActivity.java:4558)
atandroid.os.Handler.handleCallback(Handler.java:587)
atandroid.os.Handler.dispatchMessage(Handler.java:92)
atandroid.os.Looper.loop(Looper.java:123)
atandroid.app.ActivityThread.main(ActivityThread.java:4370)
atjava.lang.reflect.Method.invokeNative(Native Method)
atjava.lang.reflect.Method.invoke(Method.java:521)
atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868)
atcom.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)
atdalvik.system.NativeStart.main(Native Method)
关于网络连接，再设计的时候可以设置个timeout的时间或者放入独立的线程来处理。
关于Handler的问题，可以参考：http://developer.android.com/reference/android/os/Handler.html
案例3：
关键词：Memoryleak/Thread leak
11-1621:41:42.560 I/ActivityManager( 1190): ANR in process:android.process.acore (last in android.process.acore)
11-1621:41:42.560 I/ActivityManager( 1190): Annotation:keyDispatchingTimedOut
11-16 21:41:42.560 I/ActivityManager(1190): CPU usage:
11-16 21:41:42.560 I/ActivityManager( 1190):Load: 11.5 / 11.1 / 11.09
11-16 21:41:42.560 I/ActivityManager(1190): CPU usage from 9046ms to 4018ms ago:
11-16 21:41:42.560I/ActivityManager( 1190): d.process.acore:98%= 97% user + 0% kernel / faults: 1134 minor
11-16 21:41:42.560I/ActivityManager( 1190): system_server: 0% = 0% user + 0% kernel /faults: 1 minor
11-16 21:41:42.560 I/ActivityManager( 1190): adbd:0% = 0% user + 0% kernel
11-16 21:41:42.560 I/ActivityManager(1190): logcat: 0% = 0% user + 0% kernel
11-16 21:41:42.560I/ActivityManager( 1190): TOTAL:100% = 98% user + 1% kernel
Cmdline: android.process.acore
DALVIK THREADS:
"main"prio=5 tid=3 VMWAIT
|group="main" sCount=1 dsCount=0 s=N obj=0x40026240self=0xbda8
| sysTid=1815 nice=0 sched=0/0 cgrp=unknownhandle=-1344001376
atdalvik.system.VMRuntime.trackExternalAllocation(NativeMethod)
atandroid.graphics.Bitmap.nativeCreate(Native Method)
atandroid.graphics.Bitmap.createBitmap(Bitmap.java:468)
atandroid.view.View.buildDrawingCache(View.java:6324)
atandroid.view.View.getDrawingCache(View.java:6178)
atandroid.view.ViewGroup.drawChild(ViewGroup.java:1541)
……
atcom.android.internal.policy.impl.PhoneWindow$DecorView.draw(PhoneWindow.java:1830)
atandroid.view.ViewRoot.draw(ViewRoot.java:1349)
atandroid.view.ViewRoot.performTraversals(ViewRoot.java:1114)
atandroid.view.ViewRoot.handleMessage(ViewRoot.java:1633)
atandroid.os.Handler.dispatchMessage(Handler.java:99)
atandroid.os.Looper.loop(Looper.java:123)
atandroid.app.ActivityThread.main(ActivityThread.java:4370)
atjava.lang.reflect.Method.invokeNative(Native Method)
atjava.lang.reflect.Method.invoke(Method.java:521)
atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868)
atcom.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)
atdalvik.system.NativeStart.main(Native Method)
"Thread-408"prio=5 tid=329 WAIT
|group="main" sCount=1 dsCount=0 s=N obj=0x46910d40self=0xcd0548
| sysTid=10602 nice=0 sched=0/0 cgrp=unknownhandle=15470792
at java.lang.Object.wait(Native Method)
-waiting on <0x468cd420> (a java.lang.Object)
atjava.lang.Object.wait(Object.java:288)
atcom.android.dialer.CallLogContentHelper$UiUpdaterExecutor$1.run(CallLogContentHelper.java:289)
atjava.lang.Thread.run(Thread.java:1096)
分析：
atdalvik.system.VMRuntime.trackExternalAllocation(NativeMethod)内存不足导致block在创建bitmap上
**MEMINFO in pid 1360 [android.process.acore] **
native dalvik other total
size: 17036 23111 N/A 40147
allocated: 16484 20675 N/A 37159
free: 296 2436 N/A 2732
解决：如果机器的内存族，可以修改虚拟机的内存为36M或更大，不过最好是复查代码，查看哪些内存没有释放
========================================================================================
http://www.eoeandroid.com/forum.php?mod=viewthread&tid=165974
Log的产生大家都知道 ， 大家也都知道通过DDMS来看log ， 但什么时候会产生log文件呢 ？一般在如下几种情况会产生log文件 。
1，程序异常退出 ， uncaused exception
2，程序强制关闭 ，Force Closed (简称FC)
3，程序无响应 ， Application No Response （简称ANR) ， 顺便，一般主线程超过5秒么有处理就会ANR
4，手动生成 。
拿到一个日志文件，要分成多段来看 。 log文件很长，其中包含十几个小单元信息，但不要被吓到 ，事实上他主要由三大块儿组成 。
1，系统基本信息 ，包括 内存，CPU ，进程队列 ，虚拟内存 ， 垃圾回收等信息 。------ MEMORY INFO (/proc/meminfo) ------
------ CPU INFO (top -n 1 -d 1 -m 30 -t) ------
------ PROCRANK (procrank) ------
------ VIRTUAL MEMORY STATS (/proc/vmstat) ------
------ VMALLOC INFO (/proc/vmallocinfo) ------
格式如下：
------ MEMORY INFO (/proc/meminfo) ------
MemTotal: 347076 kB
MemFree: 56408 kB
Buffers: 7192 kB
Cached: 104064 kB
SwapCached: 0 kB
Active: 192592 kB
Inactive: 40548 kB
Active(anon): 129040 kB
Inactive(anon): 1104 kB
Active(file): 63552 kB
Inactive(file): 39444 kB
Unevictable: 7112 kB
Mlocked: 0 kB
SwapTotal: 0 kB
SwapFree: 0 kB
Dirty: 44 kB
Writeback: 0 kB
AnonPages: 129028 kB
Mapped: 73728 kB
Shmem: 1148 kB
Slab: 13072 kB
SReclaimable: 4564 kB
SUnreclaim: 8508 kB
KernelStack: 3472 kB
PageTables: 12172 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
WritebackTmp: 0 kB
CommitLimit: 173536 kB
Committed_AS: 7394524 kB
VmallocTotal: 319488 kB
VmallocUsed: 90752 kB
VmallocChunk: 181252 kB
2，时间信息 ， 也是我们主要分析的信息 。
------ VMALLOC INFO (/proc/vmallocinfo) ------
------ EVENT INFO (/proc/vmallocinfo) ------
格式如下：
------ SYSTEM LOG (logcat -b system -v time -d *:v) ------
01-15 16:41:43.671 W/PackageManager( 2466): Unknown permission com.wsomacp.permission.PROVIDER in package com.android.mms
01-15 16:41:43.671 I/ActivityManager( 2466): Force stopping package com.android.mms uid=10092
01-15 16:41:43.675 I/UsageStats( 2466): Something wrong here, didn't expect com.sec.android.app.twlauncher to be paused
01-15 16:41:44.108 I/ActivityManager( 2466): Start proc com.sec.android.widgetapp.infoalarm for service com.sec.android.widgetapp.infoalarm/.engine.DataService: pid=20634 uid=10005 gids={3003, 1015, 3002}
01-15 16:41:44.175 W/ActivityManager( 2466): Activity pause timeout for HistoryRecord{48589868 com.sec.android.app.twlauncher/.Launcher}
01-15 16:41:50.864 I/KeyInputQueue( 2466): Input event
01-15 16:41:50.866 D/KeyInputQueue( 2466): screenCaptureKeyFlag setting 0
01-15 16:41:50.882 I/PowerManagerService( 2466): Ulight 0->7|0
01-15 16:41:50.882 I/PowerManagerService( 2466): Setting target 2: cur=0.0 target=70 delta=4.6666665 nominalCurrentValue=0
01-15 16:41:50.882 I/PowerManagerService( 2466): Scheduling light animator!
01-15 16:41:51.706 D/PowerManagerService( 2466): enableLightSensor true
01-15 16:41:51.929 I/KeyInputQueue( 2466): Input event
01-15 16:41:51.933 W/WindowManager( 2466): No focus window, dropping: KeyEvent{action=0 code=26 repeat=0 meta=0 scancode=26 mFlags=9}
3，虚拟机信息 ， 包括进程的，线程的跟踪信息，这是用来跟踪进程和线程具体点的好地方 。
------ VM TRACES JUST NOW (/data/anr/traces.txt.bugreport: 2011-01-15 16:49:02) ------
------ VM TRACES AT LAST ANR (/data/anr/traces.txt: 2011-01-15 16:49:02) ------
格式如下 ：
----- pid 21161 at 2011-01-15 16:49:01 -----
Cmd line: com.android.mms
DALVIK THREADS:
"main" prio=5 tid=1 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x4001d8d0 self=0xccc8
| sysTid=21161 nice=0 sched=0/0 cgrp=default handle=-1345017808
| schedstat=( 4151552996 5342265329 10995 )
at android.media.MediaPlayer._reset(Native Method)
at android.media.MediaPlayer.reset(MediaPlayer.java:1218)
at android.widget.VideoView.release(VideoView.java:499)
at android.widget.VideoView.access$2100(VideoView.java:50)
at android.widget.VideoView$6.surfaceDestroyed(VideoView.java:489)
at android.view.SurfaceView.reportSurfaceDestroyed(SurfaceView.java:572)
at android.view.SurfaceView.updateWindow(SurfaceView.java:476)
at android.view.SurfaceView.onWindowVisibilityChanged(SurfaceView.java:206)
at android.view.View.dispatchDetachedFromWindow(View.java:6082)
at android.view.ViewGroup.dispatchDetachedFromWindow(ViewGroup.java:1156)
at android.view.ViewGroup.removeAllViewsInLayout(ViewGroup.java:2296)
at android.view.ViewGroup.removeAllViews(ViewGroup.java:2254)
at com.android.mms.ui.SlideView.reset(SlideView.java:687)
at com.android.mms.ui.SlideshowPresenter.presentSlide(SlideshowPresenter.java:189)
at com.android.mms.ui.SlideshowPresenter$3.run(SlideshowPresenter.java:531)
at android.os.Handler.handleCallback(Handler.java:587)
at android.os.Handler.dispatchMessage(Handler.java:92)
at android.os.Looper.loop(Looper.java:123)
at android.app.ActivityThread.main(ActivityThread.java:4627)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:521)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:858)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
at dalvik.system.NativeStart.main(Native Method)
---------------------------------------------------------------------------------------------------------------------------------------
闲话少说， 我总结了观察log文件的基本步骤 。 1，如果是ANR问题 ， 则搜索“ANR”关键词 。 快速定位到关键事件信息 。
2，如果是ForceClosed 和其它异常退出信息，则搜索"Fatal" 关键词， 快速定位到关键事件信息 。
3，定位到关键事件信息后 ， 如果信息不够明确的，再去搜索应用程序包的虚拟机信息 ，查看具体的进程和线程跟踪的日志，来定位到代码 。
用这种方法，出现问题，根本不需要断点调试 ， 直接定位到问题，屡试不爽 。
下面，我们就开始来分析这个例子的log 。
打开log文件 ， 由于是ANR错误，因此搜索"ANR " ， 为何要加空格呢，你加上和去掉比较一下就知道了 。 可以屏蔽掉不少保存到anr.log文件的无效信息 。
定位到关键的事件信息如下：
01-15 16:49:02.433 E/ActivityManager( 2466): ANR in com.android.mms (com.android.mms/.ui.SlideshowActivity)
01-15 16:49:02.433 E/ActivityManager( 2466): Reason: keyDispatchingTimedOut
01-15 16:49:02.433 E/ActivityManager( 2466): Load: 0.6 / 0.61 / 0.42
01-15 16:49:02.433 E/ActivityManager( 2466): CPU usage from 1337225ms to 57ms ago:
01-15 16:49:02.433 E/ActivityManager( 2466): sensorserver_ya: 8% = 0% user + 8% kernel / faults: 40 minor
......
01-15 16:49:02.433 E/ActivityManager( 2466): -com.android.mms: 0% = 0% user + 0% kernel
01-15 16:49:02.433 E/ActivityManager( 2466): -flush-179:8: 0% = 0% user + 0% kernel
01-15 16:49:02.433 E/ActivityManager( 2466): TOTAL: 25% = 10% user + 14% kernel + 0% iowait + 0% irq + 0% softirq
01-15 16:49:02.436 I/ ( 2466): dumpmesg > "/data/log/dumpstate_app_anr.log"
我们用自然语言来描述一下日志，这也算是一种能力吧 。
01-15 16:49:02.433 E/ActivityManager( 2466): ANR in com.android.mms (com.android.mms/.ui.SlideshowActivity)
翻译：在16:49分2秒433毫秒的时候 ActivityManager （进程号为2466) 发生了如下错误：com.android.mms包下面的.ui.SlideshowActivity 无响应 。
01-15 16:49:02.433 E/ActivityManager( 2466): Reason: keyDispatchingTimedOut
翻译：原因 ， keyDispatchingTimeOut - 按键分配超时
01-15 16:49:02.433 E/ActivityManager( 2466): Load: 0.6 / 0.61 / 0.42
翻译：5分钟，10分钟，15分钟内的平均负载分别为：0.6 , 0.61 , 0.42
在这里我们大概知道问题是什么了，结合我们之前的操作流程，我们知道问题是在点击按钮某时候可能处理不过来按钮事件，导致超时无响应 。那么现在似乎已经可以进行工作了 。 我们知道Activity中是通过重载dispatchTouchEvent(MotionEvent ev)来处理点击屏幕事件 。 然后我们可以顺藤摸瓜，一点点分析去查找原因 。 但这样够了么 ？
其实不够 ， 至少我们不能准确的知道到底问题在哪儿 ， 只是猜测 ，比如这个应用程序中，我就在顺藤摸瓜的时候发现了多个IO操作的地方都在主线程中，可能引起问题，但不好判断到底是哪个 ，所以我们目前掌握的信息还不够 。
于是我们再分析虚拟机信息 ， 搜索“Dalvik Thread”关键词，快速定位到本应用程序的虚拟机信息日志，如下：
----- pid 2922 at 2011-01-13 13:51:07 -----
Cmd line: com.android.mms
DALVIK THREADS:
"main" prio=5 tid=1 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x4001d8d0 self=0xccc8
| sysTid=2922 nice=0 sched=0/0 cgrp=default handle=-1345017808
| schedstat=( 3497492306 15312897923 10358 )
at android.media.MediaPlayer._release(Native Method)
at android.media.MediaPlayer.release(MediaPlayer.java:1206)
at android.widget.VideoView.stopPlayback(VideoView.java:196)
at com.android.mms.ui.SlideView.stopVideo(SlideView.java:640)
at com.android.mms.ui.SlideshowPresenter.presentVideo(SlideshowPresenter.java:443)
at com.android.mms.ui.SlideshowPresenter.presentRegionMedia(SlideshowPresenter.java:219)
at com.android.mms.ui.SlideshowPresenter$4.run(SlideshowPresenter.java:516)
at android.os.Handler.handleCallback(Handler.java:587)
at android.os.Handler.dispatchMessage(Handler.java:92)
at android.os.Looper.loop(Looper.java:123)
at android.app.ActivityThread.main(ActivityThread.java:4627)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:521)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:858)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
at dalvik.system.NativeStart.main(Native Method)
"Binder Thread #3" prio=5 tid=11 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x4837f808 self=0x242280
| sysTid=3239 nice=0 sched=0/0 cgrp=default handle=2341032
| schedstat=( 32410506 932842514 164 )
at dalvik.system.NativeStart.run(Native Method)
"AsyncQueryWorker" prio=5 tid=9 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x482f4b80 self=0x253e10
| sysTid=3236 nice=0 sched=0/0 cgrp=default handle=2432120
| schedstat=( 3225061 26561350 27 )
at java.lang.Object.wait(Native Method)
- waiting on <0x482f4da8> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:110)
at android.os.HandlerThread.run(HandlerThread.java:60)
"Thread-9" prio=5 tid=8 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x4836e2b0 self=0x25af70
| sysTid=2929 nice=0 sched=0/0 cgrp=default handle=2370896
| schedstat=( 130248 4389035 2 )
at java.lang.Object.wait(Native Method)
- waiting on <0x4836e240> (a java.util.ArrayList)
at java.lang.Object.wait(Object.java:288)
at com.android.mms.data.Contact$ContactsCache$TaskStack$1.run(Contact.java:488)
at java.lang.Thread.run(Thread.java:1096)
"Binder Thread #2" prio=5 tid=7 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x482f8ca0 self=0x130fd0
| sysTid=2928 nice=0 sched=0/0 cgrp=default handle=1215968
| schedstat=( 40610049 1837703846 195 )
at dalvik.system.NativeStart.run(Native Method)
"Binder Thread #1" prio=5 tid=6 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x482f4a78 self=0x128a50
| sysTid=2927 nice=0 sched=0/0 cgrp=default handle=1201352
| schedstat=( 40928066 928867585 190 )
at dalvik.system.NativeStart.run(Native Method)
"Compiler" daemon prio=5 tid=5 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x482f1348 self=0x118960
| sysTid=2926 nice=0 sched=0/0 cgrp=default handle=1149216
| schedstat=( 753021350 3774113668 6686 )
at dalvik.system.NativeStart.run(Native Method)
"JDWP" daemon prio=5 tid=4 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x482f12a0 self=0x132940
| sysTid=2925 nice=0 sched=0/0 cgrp=default handle=1255680
| schedstat=( 2827103 29553323 19 )
at dalvik.system.NativeStart.run(Native Method)
"Signal Catcher" daemon prio=5 tid=3 RUNNABLE
| group="system" sCount=0 dsCount=0 s=N obj=0x482f11e8 self=0x135988
| sysTid=2924 nice=0 sched=0/0 cgrp=default handle=1173688
| schedstat=( 11793815 12456169 7 )
at dalvik.system.NativeStart.run(Native Method)
"HeapWorker" daemon prio=5 tid=2 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x45496028 self=0x135848
| sysTid=2923 nice=0 sched=0/0 cgrp=default handle=1222608
| schedstat=( 79049792 1520840200 95 )
at dalvik.system.NativeStart.run(Native Method)
----- end 2922 -----
每一段都是一个线程 ，当然我们还是看线程号为1的主线程了。通过分析发现关键问题是这样：
at com.android.mms.ui.SlideshowPresenter$3.run(SlideshowPresenter.java:531)
定位到代码：
mHandler.post(new Runnable() {
public void run() {
try {
presentRegionMedia(view, (RegionMediaModel) model, dataChanged);
} catch (OMADRMException e) {
Log.e(TAG, e.getMessage(), e);
Toast.makeText(mContext,
mContext.getString(R.string.insufficient_drm_rights),
Toast.LENGTH_SHORT).show();
} catch (IOException e){
Log.e(TAG, e.getMessage(), e);
Toast.makeText(mContext,
mContext.getString(R.string.insufficient_drm_rights),
Toast.LENGTH_SHORT).show();
}
}
很清楚了， Handler.post 方法之后执行时间太长的问题 。 继续看presentRegionMedia(view, (RegionMediaModel) model, dataChanged);方法 ， 发现最终是调用的framework 中MediaPlayer.stop方法 。
至此，我们的日志分析算是告一段落 。 可以开始思考解决办法了通过Android trace文件分析死锁ANR
2013-06-15 22:26:50 欧军礼 阅读数 49628更多
分类专栏： Android性能优化
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
本文链接：https://blog.csdn.net/oujunli/article/details/9102101
对于从事Android开发的人来说，遇到ANR(Application Not Responding)是比较常见的问题。一般情况下，如果有ANR发生，系统都会在/data/anr/目录下生成trace文件，通过分析trace文件，可以定位产生ANR的原因。产生ANR的原因有很多，比如CPU使用过高、事件没有得到及时的响应、死锁等，下面将通过一次因为死锁导致的ANR问题，来说明如何通过trace文件分析ANR问题。
对应的部分trace文件内容如下：
"PowerManagerService" prio=5 tid=24 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x41dd0eb0 self=0x5241b218
| sysTid=567 nice=0 sched=0/0 cgrp=apps handle=1380038664
| state=S schedstat=( 6682116007 11324451214 33313 ) utm=450 stm=219 core=1
at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:~13045)
- waiting to lock <0x41a874a0> (a com.android.server.am.ActivityManagerService) held by tid=12 (android.server.ServerThread)
at android.app.ContextImpl.sendBroadcast(ContextImpl.java:1144)
at com.android.server.power.PowerManagerService$DisplayBlankerImpl.unblankAllDisplays(PowerManagerService.java:3442)
at com.android.server.power.DisplayPowerState$PhotonicModulator$1.run(DisplayPowerState.java:456)
at android.os.Handler.handleCallback(Handler.java:800)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:194)
at android.os.HandlerThread.run(HandlerThread.java:60)
"Binder_B" prio=5 tid=85 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x42744770 self=0x58329e88
| sysTid=3700 nice=-20 sched=0/0 cgrp=apps handle=1471424616
| state=S schedstat=( 1663727513 2044643318 6806 ) utm=132 stm=34 core=1
at com.android.server.power.PowerManagerService$DisplayBlankerImpl.toString(PowerManagerService.java:~3449)
- waiting to lock <0x41a7e420> (a com.android.server.power.PowerManagerService$DisplayBlankerImpl) held by tid=24 (PowerManagerService)
at java.lang.StringBuilder.append(StringBuilder.java:202)
at com.android.server.power.PowerManagerService.dump(PowerManagerService.java:3052)
at android.os.Binder.dump(Binder.java:264)
at android.os.Binder.onTransact(Binder.java:236)
at android.os.IPowerManager$Stub.onTransact(IPowerManager.java:373)
at android.os.Binder.execTransact(Binder.java:351)
at dalvik.system.NativeStart.run(Native Method)
"android.server.ServerThread" prio=5 tid=12 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x41a76178 self=0x507837a8
| sysTid=545 nice=-2 sched=0/0 cgrp=apps handle=1349936616
| state=S schedstat=( 15368096286 21707846934 69485 ) utm=1226 stm=310 core=0
at com.android.server.power.PowerManagerService.isScreenOnInternal(PowerManagerService.java:~2529)
- waiting to lock <0x41a7e2e8> (a java.lang.Object) held by tid=85 (Binder_B)
at com.android.server.power.PowerManagerService.isScreenOn(PowerManagerService.java:2522)
at com.android.server.wm.WindowManagerService.sendScreenStatusToClientsLocked(WindowManagerService.java:7749)
at com.android.server.wm.WindowManagerService.setEventDispatching(WindowManagerService.java:7628)
at com.android.server.am.ActivityManagerService.updateEventDispatchingLocked(ActivityManagerService.java:8083)
at com.android.server.am.ActivityManagerService.wakingUp(ActivityManagerService.java:8077)
at com.android.server.power.Notifier.sendWakeUpBroadcast(Notifier.java:474)
at com.android.server.power.Notifier.sendNextBroadcast(Notifier.java:455)
at com.android.server.power.Notifier.access$700(Notifier.java:62)
at com.android.server.power.Notifier$NotifierHandler.handleMessage(Notifier.java:600)
at android.os.Handler.dispatchMessage(Handler.java:107)
at android.os.Looper.loop(Looper.java:194)
at com.android.server.ServerThread.run(SystemServer.java:1328)
从trace文件看，是因为TID为24的线程等待一个TID为12的线程持有的锁，TID为12的线程等待一个TID为85的线程持有的锁，而TID为85的线程确等待一个TID为24的线程持有的锁，导致了循环等待的现象，对应的trace文件的语句如下：
TID 24：- waiting to lock <0x41a874a0> (a com.android.server.am.ActivityManagerService) held by tid=12 (android.server.ServerThread)
TID 12： - waiting to lock <0x41a7e2e8> (a java.lang.Object) held by tid=85 (Binder_B)
TID 85：- waiting to lock <0x41a7e420> (a com.android.server.power.PowerManagerService$DisplayBlankerImpl) held by tid=24 (PowerManagerService)
既然是死锁，那么先看各线程都有那些锁。
先看TID=24的线程的栈顶，ActivityManagerService的broadcastIntent函数代码如下:
public final int broadcastIntent(IApplicationThread caller,
Intent intent, String resolvedType, IIntentReceiver resultTo,
int resultCode, String resultData, Bundle map,
String requiredPermission, boolean serialized, boolean sticky, int userId) {
enforceNotIsolatedCaller("broadcastIntent");
synchronized(this) {
intent = verifyBroadcastLocked(intent);
final ProcessRecord callerApp = getRecordForAppLocked(caller);
final int callingPid = Binder.getCallingPid();
final int callingUid = Binder.getCallingUid();
final long origId = Binder.clearCallingIdentity();
int res = broadcastIntentLocked(callerApp,
callerApp != null ? callerApp.info.packageName : null,
intent, resolvedType, resultTo,
resultCode, resultData, map, requiredPermission, serialized, sticky,
callingPid, callingUid, userId);
Binder.restoreCallingIdentity(origId);
return res;
}
可以看到TID=24需要ActivityManagerService这个锁。再看TID=12线程的栈顶，PowerManagerService的isScreenOnInternal函数代码如下：
private boolean isScreenOnInternal() {
synchronized (mLock) {
return !mSystemReady
|| mDisplayPowerRequest.screenState != DisplayPowerRequest.SCREEN_STATE_OFF;
}
}
可以看到需要PowerManagerService的mlock这个锁。最后看TID=85线程的栈顶，同样在PowerManagerService里面，内部类DisplayBlankerImpl的toString函数：
public String toString() {
synchronized (this) {
return "blanked=" + mBlanked;
}
}
这是在内部类DisplayBlankerImpl里面实现的，所以需要DisplayBlankerImpl这个锁。
对应的表格如下：
表一 各线程等待的锁情况
从表一来看，没有出现死锁现象，似乎并不是我们所想的那样。难道不是死锁？开始有点小怀疑自己了，难道别的原因导致的。也许只看调用堆栈的顶端可能不行，栈顶只能看出各线程需要的锁，不能仅看自己要什么吧！一味索取可不好！人不是这样做的！看一下整个的堆栈调用流程，看看自己拥有了那些锁。
跟踪TID=24线程的堆栈，在PowerManagerService内部类DisplayBlankerImpl的unblankAllDisplays函数中持有锁：
public void unblankAllDisplays() {
synchronized (this) {
nativeSetAutoSuspend(false);
nativeSetInteractive(true);
mDisplayManagerService.unblankAllDisplaysFromPowerManager();
mBlanked = false;
///M: add for tvout and hdmi
mTvOut.tvoutPowerEnable(true);
mHDMI.hdmiPowerEnable(true);
///@}
if (DEBUG) {
Slog.d(TAG_P, "unblankAllDisplays out ...");
}
if (mBootCompleted) {
Intent intent = new Intent(ACTION_LOCK_SCREEN_SHOW);
mContext.sendBroadcast(intent);
}
}
}
最后发送广播的代码，是我们自己添加的。根据unblankAllDisplays函数和broadcastIntent函数，可以看到TID=24的线程此时持有了DisplayBlankerImpl锁(unblankAllDisplays)，等待ActivityManagerService锁(broadcastIntent)释放。
同样，跟踪TID=12线程的堆栈，在ActivityManagerService的wake_up函数中持有锁：
public void wakingUp() {
if (checkCallingPermission(android.Manifest.permission.DEVICE_POWER)
!= PackageManager.PERMISSION_GRANTED) {
throw new SecurityException("Requires permission "
+ android.Manifest.permission.DEVICE_POWER);
}
synchronized(this) {
Slog.i(TAG, "wakingUp");
mWentToSleep = false;
updateEventDispatchingLocked();
comeOutOfSleepIfNeededLocked();
}
}
根据wakingUp函数和isScreenOnInternal函数，可以看到TID=12的线程持有ActivityManagerService锁(wakingUp)，等待PowerManagerService.mLock锁(isScreenOnInternal)。到这，似乎看到了希望，迷雾要拨开了，有点小自信是死锁导致的，但还不能最终下结论。
一鼓作气，跟踪TID=85线程的堆栈，在PowerManagerService的dump有持有锁的操作：
protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) {
....
synchronized (mLock) {
...
}
根据toString函数和dump函数，可以看到TID=85线程此时持有PowerManagerService.mLock锁(dump)，需要DisplayBlankerImpl(toString)。
似乎谜底已经揭晓了，如果你还没有看出来（其实我也没看出来），来个表看看吧！
表二 各线程锁的情况
清楚了吗？多么清晰的循环等待呀！死锁都死的这么完美，还是图表效果好，看来有时候在纸上画画还是有用的！