App Not Responsing

標籤：android   style   blog   http   java   color   

參見原文：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