Android系统调试（02）ANR问题总结

该系列文章总纲链接：专题分纲目录 Android系统基础

ANR问题是Android系统中比较常见的问题，当出现ANR时一般情况会弹出一个带有以下文字的对话框提示（Android版本不同，展示效果会有不同）：Activity XXX(in XXXXX) is not responding。如下所示：

Android系统调试（02）ANR问题总结_第1张图片

在Android中，ActivityManagerService(简称AMS)和WindowManagerService(简称WMS)会监测应用程序的响应时间，如果应用程序主线程(即UI线程)在超时时间内对输入事件没有处理完毕，或者对特定操作没有执行完毕，就会出现ANR。对于输入事件没有处理完毕产生的ANR，Android会显示一个对话框，提示用户当前应用程序没有响应，用户可以选择继续等待或者关闭这个应用程序（也就是杀掉这个应用程序的进程并记录日志）。

ANR的产生需要同时满足三个条件：

主线程：只有应用程序进程的主线程响应超时才会产生ANR；
超时时间：产生ANR的上下文不同，超时时间也会不同，但只要在这个时间上限内没有响应就会ANR；
输入事件/特定操作：输入事件是指按键、触屏等设备输入事件，特定操作是指BroadcastReceiver和Service的生命周期中的各个函数，产生ANR的上下文不同，导致ANR的原因也会不同；

1 ANR的类型与解决方法

ANR出现的问题主要体现在超时上，即在规定时间内没有完成任务(在java层和native层都会出现该问题)

@1 在Java层出现该ANR问题的情况如下：

Android系统调试（02）ANR问题总结_第2张图片

具体的超时时间的定义在framework下的ActivityManagerService.java，代码如下：

//How long we wait until we timeout on key dispatching.staticfinal int KEY_DISPATCHING_TIMEOUT = 5*1000

几种常见的超时操作总结如下：

Android系统调试（02）ANR问题总结_第3张图片

@2 在Native层出现该ANR问题的情况如下(很少在该层出现该问题)：

一般在修改Native层显示相关的代码，尤其是在渲染时延迟，就很有可能会出现ANR，而且是偶现问题。比如：在SurfaceFlinger的渲染流程中，针对多帧数据，如果一帧数据在渲染时，偶尔会有渲染延迟也会导致ANR。

2 如何分析ANR

@1 分析流程，实例LOG如下:

