​​​​​

1.ANR简介

ANR是Application Not Responding的简称，即应用无响应。

anr trace log 一般在 /data/anr 目录.

2.ANR 分类

1. InputDispatching TimeOut（5s）

输入事件超时无响应,如点击事件,触摸事件超过5秒

2. Broadcast Timeout

前台广播 10s 未处理完,

后台广播 20 s 未处理完.

广播超时，是指广播在指定超时时间内没有处目录理完成。广播执行的方式有两种：一种是串行执行，另外一种是并行执行。并行执行的广播没有时间限定，例如动态注册的非有序广播是并行执行的；串行执行的广播是有时间限定的，前台广播的超时时间为10s，后台广播的超时时间为60s，例如静态注册的广播和有序广播都是串行执行的。

3. Service TimeOut

服务超时,是指在执行服务的方法中超时了,即在执行服务的是周期函数 onCreat(),onBind(),onStart(),onStartCommand()的时候超超时了.后台线程组服务执行超时时间为 200s ,非后台线程组服务执行超时时间为 20s .

默认情况服务在非后台线程组执行,超时时间为20s.

在 Process.java ,定义几种线程组:

THREAD_GROUP_DEFAULT 默认线程组
THREAD_GROUP_BG_NONINTERACTIVE 后台线程组
THREAD_GROUP_FOREGROUND 前台线程组
THREAD_GROUP_SYSTEM 系统线程组

4. ContentProviderClient Timeout（20s）

Provider 超时,在使用ContentProviderClient操作ContentProvider时超时，超时时间为20s。

3. Monkey  trace.txt log  案例分析

3.1. com.android.documentsui  anr

查看trace并没有发现什么异常，mainlog中显示CPU使用：
101% 227/mobile_log_d: 16% user + 84% kernel / faults: 69 minor
55% TOTAL: 21% user + 33% kernel + 1% iowait
根据Eventlog中显示ANR的发生时间点是51秒
01-04 09:27:51.027 760 775 I am_anr : [0,26870,com.android.documentsui,952680005,Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]
查看对应的进程26870启动只和报ANR的时间点相差1秒
01-04 09:27:50.049971 760 23012 I ActivityManager: AMS: *** Start proc 26870:com.android.documentsui/u0a9 for activity com.android.documentsui/.FilesActivity
1秒的时间间隔应该是不会出现ANR问题，继续查找在此之前还启动了一个documentsui进程26802但是随即已经被杀死
01-04 09:27:42.375031 760 3603 I ActivityManager: AMS: *** Start proc 26802:com.android.documentsui/u0a9 for activity com.android.documentsui/.LauncherActivity
01-04 09:27:42.902997 760 2026 I ActivityManager: Process com.android.documentsui (pid 26802) has died
查看进程的启动到完成的时间是间隔了十秒
01-04 09:27:42.308526 760 8789 I ActivityManager: START u0
{act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=com.android.documentsui/.LauncherActivity}
from uid 2000 on display 0
01-04 09:27:42.646926 760 15852 I ActivityManager: START u0
 
