ANR问题Log分析

分析问题思路：

了解用户的操作流程，查看错误出现的设备，app版本，及相关分支代码-->查看log里的堆栈信息及用户操作轨迹-->复现问题-->检查由堆栈信息里反应出来的相关的类和方法--> 检查项目代码逻辑 --> 检查trace信息 --> 检查自己项目的cmd line ：项目包名 下的每个线程的信息 --> 再检查cmd line: system_server下面的线程的信息 --> 检查EVENT LOG下面用户在出现问题时间节点前后的操作（可以看到AM信息，看到每个服务的启停状态） --> 确认问题

1.查找关键字

2.定位到查看具体哪一步出了问题。

3.检查项目代码（发现代码逻辑没问题）

定位到cursor查询铃声时的问题

4.确定发生ANR时间点（搜索关键字：am_anr和[包名]）

am_anr：

05-13 00:40:10.061  1000  1574  1605 I am_anr  : [0,15104,[包名],952647237

com.sec.android.app.clockpackage：

time="2019-05-13 00:39:34" type=MOVE_TO_FOREGROUND  package=[包名]

time="2019-05-13 00:39:34" type=MOVE_TO_FOREGROUND  package[包名].launcher

time="2019-05-13 00:39:39" type=MOVE_TO_FOREGROUND package=[包名]

确认用户是在2019-05-13 00:39:34执行添加**操作，并且在那个时候发生ANR

5.查找关键字：Cmd line: [包名]

比对ANR时间，发现下面这条信息就是我们要找的那条信息

----- pid 15104 at 2019-05-13 00:40:10 -----

Cmd line:[包名]

ABI: 'arm64'

Build type: optimized

Zygote loaded classes=10769 post zygote classes=939

Intern table: 105823 strong; 363 weak

JNI: CheckJNI is off; globals=652 (plus 43 weak)

······//带有很多当前状态的信息

Total number of allocations ：当前内存对象数量

Free memory until OOME  距离发生OOM还有多少内存

Total memory 目前总共开销的内存

然后找到下面这些信息中的“DALVIK THREADS（15）”，这个下面就是我们这个进程下的所有线程，它记录着发生ANR时当前线程的状态和信息，后面的数字标记着是数量

"main" prio=5 tid=1 Native

"Jit thread pool worker thread 0" daemon prio=5 tid=2 Native

"ReferenceQueueDaemon" daemon prio=5 tid=4 Waiting

"FinalizerDaemon" daemon prio=5 tid=5 Waiting

"Thread-7" daemon prio=1 tid=11 Waiting

········

我们在查看信息是发现了"main" prio=5 tid=1 Native 下是有记录有堆栈信息：

  at android.os.BinderProxy.transactNative(Native method)

  at android.os.BinderProxy.transact(Binder.java:1140)

  at android.app.IActivityManager$Stub$Proxy.getContentProvider(IActivityManager.java:4025)

  at android.app.ActivityThread.acquireProvider(ActivityThread.java:6252)

  - locked <0x096db8db> (a android.app.ActivityThread$ProviderKey)          （如果有被别的线程锁定，会有held by td）     

  at android.app.ContextImpl$ApplicationContentResolver.acquireUnstableProvider(ContextImpl.java:2825)

  at android.content.ContentResolver.acquireUnstableProvider(ContentResolver.java:1834)

  at android.content.ContentResolver.query(ContentResolver.java:792)

  at android.content.ContentResolver.query(ContentResolver.java:758)

  at android.content.ContentResolver.query(ContentResolver.java:716)

  at android.media.RingtoneManager.getZeroDataRingtoneTitles(RingtoneManager.java:1932)

  at android.media.RingtoneManager.zeroDataRingtonesWhereClauseForCSC(RingtoneManager.java:1956)

  at android.media.RingtoneManager.getInternalRingtonesWithTheme(RingtoneManager.java:1986)

  at android.media.RingtoneManager.getInternalRingtones(RingtoneManager.java:634)

at android.media.RingtoneManager.getCursor(RingtoneManager.java:452)

因为看了应用进程内其他的线程以及当前的状态信息，都没有问题，到这一步也只有发现getContentProvider时出问题了，但是也还是找不到其他的问题，所以ANR问题一般处理到这里就要联想到看看AMS有没有问题，在系统出现ANR时，不仅仅会把当前应用进程信息打印出来，还会把当前系统服务的一些信息反馈出来。

1.    查找关键字：cmd line: system_server

同样比对时间时间，确认是我们发生此次ANR时的信息

----- pid 1574 at 2019-05-13 00:40:12 -----

Cmd line: system_server

Build fingerprint: '···release-keys'

ABI: 'arm64'

Build type: optimized

······

发现系统服务里总共246个线程DALVIK THREADS (246)，在没有把握的情况只能慢慢一个个往下翻

"ReferenceQueueDaemon" daemon prio=5 tid=3 Waiting

"Binder:1574_1" prio=5 tid=7 Native

"Binder:1574_2" prio=5 tid=8 Native

"ActivityManager" prio=5 tid=11 Native

"PackageManager" prio=5 tid=30 Native

"android.ui" prio=5 tid=12 Native

"batterystats-worker" prio=5 tid=15 TimedWaiting

·····

终于翻到一条看起来很相关的TimedWaiting（还是建议把所有线程信息给过完）

"Binder:1574_3" prio=5 tid=89  TimedWaiting

  | group="main" sCount=1 dsCount=0 flags=1 obj=0x131c6328 self=0x7e89432c00

  | sysTid=1760 nice=0 cgrp=default sched=0/0 handle=0x7e88fe74f0

  | state=S schedstat=( 291062059253 90550248195 547818 ) utm=16974 stm=12132 core=5 HZ=100

  | stack=0x7e88eec000-0x7e88eee000 stackSize=1009KB

  | held mutexes=

  at java.lang.Object.wait(Native method)

  - waiting on <0x0cea6220> (a com.android.server.am.ContentProviderRecord)

  at java.lang.Object.wait(Object.java:422)

  at com.android.server.am.ActivityManagerService.getContentProviderImpl(ActivityManagerService.java:15868)

  - locked <0x0cea6220> (a com.android.server.am.ContentProviderRecord)

  at com.android.server.am.ActivityManagerService.getContentProviderImpl(ActivityManagerService.java:15411)

  at com.android.server.am.ActivityManagerService.getContentProvider(ActivityManagerService.java:15966)

  at android.app.IActivityManager$Stub.onTransact$getContentProvider$(IActivityManager.java:11029)

  at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:295)

  at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:4162)

