App Not Responsing

参见原文：http://rayleeya.iteye.com/blog/1955657

---

• inputDispatchingTimedOut
• contentProviderNotResponsing
• serviceTimedOut
• broadcastReceiverTimedOut

trace信息会输出到"/data/anr/traces.txt"中，这是由系统属性"dalvik.vm.stack-trace-file"来配置的，可以在adb shell中通过getprop来获得，也可以通过setprop来设定。

---

traces.txt信息详解：

//文件中输出的第一个进程的trace信息，正是发生ANR的演示程序

//开头显示进程号、ANR发生的时间点和进程名称

----- pid 9183 at 2012-09-28 22:20:42 -----

Cmd line: com.example.anrdemo

 

DALVIK THREADS: //以下是各个线程的函数堆栈信息

//mutexes表示虚拟机实例中各种线程相关对象锁的value值

(mutexes: tll=0 tsl=0 tscl=0 ghl=0 hwl=0 hwll=0)

//依次是：线程名、线程优先级、线程创建时的序号、①线程当前状态

"main" prio=5 tid=1 TIMED_WAIT

//依次是：线程组名称、suspendCount、debugSuspendCount、线程的Java对象地址、线程的Native对象地址

| group="main" sCount=1 dsCount=0 obj=0x4025b1b8 self=0xce68

//sysTid是线程号，主线程的线程号和进程号相同

| sysTid=9183 nice=0 sched=0/0 cgrp=default handle=-1345002368

| schedstat=( 140838632 210998525 213 )

at java.lang.VMThread.sleep(Native Method)

at java.lang.Thread.sleep(Thread.java:1213)

at java.lang.Thread.sleep(Thread.java:1195)

at com.example.anrdemo.ANRActivity.makeANR(ANRActivity.java:44)

at com.example.anrdemo.ANRActivity.onClick(ANRActivity.java:38)

at android.view.View.performClick(View.java:2486)

at android.view.View$PerformClick.run(View.java:9130)

at android.os.Handler.handleCallback(Handler.java:587)

at android.os.Handler.dispatchMessage(Handler.java:92)

at android.os.Looper.loop(Looper.java:130)

at android.app.ActivityThread.main(ActivityThread.java:3703)

at java.lang.reflect.Method.invokeNative(Native Method)

at java.lang.reflect.Method.invoke(Method.java:507)

at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:841)

at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:599)

at dalvik.system.NativeStart.main(Native Method)

 

//Binder线程是进程的线程池中用来处理binder请求的线程,这个应该是ViewRoot的W类，用来与WMS进行IPC通信

"Binder Thread #2" prio=5 tid=8 NATIVE

| group="main" sCount=1 dsCount=0 obj=0x40750b90 self=0x1440b8

| sysTid=9190 nice=0 sched=0/0 cgrp=default handle=1476256

| schedstat=( 915528 18463135 4 )

at dalvik.system.NativeStart.run(Native Method)

 

//应该是ActivityThread的ApplicationThread的Binder线程，用来和AMS进行IPC通信 

"Binder Thread #1" prio=5 tid=7 NATIVE

| group="main" sCount=1 dsCount=0 obj=0x4074f848 self=0x78d40

| sysTid=9189 nice=0 sched=0/0 cgrp=default handle=1308088

| schedstat=( 3509523 25543212 10 )

at dalvik.system.NativeStart.run(Native Method)

 

//线程名称后面标识有daemon，说明这是个守护线程

"Compiler" daemon prio=5 tid=6 VMWAIT

| group="system" sCount=1 dsCount=0 obj=0x4074b928 self=0x141e78

| sysTid=9188 nice=0 sched=0/0 cgrp=default handle=1506000

| schedstat=( 21606438 21636964 101 )

at dalvik.system.NativeStart.run(Native Method)

 

//JDWP线程是支持虚拟机调试的线程，不需要关心

"JDWP" daemon prio=5 tid=5 VMWAIT

| group="system" sCount=1 dsCount=0 obj=0x4074b878 self=0x16c958

| sysTid=9187 nice=0 sched=0/0 cgrp=default handle=1510224

| schedstat=( 366211 2807617 7 )

at dalvik.system.NativeStart.run(Native Method)

 

//“Signal Catcher”负责接收和处理kernel发送的各种信号，例如SIGNAL_QUIT、SIGNAL_USR1等就是被该线程

//接收到，这个文件的内容就是由该线程负责输出的，可以看到它的状态是RUNNABLE，不过此线程也不需要关心

"Signal Catcher" daemon prio=5 tid=4 RUNNABLE

| group="system" sCount=0 dsCount=0 obj=0x4074b7b8 self=0x150008

| sysTid=9186 nice=0 sched=0/0 cgrp=default handle=1501664

| schedstat=( 1708985 6286621 9 )

at dalvik.system.NativeStart.run(Native Method)

 

"GC" daemon prio=5 tid=3 VMWAIT

| group="system" sCount=1 dsCount=0 obj=0x4074b710 self=0x168010

| sysTid=9185 nice=0 sched=0/0 cgrp=default handle=1503184

| schedstat=( 305176 4821778 2 )

at dalvik.system.NativeStart.run(Native Method)

 

"HeapWorker" daemon prio=5 tid=2 VMWAIT

| group="system" sCount=1 dsCount=0 obj=0x4074b658 self=0x16a080

