参见原文: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