at android.os.Binder.execTransact(Binder.java:739)

在这个时候发现Binder:1574_3一致处于ContentProviderRecord一直处于等待状态，所以才会导致ANR，因为我们的binder最大线程数的是有限的，所以当时第一反应就是binder没调度过来一直让AMS调用contentProvider的时候才崩溃的，所以就猜想binder进程被占完了，导致这个问题。

但是为什么会导致这个问题？

自己也在想binder调度系统按道理应该不会出现这种情况，后面又继续看线程信息，有个奇怪线程叫watchdog，

  "watchdog" prio=5 tid=169 TimedWaiting

  | group="main" sCount=1 dsCount=0 flags=1 obj=0x1478b750 self=0x7e7eb0e400

Watchdog字面上是“看门狗”的意思，有做过嵌入式低层的朋友应该知道，为了防止嵌入式系统MCU里的程序因为干扰而跑飞，专门在MCU里设计了一个定时器电路，叫做看门狗。当MCU正常工作的，每隔一段时间会输出一个信号给看门狗，

也就是所谓的喂狗。如果程序跑飞，MCU在规定的时间内没法喂狗，这时看门狗就会直接触发一个reset信号，让CPU重新启动。

如果真的会处理不过来的，这个时候手机应该会重启才对，但是log信息最后一次重启是在5月10号还是用户自己请求的。

19/05/10 23:33:27

reason : userrequested

java.lang.Exception: It is not an exception!! just save the trace for process which called shutdown thread!! ShutdownThread.shutdown

    at com.android.server.power.ShutdownThread.shutdownInner(ShutdownThread.java:552)

    at com.android.server.power.ShutdownThread.shutdown(ShutdownThread.java:407)

所以到这里，我的那个猜想又失败了。

6.查看EventLog信息

05-13 00:39:25.534  1000  1574  1605 I am_kill : [0,14882,android.process.media,900,timeout publishing content providers]

05-13 00:39:25.545  1000  1574  1605 I am_wtf  : [0,14806,system_server,-1,ActivityManager,Timeout waiting for provider com.android.providers.media/10043 for provider media providerRunning=false]

05-13 00:38:32.813  1000  1574  1607 I am_proc_start: [0,14536,10043,android.process.media,content provider,com.android.providers.media/.MediaProvider]

05-13 00:38:32.846  1000  1574  2344 I am_proc_bound: [0,14536,android.process.media]

05-13 00:39:36.233  1000  1574  1605 I am_kill : [0,14964,android.process.media,200,timeout publishing content providers]

05-13 00:39:36.236  1000  1574  1605 I am_wtf  : [0,14918,system_server,-1,ActivityManager,Timeout waiting for provider com.android.providers.media/10043 for provider media providerRunning=false]

05-13 00:39:46.310  1000  1574  1605 I am_kill : [0,15002,android.process.media,900,timeout publishing content providers]

05-13 00:39:46.316  1000  1574  1605 I am_wtf  : [0,14918,system_server,-1,ActivityManager,Timeout waiting for provider com.android.providers.media/10043 for provider media providerRunning=false]

定位到问题，系统一直在报timeout publishing content providers这个错，然后服务被kill了，然后导致我们拿不到media provider。

但是只是能看到timeout publishing content providers这个问题，但其实还是不知道真正的原因，但确定了不是我们的代码问题，而是media provider的问题。

总结：

ANR出现的一般原因：

1. 系统级别的线程阻塞导致的ANR
2. CPU满负荷（关键字：Cpu usage）
3. 内存原因（从进程的头部信息可以看到数据）
4. UI线程耗时操作

一般解决办法：

查看进程头部信息—>查看进程资源状态à查看每一条可疑线程的信息

关键字：am_anr ,cmd line: system_server，cmd line:[package name], TimedWaiting , Blocked，am_kill，am_proc_start，EventLog , lock