先声明这里只是讨论,因为很多ANR其实都属于异类的,看完Log一般都不知道真正原因及发生点,所以有高手知道怎么解决的话请在评论中指教!!!
先简单说说什么是异类ANR?
通常分析ANR先看MAIN_Log,确定ANR类型 ,发生类,发生时间、CPU状态、负载;再看trace.txt确定ANR发生位置。通过这两步能找出ANR原因的将之称为正常的。
看了Log和trace文件无法确定原因的称之为异类。
下面看看这个ANR:
10-21 03:16:19.350 743 764 E ANRManager: ANR in com.android.email (com.android.email/.activity.setup.AccountSetupBasics)
10-21 03:16:19.350 743 764 E ANRManager: Reason: Input dispatching timed out (Waiting because the focused window has not finished processing the input events that were previously delivered to it.)
10-21 03:16:19.350 743 764 E ANRManager: Load: 13.78 / 13.76 / 13.78
10-21 03:16:19.350 743 764 E ANRManager: Android time :[2014-10-21 03:16:19.338] [45486.172]
10-21 03:16:19.350 743 764 E ANRManager: CPU usage from 0ms to 8343ms later:
10-21 03:16:19.350 743 764 E ANRManager: 25% 4239/com.android.email: 22% user + 2.6% kernel / faults: 664 minor 34 major
10-21 03:16:19.350 743 764 E ANRManager: 19% 743/system_server: 13% user + 5.8% kernel / faults: 1922 minor 48 major
10-21 03:16:19.350 743 764 E ANRManager: 4.3% 875/com.android.systemui: 2.7% user + 1.5% kernel / faults: 1133 minor 7 major
10-21 03:16:19.350 743 764 E ANRManager: 3.7% 159/surfaceflinger: 1.1% user + 2.5% kernel / faults: 53 minor 5 major
10-21 03:16:19.350 743 764 E ANRManager: 2.7% 4754/mobile_log_d: 1.5% user + 1.1% kernel
10-21 03:16:19.350 743 764 E ANRManager: 2.1% 1124/com.android.inputmethod.latin: 1.9% user + 0.2% kernel / faults: 21 minor
10-21 03:16:19.350 743 764 E ANRManager: 1.7% 153/mobile_log_d: 0.1% user + 1.6% kernel / faults: 132 minor
10-21 03:16:19.350 743 764 E ANRManager: 1% 4757/mobile_log_d: 0% user + 1% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0.9% 1139/com.android.phone: 0.7% user + 0.2% kernel / faults: 385 minor 29 major
10-21 03:16:19.350 743 764 E ANRManager: 0.8% 28345/kworker/0:1: 0% user + 0.8% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0.4% 4221/adbd: 0% user + 0.3% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0.5% 46/kswapd0: 0% user + 0.5% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0.3% 4810/com.android.commands.monkey: 0.2% user + 0.1% kernel / faults: 23 minor
10-21 03:16:19.350 743 764 E ANRManager: 0.2% 83/mmcqd/0: 0% user + 0.2% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0% 1152/com.mediatek.bluetooth: 0% user + 0% kernel / faults: 302 minor 14 major
10-21 03:16:19.350 743 764 E ANRManager: 0% 4098/debuggerd: 0% user + 0% kernel / faults: 51 minor 12 major
10-21 03:16:19.350 743 764 E ANRManager: 0.3% 22987/kworker/u:1: 0% user + 0.3% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0.2% 73/bat_thread_kthr: 0% user + 0.2% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0.1% 88/disp_config_upd: 0% user + 0.1% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0.2% 1106/sdcard: 0% user + 0.2% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0.1% 28417/kworker/u:0: 0% user + 0.1% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0% 90/disp_ovl_kthrea: 0% user + 0% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0% 144/healthd: 0% user + 0% kernel
10-21 03:16:19.350 743 764 E ANRManager: 0% 154/netd: 0% user + 0% kernel / faults: 6 minor
10-21 03:16:19.350 743 764 E ANRManager: 0% 163/mediaserver: 0% user + 0% kernel / faults: 85 minor 80 major
10-21 03:16:19.350 743 764 E ANRManager: 0% 26563/kworker/0:3: 0% user + 0% kernel
10-21 03:16:19.350 743 764 E ANRManager: +0% 28480/migration/1: 0% user + 0% kernel
10-21 03:16:19.350 743 764 E ANRManager: +0% 28481/kworker/1:0: 0% user + 0% kernel
10-21 03:16:19.350 743 764 E ANRManager: +0% 28482/ksoftirqd/1: 0% user + 0% kernel
10-21 03:16:19.350 743 764 E ANRManager: +0% 28492/kworker/1:1: 0% user + 0% kernel
10-21 03:16:19.350 743 764 E ANRManager: 25% TOTAL: 16% user + 7.6% kernel + 0.8% iowait
Log如上:大体可以看到Email的AccountSetupBasics发送了触摸按键无响应的ANR,再看下面TOTAL,CPU不忙,内存充足,IO不阻塞,但就是没响应。
再看看trace.txt文件:
----- pid 4239 at 2014-10-21 03:16:11 -----
Cmd line: com.android.email
JNI: CheckJNI is off; workarounds are off; pins=0; globals=590 (plus 332 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=0x419cadf8 self=0x418e0900
| sysTid=4239 nice=-6 sched=0/0 cgrp=apps handle=1074233732
| state=S schedstat=( 9173941507546 2249617438186 11675112 ) utm=813012 stm=104382 core=0
#00 pc 00025b68 /system/lib/libc.so (__futex_syscall3+8)
#01 pc 0000fe98 /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
#02 pc 0000fef8 /system/lib/libc.so (__pthread_cond_timedwait+64)
#03 pc 00055953 /system/lib/libdvm.so
#04 pc 00055fe9 /system/lib/libdvm.so (dvmChangeStatus(Thread*, ThreadStatus)+34)
#05 pc 0004be7d /system/lib/libdvm.so
#06 pc 0004f249 /system/lib/libandroid_runtime.so (android::AndroidRuntime::getJNIEnv()+16)
#07 pc 00062ab3 /system/lib/libandroid_runtime.so (android::NativeDisplayEventReceiver::dispatchVsync(long long, int, unsigned int)+14)
#08 pc 00062c95 /system/lib/libandroid_runtime.so (android::NativeDisplayEventReceiver::handleEvent(int, int, void*)+80)
#09 pc 00010763 /system/lib/libutils.so (android::Looper::pollInner(int)+478)
#10 pc 00010811 /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)
#11 pc 0006c95d /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
#12 pc 0001e90c /system/lib/libdvm.so (dvmPlatformInvoke+112)
#13 pc 0004fdd1 /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+484)
#14 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:150)
at android.app.ActivityThread.main(ActivityThread.java:5323)
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:824)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:640)
at dalvik.system.NativeStart.main(Native Method)
主线程看上去很正常,没阻塞,没卡住,根本无法定位ANR发送的位置。
怎么办呢,看看event_log
event_log:
10-21 03:16:01.345 743 764 I am_proc_start: [0,28424,10048,com.google.android.talk,broadcast,com.google.android.talk/com.google.android.apps.babel.realtimechat.RealTimeChatService$AlarmReceiver]
10-21 03:16:01.383 743 902 I am_proc_bound: [0,28424,com.google.android.talk]
10-21 03:16:01.588 743 2776 I am_create_service: [0,1104933544,.RealTimeChatService,10048,28424]
10-21 03:16:01.593 743 753 I am_create_service: [0,1111721680,.UploaderIntentService,10007,32508]
10-21 03:16:01.688 743 1066 I am_destroy_service: [0,1104933544,28424]
10-21 03:16:06.636 743 4675 I am_create_service: [0,1114213488,.AnalyticsService,10007,32508]
10-21 03:16:11.020 743 764 I am_anr : [0,4239,com.android.email,8961605,Input dispatching timed out (Waiting because the focused window has not finished processing the input events that were previously delivered to it.)]
10-21 03:16:11.589 4239 4239 I menu_opened: 0
10-21 03:16:13.289 4239 4239 I menu_opened: 0
10-21 03:16:14.910 743 1191 I am_destroy_service: [0,1115715648,4863]
可以看出ANR前在创建一个聊天的服务和AnalyticsService服务,之后则在打开menu
到这里再次看看main_log,既然是输入事件没得到响应,那就看看是哪个输入事件没得到响应:根据时间点,搜索windowManager:
10-21 03:16:02.938 743 790 D WindowManager: interceptKeyTi keyCode=23 down=true repeatCount=0 keyguardOn=false mHomePressed=false canceled=false metaState:0
10-21 03:16:10.947 743 790 I WindowManager: Input event dispatching timed out sending to com.android.email/com.android.email.activity.setup.AccountSetupBasics
搜索后,可以看出03:16:02.938这个时间点输入一个keyCode=23的输入事件,直到 03:16:10.947 整整8s还没得到响应,所以报ANR了。
那么就得着重看这短时间CPU都在干嘛呢????
刚才event_log已有显示在忙着创建10-21 03:16:06.636 743 4675 I am_create_service: [0,1114213488,.AnalyticsService,10007,32508]服务 。
该服务在main_log中如下:
10-21 03:16:06.640 32508 32508 D ActivityThread: SVC-Creating service: CreateServiceData{token=android.os.BinderProxy@41e095f8 className=com.google.android.gms.analytics.service.AnalyticsService packageName=com.google.android.gms intent=null}
属于gms包中的一个登陆Google邮箱配置邮箱参数的解析服务。
所以这是一个Google的服务,是登陆Google邮箱需要的一个服。而ANR发生的类是com.android.email.activity.setup.AccountSetupBasics邮箱登陆时基本配置类。
就此,可以推断出,该ANR是因为登录配置时无法创建Google的com.google.android.gms.analytics.service.AnalyticsService服务导致的。
不过似乎还没确定问题的发生点:
查看AccountSetupBasics.java类,就只有onCreate方法中有Service相关登陆邮箱配置初始化参数的操作:
if (ServiceProxy.getIntentStringForEmailPackage(
this, ACTION_CREATE_ACCOUNT).equals(action)) {
mSetupData = new SetupData(SetupData.FLOW_MODE_FORCE_CREATE);
} else {
final int intentFlowMode =
intent.getIntExtra(EXTRA_FLOW_MODE, SetupData.FLOW_MODE_UNSPECIFIED);
if (intentFlowMode != SetupData.FLOW_MODE_UNSPECIFIED) {
mSetupData = new SetupData(intentFlowMode,
intent.getStringExtra(EXTRA_FLOW_ACCOUNT_TYPE));
}
}
不知道上面的分析是否正确,欢迎各位大虾指教!!!!!!