17-02 13:12:11.572 I/InputDispatcher( 220): Application is not responding:Window{2b263310com.android.email/com.android.email.activity.SplitScreenActivitypaused=false}.  5009.8ms since event, 5009.5ms since waitstarted17-02 13:12:11.572 I/WindowManager( 220): Input event dispatching timedout sending tocom.android.email/com.android.email.activity.SplitScreenActivity17-02 13:12:14.123 I/Process(  220): Sending signal. PID: 21404 SIG: 3---发生ANR的时间和生成trace.txt的时间17-02 13:12:14.123 I/dalvikvm(21404):threadid=4: reacting to signal 3 ……17-02 13:12:15.872 E/ActivityManager(  220): ANR in com.android.email(com.android.email/.activity.SplitScreenActivity)17-02 13:12:15.872 E/ActivityManager(  220): Reason:keyDispatchingTimedOut17-02 13:12:15.872 E/ActivityManager(  220): Load: 8.68 / 8.37 / 8.5317-02 13:12:15.872 E/ActivityManager(  220): CPUusage from 4361ms to 699ms ago ----CPU在ANR发生前的使用情况      17-02 13:12:15.872 E/ActivityManager(  220):   5.5%21404/com.android.email: 1.3% user + 4.1% kernel / faults: 10 minor17-02 13:12:15.872 E/ActivityManager(  220):   4.3%220/system_server: 2.7% user + 1.5% kernel / faults: 11 minor 2 major17-02 13:12:15.872 E/ActivityManager(  220):   0.9%52/spi_qsd.0: 0% user + 0.9% kernel17-02 13:12:15.872 E/ActivityManager(  220):   0.5%65/irq/170-cyttsp-: 0% user + 0.5% kernel17-02 13:12:15.872 E/ActivityManager(  220):   0.5%296/com.android.systemui: 0.5% user + 0% kernel17-02 13:12:15.872 E/ActivityManager(  220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait17-02 13:12:15.872 E/ActivityManager(  220): CPUusage from 3697ms to 4223ms later:-- ANR后CPU的使用量17-02 13:12:15.872 E/ActivityManager(  220):   25%21404/com.android.email: 25% user + 0% kernel / faults: 191 minor17-02 13:12:15.872 E/ActivityManager(  220):    16% 21603/__eas(par.hakan: 16% user + 0% kernel17-02 13:12:15.872 E/ActivityManager(  220):    7.2% 21406/GC: 7.2% user + 0% kernel17-02 13:12:15.872 E/ActivityManager(  220):    1.8% 21409/Compiler: 1.8% user + 0% kernel17-02 13:12:15.872 E/ActivityManager(  220):   5.5%220/system_server: 0% user + 5.5% kernel / faults: 1 minor17-02 13:12:15.872 E/ActivityManager(  220):    5.5% 263/InputDispatcher: 0% user + 5.5% kernel17-02 13:12:15.872 E/ActivityManager(  220): 32%TOTAL: 28% user + 3.7% kernel

从LOG可以看出ANR的类型，CPU的使用情况，如果CPU使用量接近100%，说明当前设备很忙，有可能是CPU饥饿导致了ANR
。分析中如果发现CPU使用量很少，说明主线程被BLOCK了；如果IOwait很高，说明ANR有可能是主线程在进行I/O操作造成的
。除了看LOG，解决ANR还得需要trace.txt文件，可以用如下命令获取trace.txt文件，如下：

$chmod 777 /data/anr$rm /data/anr/traces.txt$ps$kill -3 PIDadb pull data/anr/traces.txt ./mytraces.txt

从trace.txt文件，看到最多的是如下的信息：

-----pid 21404 at 2017-02-09 13:12:14 -----  Cmdline: com.android.emailDALVIK THREADS:(mutexes: tll=0tsl=0 tscl=0 ghl=0 hwl=0 hwll=0)"main" prio=5 tid=1NATIVE  | group="main" sCount=1 dsCount=0obj=0x2aad2248 self=0xcf70  | sysTid=21404 nice=0 sched=0/0cgrp=[fopen-error:2] handle=1876218976  atandroid.os.MessageQueue.nativePollOnce(Native Method)  atandroid.os.MessageQueue.next(MessageQueue.java:119)  atandroid.os.Looper.loop(Looper.java:110) at android.app.ActivityThread.main(ActivityThread.java:3688) at java.lang.reflect.Method.invokeNative(Native Method)  atjava.lang.reflect.Method.invoke(Method.java:507)  atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:624) at dalvik.system.NativeStart.main(Native Method)

说明主线程在等待下条消息进入消息队列
调查并解决ANR问题的流程如下：

首先分析log
从trace.txt文件查看调用stack.
看代码
仔细查看ANR的成因（无外乎几种，iowait block memoryleak）

@2 案例，关键词:ContentResolver in AsyncTask onPostExecute, high iowait

Process:com.android.emailActivity:com.android.email/.activity.MessageViewSubject:keyDispatchingTimedOutCPU usage from 2550ms to -2814ms ago:5%187/system_server: 3.5% user + 1.4% kernel / faults: 86 minor 20major4.4% 1134/com.android.email: 0.7% user + 3.7% kernel /faults: 38 minor 19 major4% 372/com.android.eventstream: 0.7%user + 3.3% kernel / faults: 6 minor1.1% 272/com.android.phone:0.9% user + 0.1% kernel / faults: 33 minor0.9%252/com.android.systemui: 0.9% user + 0% kernel0%409/com.android.eventstream.telephonyplugin: 0% user + 0% kernel /faults: 2 minor0.1% 632/com.android.devicemonitor: 0.1% user + 0%kernel100%TOTAL: 6.9% user + 8.2% kernel +84%iowait

日志信息如下：

-----pid 1134 at 2016-12-17 16:46:51 -----Cmd line:com.android.emailDALVIK 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=1876218976at java.lang.Object.wait(Native Method)-waiting on <0x2aaca218> (a java.lang.VMThread)atjava.lang.Thread.parkFor(Thread.java:1424)atjava.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)atsun.misc.Unsafe.park(Unsafe.java:337)atjava.util.concurrent.locks.LockSupport.park(LockSupport.java:157)atjava.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:808)atjava.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:841)atjava.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1171)atjava.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:200)atjava.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261)atandroid.database.sqlite.SQLiteDatabase.lock(SQLiteDatabase.java:378)atandroid.database.sqlite.SQLiteCursor.(SQLiteCursor.java:222)atandroid.database.sqlite.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:53)atandroid.database.sqlite.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1356)atandroid.database.sqlite.SQLiteDatabase.queryWithFactory(SQLiteDatabase.java:1235)atandroid.database.sqlite.SQLiteDatabase.query(SQLiteDatabase.java:1189)atandroid.database.sqlite.SQLiteDatabase.query(SQLiteDatabase.java:1271)atcom.android.email.provider.EmailProvider.query(EmailProvider.java:1098)atandroid.content.ContentProvider$Transport.query(ContentProvider.java:187)atandroid.content.ContentResolver.query(ContentResolver.java:268)atcom.android.email.provider.EmailContent$Message.restoreMessageWithId(EmailContent.java:648)atcom.android.email.Controller.setMessageRead(Controller.java:658)atcom.android.email.activity.MessageView.onMarkAsRead(MessageView.java:700)atcom.android.email.activity.MessageView.access$2500(MessageView.java:98)atcom.android.email.activity.MessageView$LoadBodyTask.onPostExecute(MessageView.java:1290)atcom.android.email.activity.MessageView$LoadBodyTask.onPostExecute(MessageView.java:1255)atandroid.os.AsyncTask.finish(AsyncTask.java:417)atandroid.os.AsyncTask.access$300(AsyncTask.java:127)atandroid.os.AsyncTask$InternalHandler.handleMessage(AsyncTask.java:429)atandroid.os.Handler.dispatchMessage(Handler.java:99)atandroid.os.Looper.loop(Looper.java:123)atandroid.app.ActivityThread.main(ActivityThread.java:3652)atjava.lang.reflect.Method.invokeNative(Native Method)atjava.lang.reflect.Method.invoke(Method.java:507)atcom.android.internal.os.ZygoteIn

