traces文件分析
簡單了解ANR
各個應(yīng)用進程和系統(tǒng)進程的函數(shù)堆棧信息都輸出到了/data/anr/traces.txt的文件中,
獲取traces 文件:adb pull /data/anr
pull目錄的原因是有些手機會對不同的應(yīng)用輸出專屬的traces文件,所以/data/anr目錄下會有一堆traces文件。一般三方app開發(fā)只關(guān)心自己的應(yīng)用,而且沒有root權(quán)限。所以只能分析traces文件定位anr,根據(jù)問題復現(xiàn)的模塊、頁面再結(jié)合traces文件三大常見的anr問題都能解決。打開traces文件搜索自己的應(yīng)用包名就能在前后的位置上找到引發(fā)anr的類和方法。如下:
1.主線程被阻塞,輸入事件5s沒有響應(yīng),如onClick事件。這是anr問題的主要類型,一般開發(fā)者不會犯這樣的錯,凡是耗時的操作都另開線程處理,如果疏忽了看看自己的代碼就知道怎么處理

- BroadcastReceiver是在程序主線程運行,而且默認情況下BroadcastReceiver的運行時間為10s,所以不能有耗時操作,如果耗時超過10s就會導致anr,從traces文件log就可以看出onReceive不能進行耗時任務(wù)。
image.png
BroadcastReceiver是Android的消息組件,用來組件之間、應(yīng)用之間的消息傳遞,生命周期太短也不能開子線程處理耗時任務(wù),耗時任務(wù)一般轉(zhuǎn)交給IntentService或者JobIntentService去做。
3.Service是計算型組件,雖然在后臺運行,但是本質(zhì)上它也跑在主線程,如果你的服務(wù)要做任何CPU密集型(如MP3播放)或阻塞(如網(wǎng)絡(luò))操作,都要放在子線程中,否則耗時超過20s就會導致anr。注意anr方法是我自己寫的方法。onStartCommand()方法中有耗時任務(wù)將其放到子線程中去就可以了,例如:將下面的anr()方法放到子線程

