ANR日誌traces.txt分析 （mark~ 很詳細）
阿新 • • 發佈：2018-12-01
ANR日誌traces.txt分析
2018.07.24 19:58* 字數 806 閱讀 234評論 0喜歡 0
導致ANR的幾種情況
- KeyDispatchTimeout(5s): 按鍵或觸控事件在特定時間內無法處理完成
- BroadcastTimeout(前臺10s,後臺60s): 廣播在特定時間內無法處理完成
- ServiceTimeout(前臺20s,後臺200s): Service在特定的時間無法處理完成 另外還有ProviderTimeout和WatchDog等導致的ANR
常見的原因
A.耗時操作，如複雜的layout，龐大的for迴圈，IO等。 B.被Binder 對端block C.被子執行緒同步鎖block D.Binder被佔滿導致主執行緒無法和SystemServer通訊 E.得不到系統資源（CPU/RAM/IO） 其中ABCD比較好分析，而E比較困難。
應用ANR產生的時候,ActivityManagerService的appNotResponding方法就會被呼叫,然後在/data/anr/traces.txt檔案中寫入ANR相關資訊.
ANR就不作介紹了，下面只介紹如何分析ANR異常.
通常發生了ANR，ActivityManager會列印報錯資訊：
E/ActivityManager: ANR in com.rui.android.poc // ANR出現的程序包名 PID: 1322 // ANR程序ID Reason: Broadcast of Intent { act=android.intent.action.SCREEN_ON flg=0x50000010 }//導致ANR的原因 Load: 4.13 / 2.52 / 1.05 CPU usage from 0ms to 12843ms later://CPU在ANR發生後的使用情況 98% 1322/com.rui.android.poc: 0.5% user + 98% kernel / faults: 1044 minor 104 major 5.6% 567/system_server: 3.4% user + 2.1% kernel / faults: 1940 minor 217 major 2.3% 766/com.android.systemui: 1.2% user + 1% kernel / faults: 251 minor 165 major 1.4% 268/kworker/0:2: 0% user + 1.4% kernel 1.2% 1690/adbd: 0.1% user + 1% kernel / faults: 2 minor 3 major 1% 756/com.android.phone: 0.6% user + 0.3% kernel / faults: 347 minor 61 major 0.9% 139/surfaceflinger: 0.3% user + 0.5% kernel / faults: 1 minor 5 major 0.2% 929/com.sprd.opm: 0.2% user + 0% kernel / faults: 279 minor 115 major 0.2% 23/kworker/u4:1: 0% user + 0.2% kernel 0.2% 368/kworker/u5:1: 0% user + 0.2% kernel 0.1% 914/com.android.modemassert: 0% user + 0% kernel / faults: 182 minor 66 major 0.1% 44/ksmd: 0% user + 0.1% kernel 0% 909/com.spreadst.validator: 0% user + 0% kernel / faults: 164 minor 39 major 0% 8/rcu_preempt: 0% user + 0% kernel 0% 43/kswapd0: 0% user + 0% kernel 0% 117/mmcqd/0: 0% user + 0% kernel +0% 1770/kworker/0:3: 0% user + 0% kernel +0% 1774/debuggerd: 0% user + 0% kernel 97% TOTAL: 3.7% user + 55% kernel + 38% iowait // CUP佔用情況 CPU usage from 12301ms to 12824ms later: 100% 1322/com.rui.android.poc: 0% user + 100% kernel 100% 1322/rui.android.poc: 0% user + 100% kernel 1.9% 1333/Binder_2: 0% user + 1.9% kernel 3.8% 567/system_server: 1.9% user + 1.9% kernel 3.8% 581/ActivityManager: 1.9% user + 1.9% kernel 1.3% 139/surfaceflinger: 1.3% user + 0% kernel 1.3% 249/DispSync: 0% user + 1.3% kernel 1.5% 766/com.android.systemui: 1.5% user + 0% kernel / faults: 2 minor 1.5% 766/ndroid.systemui: 0% user + 1.5% kernel 1.6% 1770/kworker/0:3: 0% user + 1.6% kernel 100% TOTAL: 0% user + 54% kernel + 45% iowait
Log分析：
log列印了ANR的基本資訊,我們可以分析CPU使用率得知ANR的簡單情況;如果CPU使用率很高,接近100%,可能是在進行大規模的計算更可能是陷入死迴圈;如果CUP使用率很低,說明主執行緒被阻塞了,並且當IOwait很高,可能是主執行緒在等待I/O操作的完成.
對於ANR只是分析Log很難知道問題所在,我們還需要通過Trace檔案分析stack呼叫情況.
traces.txt是如何生成的
當APP(包括系統APP和使用者APP)程序出現ANR、應用響應慢或WatchDog的監視沒有得到回饋時,系統會dump此時的top程序,程序中Thread的執行狀態就都dump到這個Trace檔案中了.每次發生ANR， 這個檔案都會被清空，寫入新的內容. 如果想檢視以前發生ANR的資訊， 可以去檢視DB檔案.
DropBox中的log
traces.txt只保留最後一次發生ANR時的資訊, android 2.2開始增加了DropBox功能, 保留歷史上發生的所有ANR的log.
“/data/system/dropbox”是DB指定的檔案存放位置.
日誌儲存的最長時間， 預設是3天.
[email protected]_Rui8503:/data # cd system/dropbox/
[email protected]_Rui8503:/data/system/dropbox # ls
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]_Rui8503:/data/system/dropbox #
SystemServer在啟動時， 會建立並新增DROPBOX_SERVICE.
//SystemServer.java
private void startOtherServices() {
... ...
try {
Slog.i(TAG, "DropBox Service");
ServiceManager.addService(Context.DROPBOX_SERVICE,
new DropBoxManagerService(context, new File("/data/system/dropbox")));
} catch (Throwable e) {
reportWtf("starting DropBoxManagerService", e);
}
... ...
}
在traces.txt中可以看到如下資訊：
//說明了發生ANR的程序id、時間和程序名稱。
----- pid 2023 at 2018-07-24 19:33:17 -----
Cmd line: com.rui.android.poc
//下面三行是執行緒的基本資訊
JNI: CheckJNI is off; workarounds are off; pins=0; globals=348
DALVIK THREADS://以下是各個執行緒的函式堆疊資訊
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
//下面一行說明了執行緒名稱、daemon表示守護程序，執行緒的優先順序（預設5）、執行緒鎖id和執行緒狀態，
//執行緒名稱是啟動執行緒的時候手動指明的，這裡的main標識是主執行緒，是Android自動設定的
//一個執行緒名稱，如果是自己手動建立的執行緒，一般會被命名成“Thread-xx”的格式，其中xx是
//執行緒id，它只增不減不會被複用；注意這其中的tid不是執行緒的id,它是一個在Java虛擬機器中用
//來實現執行緒鎖的變數，隨著執行緒的增減，這個變數的值是可能被複用的；
"main" prio=5 tid=1 NATIVE
//group是執行緒組名稱。sCount是此執行緒被掛起的次數，dsCount是執行緒被偵錯程式掛起的次數，
//當一個程序被除錯後，sCount會重置為0，除錯完畢後sCount會根據是否被正常掛起增長，
//但是dsCount不會被重置為0，所以dsCount也可以用來判斷這個執行緒是否被除錯過。obj表示
//這個執行緒的Java物件的地址，self表示這個執行緒Native的地址。
| group="main" sCount=1 dsCount=0 obj=0x4164dcf0 self=0x41565628
//此後是執行緒的排程資訊，sysTid是Linux下的核心執行緒id，nice是執行緒的排程優先順序，
//sched分別標誌了執行緒的排程策略和優先順序，cgrp是排程屬組，handle是執行緒的處理函式地址。
| sysTid=2023 nice=-1 sched=0/0 cgrp=apps handle=1074626900
//執行緒當前上下文資訊，state是排程狀態；schedstat從 /proc/[pid]/task/[tid]/schedstat讀出，
//三個值分別表示執行緒在cpu上執行的時間、執行緒的等待時間和執行緒執行的時間片長度，有的
//android核心版本不支援這項資訊，得到的三個值都是0；utm是執行緒使用者態下使用的時間
//值(單位是jiffies）;stm是核心態下的排程時間值；core是最後執行這個執行緒的cpu核的序號。
| state=S schedstat=( 0 0 0 ) utm=49 stm=21 core=0
//執行緒的呼叫棧資訊(這裡可檢視導致ANR的程式碼呼叫流程，分析ANR最重要的資訊)
(native backtrace unavailable)
at libcore.io.Posix.open(Native Method)
at libcore.io.BlockGuardOs.open(BlockGuardOs.java:110)
at libcore.io.IoBridge.open(IoBridge.java:430)
at java.io.FileInputStream.<init>(FileInputStream.java:78)
at com.ruiven.android.Peripheral.util.kingFiles.write(kingFiles.java:58)
at com.ruiven.android.Peripheral.util.kingFiles.write(kingFiles.java:51)
at com.ruiven.android.Peripheral.util.kingLog.writeToFiles(kingLog.java:71)
at com.ruiven.android.Peripheral.util.kingLog.f(kingLog.java:47)
at com.ruiven.android.poc.receiver.ReceiverBatteryChanged.onReceive(ReceiverBatteryChanged.java:114)
at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:767)
at android.os.Handler.handleCallback(Handler.java:769)
at android.os.Handler.dispatchMessage(Handler.java:97)
at android.os.Looper.loop(Looper.java:136)
at com.ruiven.android.Peripheral.util.Cockroach$1.run(Cockroach.java:38)
at android.os.Handler.handleCallback(Handler.java:769)
at android.os.Handler.dispatchMessage(Handler.java:97)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5375)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:976)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:792)
at dalvik.system.NativeStart.main(Native Method)
//Binder執行緒是程序的執行緒池中用來處理binder請求的執行緒
"Binder_3" prio=5 tid=23 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x41b765f8 self=0x4f213f18
| sysTid=1347 nice=0 sched=0/0 cgrp=apps handle=1327603952
| state=S schedstat=( 0 0 0 ) utm=0 stm=3 core=1
#00 pc 000205d0 /system/lib/libc.so (__ioctl+8)
#01 pc 0002d01f /system/lib/libc.so (ioctl+14)
#02 pc 0001e519 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
#03 pc 0001ec67 /system/lib/libbinder.so (android::IPCThreadState::getAndExecuteCommand()+6)
#04 pc 0001ecfd /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+48)
#05 pc 000236cd /system/lib/libbinder.so
#06 pc 0000ea19 /system/lib/libutils.so (android::Thread::_threadLoop(void*)+216)
#07 pc 0004e769 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
#08 pc 0000e54b /system/lib/libutils.so
#09 pc 0000d240 /system/lib/libc.so (__thread_entry+72)
#10 pc 0000d3dc /system/lib/libc.so (pthread_create+240)
at dalvik.system.NativeStart.run(Native Method)
//JDWP執行緒是支援虛擬機器除錯的執行緒，daemon表示守護程序，不需要關心
"JDWP" daemon prio=5 tid=4 VMWAIT
| group="system" sCount=1 dsCount=0 obj=0x41a21868 self=0x4cc821b0
| sysTid=785 nice=0 sched=0/0 cgrp=apps handle=1257589656
| state=S schedstat=( 0 0 0 ) utm=0 stm=0 core=1
#00 pc 00021420 /system/lib/libc.so (recvmsg+8)
#01 pc 000668ab /system/lib/libdvm.so
#02 pc 00066adf /system/lib/libdvm.so
#03 pc 000697af /system/lib/libdvm.so
#04 pc 00059fdd /system/lib/libdvm.so
#05 pc 0000d240 /system/lib/libc.so (__thread_entry+72)
#06 pc 0000d3dc /system/lib/libc.so (pthread_create+240)
at dalvik.system.NativeStart.run(Native Method)
//“Signal Catcher”負責接收和處理kernel傳送的各種訊號，例如SIGNAL_QUIT、SIGNAL_USR1等就是被該執行緒
//接收到並處理的，traces.txt 檔案中的內容就是由該執行緒負責輸出的，可以看到它的狀態是RUNNABLE.
"Signal Catcher" daemon prio=5 tid=3 RUNNABLE
| group="system" sCount=0 dsCount=0 obj=0x41a21770 self=0x4af3e5e0
| sysTid=784 nice=0 sched=0/0 cgrp=apps handle=1257677168
| state=R schedstat=( 0 0 0 ) utm=2 stm=2 core=1
at dalvik.system.NativeStart.run(Native Method)
----- end 2023 -----
如果ANR在native層,那麼堆疊中就不會有相關呼叫的路徑,這種情況只能在native層新增更多的Log,一步步來查找了
NATIVE表示當前執行緒的狀態：
Thread狀態及其對應的值
ThreadState (defined at “dalvik/vm/thread.h “)
THREAD_UNDEFINED = -1, /* makes enum compatible with int32_t */
THREAD_ZOMBIE = 0, /* TERMINATED */( 執行緒死亡，終止執行)
THREAD_RUNNING = 1, /* RUNNABLE or running now */(執行緒可執行或正在執行)
THREAD_TIMED_WAIT = 2, /* TIMED_WAITING in Object.wait() */(執行了帶有超時引數的wait、sleep或join函式)
THREAD_MONITOR = 3, /* BLOCKED on a monitor */(執行緒阻塞，等待獲取物件鎖)
THREAD_WAIT = 4, /* WAITING in Object.wait() */( 執行了無超時引數的wait函式)
THREAD_INITIALIZING= 5, /* allocated, not yet running */(新建，正在初始化，為其分配資源)
THREAD_STARTING = 6, /* started, not yet on thread list */(新建，正在啟動)
THREAD_NATIVE = 7, /* off in a JNI native method */(正在執行JNI本地函式)
THREAD_VMWAIT = 8, /* waiting on a VM resource */(正在等待VM資源)
THREAD_SUSPENDED = 9, /* suspended, usually by GC or debugger */(執行緒暫停，通常是由於GC或debug被暫停)
**特別說明一下MONITOR狀態和SUSPEND狀態，MONITOR狀態一般是類的同步塊或者同步方法造成的，SUSPENDED狀態在debugger的時候會出現，可以用來區別是不是真的是使用者正常操作跑出了ANR。
mutexes(互斥)的選項簡寫對應含義：
tll--thread list lock
tsl-- thread suspend lock
tscl-- thread suspend count lock
ghl--gc heap lock
hwl--heap worker lock
hwll--heap worker list lock
- 通過Cmd line: packagename可以找到要分析的程序
- 並不是trace檔案包含的應用就一定是造成ANR的幫凶，應用出現在trace檔案中，只能說明出現ANR的時候這個應用程序還活著，trace檔案的頂部則是觸發ANR的應用資訊。因此，如果你的應用出現在了trace檔案的頂部，那麼很有可能是因為你的應用造成了ANR，否則是你的應用造成ANR的可能性不大，但是具體是不是還需要進一步分析