分析原因：从日志中看出，IOWait很高，说明当前系统在忙于I/O，因此数据库操作被阻塞，问题关键点在这，原来：

finalMessagemessage=Message.restoreMessageWithId(mProviderContext,messageId);//可能阻塞if(message==null){   return;}Accountaccount=Account.restoreAccountWithId(mProviderContext,message.mAccountKey);//可能阻塞if(account==null){   return;//isMessagingController returns false for null, but let's make itclear.}if(isMessagingController(account)){   newThread(){       @Override       publicvoidrun(){          mLegacyController.processPendingActions(message.mAccountKey);       }   }.start();}

解决后：

newThread() {    finalMessagemessage=Message.restoreMessageWithId(mProviderContext,messageId);    if(message==null){       return;    }    Accountaccount=Account.restoreAccountWithId(mProviderContext,message.mAccountKey);    if(account==null){        return;//isMessagingController returns false for null, but let's make itclear.    }    if(isMessagingController(account)) {        mLegacyController.processPendingActions(message.mAccountKey);      }}.start();

@3 案例，关键词:在UI线程进行网络数据的读写

ANR in process: com.android.mediascape:PhotoViewer (last incom.android.mediascape:PhotoViewer)Annotation:keyDispatchingTimedOutCPU usage:Load: 6.74 / 6.89 / 6.12CPUusage from 8254ms to 3224ms ago:ovider.webmedia: 4% = 4% user +0% kernel / faults: 68 minorsystem_server: 2% = 1% user + 0%kernel / faults: 18 minorre-initialized>: 0% = 0% user + 0%kernel / faults: 50 minorevents/0: 0% = 0% user + 0%kernelTOTAL:7% = 6% user + 1% kernel

日志信息如下：

DALVIKTHREADS:""main"" prio=5 tid=3 NATIVE|group=""main"" sCount=1 dsCount=0 s=Yobj=0x4001b240 self=0xbda8| sysTid=2579 nice=0 sched=0/0cgrp=unknown handle=-1343993184atorg.apache.harmony.luni.platform.OSNetworkSystem.receiveStreamImpl(NativeMethod)atorg.apache.harmony.luni.platform.OSNetworkSystem.receiveStream(OSNetworkSystem.java:478)atorg.apache.harmony.luni.net.PlainSocketImpl.read(PlainSocketImpl.java:565)atorg.apache.harmony.luni.net.SocketInputStream.read(SocketInputStream.java:87)atorg.apache.harmony.luni.internal.net.www.protocol.http.HttpURLConnection$LimitedInputStream.read(HttpURLConnection.java:303)atjava.io.InputStream.read(InputStream.java:133)atjava.io.BufferedInputStream.fillbuf(BufferedInputStream.java:157)atjava.io.BufferedInputStream.read(BufferedInputStream.java:346)atandroid.graphics.BitmapFactory.nativeDecodeStream(Native Method)atandroid.graphics.BitmapFactory.decodeStream(BitmapFactory.java:459)atcom.android.mediascape.activity.PhotoViewerActivity.getPreviewImage(PhotoViewerActivity.java:4465)atcom.android.mediascape.activity.PhotoViewerActivity.dispPreview(PhotoViewerActivity.java:4406)atcom.android.mediascape.activity.PhotoViewerActivity.access$6500(PhotoViewerActivity.java:125)atcom.android.mediascape.activity.PhotoViewerActivity$33$1.run(PhotoViewerActivity.java:4558)atandroid.os.Handler.handleCallback(Handler.java:587)atandroid.os.Handler.dispatchMessage(Handler.java:92)atandroid.os.Looper.loop(Looper.java:123)atandroid.app.ActivityThread.main(ActivityThread.java:4370)atjava.lang.reflect.Method.invokeNative(Native Method)atjava.lang.reflect.Method.invoke(Method.java:521)atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868)atcom.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)at dalvik.system.NativeStart.main(Native Method)