traces文件信息解析
//開頭顯示進程號、ANR發(fā)生的時間點和進程名稱
----- pid 9183 at 2012-09-28 22:20:42 ----
Cmd line: com.example.anrdemo
DALVIK THREADS: //以下是各個線程的函數(shù)堆棧信息
//依次是:線程名、線程優(yōu)先級、線程號、線程當前狀態(tài)(TIMED_WAIT或SUSPENDED在anr時很常見)
//線程名稱后面標識有daemon,說明這是個守護線程
"main" prio=5 tid=1 TIMED_WAIT
//依次是:線程組名稱、suspendCount個數(shù)、debugSuspendCount個數(shù)、線程的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)
.......
//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)
//JDWP線程是支持虛擬機調(diào)試的線程,不需要關(guān)心
"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 )
t dalvik.system.NativeStart.run(Native Method)
//“Signal Catcher”負責接收和處理kernel發(fā)送的各種信號,例如SIGNAL_QUIT、SIGNAL_USR1等就是被該線程
//接收到,這個文件的內(nèi)容就是由該線程負責輸出的,可以看到它的狀態(tài)是RUNNABLE,不過此線程也不需要關(guān)心
"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 )
三方應(yīng)用開發(fā)如何避免ANR
三方應(yīng)用開發(fā)常見的anr三種情況前文已經(jīng)詳細呈現(xiàn),避免anr思路已經(jīng)清晰,簡單總結(jié)下:
- 絕對不要在主線程上進行復雜耗時的操作,比如說發(fā)送接收網(wǎng)絡(luò)數(shù)據(jù)、進行大量計算、操作數(shù)據(jù)庫、讀寫文件等,統(tǒng)統(tǒng)采用異步操作
2.broadCastReceiver 要進行復雜操作的的時候,可以在onReceive()方法中啟動一個IntentService或者JobIntentService去做。
- Service中的耗時操作最好也是采用異步任務(wù)
4.在設(shè)計及代碼編寫階段避免出現(xiàn)出現(xiàn)同步/死鎖、死循環(huán)等不恰當情況
Android系統(tǒng)開發(fā)中的ANR
對系統(tǒng)開發(fā)者來說只有/data/anr/traces.txt文件是遠遠不夠的。因為雖然anr了但是traces文件沒有anr的log或者traces文件有l(wèi)og,但是并不能定位到導致anr問題的原因。
ANR對系統(tǒng)的穩(wěn)定性影響是比較大的,測試中心會將ANR作為系統(tǒng)穩(wěn)定性的重要case。系統(tǒng)開發(fā)者一般就要依賴工具和系統(tǒng)log來分析,anr報在你負責的模塊,但是導致anr的原因很可能在別的模塊,尤其在跑穩(wěn)定性測試的時候一些個別ANR問題很難調(diào)查清楚,畢竟腳本跟手動操作還是有些區(qū)別,而且像內(nèi)存碎片,硬件故障等等的問題基本應(yīng)用層是無從查起的,至少依靠個人是很難找出來,可能需要個團隊一起關(guān)注(比如內(nèi)核,BSP),甚至是反饋給廠商去解決。
根據(jù)我的經(jīng)驗以下幾種情況都會導致ANR:
- CPU密集,導致主線程沒法搶占cpu時間片,要注意cpu占用高的進程
- 高IO,如不當訪問數(shù)據(jù)庫導致數(shù)據(jù)庫負載過重時(log中cpu的使用iowait占比高)
- 低內(nèi)存(low memory),如內(nèi)存不足導致block在創(chuàng)建bitmap上
- 死鎖引發(fā)ANR,非主線程持有主線程需要的鎖對象,導致主線程等待超時,通常log中會有以下字段 Blocked | - locked | waiting to lock | held by thread,這個時候cpu多數(shù)是空閑,使用占比很低
- 當前應(yīng)用進程進行進程間通信請求其他進程,其他進程的操作長時間沒有反饋,例如操作硬件Camera
- Service binder數(shù)量達到上限
- 在system_server中觸發(fā)WatchDog ANR
當然前面app中的ANR問題也會出現(xiàn),系統(tǒng)開發(fā)比較龐雜,也沒法整理出通用的情況案例,只能說ANR之后去如何分析。
我個人是MTK平臺做的比較多,平臺都有自己的工具,也會提供文檔,看看文檔摸索一下基本就能干活了
使用GAT工具
GAT是MTK在DDMS基礎(chǔ)上進行二次開發(fā)封裝的一個集多種debug功能為一體的工具,除了包含原有DDMS的功能以外還支持kernel抓取,獲取native進程列表,backtrace decode,提取手機端debug信息等功能。當MTKLogger出現(xiàn)異常時,經(jīng)常會需要使用GAT工具來抓取log。
mtklog里面都有意個aee_exp文件,里面有兩個文件一個是ZZ_INTERNAL,只有一句話,說出報的是什么錯誤,發(fā)生錯誤的進程號,發(fā)生錯誤的程序,報錯時間等信息。

另外一個文件叫db.01.JE,這個文件里面放的報錯的具體信息以及報錯時候機器各種狀態(tài)的保存,但是這個文件只能用mtk特制的gat軟件打開。
點擊菜單上window--openlogView,點擊file-OpenAeeDB,選擇要打開的dbg格式的文件,左邊的一列目錄是各種報錯時候的信息,最主要的是第一項exp_main.txt,在同級目錄下會輸出所有文件。

