Traces.txt阅读

http://rayleeya.iteye.com/blog/1955657

/文件中输出的第一个进程的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请求的线程

"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)

 

"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时间过长，超过了超时上限导致。这是一种比较简单的情况，实际开发中会遇到很多诡异的、更加复杂的情况，在后面的实例讲解一节会详细说明。