Android系统调试(02)ANR问题总结（android调试技巧）

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

在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问题的情况如下：

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

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

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

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

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

2 如何分析ANR

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

Bash
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 waitstarted
17-02 13:12:11.572 I/WindowManager( 220): Input event dispatching timedout sending tocom.android.email/com.android.email.activity.SplitScreenActivity
17-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:keyDispatchingTimedOut
17-02 13:12:15.872 E/ActivityManager( 220): Load: 8.68 / 8.37 / 8.53
17-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 minor
17-02 13:12:15.872 E/ActivityManager( 220): 4.3%220/system_server: 2.7% user + 1.5% kernel / faults: 11 minor 2 major
17-02 13:12:15.872 E/ActivityManager( 220): 0.9%52/spi_qsd.0: 0% user + 0.9% kernel
17-02 13:12:15.872 E/ActivityManager( 220): 0.5%65/irq/170-cyttsp-: 0% user + 0.5% kernel
17-02 13:12:15.872 E/ActivityManager( 220): 0.5%296/com.android.systemui: 0.5% user + 0% kernel
17-02 13:12:15.872 E/ActivityManager( 220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait
17-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 minor
17-02 13:12:15.872 E/ActivityManager( 220): 16% 21603/__eas(par.hakan: 16% user + 0% kernel
17-02 13:12:15.872 E/ActivityManager( 220): 7.2% 21406/GC: 7.2% user + 0% kernel
17-02 13:12:15.872 E/ActivityManager( 220): 1.8% 21409/Compiler: 1.8% user + 0% kernel
17-02 13:12:15.872 E/ActivityManager( 220): 5.5%220/system_server: 0% user + 5.5% kernel / faults: 1 minor
17-02 13:12:15.872 E/ActivityManager( 220): 5.5% 263/InputDispatcher: 0% user + 5.5% kernel
17-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文件，如下：

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

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

Bash
-----pid 21404 at 2017-02-09 13:12:14 ----- 
Cmdline: com.android.email
DALVIK 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

Bash
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

日志信息如下：

Bash
-----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.ReentrantLock.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.invokeNative(Native Method)
atjava.lang.reflect.Method.invoke(Method.java:507)
atcom.android.internal.os.ZygoteIn

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

Java
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();
}

解决后：

Java
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线程进行网络数据的读写

Bash
ANR in process: com.android.mediascape:PhotoViewer (last incom.android.mediascape:PhotoViewer)
Annotation:keyDispatchingTimedOut
CPU usage:
Load: 6.74 / 6.89 / 6.12
CPUusage from 8254ms to 3224ms ago:
ovider.webmedia: 4% = 4% user +0% kernel / faults: 68 minor
system_server: 2% = 1% user + 0%kernel / faults: 18 minor
re-initialized>: 0% = 0% user + 0%kernel / faults: 50 minor
events/0: 0% = 0% user + 0%kernel
TOTAL:7% = 6% user + 1% kernel

日志信息如下：

Bash
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=-1343993184
atorg.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

Bash
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:keyDispatchingTimedOut
11-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.09
11-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 minor
11-16 21:41:42.560I/ActivityManager( 1190): system_server: 0% = 0% user + 0% kernel /faults: 1 minor
11-16 21:41:42.560 I/ActivityManager( 1190): adbd:0% = 0% user + 0% kernel
11-16 21:41:42.560 I/ActivityManager(1190): logcat: 0% = 0% user + 0% kernel
11-16 21:41:42.560I/ActivityManager( 1190): TOTAL:100% = 98% user + 1% kernel

日志信息如下：

Bash
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=-1344001376
atdalvik.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=15470792
at 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上。

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

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

Bash
 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

信号的详细描述如下：

Bash
Signal Description
SIGABRT 由调用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 实现相关的硬件异常，一般对应SIGABRT
SIGKILL 无法处理和忽略。中止某个进程
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 1
SIGUSR2 用户自定义signal 2
SIGVTALRM setitimer函数设置的Virtual Interval Timer超时的时候
SIGWAITING Solaris Thread Library内部实现专用
SIGWINCH 当Terminal的窗口大小改变的时候，发送给Foreground Group的所有进程
SIGXCPU 当CPU时间限制超时的时候
SIGXFSZ 进程超过文件大小限制
SIGXRES Solaris专用，进程超过资源限制的时候发送