关于网络连接，再设计的时候可以设置个timeout的时间(小于)或者放入独立的线程来处理。

@4 案例，关键词：Memoryleak/Thread leak

11-16 21:41:42.560 I/ActivityManager( 1190): ANR in process:android.process.acore (last in android.process.acore)11-16 21:41:42.560 I/ActivityManager( 1190): Annotation:keyDispatchingTimedOut11-16 21:41:42.560 I/ActivityManager(1190): CPU usage:11-16 21:41:42.560 I/ActivityManager( 1190):Load: 11.5 / 11.1 / 11.0911-16 21:41:42.560 I/ActivityManager(1190): CPU usage from 9046ms to 4018ms ago:11-16 21:41:42.560I/ActivityManager( 1190): d.process.acore:98%= 97% user + 0% kernel / faults: 1134 minor11-16 21:41:42.560I/ActivityManager( 1190): system_server: 0% = 0% user + 0% kernel /faults: 1 minor11-16 21:41:42.560 I/ActivityManager( 1190): adbd:0% = 0% user + 0% kernel11-16 21:41:42.560 I/ActivityManager(1190): logcat: 0% = 0% user + 0% kernel11-16 21:41:42.560I/ActivityManager( 1190): TOTAL:100% = 98% user + 1% kernel

日志信息如下：

DALVIK THREADS:"main"prio=5 tid=3 VMWAIT|group="main" sCount=1 dsCount=0 s=N obj=0x40026240self=0xbda8| sysTid=1815 nice=0 sched=0/0 cgrp=unknownhandle=-1344001376atdalvik.system.VMRuntime.trackExternalAllocation(NativeMethod)atandroid.graphics.Bitmap.nativeCreate(Native Method)atandroid.graphics.Bitmap.createBitmap(Bitmap.java:468)atandroid.view.View.buildDrawingCache(View.java:6324)atandroid.view.View.getDrawingCache(View.java:6178)atandroid.view.ViewGroup.drawChild(ViewGroup.java:1541)……atcom.android.internal.policy.impl.PhoneWindow$DecorView.draw(PhoneWindow.java:1830)atandroid.view.ViewRoot.draw(ViewRoot.java:1349)atandroid.view.ViewRoot.performTraversals(ViewRoot.java:1114)atandroid.view.ViewRoot.handleMessage(ViewRoot.java:1633)atandroid.os.Handler.dispatchMessage(Handler.java:99)atandroid.os.Looper.loop(Looper.java:123)atandroid.app.ActivityThread.main(ActivityThread.java:4370)atjava.lang.reflect.Method.invokeNative(Native Method)atjava.lang.reflect.Method.invoke(Method.java:521)atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868)atcom.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)atdalvik.system.NativeStart.main(Native Method)"Thread-408"prio=5 tid=329 WAIT|group="main" sCount=1 dsCount=0 s=N obj=0x46910d40self=0xcd0548| sysTid=10602 nice=0 sched=0/0 cgrp=unknownhandle=15470792at java.lang.Object.wait(Native Method)-waiting on <0x468cd420> (a java.lang.Object)atjava.lang.Object.wait(Object.java:288)atcom.android.dialer.CallLogContentHelper$UiUpdaterExecutor$1.run(CallLogContentHelper.java:289)atjava.lang.Thread.run(Thread.java:1096)

分析：at dalvik.system.VMRuntime.trackExternalAllocation(NativeMethod)内存不足导致block在创建bitmap上。

**MEMINFO in pid 1360 [android.process.acore] **native dalvik other totalsize: 17036 23111 N/A 40147allocated: 16484 20675 N/A 37159free: 296 2436 N/A 2732