點開能發(fā)現(xiàn)最主要的報錯信息,信息描述的很直接,對應(yīng)自己的程序就明白這些信息
Build Info: //編譯信息
Flavor Info: 'None'
Exception Log Time: //anr記錄時間
Exception Class: ANR
Exception Type: system_app_anr
Current Executing Process:
com.android.settings
com.android.settings v19 (4.4.4-eng.scm.1428072972)
Backtrace:
Process: com.android.settings
Flags: 0x40c8be45
Package: com.android.settings v19 (4.4.4-eng.scm.1428072972)
Subject: Broadcast of Intent { act=[android.net] (http://android.net/).conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.android.settings/.ales.NetworkReceiver (has extras) }
//如果是在某個頁面的話,會將頁面類名也輸出
Build: alps**************/1428069651:user/test-keys
Android time :[2017-12-14 20:07:52.45] [5284.377]
CPU usage from 3399ms to 151ms ago:
100% 2281/com.***.app: 90% user + 10% kernel / faults: 20828 minor 4 major
22% 1717/system_server: 13% user + 9.1% kernel / faults: 821 minor 7 major
21% 192/logd: 3.6% user + 17% kernel / faults: 6 minor
20% 237/mediaserver: 7.3% user + 13% kernel / faults: 1301 minor
8.2% 243/mobile_log_d: 2.4% user + 5.7% kernel / faults: 66 minor
3.3% 2442/tx_thread: 0% user + 3.3% kernel
3.3% 6208/logcat: 0.3% user + 3% kernel
2.7% 212/surfaceflinger: 0.3% user + 2.4% kernel
2.4% 2138/com.android.systemui: 1.8% user + 0.6% kernel / faults: 40 minor
1.2% 2128/sdcard: 0% user + 1.2% kernel
0.9% 7/rcu_preempt: 0% user + 0.9% kernel
............
56% TOTAL: 37% user + 18% kernel + 0% iowait + 0.6% softirq
Android time :[2017-12-14 20:08:14.42] [5306.347]
CPU usage from 35171ms to 0ms ago:
76% 2281/com.****.app: 61% user + 14% kernel / faults: 120156 minor
52% 237/mediaserver: 21% user + 31% kernel / faults: 13346 minor
43% 192/logd: 6.8% user + 36% kernel / faults: 116 minor
20% 1717/system_server: 12% user + 7.6% kernel / faults: 1734 minor 6 major
18% 212/surfaceflinger: 3.3% user + 14% kernel / faults: 30 minor
16% 243/mobile_log_d: 5.7% user + 10% kernel / faults: 1236 minor
7.5% 6208/logcat: 0.7% user + 6.7% kernel
2.4% 2138/com.android.systemui: 1.5% user + 0.9% kernel / faults: 307 minor
2.2% 2442/tx_thread: 0% user + 2.2% kernel
......
70% TOTAL: 33% user + 36% kernel + 0% iowait + 0.3% softirq
ANR發(fā)生之前和之后一段時間的CPU使用率
CPU使用率可以理解為一段時間(記作T)內(nèi)除CPU空閑時間(記作I)之外的時間與這段時間T的比值,用公式表示可以寫為:
CPU使用率= (T – I) / T
而時間段T是兩個采樣時間點的時間差值。之所以可以這樣計算,是因為Linux內(nèi)核會把從系統(tǒng)啟動開始到當前時刻CPU活動的所有時間信息都記錄下來,我們可以通過查看“/proc/stat”文件獲取這些信息。主要包括以下幾種時間,這些時間都是從系統(tǒng)啟動開始計算的,單位都是0.01秒:
user: CPU在用戶態(tài)的運行時間,不包括nice值為負數(shù)的進程運行的時間
nice: CPU在用戶態(tài)并且nice值為負數(shù)的進程運行的時間
system:CPU在內(nèi)核態(tài)運行的時間
idle: CPU空閑時間,不包括iowait時間
iowait: CPU等待I/O操作的時間
irq: CPU硬中斷的時間
softirq:CPU軟中斷的時間
進程的CPU使用率最后輸出的“faults: xxx minor/major”部分表示的是頁錯誤次數(shù),當次數(shù)為0時不顯示。major是指Major Page Fault(主要頁錯誤,簡稱MPF),內(nèi)核在讀取數(shù)據(jù)時會先后查找CPU的高速緩存和物理內(nèi)存,如果找不到會發(fā)出一個MPF信息,請求將數(shù)據(jù)加載到內(nèi)存。Minor是指Minor Page Fault(次要頁錯誤,簡稱MnPF),磁盤數(shù)據(jù)被加載到內(nèi)存后,內(nèi)核再次讀取時,會發(fā)出一個MnPF信息。一個文件第一次被讀寫時會有很多的MPF,被緩存到內(nèi)存后再次訪問MPF就會很少,MnPF反而變多,這是內(nèi)核為減少效率低下的磁盤I/O操作采用的緩存技術(shù)的結(jié)果。
如果ANR發(fā)生時發(fā)現(xiàn)CPU使用率中iowait占比很高,可以通過查看進程的major次數(shù)來推斷是哪個進程在進行磁盤I/O操作。
LOG怎么分析
首先了解一下主要的log文件
__exp_main.txt:異常類型,調(diào)用棧等關(guān)鍵信息。
SYS_ANDROID_LOG:android main log
SYS_KERNEL_LOG:kernel log
SYS_VERSION_INFO:kernel版本,用于和vmlinux對比,只有匹 配的vmlinux才能用于分析這個異常。
SYS_ANDROID_EVENT_LOG:系統(tǒng)事件信息
DUMPSYS_ACTIVITY:AMS日志
DUMPSYS_DBINFO :數(shù)據(jù)庫操作記錄
DUMPSYS_WINDOW :窗口記錄,記錄anr發(fā)生的窗口頁面
PROCESS_STATE: 發(fā)生ANR程序的進程信息,虛擬機信息?
SWT_JBT_TRACES:不知道怎么描述,自認為堆棧調(diào)用相關(guān)的記錄吧
SYS_ANDROID_EVENT_LOG:事件log,如ActivityManager、powerManager相關(guān)的活動記錄
SYS_ANDROID_LOG: 上層app以及framework相關(guān)活動的log
SYS_ANDROID_RADIO_LOG: 聯(lián)網(wǎng)相關(guān)
//binder相關(guān)
SYS_BINDER_INFO:
SYS_BINDER_MEM_USED:
//parser解析文件夾,基本解析了anr相關(guān)的信息,CPU、內(nèi)存的診斷,binder分析
parser
log很多沒有列舉全,常用的基本就這些,主要的log文件大概了解一下。首先ZZ_INTERNAL、__exp_main.txt文件中找到ANR的應(yīng)用進程號、進程名, SYS_ANDROID_EVENT_LOG中記錄的事件log中過濾am_anr,并且要對應(yīng)上進程號,這個事件log基本就指出當前在哪個類或者是什么操作,你就可以看看自己的代碼了

SWT_JBT_TRACES同樣找到對應(yīng)的進程號,看看Heap是否不夠用了、線程是否被Blocked。一般線程被Blocked了,通常cpu的占用比較低。

Blocked就一定有被持有的對象,這個有時候是發(fā)生在binder,就需要分析binder相關(guān)的log

binder分配使用情況、診斷分析報告


ANR發(fā)生之后log中記錄的關(guān)鍵字段
-
am_anr: 描述了anr發(fā)生時的事件,原因,進程。如果是自己的代碼導致的,這里會輸出你代碼具體的調(diào)用類
image.png
image.png
image.png
-
ANR in:main_log 或 Sys_log ,描述anr發(fā)生的應(yīng)用模塊
Reason:原因
Android time :時間 ,有些時候需要根據(jù)時間到其他模塊追蹤問題
上面這三個字段都會同時出現(xiàn)
image.png Blocked | - locked | waiting to lock | held by thread
//發(fā)生在死鎖的情況下就會出現(xiàn)這三個關(guān)鍵字段
根據(jù)官網(wǎng)論述,死鎖現(xiàn)象會作為ANR的一種表現(xiàn)方式出現(xiàn),也會把日志記錄到/data/anr目錄下,但是如果死鎖發(fā)生在system server進程中,則看門狗(watchdog)會殺掉system server進程,并且在main log中會看到關(guān)鍵字"WATCHDOG KILLING SYSTEM PROCESS",系統(tǒng)運行時將會重啟,system server也會重啟,此時用戶會看到開機動畫會再次播放。
- WATCHDOG KILLING SYSTEM PROCESS
綜上所屬總結(jié)了一條快速過濾命令,一般穩(wěn)定性測試結(jié)束上傳的log非常大,解壓后幾個G的log文件是很正常,不可能打開搜索,即便時間多的用不完,打開的速度正常人也沒法忍受,所以直接linux命令過濾,之后再打開那個已經(jīng)過濾輸出的文件,命令如下:
grep -rn "ANR in\|ANRManager: Reason:\|ANRManager: Android time\|am_anr\|WATCHDOG KILLING SYSTEM PROCESS\| iowait\| Blocked\| held by thread\| waiting to lock"
高效的過濾命令,雖然grep很好用,文件超大的時候還是ag速度快
ag "ANR in|ANRManager: Reason:|ANRManager: Android time|am_anr|WATCHDOG KILLING SYSTEM PROCESS| iowait| Blocked| held by thread| waiting to lock"
可以用過濾mobilelog文件夾進行分析,不同的廠商系統(tǒng)日志輸出的地方不一樣。
ANR的一點源碼
ANR出現(xiàn)時調(diào)用的函數(shù)(源碼)
// 記錄ANR event log
EventLog.writeEvent(EventLogTags.AM_ANR, app.userId, app.pid,app.processName, app.info.flags, annotation);
// 記錄ANR 到 main log
StringBuilder info = new StringBuilder();
info.setLength(0);
info.append("ANR in ").append(app.processName); //關(guān)鍵字"ANR in"
if (activity != null && activity.shortComponentName != null) {
info.append(" (").append(activity.shortComponentName).append(")");
}
info.append("\n");
info.append("PID: ").append(app.pid).append("\n");
if (annotation != null) {
info.append("Reason: ").append(annotation).append("\n");
}
if (parent != null && parent != activity) {
info.append("Parent: ").append(parent.shortComponentName).append("\n");
}
final ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(true);
// dump堆棧log
File tracesFile = dumpStackTraces(true, firstPids, processCpuTracker, lastPids,
NATIVE_STACKS_OF_INTEREST);