| sysTid=9184 nice=0 sched=0/0 cgrp=default handle=550856

| schedstat=( 33691407 26336669 15 )

at dalvik.system.NativeStart.run(Native Method)

 

----- end 9183 -----

 

----- pid 127 at 2012-09-28 22:20:42 -----

Cmd line: system_server

... ...

//省略其他进程的信息

 

有一个关键点需要注意：

➀ 线程有很多状态，了解这些状态的意义对分析ANR的原因是有帮助的，总结如下：

 

Thread.java中定义的状态	Thread.cpp中定义的状态	说明
TERMINATED	ZOMBIE	线程死亡，终止运行
RUNNABLE	RUNNING/RUNNABLE	线程可运行或正在运行
TIMED_WAITING	TIMED_WAIT	执行了带有超时参数的wait、sleep或join函数
BLOCKED	MONITOR	线程阻塞，等待获取对象锁
WAITING	WAIT	执行了无超时参数的wait函数
NEW	INITIALIZING	新建，正在初始化，为其分配资源
NEW	STARTING	新建，正在启动
RUNNABLE	NATIVE	正在执行JNI本地函数
WAITING	VMWAIT	正在等待VM资源
RUNNABLE	SUSPENDED	线程暂停，通常是由于GC或debug被暂停
	UNKNOWN	未知状态

 

Thread.java中的状态和Thread.cpp中的状态是有对应关系的。可以看到前者更加概括，也比较容易理解，面向Java的使用者；而后者更详细，面向虚拟机内部的环境。traces.txt中显示的线程状态都是Thread.cpp中定义的。另外，所有的线程都是遵循POSIX标准的本地线程。关于线程更多的说明可以查阅源码/dalvik/vm/Thread.cpp中的说明。<!-- 线程的ThreadGroup最好也写进去 -->

traces.txt文件中的这些信息是由每个Dalvik进程的SignalCatcher线程输出的，相关代码可以查看/dalvik/vm/目录下的SignalCatcher.cpp::logThreadStacks函数和Thread.cpp:: dvmDumpAllThreadsEx函数。另外请注意，输出堆栈信息时SignalCatcher会暂停所有线程。

通过该文件很容易就能知道问题进程的主线程发生ANR时正在执行怎样的操作。例如上述示例，ANRActivity在makeANR函数中执行线程sleep时发生ANR，可以推测sleep时间过长，超过了超时上限导致。这是一种比较简单的情况，实际开发中会遇到很多诡异的、更加复杂的情况，在后面的实例讲解一节会详细说明。

---

Log信息详情：

//WindowManager所在的进程是system_server，进程号是127

I/WindowManager( 127): Input event dispatching timed out sending to com.example.anrdemo/com.example.anrdemo.ANRActivity

 

//system_server进程中的ActivityManagerService请求kernel向5033进程发送SIGNAL_QUIT请求

//你可以在shell中使用命令达到相同的目的：adb shell kill -3 5033

//和其他的Java虚拟机一样，SIGNAL_QUIT也是Dalvik内部支持的功能之一

I/Process ( 127): Sending signal. PID: 5033 SIG: 3

 

//5033进程的虚拟机实例接收到SIGNAL_QUIT信号后会将进程中各个线程的函数堆栈信息输出到traces.txt文件中

//发生ANR的进程正常情况下会第一个输出

I/dalvikvm( 5033): threadid=4: reacting to signal 3

I/dalvikvm( 5033): Wrote stack traces to '/data/anr/traces.txt'

... ...//另外还有其他一些进程

 

//随后会输出CPU使用情况

E/ActivityManager( 127): ANR in com.example.anrdemo (com.example.anrdemo/.ANRActivity)

//Reason表示导致ANR问题的直接原因

E/ActivityManager( 127): Reason: keyDispatchingTimedOut

E/ActivityManager( 127): Load: 3.85 / 3.41 / 3.16

 

//请注意ago，表示ANR发生之前的一段时间内的CPU使用率，并不是某一时刻的值

E/ActivityManager( 127): CPU usage from 26835ms to 3662ms ago with 99% awake:

E/ActivityManager( 127): 9.4% 98/mediaserver: 9.4% user + 0% kernel

E/ActivityManager( 127): 8.9% 127/system_server: 6.9% user + 2% kernel / faults: 1823 minor

... ...

E/ActivityManager( 127): +0% 5033/com.example.anrdemo: 0% user + 0% kernel

E/ActivityManager( 127): 39% TOTAL: 32% user + 6.1% kernel

 

//这里是later，表示ANR发生之后

E/ActivityManager( 127): CPU usage from 601ms to 1132ms later with 99% awake:

E/ActivityManager( 127): 10% 127/system_server: 1.7% user + 8.9% kernel / faults: 5 minor

E/ActivityManager( 127): 10% 163/InputDispatcher: 1.7% user + 8.9% kernel

E/ActivityManager( 127): 1.7% 127/system_server: 1.7% user + 0% kernel

E/ActivityManager( 127): 1.7% 135/SurfaceFlinger: 0% user + 1.7% kernel

E/ActivityManager( 127): 1.7% 2814/Binder Thread #: 1.7% user + 0% kernel

... ...

E/ActivityManager( 127): 37% TOTAL: 27% user + 9.2% kernel

 

---