解决：如果机器的内存足，可以修改虚拟机的内存为36M或更大，不过最好是复查代码，查看哪些内存没有释放
附加说明：Linux信号说明{在出现堆栈错误问题时，一般都会有相应的SIGNAL，9和11最常见}

 1) SIGHUP       2) SIGINT       3) SIGQUIT      4) SIGILL       5) SIGTRAP   6) SIGABRT      7) SIGBUS       8) SIGFPE       9) SIGKILL     10) SIGUSR1  11) SIGSEGV     12) SIGUSR2     13) SIGPIPE     14) SIGALRM     15) SIGTERM 16) SIGSTKFLT   17) SIGCHLD     18) SIGCONT     19) SIGSTOP     20) SIGTSTP  21) SIGTTIN     22) SIGTTOU     23) SIGURG      24) SIGXCPU     25) SIGXFSZ  26) SIGVTALRM   27) SIGPROF     28) SIGWINCH    29) SIGIO       30) SIGPWR  31) SIGSYS      34) SIGRTMIN    35) SIGRTMIN+1  36) SIGRTMIN+2  37) SIGRTMIN+3  38) SIGRTMIN+4  39) SIGRTMIN+5  40) SIGRTMIN+6  41) SIGRTMIN+7  42) SIGRTMIN+8  43) SIGRTMIN+9  44) SIGRTMIN+10 45) SIGRTMIN+11 46) SIGRTMIN+12 47) SIGRTMIN+13  48) SIGRTMIN+14 49) SIGRTMIN+15 50) SIGRTMAX-14 51) SIGRTMAX-13 52) SIGRTMAX-12  53) SIGRTMAX-11 54) SIGRTMAX-10 55) SIGRTMAX-9  56) SIGRTMAX-8  57) SIGRTMAX-7  58) SIGRTMAX-6  59) SIGRTMAX-5  60) SIGRTMAX-4  61) SIGRTMAX-3  62) SIGRTMAX-2  63) SIGRTMAX-1  64) SIGRTMAX

信号的详细描述如下：

Signal     DescriptionSIGABRT    由调用abort函数产生，进程非正常退出SIGALRM    用alarm函数设置的timer超时或setitimer函数设置的interval timer超时SIGBUS     某种特定的硬件异常，通常由内存访问引起SIGCANCEL  由Solaris Thread Library内部使用，通常不会使用SIGCHLD    进程Terminate或Stop的时候，SIGCHLD会发送给它的父进程。缺省情况下该Signal会被忽略SIGCONT    当被stop的进程恢复运行的时候，自动发送SIGEMT     和实现相关的硬件异常SIGFPE     数学相关的异常，如被0除，浮点溢出，等等SIGFREEZE  Solaris专用，Hiberate或者Suspended时候发送SIGHUP     发送给具有Terminal的Controlling Process，当terminal被disconnect时候发送SIGILL     非法指令异常SIGINFO    BSD signal。由Status Key产生，通常是CTRL+T。发送给所有Foreground Group的进程SIGINT     由Interrupt Key产生，通常是CTRL+C或者DELETE。发送给所有ForeGround Group的进程SIGIO      异步IO事件SIGIOT     实现相关的硬件异常，一般对应SIGABRTSIGKILL    无法处理和忽略。中止某个进程SIGLWP     由Solaris Thread Libray内部使用SIGPIPE    在reader中止之后写Pipe的时候发送SIGPOLL    当某个事件发送给Pollable Device的时候发送SIGPROF    Setitimer指定的Profiling Interval Timer所产生SIGPWR     和系统相关。和UPS相关。SIGQUIT    输入Quit Key的时候（CTRL+\）发送给所有Foreground Group的进程SIGSEGV    非法内存访问SIGSTKFLT  Linux专用，数学协处理器的栈异常SIGSTOP    中止进程。无法处理和忽略。SIGSYS     非法系统调用SIGTERM    请求中止进程，kill命令缺省发送SIGTHAW    Solaris专用，从Suspend恢复时候发送SIGTRAP    实现相关的硬件异常。一般是调试异常SIGTSTP    Suspend Key，一般是Ctrl+Z。发送给所有Foreground Group的进程SIGTTIN    当Background Group的进程尝试读取Terminal的时候发送SIGTTOU    当Background Group的进程尝试写Terminal的时候发送SIGURG     当out-of-band data接收的时候可能发送SIGUSR1    用户自定义signal 1SIGUSR2    用户自定义signal 2SIGVTALRM  setitimer函数设置的Virtual Interval Timer超时的时候SIGWAITING Solaris Thread Library内部实现专用SIGWINCH   当Terminal的窗口大小改变的时候，发送给Foreground Group的所有进程SIGXCPU    当CPU时间限制超时的时候SIGXFSZ    进程超过文件大小限制SIGXRES    Solaris专用，进程超过资源限制的时候发送

更多相关文章

随机推荐