{dat=//com.android.documentsui.launchControl flg=0x10200000 cmp=com.android.documentsui/.FilesActivity (has extras)}
from uid 10009 on display 0
01-04 09:27:53.391940 760 783 I ActivityManager: Displayed com.android.documentsui/.FilesActivity: +10s715ms (total +11s42ms)
这个启动时间和26802进程与26870进程启动的间隔几乎相等，怀疑和AMS有关

log 分析:

分析log发现：
01-04 09:27:42.375 760 3603 I ActivityManager: AMS: *** Start proc 26802:com.android.documentsui/u0a9 for activity com.android.documentsui/.LauncherActivity
01-04 09:27:42.903 760 2026 D ActivityManager: handleAppDiedLocked: app = ProcessRecord
 
{c686e1e 26802:com.android.documentsui/u0a9}
, app.pid = 26802
01-04 09:27:42.903 760 2026 D ActivityManager: cleanUpApplicationRecord – 26802
从出生到结束的时间很短。
期间：
01-04 09:27:42.803 760 5544 D ActivityManager: AMS: doLMKCrazyClean (3) Normal start {{{{
也就是说LMKCrazyClean杀死了他，导致他的触摸事件没来得及处理，导致ANR。
 
由于手机为低内存，Monkey启动了太多应用，优先级低的就可能被杀死。
解决方式，让LMKCrazyClean添加白名单，或者下载模块添加临时优先级保护。

出现anr的问题原因如下：

在09:27:42时间点附近启动了FilesActivity,并将焦点切换到了此app上
01-04 09:27:42.653413 760 15852 I am_create_activity: [0,220999959,4820,com.android.documentsui/.FilesActivity,NULL,NULL,//com.android.documentsui.launchControl,271056896]
01-04 09:27:42.665296 760 15852 I am_focused_activity: [0,com.android.documentsui/.FilesActivity,startedActivity]
在此之后，documentsui进程被杀了
01-04 09:27:42.903073 760 2026 I am_proc_died: [0,26802,com.android.documentsui]
因为前台进程被杀，所以重启了前台进程的activity,开始了下一轮start proc for activity
01-04 09:27:50.049805 760 23012 I am_proc_start: [0,26870,10009,com.android.documentsui,activity,com.android.documentsui/.FilesActivity]
进程刚启动，activity的启动暂未完成，因焦点仍在该app上，但是activity没有绘制完成，有焦点app没有焦点activity, 所以发生了anr
01-04 09:27:51.027798 760 775 I am_anr : [0,26870,com.android.documentsui,952680005,Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]

现在有2个问题：
1) 怎么died的？

对应的时间段的kernel.log丢失了，无法确认是否是lmk杀死进程，但是查看anr时间点的memory dump发现当前的内存状态非常的紧张
Total RAM: 987,940K (status critical)
Free RAM: 186,208K ( 0K cached pss + 127,824K cached kernel + 53,552K free + 4,832K ion cached + 0K gpu cached)
Used RAM: 993,954K ( 852,482K used pss + 134,960K kernel + 28K trace buffer + 6,484K ion disp + 0K cma usage)
Lost RAM: -26,430K
ZRAM: 82,216K physical used for 310,504K in swap ( 493,968K total swap)
Tuning: 128 (large 256), oom 225,280K, restore limit 37,546K (high-end-gfx)
另外进程被杀时间点前后出现了频繁的doLMKCrazyClean, kill次数超过4次，每次kill时间间隔不超过1s，包含了2次deep kill
综上所诉，怀疑此次died是低内存杀进程导致，查看系统当时存在的进程，发现B类service仍然存在在系统中
22,359K: B Services
9,385K: com.android.mms (pid 26647)
8,278K: com.google.android.apps.translate:copydrop (pid 26093)
4,696K: com.mediatek.FMRadio (pid 27218)
B类service的adj为8，其实比较低了，可以考虑杀掉，降低系统内存压力

2) 为什么前台进程的死掉和重启之间等待了7s？

在activity重启的过程中47s左右出现了动画切换超时问题app_transition_timeout
01-04 09:27:47.654253 760 783 V WindowManager: *** APP TRANSITION TIMEOUT. isTransitionSet()=true mOpeningApps.size()=1 mClosingApps.size()=3
APP TRANSITION TIMEOUT消息是在prepareAppTransition中设置的，在activity resume完成后会进行执行切换动画操作，并将timeout message移除出队列，出现该log说明当前系统进行activity启动调度缓慢，超过了5s的时间activity仍然没有完成resume操作
查看此时间段内的sys_log以及main_log发现在此时间内系统关键服务log极少，一秒就一行log，kernel.log缺失，anr出现后实际上系统已经开始正常的执行activity启动调度，吞吐Log也很正常，打印的trace无法说明出现问题时间段的系统信息，因缺失log，无法确定当前系统状态，无法分析

3.2 system.ui anr (gc 导致)

从traces_2.txt的trace分析，应该是在启动ResolverActivity过程中，system:ui进程会通过binder调用WindowManagerService的relayoutWindow方法。但是此时WindowManagerService正在做screenshotApplicationsInner（截屏）处理。在做截屏处理的过程中，会给mWindowMap加锁。
而relayoutWindow的调用，也需要这把锁。由于screenshotApplicationsInner过程被SurfaceFlinger阻塞，导致relayoutWindow的调用无法返回，进而导致system:ui进程阻塞从而发生ANR。

但是SurfaceFlinger的native trace log中没有找到。

从log中找到了ResolverActivity启动过程中的时间戳：

mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3791:04-12 08:34:37.045  1045  1190 I am_create_task: [0,4237]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3792:04-12 08:34:37.045  1045  1190 I am_create_activity: [0,154909728,4237,android/com.android.internal.app.ResolverActivity,android.intent.action.MAIN,NULL,NULL,276824064]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3793:04-12 08:34:37.048  1045  1190 I wm_task_created: [4237,1]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3794:04-12 08:34:37.049  1045  1190 I wm_task_moved: [4237,1,35]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3795:04-12 08:34:37.050  1045  1190 I wm_task_moved: [4237,1,35]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3796:04-12 08:34:37.060  1045  1190 I am_focused_activity: [0,android/com.android.internal.app.ResolverActivity,startedActivity]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3797:04-12 08:34:37.061  1045  1190 I am_pause_activity: [0,223171573,com.gy.cy/com.gangyun.makeup.gallery3d.makeup.MakeUpActivity]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3798:04-12 08:34:37.064 32357 32357 I am_on_paused_called: [0,com.gangyun.makeup.gallery3d.makeup.MakeUpActivity,handlePauseActivity]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3802:04-12 08:34:37.118  1045  2094 I am_proc_start: [0,32408,1000,system:ui,activity,android/com.android.internal.app.ResolverActivity]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3838:04-12 08:34:37.208  1045 32344 I am_proc_bound: [0,32408,system:ui]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3839:04-12 08:34:37.227  1045 32344 I am_restart_activity: [0,154909728,4237,android/com.android.internal.app.ResolverActivity]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3844:04-12 08:34:45.201 32408 32408 I am_on_resume_called: [0,com.android.internal.app.ResolverActivity,LAUNCH_ACTIVITY]
mtklog/aee_exp/db.03.ANR/20170418_115652_097/db.03.ANR.dbg.DEC/SYS_ANDROID_EVENT_LOG:3845:04-12 08:34:45.243  1045  1099 I am_anr  : [0,32408,system:ui,952679945,Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]

ResolverActivity的启动时序如下：

  • 08:34:37.045 am_create_activity 表示 调用了startActivity;
  • 08:34:37.118 am_proc_start 表示创建system:ui进程成功；
  • 08:34:37.208 am_proc_bound 表示system:ui attachAppicaiton成功;
  • 08:34:37.227am_restart_activity 表示AMS发起handleLaunchActivity的调用
  • 08:34:45.201 am_on_resume_called 表示ResolverActivity的onResume被调用

从am_restart_activity到am_on_resume_called，这期间花费了将近8秒的时间。

而在mtklog/aee_exp/db.03.ANR/20170418_115732_148/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG中，可以发现system:ui加载资源是发生在04-12 08:34:37.276，说明am_restart_activity很及时的得到了处理。
SYS_ANDROID_LOG

SYS_ANDROID_LOG:5626:04-12 08:34:37.262 32408 32408 W asset   : AssetManager-->addDefaultAssets isok4 is true
SYS_ANDROID_LOG:5638:04-12 08:34:37.276 32408 32408 I LoadedApk: No resource references to update in package com.transsion.theme.ico

所以，真正的ANR原因，应该可能出在ResolverActivity的onCreate，onStart，onResume过程中消耗的时间时间过多。耗时过多的原因可能为：

  • 在onCreate，onResume过程中做了耗时的操作
  • 没有抢占到cpu，system:ui进程处于freeze状态

分析了ResolverActivity的代码，在上述过程中，并不存在耗时的操作。唯一可能导致耗时的操作是ResolverActivity中存在和system_server进程中的AMS，PMS的交互。根据发生ANR的时候，系统的cpu usage为70%，但是system:ui的使用率居然为0，这点不是很正常。加上system_server过高的使用率，推测此ANR是由于system:ui抢占不到cpu或者是在onCreate的过程中，与AMS和PMS的交互花费了较长时间，导致ANR的发生。

monkey.txt中log如下：

ANR in system:ui (android/com.android.internal.app.ResolverActivity), time=68980227
Reason: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
Load: 13.37 / 10.24 / 8.67
Android time :[2017-04-12 08:34:48.93] [68983.977]
CPU usage from 136564ms to 0ms ago (2017-04-12 08:32:28.625 to 2017-04-12 08:34:45.189):
  87% 1045/system_server: 70% user + 16% kernel / faults: 331683 minor 4694 major
  34% 315/surfaceflinger: 13% user + 20% kernel / faults: 19719 minor 126 major
  21% 1843/com.android.systemui: 16% user + 5.1% kernel / faults: 140832 minor 1179 major
  11% 207/exe_cq: 0% user + 11% kernel
  6.6% 16457/com.mediatek.FMRadio: 4.4% user + 2.1% kernel / faults: 39531 minor 1567 major
  6.4% 272/logd: 2.1% user + 4.3% kernel / faults: 2767 minor 85 major
  5.5% 323/mobile_log_d: 3.1% user + 2.3% kernel / faults: 4406 minor 10 major
  0.2% 27544/com.android.inputmethod.latin: 0.1% user + 0% kernel / faults: 49039 minor 299 major
  2.8% 208/mmcqd/0: 0% user + 2.8% kernel
  3% 87/kswapd0: 0% user + 3% kernel
  0.5% 28083/kworker/u17:0: 0% user + 0.5% kernel
  2.3% 2047/com.android.phone: 1.7% user + 0.6% kernel / faults: 20033 minor 233 major
  2.3% 22717/kworker/u17:3: 0% user + 2.3% kernel
  2.2% 18369/com.android.commands.monkey: 1.5% user + 0.7% kernel / faults: 9515 minor 68 major
  0.1% 73/ion_mm_heap: 0% user + 0.1% kernel
  2% 314/servicemanager: 0.7% user + 1.2% kernel / faults: 447 minor 1 major
  0.8% 2651/com.transsion.phonemanager: 0.3% user + 0.4% kernel / faults: 19432 minor 2242 major
  0.3% 355/audioserver: 0.1% user + 0.1% kernel / faults: 3014 minor 236 major
  1.1% 2271/com.android.contacts: 0.6% user + 0.4% kernel / faults: 24650 minor 1424 major
  1.1% 3185/adbd: 0% user + 1% kernel / faults: 6593 minor
  0.3% 20109/com.google.android.gms.persistent: 0.1% user + 0.2% kernel / faults: 22811 minor 1158 major
  1.1% 328/aal: 0.2% user + 0.8% kernel / faults: 472 minor
  0% 27646/com.google.android.gms: 0% user + 0% kernel / faults: 28195 minor 719 major
  0% 16052/android.process.media: 0% user + 0% kernel / faults: 14802 minor 161 major
  0.9% 112/hps_main: 0% user + 0.9% kernel
  0.8% 353/zygote64: 0.1% user + 0.7% kernel / faults: 14044 minor 1 major
  0.7% 342/fuelgauged: 0% user + 0.7% kernel / faults: 358 minor 1 major
  0.6% 1829/sdcard: 0% user + 0.5% kernel / faults: 450 minor 25 major
  0% 2161/sdcard: 0% user + 0% kernel / faults: 328 minor 16 major
  0.3% 143/present_fence_w: 0% user + 0.3% kernel
  0.4% 220/bat_routine_thr: 0% user + 0.4% kernel
  0% 359/installd: 0% user + 0% kernel / faults: 289 minor 7 major
  0% 1//init: 0% user + 0% kernel / faults: 233 minor
  0.3% 10963/kworker/u16:1: 0% user + 0.3% kernel
  0.2% 7/rcu_preempt: 0% user + 0.2% kernel
  0.2% 10/migration/0: 0% user + 0.2% kernel
  0.1% 26703/kworker/u16:3: 0% user + 0.1% kernel
  0.2% 17173/com.google.android.youtube: 0.1% user + 0% kernel / faults: 5475 minor 91 major
  0% 16303/android.process.acore: 0% user + 0% kernel / faults: 5201 minor 229 major
  0.1% 27804/kworker/u16:4: 0% user + 0.1% kernel
  0.1% 22506/kworker/u16:2: 0% user + 0.1% kernel
  0.1% 23/migration/4: 0% user + 0.1% kernel
  0.1% 27/migration/5: 0% user + 0.1% kernel
  0.1% 2425/ged_srv: 0% user + 0.1% kernel / faults: 936 minor 11 major
  0.1% 31/migration/6: 0% user + 0.1% kernel
  0.1% 247/jbd2/mmcblk0p28: 0% user + 0.1% kernel
  0.1% 11/migration/1: 0% user + 0.1% kernel
  0% 35/migration/7: 0% user + 0% kernel
  0.1% 222/bat_update_thre: 0% user + 0.1% kernel
  0.1% 8/rcu_sched: 0% user + 0.1% kernel
  0% 330/media.codec: 0% user + 0% kernel / faults: 634 minor 246 major
  0.1% 329/vtservice: 0% user + 0% kernel / faults: 406 minor
  0% 15/migration/2: 0% user + 0% kernel
  0% 2062/com.rlk.powersavemanagement: 0% user + 0% kernel / faults: 5052 minor 167 major
  0% 2/kthreadd: 0% user + 0% kernel
  0% 313/lmkd: 0% user + 0% kernel / faults: 220 minor 1 major
  0% 365/netd: 0% user + 0% kernel / faults: 824 minor 8 major
  0% 197/kworker/5:1H: 0% user + 0% kernel
  0% 15670/kworker/4:0: 0% user + 0% kernel
  0% 72/cfinteractive: 0% user + 0% kernel
  0% 354/zygote: 0% user + 0% kernel / faults: 2833 minor 258 major
  0% 19/migration/3: 0% user + 0% kernel
  0% 113/pbm: 0% user + 0% kernel
  0% 216/kworker/4:1H: 0% user + 0% kernel
  0% 29727/com.mediatek.mtklogger: 0% user + 0% kernel / faults: 4772 minor 64 major
  0% 196/kworker/6:1H: 0% user + 0% kernel
  0% 160/btif_rxd: 0% user + 0% kernel
  0% 194/kworker/7:1H: 0% user + 0% kernel
  0% 32/ksoftirqd/6: 0% user + 0% kernel
  0% 141/display_check_a: 0% user + 0% kernel
  0% 217/mmcqd/1: 0% user + 0% kernel
  0% 2570/com.reallytek.weather: 0% user + 0% kernel / faults: 4510 minor 43 major
  0% 6949/kworker/5:1: 0% user + 0% kernel
  0% 22297/mtkmal: 0% user + 0% kernel / faults: 1871 minor 1 major
  0% 22572/mtkrild: 0% user + 0% kernel / faults: 1577 minor 5 major
  0% 223/mtk charger_hv_: 0% user + 0% kernel
  0% 10249/kworker/6:2: 0% user + 0% kernel
  0% 17773/com.android.gallery3d: 0% user + 0% kernel / faults: 2080 minor 83 major
  0% 24/ksoftirqd/4: 0% user + 0% kernel
  0% 28/ksoftirqd/5: 0% user + 0% kernel
  0% 137/disp_idlemgr: 0% user + 0% kernel
  0% 317/mtk_stp_psm: 0% user + 0% kernel
  0% 320/mtk_wmtd: 0% user + 0% kernel
  0% 362/media.extractor: 0% user + 0% kernel / faults: 430 minor 170 major
  0% 364/mediaserver: 0% user + 0% kernel / faults: 517 minor 166 major
  0% 22429/gsm0710muxd: 0% user + 0% kernel / faults: 478 minor 2 major
  0% 22668/rilproxy: 0% user + 0% kernel / faults: 1243 minor 9 major
  0% 27238/kworker/4:1: 0% user + 0% kernel
  0% 3/ksoftirqd/0: 0% user + 0% kernel
  0% 36/ksoftirqd/7: 0% user + 0% kernel
  0% 224/kworker/0:1H: 0% user + 0% kernel
  0% 225/ueventd: 0% user + 0% kernel / faults: 108 minor 40 major
  0% 5/kworker/0:0H: 0% user + 0% kernel
  0% 142/disp_delay_trig: 0% user + 0% kernel
  0% 340/thermal: 0% user + 0% kernel / faults: 451 minor
  0% 15419/kworker/0:2: 0% user + 0% kernel
  0% 16649/com.google.android.gms.feedback: 0% user + 0% kernel / faults: 3281 minor 297 major
  0% 12/ksoftirqd/1: 0% user + 0% kernel
  0% 18/kworker/2:0H: 0% user + 0% kernel
  0% 215/kworker/1:1H: 0% user + 0% kernel
  0% 663/kworker/2:2: 0% user + 0% kernel
  0% 12587/kworker/0:0: 0% user + 0% kernel
  0% 23729/kworker/3:2H: 0% user + 0% kernel
  0% 24220/kworker/0:3: 0% user + 0% kernel
  0% 13/kworker/1:0: 0% user + 0% kernel
  0% 14/kworker/1:0H: 0% user + 0% kernel
  0% 16/ksoftirqd/2: 0% user + 0% kernel
  0% 17/kworker/2:0: 0% user + 0% kernel
  0% 20/ksoftirqd/3: 0% user + 0% kernel
  0% 26/kworker/4:0H: 0% user + 0% kernel
  0% 34/kworker/6:0H: 0% user + 0% kernel
  0% 199/wdtk-0: 0% user + 0% kernel
  0% 201/wdtk-2: 0% user + 0% kernel
  0% 214/kworker/2:1H: 0% user + 0% kernel
  0% 221/kworker/2:1: 0% user + 0% kernel
  0% 287/vold: 0% user + 0% kernel / faults: 516 minor 56 major
  0% 304/healthd: 0% user + 0% kernel / faults: 12 minor 24 major
  0% 307/wmt_launcher: 0% user + 0% kernel / faults: 331 minor
  0% 346/batterywarning: 0% user + 0% kernel / faults: 223 minor 1 major
  0% 356/cameraserver: 0% user + 0% kernel / faults: 507 minor 99 major
  0% 357/drmserver: 0% user + 0% kernel / faults: 344 minor 39 major
  0% 368/program_binary_service: 0% user + 0% kernel / faults: 516 minor
  0% 487/kworker/1:1: 0% user + 0% kernel
  0% 2932/kworker/1:2: 0% user + 0% kernel
  0% 4492/debuggerd64: 0% user + 0% kernel / faults: 105 minor 29 major
  0% 15014/kworker/2:3: 0% user + 0% kernel
  0% 15557/kworker/4:2: 0% user + 0% kernel
  0% 16097/kworker/6:1: 0% user + 0% kernel
  0% 17003/kworker/5:2: 0% user + 0% kernel
 +0% 29655/kworker/u17:1: 0% user + 0% kernel
 +0% 29720/kworker/u17:2: 0% user + 0% kernel
 +0% 29721/kworker/7:2: 0% user + 0% kernel
 +0% 29784/com.afmobi.boomplayer: 0% user + 0% kernel
 +0% 29874/com.google.android.apps.photos:CameraShortcut: 0% user + 0% kernel
 +0% 30103/com.google.process.gapps: 0% user + 0% kernel
 +0% 30532/com.google.android.music:main: 0% user + 0% kernel
 +0% 30731/com.google.android.tts: 0% user + 0% kernel
 +0% 30758/kworker/u16:0: 0% user + 0% kernel
 +0% 31330/com.rlk.feedback: 0% user + 0% kernel
 +0% 31352/kbase_event: 0% user + 0% kernel
 +0% 31712/kworker/u17:4: 0% user + 0% kernel
 +0% 31889/com.android.settings: 0% user + 0% kernel
 +0% 31913/kbase_event: 0% user + 0% kernel
 +0% 31984/kworker/u16:5: 0% user + 0% kernel
 +0% 31995/com.google.android.gms.ui: 0% user + 0% kernel
 +0% 32022/com.android.defcontainer: 0% user + 0% kernel
 +0% 32044/kbase_event: 0% user + 0% kernel
 +0% 32326/debuggerd64: 0% user + 0% kernel
 +0% 32327/aee_dumpstate: 0% user + 0% kernel
 +0% 32357/com.gy.cy: 0% user + 0% kernel
 +0% 32383/kbase_event: 0% user + 0% kernel
 +0% 32408/system:ui: 0% user + 0% kernel
71% TOTAL: 40% user + 30% kernel + 1% iowait + 0% softirq

另外也有log证实，在发生anr期间，system_server处于非常繁忙的场景，不停的在进行垃圾回收，log见下：

mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5572:04-12 08:34:37.119  1045  2094 I ActivityManager: AMS: *** Start proc 32408:system:ui/1000 for activity android/com.android.internal.app.ResolverActivity
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5610:04-12 08:34:37.212  1045  1107 V WindowManager: Looking for focus: 30 = Window{dd22b3b u0 StatusBar}, flags=-2122055608, canReceive=false
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5611:04-12 08:34:37.213  1045  1107 V WindowManager: findFocusedWindow: Reached focused app=AppWindowToken{807aa7f token=Token{28109d9 ActivityRecord{93bbc20 u0 android/com.android.internal.app.ResolverActivity t4237}}}
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5612:04-12 08:34:37.219  1045 32344 D InputReader: InputReader:: getSwitchState lock 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5613:04-12 08:34:37.219  1045 32344 D InputReader: InputReader::getStateLocked:: return 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5615:04-12 08:34:37.228  1045 32344 I PPSWrapper: PPS onAfterActivityResumed.
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5616:04-12 08:34:37.228  1045  1769 I libPerfService: [perfNotifyAppState] foreground:android, pid:32408
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5617:04-12 08:34:37.228  1045  1769 I libPerfService: [switchSportsMode] enable:0
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5618:04-12 08:34:37.228  1045 32344 I PPS     : [PPSNotifyAppState] pack:android, com:com.android.internal.app.ResolverActivity, state:1,ActiveCount = 1
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5619:04-12 08:34:37.228  1045 32344 I PPS     : [PPSNotifyAppState] nPackNum:105, pack:android, com:com.android.internal.app.ResolverActivity, state:1, pid:32408, last_boost_tid:32408
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5620:04-12 08:34:37.229  1045 32344 I FreezeManager: In AMS appForeground:1000
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5623:04-12 08:34:37.236  1045  1769 I libPerfService: 2: set: 3, -1, 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5624:04-12 08:34:37.237  1045  1769 I libPerfService: 2: set freq: 1001000, -1, 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5637:04-12 08:34:37.276  1045  6954 W asset   : AssetManager-->addDefaultAssets isok4 is true
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5639:04-12 08:34:37.285  1045  6954 W ResourceType: Invalid package identifier when getting bag for resource number 0xffffffff
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5640:04-12 08:34:37.286  1045  6954 I WindowManager: Destroying surface Surface(name=VolumeDialog) called by com.android.server.wm.WindowStateAnimator.destroySurface:2134 com.android.server.wm.WindowStateAnimator.destroySurfaceLocked:947 com.android.server.wm.WindowState.removeLocked:1452 com.android.server.wm.WindowManagerService.removeWindowInnerLocked:2700 com.android.server.wm.WindowManagerService.removeWindowLocked:2648 com.android.server.wm.WindowManagerService.removeWindowLocked:2514 com.android.server.wm.WindowManagerService.removeWindow:2509 com.android.server.wm.Session.remove:196 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5644:04-12 08:34:37.290  1045  6954 V WindowManager: Looking for focus: 30 = Window{dd22b3b u0 StatusBar}, flags=-2122055608, canReceive=false
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5645:04-12 08:34:37.291  1045  6954 V WindowManager: findFocusedWindow: Reached focused app=AppWindowToken{807aa7f token=Token{28109d9 ActivityRecord{93bbc20 u0 android/com.android.internal.app.ResolverActivity t4237}}}
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5648:04-12 08:34:37.302  1045  5778 D PowerManagerNotifier: onUserActivity: event=0, uid=10029
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5649:04-12 08:34:37.302  1045  5778 D DisplayPowerController: requestPowerState: policy=BRIGHT, useProximitySensor=false, screenBrightness=5, screenAutoBrightnessAdjustment=0.0, brightnessSetByUser=true, useAutoBrightness=false, blockScreenOn=false, lowPowerMode=false, boostScreenBrightness=false, dozeScreenBrightness=-1, dozeScreenState=UNKNOWN, useTwilight=false, waitForNegativeProximity=false, changed=false
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5651:04-12 08:34:37.303  1045  6950 V SettingsProvider: packageValueForCallResult, name = null, value : Bundle[{_track_generation=android.util.MemoryIntArray@5f, value=null, _generation_index=2, _generation=1084}]
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5696:04-12 08:34:37.495  1045  1743 V SettingsProvider: name : volume_alarm_speaker callingUid : 1000
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5697:04-12 08:34:37.508  1045  1743 V SettingsProvider: name : volume_alarm_speaker callingUid : 1000
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5699:04-12 08:34:37.626  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 44294(4MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 77MB/80MB, paused 5.927ms total 49.727ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5712:04-12 08:34:37.699  1045  5059 V WindowManager: Looking for focus: 30 = Window{dd22b3b u0 StatusBar}, flags=-2122055608, canReceive=false
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5713:04-12 08:34:37.699  1045  5059 V WindowManager: findFocusedWindow: Reached focused app=AppWindowToken{807aa7f token=Token{28109d9 ActivityRecord{93bbc20 u0 android/com.android.internal.app.ResolverActivity t4237}}}
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5716:04-12 08:34:37.723  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 40888(4MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 77MB/80MB, paused 5.475ms total 47.150ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5717:04-12 08:34:37.743  1045  1107 I WindowManager: Destroying surface Surface(name=com.gy.cy/com.gangyun.makeup.gallery3d.makeup.MakeUpActivity) called by com.android.server.wm.WindowStateAnimator.destroySurface:2134 com.android.server.wm.WindowStateAnimator.destroySurfaceLocked:947 com.android.server.wm.WindowState.destroyOrSaveSurface:2076 com.android.server.wm.AppWindowToken.destroySurfaces:363 com.android.server.wm.WindowStateAnimator.finishExit:586 com.android.server.wm.WindowStateAnimator.stepAnimationLocked:512 com.android.server.wm.WindowAnimator.updateWindowsLocked:311 com.android.server.wm.WindowAnimator.animateLocked:721 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5718:04-12 08:34:37.745  1045  1769 D PerfServiceManager: [PerfService] MESSAGE_TIMEOUT:107 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5719:04-12 08:34:37.746  1045  1769 I libPerfService: 7: set: -1, -1, 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5720:04-12 08:34:37.746  1045  1769 I libPerfService: 7: set freq: -1, -1, 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5721:04-12 08:34:37.747  1045  1769 D PerfServiceManager: [PerfService] set utilization:0.8 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5742:04-12 08:34:38.083  1045  2159 I libPerfService: 18: set max: -1, -1, 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5743:04-12 08:34:38.083  1045  2159 I libPerfService: [perfScnEnable] scn:18, ppm mode:2
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5746:04-12 08:34:38.084  1045 13908 D PerfServiceManager: [PerfService] notifyDisplayType:2 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5747:04-12 08:34:38.084  1045 13908 I libPerfService: perfNotifyDisplayType - type:2
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5754:04-12 08:34:38.845  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 44198(5MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 78MB/80MB, paused 5.222ms total 63.615ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5760:04-12 08:34:39.257  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 37494(4MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 77MB/80MB, paused 5.946ms total 43.330ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5786:04-12 08:34:39.894  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 31607(4MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 77MB/80MB, paused 5.595ms total 40.496ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5813:04-12 08:34:41.117  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 33495(3MB) AllocSpace objects, 0(0B) LOS objects, 2% free, 78MB/80MB, paused 6.928ms total 65.358ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5817:04-12 08:34:41.203  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 33501(4MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 77MB/80MB, paused 5.263ms total 43.723ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5818:04-12 08:34:41.299  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 35386(4MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 78MB/80MB, paused 5.245ms total 43.932ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5819:04-12 08:34:41.372  1045  1110 D DisplayPowerController: requestPowerState: policy=BRIGHT, useProximitySensor=false, screenBrightness=5, screenAutoBrightnessAdjustment=0.0, brightnessSetByUser=true, useAutoBrightness=false, blockScreenOn=false, lowPowerMode=false, boostScreenBrightness=false, dozeScreenBrightness=-1, dozeScreenState=UNKNOWN, useTwilight=false, waitForNegativeProximity=false, changed=false
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5820:04-12 08:34:41.375  1045  1110 D lights  : write_int open fd=-1
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5825:04-12 08:34:41.398  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 33493(3MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 78MB/80MB, paused 9.400ms total 48.319ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5826:04-12 08:34:41.490  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 34776(3MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 78MB/80MB, paused 5.311ms total 43.827ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5827:04-12 08:34:41.584  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 33287(3MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 77MB/80MB, paused 6.093ms total 45.139ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5828:04-12 08:34:41.680  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 33418(3MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 77MB/80MB, paused 5.357ms total 43.729ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5829:04-12 08:34:41.769  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 34366(3MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 78MB/80MB, paused 5.263ms total 43.065ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5830:04-12 08:34:41.867  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 33896(3MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 78MB/80MB, paused 5.177ms total 44.342ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5833:04-12 08:34:41.960  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 33248(4MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 78MB/80MB, paused 5.327ms total 43.419ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5834:04-12 08:34:42.055  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 32257(3MB) AllocSpace objects, 0(0B) LOS objects, 3% free, 78MB/80MB, paused 5.200ms total 43.388ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5835:04-12 08:34:42.102  1045  1107 V WindowManager: *** APP TRANSITION TIMEOUT. isTransitionSet()=true mOpeningApps.size()=1 mClosingApps.size()=0
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5840:04-12 08:34:42.114  1045 26055 I libPerfService: [perfScnUpdate] scn:18
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5843:04-12 08:34:42.116  1045  2094 I libPerfService: [perfScnUpdate] scn:18
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5844:04-12 08:34:42.120  1045  1107 V WindowManager: Looking for focus: 29 = Window{dd22b3b u0 StatusBar}, flags=-2122055608, canReceive=false
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5845:04-12 08:34:42.120  1045  1107 V WindowManager: findFocusedWindow: Reached focused app=AppWindowToken{807aa7f token=Token{28109d9 ActivityRecord{93bbc20 u0 android/com.android.internal.app.ResolverActivity t4237}}}
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5846:04-12 08:34:42.120  1045  1107 D WindowManager: notifyActivityDrawnForKeyguard: waiting=false Callers=com.android.server.wm.WindowSurfacePlacer.handleAppTransitionReadyLocked:1227 com.android.server.wm.WindowSurfacePlacer.performSurfacePlacementInner:337 com.android.server.wm.WindowSurfacePlacer.performSurfacePlacementLoop:235 com.android.server.wm.WindowSurfacePlacer.performSurfacePlacement:183 com.android.server.wm.WindowManagerService$H.handleMessage:8683 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5847:04-12 08:34:42.121  1045  1107 V WindowManager: Looking for focus: 29 = Window{dd22b3b u0 StatusBar}, flags=-2122055608, canReceive=false
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5848:04-12 08:34:42.121  1045  1107 V WindowManager: findFocusedWindow: Reached focused app=AppWindowToken{807aa7f token=Token{28109d9 ActivityRecord{93bbc20 u0 android/com.android.internal.app.ResolverActivity t4237}}}
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5850:04-12 08:34:42.143  1045  2094 I libPerfService: 18: set max: -1, -1, 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5852:04-12 08:34:42.146  1045  1769 D PerfServiceManager: [PerfService] MESSAGE_USER_DISABLE: 18 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5853:04-12 08:34:42.147  1045  1769 I libPerfService: 18: set max: -1, -1, 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5854:04-12 08:34:42.147  1045  1769 I libPerfService: 18: set: -1, -1, 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5855:04-12 08:34:42.147  1045  1769 I libPerfService: 18: set freq: -1, -1, 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5856:04-12 08:34:42.147  1045  1769 I libPerfService: [perfScnDisable] scn:18, ppm mode:Performance
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5859:04-12 08:34:42.149  1045  3718 D PerfServiceManager: [PerfService] notifyDisplayType:1 
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5860:04-12 08:34:42.149  1045  3718 I libPerfService: perfNotifyDisplayType - type:1
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5861:04-12 08:34:42.158  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 32380(4MB) AllocSpace objects, 0(0B) LOS objects, 2% free, 78MB/80MB, paused 6.579ms total 55.619ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5895:04-12 08:34:43.571  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 60783(3MB) AllocSpace objects, 0(0B) LOS objects, 2% free, 78MB/80MB, paused 16.378ms total 112.284ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5898:04-12 08:34:44.062  1045  1054 I art     : Background sticky concurrent mark sweep GC freed 47477(3MB) AllocSpace objects, 0(0B) LOS objects, 2% free, 78MB/80MB, paused 5.582ms total 37.862ms
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5899:04-12 08:34:44.085  1045 13908 D ConnectivityService: getActiveNetworkInfo networkInfo = null
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5908:04-12 08:34:45.074  1045  2159 V ActivityManager: Broadcast sticky: Intent { act=android.intent.action.SIG_STR flg=0x20000010 (has extras) } ordered=false userid=-1 callerApp=ProcessRecord{c0c0a8f 1045:system/1000}
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5909:04-12 08:34:45.082  1045  1107 I Choreographer: Skipped 169 frames!  The application may be doing too much work on its main thread.
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5911:04-12 08:34:45.102  1045  1190 I InputDispatcher: Application is not responding: AppWindowToken{807aa7f token=Token{28109d9 ActivityRecord{93bbc20 u0 android/com.android.internal.app.ResolverActivity t4237}}}.  It has been 8006.2ms since event, 8003.4ms since wait started.  Reason: Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5912:04-12 08:34:45.127  1045  1190 I WindowManager: Input event dispatching timed out sending to application AppWindowToken{807aa7f token=Token{28109d9 ActivityRecord{93bbc20 u0 android/com.android.internal.app.ResolverActivity t4237}}}.  Reason: Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5915:04-12 08:34:45.183  1045  1789 W InputManager: Input event injection from pid 18369 timed out.
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5916:04-12 08:34:45.186  1045 24784 D WindowManager: interceptKeyBeforeQueueing keyCode = 22
mtklog/aee_exp/db.03.ANR/20170426_100155_458/db.03.ANR.dbg.DEC/SYS_ANDROID_LOG:5918:04-12 08:34:45.188  1045  1099 I FreezeManager: App 1000 is not freezed, But ANR

发生anr的时候，可用内存为44,592K free

Free RAM:   253,539K (    9,091K cached pss +   199,856K cached kernel +    44,592K free +         0K ion cached +         0K gpu cached)

所以这个anr可能是由于内存不够导致内存抖动，cpu过高的用在了内存交换上面,导致activity主进程超时.

3.3 ANR com.android.contactsv24 (界面切换失去焦点)

Process: com.android.contacts
Flags: 0x38d8be4d
Package: com.android.contacts v24 (1.2)
Foreground: No
Activity: com.mediatek.camera/com.android.camera.CaptureActivity
Parent-Activity: com.android.contacts/.activities.PeopleActivity
Subject: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)

这是跑monkey出现的异常，界面切换导致的。
在两个应用页面之间切换的时候,这个临界点的时候,一个页面正在起来,另外一个页面已经"压栈",即失去焦点,并且在这个页面切换的时候快速点击返回back键.

按照目前android系统的约定是先判断是否有window获得focus,发送按键message必须要有有效的focus窗口来接收,否则input event消息将会在系统里面Block,一但Block,系统就开始计时(即timeout),时间一到即ANR.

10-05 07:48:07.181 1045 3307 I wm_task_moved: [3903,0,0]   界面点击
10-05 07:48:07.187 1045 3307 I am_pause_activity: [0,144872800,com.android.contacts/.activities.PeopleActivity]  界面失去焦点,event 事件 block
10-05 07:48:07.204 1905 1905 I am_on_paused_called: [0,com.android.contacts.activities.PeopleActivity,handlePauseActivity] //contacts
10-05 07:48:07.251 1045 1057 I am_resume_activity: [0,123383463,864,com.mediatek.camera/com.android.camera.CaptureActivity] //camera
10-05 07:48:07.263 1045 1061 I sysui_count: [window_time_0,5]
10-05 07:48:15.745 1045 1061 I am_anr : [0,1905,com.android.contacts,953728589,Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]  event 事件到时触发

因此这个问题是monkey快速操作,event 事件在焦点切换临界点,才会出现的，非app本身的问题。正常操作不会有。

3.4 温度过高,cpu 过载 (anr)

此ANR是当时测试时，手机的板温太高，导致thermal这边压cpu，cpu loading达到了100%，所以才会频繁出现这类问题。

对于这种情况，建议查看一下当时的复现步骤，是否跟monkey或者其他压力测试有关？如果不是，用户操作过程中很容易就板温升高的话，建议修改硬件结构或者增加散热辅材，例如添加风冷的方式来缓解板温升高的情况。

从log来看，如下时间点发生了三次ANR，ANR的类型和发生进程都不相同：

11-09 16:20:20.434036 1064 1080 E ANRManager: ANR in com.android.systemui, time=156405952
11-09 16:20:20.434036 1064 1080 E ANRManager: 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: 9. Wait queue head age: 10596.7ms.)
11-09 16:20:44.538118 1064 1080 E ANRManager: ANR in com.evernote, time=156438060
11-09 16:20:44.538118 1064 1080 E ANRManager: Reason: Broadcast of Intent { act=com.google.firebase.INSTANCE_ID_EVENT flg=0x14 cmp=com.evernote/com.google.firebase.iid.FirebaseInstanceIdInternalReceiver (has extras) }
11-09 16:21:15.217680 1064 1080 E ANRManager: ANR in android.process.media, time=156468804
11-09 16:21:15.217680 1064 1080 E ANRManager: Reason: Broadcast of Intent { act=android.hardware.usb.action.USB_STATE flg=0x30000010 cmp=com.android.providers.media/.MtpReceiver (has extras) }

从kernel log来看，如下时间点，有发生了限频的动作：

11-09 16:18:42.055 <4>[156327.417218] (0)[23342:kworker/0:2][CPU_Thermal]set_adaptive_cpu_power_limit 1232 T=67300, 1365 T=63500, 1282 T=64100, 1219 T=66000, 0 T=58100

11-09 16:18:42.055 <4>[156327.417245] (0)[23342:kworker/0:2][Power/cpufreq] mt_cpufreq_thermal_protect(): limited_power = 1232

11-09 16:18:42.055 <7>[156327.417267] (0)[23342:kworker/0:2][name:mt_cpufreq&][Power/cpufreq] @mt_cpufreq_thermal_protect: found = 1, limited_power_idx = 1, limited_max_freq = 1027000, limited_max_ncpu = 4

11-09 16:18:42.055 <7>[156327.417500] (0)[23342:kworker/0:2][name:mt_cpufreq&][Power/cpufreq] @_mt_cpufreq_set_locked(): Vproc = 1125mv, freq = 1027000 KHz

....

//记录了和当前4次cpu power调节的温度和limit信息，总共会记录五次历史信息，

//当前5th调节，CPU温度为65度，设置的power limit为891，

//1th ,CPU温度为64.6度，设置Power limit为596

power limit 为0的话，表示不限制power

11-09 16:21:32.055 <4>[156497.417082] (0)[23342:kworker/0:2][CPU_Thermal]set_adaptive_cpu_power_limit 891 T=65000, 858 T=64600, 765 T=64400, 659 T=64100, 596 T=64600

查看但是手机板温，看起来有从50度开始持续升高，这个温度其实已经非常高了：

11-09 16:18:49.095 <7>[156334.457262] (1)[23759:kworker/1:1][name:mtk_ts_bts&][Power/BTS_Thermal] T_AP=50000

....

11-09 16:21:33.105 <7>[156498.467064] (1)[23759:kworker/1:1][name:mtk_ts_bts&][Power/BTS_Thermal] T_AP=53000

从cpu loading来看，这段时间cpu都是100%的情况：(4),(3)分别代表使用了4,3个核，(400),(300)满负荷工作

11-09 16:19:04.059 <4>[156349.420748] (0)[97:hps_main][HPS] (0008)(4)action end(400)

....

11-09 16:21:26.063 <4>[156491.424828] (0)[97:hps_main][HPS] (0020)(3)action end(300)

综上分析，看起来板子温度高才是此问题的症结所在，请保证板温的温度在合理范围之内.因为 cpu 温度过高会进行降频,其处理能力会下降,导致进程得不到快速处理.

3.5 主线程 waiting 超时等待

1.查找关键字,确定发生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

2. 查找关键字：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时，不仅仅会把当前应用进程信息打印出来，还会把当前系统服务的一些信息反馈出来。

3.    查找关键字：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)
所以到这里，我的那个猜想又失败了。

4. 查看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的问题。

3.6 anr 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 2016-12-17 16: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.Reentr代码段 小部件antLock.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.invoke代码段 小部件Native(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(){@Overridepublicvoidrun(){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();

3.7 anr trace log 解读

导出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)

    第一二行

----- pid 901 at 2015-11-28 14:38:34 -----
Cmd line: system_server

说明了发生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)

其中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 4 allocated not yet running
THREAD_STARTING 5 started not yet on thread list
THREAD_NATIVE 6 off in a JNI native method
THREAD_VMWAIT 7 waiting on a VM resource
THREAD_SUSPENDED 8 suspended usually by GC or debugger

特别说明一下MONITOR状态和SUSPEND状态，MONITOR状态一般是类的同步块或者同步方法造成的，SUSPENDED状态在debugger的时候会出现，可以用来区别是不是真的是用户正常操作跑出了ANR。

后面一行

| group="main" sCount=1 dsCount=0 obj=0x415a4e88 self=0x414c48d8

group是线程组名称。sCount是此线程被挂起的次数，dsCount是线程被调试器挂起的次数，当一个进程被调试后，sCount会重置为0，调试完毕后sCount会根据是否被正常挂起增长，但是dsCount不会被重置为0，所以dsCount也可以用来判断这个线程是否被调试过。obj表示这个线程的Java对象的地址，self表示这个线程本身的地址。

此后是线程的调度信息

sysTid=901 nice=-2 sched=0/0 cgrp=apps handle=1073926484

sysTid是Linux下的内核线程id，nice是线程的调度优先级，sched分别标志了线程的调度策略和优先级，cgrp是调度属组，handle是线程的处理函数地址。

然后是线程当前上下文信息

state=S schedstat=( 303590361913 618664734427 651535 ) utm=19466 stm=10893 core=0

state是调度状态；schedstat从 /proc/[pid]/task/[tid]/schedstat读出，三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度，有的android内核版本不支持这项信息，得到的三个值都是0；utm是线程用户态下使用的时间值(单位是jiffies）;stm是内核态下的调度时间值；core是最后执行这个线程的cpu核的序号。

最后就是这个线程的调用栈信息。

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)

虽然应用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)
      ...

这种情况说明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)

从trace文件可以看出，发生ANR的主线程正处于monitor状态，也就是它在等待一个synchronized块或者方法，但是目前这个monitor正在被tid=11的线程持有，所以造成了主线程被阻塞，从而发生了ANR。死锁的分析也是类似，发生死锁的线程一般处于MONITOR状态或者WAIT状态，等待其他进程的锁或者monitor，而其他进程又在等待另外线程的锁或者monitor，一直这样依赖下去，直到形成一个环。

当然有的时候 trace back 中daemon 线程 含有 wailting 等 字眼可以忽略,因为他们是守护线程.

如:

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

````

"FinalizerWatchdogDaemon" daemon prio=5 tid=4 Waiting

`````

4.ANR 常见原因 总结

A.耗时操作，如复杂的layout，庞大的for循环，IO等。
    B.被Binder 对端block
    C.被子线程同步锁block
    D.Binder被占满导致主线程无法和SystemServer通信
    E.得不到系统资源（CPU/RAM/IO

1. 系统级别的线程阻塞导致的ANR

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

一般解决办法：

仔细查看ANR的成因（无外乎几种，iowait block memoryleak）

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

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

文章参考:

ANR问题Log分析

跑Monkey过程中出现的ANR问题分析

Android ANR问题原因分析

Android ANR分析

monkey 测试 ANR 问题 整理分析相关推荐

  1. Android Monkey测试入门：安装sdk、studio、模拟器，并分析monkey日志

    Android Monkey测试入门:安装sdk.studio.模拟器,并分析monkey测试报告结果 1. 安装Java JDK和android SDK 2. 安装Andriod studio及模拟 ...

  2. 由Monkey测试引发的跨多个进程的Android系统死锁问题分析

    一.问题现象 1.界面定住,没有任何刷新,所有输入事件无效,包括power key 2.adb shell可以连接并操作手机 3.手机的data和sdcard存储空间已满 4.watchdog没有重启 ...

  3. Monkey测试结果分析

    测试准备: Monkey压力测试时除了添加测试APP,还可另外添加2-3个第三方app进行对比测试. 1.在D盘新建一个txt文件,添加APP包名,命名为whitelist.txt 2.用cmd命令把 ...

  4. Android软件测试Monkey测试工具

    前言: 最近开始研究Android自动化测试方法,对其中的一些工具.方法和框架做了一些简单的整理,其中包括android测试框架.CTS.Monkey.Monkeyrunner.benchmark.其 ...

  5. 【Monkey测试】Monkey测试详解

    一.什么是 Monkey 测试 Monkey 测试是通过向系统发送伪随机的用户事件流(如按键输入.触摸屏输入.手势输入等),实现对应用程序客户端的稳定性测试: 通俗来说,Monkey 测试即" ...

  6. Monkey测试教程

    20170209整理 很抱歉,文档里的图片都未能copy过来... 什么是monkey,它能干什么? Monkey术语叫"猴子测试",是指没有测试经验的人进行的测试是毫无目的,乱按 ...

  7. App之Monkey测试

    作为初入测试行业的小白,了解一些Monkey测试是很有必要的,在此小编整理了一些App方面Monkey测试的基础以及Monkey脚本的编写,希望可以帮助到大家. 1. Monkey的概念 Monkey ...

  8. cmd与monkey测试

    monkey测试的相关命令 monkey是模拟用户触摸操作,不支持条件判断. monkey命令格式:  启动安卓模拟器/真机 点击运行->输入cmd->进入命令行界面 查看设备连接情况,a ...

  9. monkey测试_爱码小士丨 APP稳定性测试（附视频详解）

    在实际的测试过程中,主要是对系统的功能来进行测试,用于校验功能的正确性 还需要考虑到系统在未修改的状态下,是否能够稳定运行,即崩溃.闪退.重启.系统异常等等等地情况 在APP中,稳定性测试一般是交由M ...

最新文章

  1. 从文件中读取数据，排序之后输出到另一个文件中
  2. [机器学习-sklearn]K-means之make_blobs聚类数据生成器
  3. vs ajax工具包引用,vs2008中使用AJAX Control Tookit工具的问题？
  4. 【多媒体封装格式详解】---MKV【3】完
  5. FMEA-MSR 步骤五：风险分析（一）
  6. ssm框架整合springSecurity
  7. 删除计算机用户时拒绝访问权限,c盘为什么拒绝访问 删除c盘文件需要管理员权限怎么办...
  8. Vue 上传图片裁剪
  9. 戒指戴在不同手指上的含义
  10. 知识点滴 - X射线和伽马射线有什么区别？
  11. 让你久等了！《开源安全运维平台OSSIM疑难解析--入门篇》9月上市
  12. python结合conda安装ifcopenshell报错Preparing transaction: failed的解决办法
  13. win7设置防火墙允许Ping与telnet
  14. 视频压缩发微信朋友圈怎么弄
  15. 常用MySQL字段类型解析
  16. 计算机一级试题上网题收发邮件,计算机等级一级MS Office考题：第一套上网题
  17. Android一键锁屏代码
  18. 基于遗传算法的BP神经网络齿轮箱故障诊断实例
  19. Linux 的信号量
  20. ＜python开发＞ python开发 环境搭建(windows)

热门文章

  1. 机器人导航(仿真)(三)——路径规划(更新中)
  2. 正则表达式限制非中文字符输入
  3. 五大经典算法之四贪心算法
  4. 仿网易163的在线HTML编辑器及其轻量化结构
  5. 使用jQuery制作图书简介
  6. Uncaught ReferenceError: regeneratorRuntime is not defined 解决方法
  7. 使用AirCrack破解wifi密码（wpa/wpa2）
  8. 数据分析之数据相关性分析
  9. Java EE(进阶版)
  10. PPP 协议及配置解析