天天看点

讨论异类ANR解决之道?????

先声明这里只是讨论,因为很多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{[email protected] 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));

            }

        }

故发生问题点确定。

不知道上面的分析是否正确,欢迎各位大虾指教!!!!!!

继续阅读