Android ANR那些事
從技術的角度看，ANR對使用者體驗的傷害僅次於Crash。多年的開發實踐過程中遇到過不少ANR問題，有兩次印象比較深，都是App冷啟動後卡死在廣告頁進不了主頁導致應用市場稽核不通過。
在發版稽核這種關鍵節點，分析原因解決問題的速度很重要，而速度取決於分析問題的思路，相關技術的日常總結以及對業務和程式碼的熟悉度。下面先從一個實際例子開始。
1 實際案例
這是一次ANR後，分析trace檔案得到的執行緒等待關係圖
ANR-執行緒關係圖.png
圖中UI執行緒(tid=1)和另外兩個Rx排程執行緒(tid=55,tid=96)都在等待鎖 <0x33199586> *Provider，鎖<0x33199586> *Provider被另一個Rx排程執行緒（tid=49）持有，執行緒49持有鎖<0x33199586> *Provider後，又呼叫了一個同步方法持有了鎖<0x14818fd3> Object（被執行緒84等待），這個同步方法內部在執行網路請求導致UI執行緒長時間Block進而造成了ANR。
UI執行緒參與併發很容易造成ANR, 併發一般涉及到鎖，如果UI執行緒等待鎖的時間過長都會發生ANR。圖中如果不是執行緒49，而是執行緒55或執行緒96先持有了鎖<0x33199586> *Provider並去執行一段很耗時程式碼也會造成ANR。
UI執行緒長時間Block會造成ANR, 網路執行緒長時間Block有時也會造成嚴重的問題。開發中遇到過鎖競爭造成網路執行緒Block導致進首頁後長時間loading的case，Block的原因是傳送請求時在攔截器裡需要新增一個公參，獲取公參的方法有鎖相關的邏輯。圖中執行緒55和執行緒96都是網路執行緒，即使UI執行緒沒有參與鎖競爭造成ANR，這兩個網路執行緒也會因為Block造成端到端（從客戶端發出請求到客戶端收到響應）時間過長。
定位到原因後問題就迎刃而解了，UI執行緒使用不會Block的api，同時消除網路執行緒之間的鎖競爭就可以快速解決這個問題。
2 分析方法
至今還記得剛入行第一次遇到ANR時自己完全沒有思路的情形。不知道看哪些日誌，面對海量日誌不知道怎麼快速分析提取有效資訊，更不清楚系統檢測ANR的機制。只是大概知道UI執行緒執行耗時操作超過一定閾值時會被系統檢測到，然後彈FC對話方塊。這段重點從實操的角度說下分析ANR的方法。
2.1 分析Trace檔案
Trace檔案記錄了發生ANR時的程序和執行緒資訊，分析過程主要分3步
-
找到trace檔案並匯出
trace檔案一般都在/data/anr/目錄下，trace檔名有的不帶包名，有的帶包名，有的既帶包名又帶日期
系統儲存ANR檔案的位置可以通過 adb shell getprop 得到，[dalvik.vm.stack-trace-file]:[/data/anr/traces.txt]
shell@PD1415BA:/data/anr $ ls -al -rw-rw-rw- systemsystem0 2018-09-12 15:20 packages-fail.txt -rw-rw-rw- systemsystem615759 2017-02-16 15:47 traces_com.*.*.txt -rw-rw-rw- systemsystem642303 2018-09-11 16:12 traces_com.*.*.txt -rw-rw-rw- systemsystem475820 2018-02-01 19:44 traces_com.omottec.demoapp.txt
系統還有個儲存ANR歷史檔案的地方
shell@PD1415BA:/data/system/dropbox $ ls -al -rw------- systemsystem316 2018-09-10 03:31 [email protected] -rw-r--r-- systemsystem49681 2018-09-11 16:13 [email protected]
-
找到發生ANR的程序和UI執行緒
Trace檔案裡的第一個程序一般就是發生ANR的程序(和系統寫ANR日誌檔案的邏輯有關)，程序下的第一個執行緒一般就是UI執行緒，UI執行緒更準確的判斷方法是看sysTid和pid是否相等，相等的就是UI執行緒，tid是建立執行緒時的序號。
----- pid 13178 at 2018-05-03 00:54:42 ----- Cmd line: com.*.* ... DALVIK THREADS (97): // "執行緒名" prio=優先順序 tid=執行緒建立序號 執行緒Native層的狀態 "main" prio=5 tid=1 Blocked // group=執行緒組名 sCount=掛起次數(suspend count) dsCount=除錯被掛起次數(debug suspend count) obj=執行緒的Java物件地址 self=執行緒Native物件地址 | group="main" sCount=1 dsCount=0 obj=0x74240c30 self=0xf5027800 // sysTid=核心執行緒id nice=排程優先順序 cgrp=排程屬組 sched=執行緒排程策略/優先順序 handle=執行緒處理函式地址 | sysTid=13178 nice=0 cgrp=default sched=0/0 handle=0xf7753bec // state=排程狀態 schedstat=(執行緒執行時間 執行緒等待時間 執行緒執行的時間片長度) utm=使用者態時間 stm=核心態時間 core=最後執行執行緒的cup核序號 | state=S schedstat=( 5541520948 4506511097 13597 ) utm=430 stm=124 core=2 HZ=100 // stack=執行緒棧地址範圍 stackSize=執行緒棧大小 | stack=0xff122000-0xff124000 stackSize=8MB | held mutexes= at com.*.*.*Provider.query(*Provider.java:-1) - waiting to lock <0x33199586> (a com.*.uuid.*Provider) held by thread 49 at android.content.ContentProvider.query(ContentProvider.java:1010) at android.content.ContentProvider$Transport.query(ContentProvider.java:214) at android.content.ContentResolver.query(ContentResolver.java:504) at android.content.ContentResolver.query(ContentResolver.java:439) at com.*.*(*.java:96) at com.*.*(*.java:84) at com.*.*.utils.ag.b(*.java:38) at com.*.*.*Activity.n(*Activity.java:81) at com.*.*.*Activity.onCreate(*Activity.java:64) at android.app.Activity.performCreate(Activity.java:6049) at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1106) at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2304) at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2413) at android.app.ActivityThread.access$800(ActivityThread.java:154) at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1317) at android.os.Handler.dispatchMessage(Handler.java:102) at android.os.Looper.loop(Looper.java:135) at android.app.ActivityThread.main(ActivityThread.java:5308) at java.lang.reflect.Method.invoke!(Native method) at java.lang.reflect.Method.invoke(Method.java:372) at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:913) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:708)
直接搜尋main也可以快速定位UI執行緒, 搜尋的結果可能有很多處，因為很多執行緒所屬執行緒組的name為main，要注意和name為main的UI執行緒區分開。
-
分析UI執行緒和相關執行緒的狀態
trace檔案裡的執行緒狀態和Java裡面java.lang.Thread.State列舉表示的執行緒狀態不是一個概念，有個對映關係。trace檔案裡的執行緒狀態是native層的執行緒狀態，理解執行緒狀態可以幫助更好的分析問題，對映關係如下，在Android原始碼裡有定義。
class VMThread
{
...
/**
* Holds a mapping from native Thread statii to Java one. Required for
* translating back the result of getStatus().
*/
static final Thread.State[] STATE_MAP = new Thread.State[] {
Thread.State.TERMINATED,// ZOMBIE
Thread.State.RUNNABLE,// RUNNING
Thread.State.TIMED_WAITING,// TIMED_WAIT
Thread.State.BLOCKED,// MONITOR
Thread.State.WAITING,// WAIT
Thread.State.NEW,// INITIALIZING
Thread.State.NEW,// STARTING
Thread.State.RUNNABLE,// NATIVE
Thread.State.WAITING,// VMWAIT
Thread.State.RUNNABLE// SUSPENDED
};
...
}
https://android.googlesource.com/platform/dalvik/+/eclair-release/vm/Thread.h
/*
* Current status; these map to JDWP constants, so don't rearrange them.
* (If you do alter this, update the strings in dvmDumpThread and the
* conversion table in VMThread.java.)
*
* Note that "suspended" is orthogonal to these values (so says JDWP).
*/
typedef enum ThreadStatus {
/* these match up with JDWP values */
THREAD_ZOMBIE= 0,/* TERMINATED */
THREAD_RUNNING= 1,/* RUNNABLE or running now */
THREAD_TIMED_WAIT= 2,/* TIMED_WAITING in Object.wait() */
THREAD_MONITOR= 3,/* BLOCKED on a monitor */
THREAD_WAIT= 4,/* WAITING in Object.wait() */
/* non-JDWP states */
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 */
THREAD_VMWAIT= 8,/* waiting on a VM resource */
} ThreadStatus;
/*
* Thread suspend/resume, used by the GC and debugger.
*/
typedef enum SuspendCause {
SUSPEND_NOT = 0,
SUSPEND_FOR_GC,
SUSPEND_FOR_DEBUG,
SUSPEND_FOR_DEBUG_EVENT,
SUSPEND_FOR_STACK_DUMP,
SUSPEND_FOR_DEX_OPT,
#if defined(WITH_JIT)
SUSPEND_FOR_JIT,
#endif
} SuspendCause;
上面案例裡面執行緒1，55，96，84都處於Blocked狀態, 在等待monitor鎖，執行緒49處於Native狀態，在執行一個Native方法，具體呼叫棧如下
"RxIoScheduler-3" daemon prio=5 tid=49 Native | group="main" sCount=1 dsCount=0 obj=0x32c0aa60 self=0xf5226c00 | sysTid=13308 nice=0 cgrp=default sched=0/0 handle=0xf5313a80 | state=S schedstat=( 1354206596 302762808 4264 ) utm=111 stm=24 core=2 HZ=100 | stack=0xde4b3000-0xde4b5000 stackSize=1036KB | held mutexes= kernel: (couldn't read /proc/self/task/13308/stack) native: #00 pc 0003838c/system/lib/libc.so (read+8) native: #01 pc 000317f5/system/lib/libc.so (__sread+8) native: #02 pc 0003153f/system/lib/libc.so (__srefill+206) native: #03 pc 000501f3/system/lib/libc.so (fread+162) native: #04 pc 0001d431/system/lib/libc.so (android_getaddrinfofornet+1364) native: #05 pc 00000c3f/system/vendor/lib/libNimsWrap.so (android_getaddrinfofornet+38) native: #06 pc 0002098f/system/lib/libjavacore.so (???) native: #07 pc 0009ba6b/data/dalvik-cache/arm/system@[email protected] (Java_libcore_io_Posix_android_1getaddrinfo__Ljava_lang_String_2Landroid_system_StructAddrinfo_2I+134) at libcore.io.Posix.android_getaddrinfo(Native method) at libcore.io.ForwardingOs.android_getaddrinfo(ForwardingOs.java:55) at java.net.InetAddress.lookupHostByName(InetAddress.java:438) at java.net.InetAddress.getAllByNameImpl(InetAddress.java:252) at java.net.InetAddress.getAllByName(InetAddress.java:215) at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:142) at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:169) at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:124) at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:365) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:560) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:658) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:632) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:621) at com.*.*(*.java:592) - locked <0x14818fd3> (a java.lang.Object) at com.*.*.*Provider.query(*Provider.java:149) - locked <0x33199586> (a com.*.*.*Provider) at android.content.ContentProvider.query(ContentProvider.java:1010) at android.content.ContentProvider$Transport.query(ContentProvider.java:214) at android.content.ContentResolver.query(ContentResolver.java:504) at android.content.ContentResolver.query(ContentResolver.java:439) at com.*.*(*.java:696) at com.*.*(*.java:183) at com.*.*(*.java:162) at com.*.*.utils.ag$1.a(*.java:30) at com.*.*.utils.ag$1.call(*.java:26) at rx.c.a(Observable.java:8666) at rx.internal.operators.ac$1.call(OperatorSubscribeOn.java:94) at rx.internal.schedulers.a$b$1.call(CachedThreadScheduler.java:220) at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422) at java.util.concurrent.FutureTask.run(FutureTask.java:237) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:152) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:265) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587) at java.lang.Thread.run(Thread.java:818)
如果ANR的原因是UI執行緒參與鎖競爭，梳理一張執行緒之間的關係圖可以讓原因一目瞭然。
2.2 分析Logcat日誌
發生ANR時logcat會列印很多資訊，下面ANR in指向的Activity和trace日誌中UI執行緒發生Block時的Activity一致, Reason給出了輸入事件分發超時的原因。
// 發生ANR的Activity 05-03 00:54:46.888 2479 2504 E ActivityManager: ANR in com.*.*(com.*.*/.*.*Activity) 05-03 00:54:46.888 2479 2504 E ActivityManager: PID: 13178 // 有應用但沒有焦點視窗來處理輸入事件 05-03 00:54:46.888 2479 2504 E ActivityManager: Reason: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.) // 最近1分鐘/5分鐘/15分鐘的CPU平均負載 05-03 00:54:46.888 2479 2504 E ActivityManager: Load: 8.41 / 7.82 / 7.5 // ANR發生前各程序的CPU使用率，每個程序的使用率又分為使用者態和核心態 05-03 00:54:46.888 2479 2504 E ActivityManager: CPU usage from 897ms to -4816ms ago: 05-03 00:54:46.888 2479 2504 E ActivityManager: 70% 2479/system_server: 37% user + 33% kernel / faults: 12344 minor // 發生ANR程序的CPU使用率 / 缺頁錯誤次數 05-03 00:54:46.888 2479 2504 E ActivityManager: 66% 13178/com.*.*: 50% user + 16% kernel / faults: 30732 minor 11 major ... // +表示程序是在ANR發生前後的兩個取樣時間段內新建的 05-03 00:54:46.888 2479 2504 E ActivityManager: +0% 13871/screencap: 0% user + 0% kernel 05-03 00:54:46.888 2479 2504 E ActivityManager: 0% TOTAL: 0.1% user + 0% kernel + 0% irq + 0% softirq // ANR發生後各程序的CPU使用率 05-03 00:54:46.888 2479 2504 E ActivityManager: CPU usage from 4268ms to 4791ms later: 05-03 00:54:46.888 2479 2504 E ActivityManager: 23% 13178/com.*.*: 17% user + 5.7% kernel / faults: 821 minor ...
某一時間點的CPU負載可以理解為正在使用和等待使用CPU的活動程序數，對一段時間內的多個時間點取樣可以得到這一段時間的平均負載，由於ANR的超時限制基本都在1分鐘以內，所以最近1分鐘的平均負載參考價值更大，也可以通過 /proc/loadavg 檔案檢視CPU負載。如果CPU負載過高導致當前程序的UI執行緒分配不到充足的CPU時間片也會導致ANR。
logcat一般會列印ANR發生前後兩段時間的CPU使用率，有時候是ANR發生之後的兩段時間，也可以通過/proc/pid/stat, /proc/pid/task/tid/stat 檔案檢視CPU使用率。如果當前程序的其他執行緒或其他程序的CPU使用率過高導致當前程序的UI執行緒分配不到充足的CPU時間片也會導致ANR。
faults: *** minor *** major
minor指Minor Page Fault(次要頁錯誤)和major指Major Page Fault(主要頁錯誤)，核心讀資料時會先後查詢CPU的快取記憶體和實體記憶體，如果如果找不到會發出一個MPF資訊，請求將資料載入到記憶體，資料被載入到記憶體後，核心再次讀取時，會發出一個MnPF資訊。所以minor可以理解為程序在訪問記憶體，major可以理解為程序在做磁碟io，分析問題需要注意MPF過多，iowait CPU佔用過高的資訊。
3 系統檢測和報告ANR的機制
3.1 檢測機制
3.1.1 InputEvent超時檢測
linux底層識別到按鍵，觸屏這些物理輸入時會把他們抽象轉換成Android系統可以處理的輸入事件。system_server程序的InputDispatcherThread執行緒中InputDispatcher負責分發輸入事件，等待分發的輸入事件都會進入outboundQueue排隊，InputDispatcher分發事件時會尋找接收輸入事件的焦點視窗並判斷視窗是否準備好處理更多的輸入事件，如果視窗可以處理就會通過IPC機制（InputChanel）把輸入事件傳送給應用程序的視窗，傳送成功後輸入事件會從outboundQueue轉移到waitQueue，視窗一般會把接收到的輸入事件傳遞給View樹處理並通過IPC機制通知InputDispatcher把成功分發的事件從waitQueue中移除，開發分發新事件。
如果沒有焦點視窗或視窗無法處理更多輸入事件導致等待超時，會觸發AMS報告ANR並丟棄當前事件開始分發其他事件。
ANR-InputEvent檢測.png
int32_t InputDispatcher::findFocusedWindowTargetsLocked(nsecs_t currentTime,
const EventEntry* entry, Vector<InputTarget>& inputTargets, nsecs_t* nextWakeupTime) {
int32_t injectionResult;
std::string reason;
// If there is no currently focused window and no focused application
// then drop the event.
if (mFocusedWindowHandle == NULL) {
if (mFocusedApplicationHandle != NULL) {
injectionResult = handleTargetsNotReadyLocked(currentTime, entry,
mFocusedApplicationHandle, NULL, nextWakeupTime,
"Waiting because no window has focus but there is a "
"focused application that may eventually add a window "
"when it finishes starting up.");
goto Unresponsive;
}
ALOGI("Dropping event because there is no focused window or focused application.");
injectionResult = INPUT_EVENT_INJECTION_FAILED;
goto Failed;
}
...
// Check whether the window is ready for more input.
reason = checkWindowReadyForMoreInputLocked(currentTime,
mFocusedWindowHandle, entry, "focused");
...
}
案例中InputDispatcher在尋找焦點應用和視窗時發現mFocusedWindowHandle == NULL && mFocusedApplicationHandle != NULL，所以列印了下面的日誌。
Reason: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
3.1.2 Service超時檢測
AMS啟動Service時會給system_server程序的ActivityManager執行緒所繫結的MessageQueue中傳送一個用於檢測超時的訊息。如果應用程序的UI執行緒上Service的生命週期方法在限定的時間內執行完，會呼叫AMS的serviceDoneExecuting方法移除這個訊息，使AMS不再處理這個訊息。如果限定時間內，Service的生命週期方法未執行完，AMS就會處理這個訊息，進而報告ANR
ANR-Service檢測.png
3.1.3 Broadcast超時檢測
Broadcast超時檢測的機制和Service類似也是利用了訊息機制，廣播分為並行廣播和序列廣播，只有序列廣播會發生ANR。systerm_server程序中的BroadcastQueue每次分發廣播時會檢測廣播總的處理時間是否超過了2×time×num，time是單個接收器處理廣播的超時時間，num是接收器的數量。如果超過了會進入一個超時判斷，如果未超過會開始分發廣播，分發廣播給第一個接收器時會給AMS執行緒傳送一個定時訊息BROADCAST_TIMEOUT_MSG，
每次處理定時訊息時也會進入一個超時判斷，如果發生了超時則會丟棄當前廣播，報告ANR，並開始分發新廣播。定時訊息只有在序列廣播被所有接收器處理完後才會移除。
ANR-Broadcast檢測.png
判斷超時的邏輯比較巧妙
final void broadcastTimeoutLocked(boolean fromMsg) {
...
long now = SystemClock.uptimeMillis();
BroadcastRecord r = mOrderedBroadcasts.get(0);
if (fromMsg) {
...
// r.receiverTime是 當前接收器 接收廣播的時間，這個值會動態更新
// mTimeoutPeriod是單個廣播的超時時間
long timeoutTime = r.receiverTime + mTimeoutPeriod;
if (timeoutTime > now) {
// We can observe premature timeouts because we do not cancel and reset the
// broadcast timeout message after each receiver finishes.Instead, we set up
// an initial timeout then kick it down the road a little further as needed
// when it expires.
if (DEBUG_BROADCAST) Slog.v(TAG_BROADCAST,
"Premature timeout ["
+ mQueueName + "] @ " + now + ": resetting BROADCAST_TIMEOUT_MSG for "
+ timeoutTime);
setBroadcastTimeoutLocked(timeoutTime);
return;
}
}
...
r.receiverTime = now;
...
// Move on to the next receiver.
finishReceiverLocked(r, r.resultCode, r.resultData,
r.resultExtras, r.resultAbort, false);
scheduleBroadcastsLocked();
if (!debugging && anrMessage != null) {
// Post the ANR to the handler since we do not want to process ANRs while
// potentially holding our lock.
mHandler.post(new AppNotResponding(app, anrMessage));
}
}
假設一條序列廣播有2個接收器，在時間點t1給第一個接收器傳送了廣播，則r.receiverTime的初始值為t1, AMS執行緒在t1+x（x為超時時間）的時間點會處理這個訊息，如果這段時間內第一個接收器處理完了廣播並通知了BroadcastQueue廣播已處理，BroadcastQueue會在時間點t2給第二個接收器傳送廣播，此時r.receiverTime=t2，這樣在第一次處理超時訊息時 timeoutTime = r.receiverTime + mTimeoutPeriod = t2 + x > now = t1 + x，這樣就不會走下面分發新廣播和報告ANR的邏輯了，並且會再發送一個超時訊息，在時間點t2+x檢測第二個接收器是否處理完了廣播，如果在t2到t2+x期間第二個接收器處理完了廣播，則會移除t2+x時間點的超時訊息，不再檢測ANR, 並開始下一個序列廣播的分發。
ANR-廣播檢測定時訊息.png
三種檢測機制中InputEvent的檢測利用了Native層的超時機制，Service, Broadcast的檢測利用了Java層的訊息機制。這裡用於檢測超時的訊息機制執行在system_server程序中，注意和應用程序中處理應用邏輯的訊息機制區分開。系統檢測ANR的機制側重於講解整體流程和基本原理，更多細節可以參考相關連結裡的原始碼分析。
3.2 報告機制
無論是哪種型別的ANR，最終都會調AppErrors的appNotResponding方法，方法內部的主要邏輯就是寫trace檔案，列印logcat日誌，寫dropbox檔案，彈ANR對話方塊。
/**
* ProcessRecord app：發生ANR的程序
* ActivityRecord activity：發生ANR的Activity
* String annotation：發生ANR的原因
*/
final void appNotResponding(ProcessRecord app, ActivityRecord activity,
ActivityRecord parent, boolean aboveSystem, final String annotation) {
...
long anrTime = SystemClock.uptimeMillis();
if (ActivityManagerService.MONITOR_CPU_USAGE) {
mService.updateCpuStatsNow();
}
...
// Log the ANR to the main log.
StringBuilder info = new StringBuilder();
info.setLength(0);
info.append("ANR in ").append(app.processName);
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");
}
ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(true);
...
// For background ANRs, don't pass the ProcessCpuTracker to
// avoid spending 1/2 second collecting stats to rank lastPids.
File tracesFile = ActivityManagerService.dumpStackTraces(
true, firstPids,
(isSilentANR) ? null : processCpuTracker,
(isSilentANR) ? null : lastPids,
nativePids);
String cpuInfo = null;
if (ActivityManagerService.MONITOR_CPU_USAGE) {
mService.updateCpuStatsNow();
synchronized (mService.mProcessCpuTracker) {
cpuInfo = mService.mProcessCpuTracker.printCurrentState(anrTime);
}
info.append(processCpuTracker.printCurrentLoad());
info.append(cpuInfo);
}
info.append(processCpuTracker.printCurrentState(anrTime));
Slog.e(TAG, info.toString());
if (tracesFile == null) {
// There is no trace file, so dump (only) the alleged culprit's threads to the log
Process.sendSignal(app.pid, Process.SIGNAL_QUIT);
}
...
mService.addErrorToDropBox("anr", app, app.processName, activity, parent, annotation,
cpuInfo, tracesFile, null);
...
synchronized (mService) {
...
// Bring up the infamous App Not Responding dialog
Message msg = Message.obtain();
msg.what = ActivityManagerService.SHOW_NOT_RESPONDING_UI_MSG;
msg.obj = new AppNotRespondingDialog.Data(app, activity, aboveSystem);
mService.mUiHandler.sendMessage(msg);
}
}
AMS的dumpStackTraces方法會寫trace檔案，檔案格式一般如下
----- pid 發生ANR的程序號 at Date -----
Cmd line: 發生ANR的程序名
記憶體和GC資訊
DALVIK THREADS (執行緒總數):
UI執行緒的呼叫棧
其他執行緒的呼叫棧
----- end 發生ANR的程序號 -----
----- pid 其他程序的程序號 at Date -----
...
----- end 其他程序的程序號 -----
知道日誌格式後分析動輒上萬行的ANR日誌時心裡也不會慌
4 避坑挖坑經驗
瞭解了系統檢測ANR的機制後，在日常開發中要注意兩點：
- 不要在UI執行緒上寫可能導致超時的邏輯
- 耗時操作非同步化，可以利用AsyncTask, HandlerThread，AsyncQueryHandler，CursorLoader, IntentService, 註冊廣播時指定處理執行緒, RxJava及基於RxJava的擴充套件庫等實現非同步化
- 注意UI執行緒參與鎖競爭
- 注意UI效能的優化
- 注意死迴圈
- 注意死鎖
- 非UI執行緒上如果有太耗CPU的操作要考慮對UI執行緒CPU使用率的影響
如果是做SDK的同學還應該多注意兩點
- 儘量少寫同步邏輯，如果必須寫，儘量縮小同步的範圍
- public api儘量加上UiThread，WorkerThread，AnyThread這些Android支援庫的註解，防止業務同學誤用
開發中遇到過App冷啟動時十幾個庫的初始化和多處業務程式碼都呼叫一個底層庫的api來獲取一個通用資料，這個api的內部有多處鎖的邏輯導致啟動時發生了ANR。對於這種複雜case既需要考慮api內部的設計，也要考慮業務方對api的使用場景，最後的解決方案是業務方建立快取，開一個單執行緒調可能導致block的api去獲取資料和寫快取，其他執行緒調不會導致block的方法去讀快取，讀不到時給單執行緒提交獲取資料的任務（梳理各種庫和業務邏輯後發現第一次可以取不到），快取的讀寫邏輯用volatile保持可見性即可，不必使用比較重的鎖邏輯。
5 自動化監控上報分析
除了日常開發中踐行良好的程式碼實踐保證開發質量，應用上線後我們還需要一套自動化的機制來監控上報分析每天線上發生的ANR。
ANR-自動化監控方案.png
5.1 監聽ANR及UI執行緒Block
5.1.1 監聽ANR
主要原理是利用了系統報告ANR的機制和Java的FileObserver機制監聽trace檔案，如果監聽到trace檔案有寫操作則說明發生了ANR。
5.1.2 監聽UI執行緒Block
這裡介紹兩種監聽UI執行緒Block的方式
-
利用訊息機制監聽UI執行緒是否有發生Block， 可以建立一個watch執行緒，在時間點t給一個int型變數tick賦值x即tick=x, 同時給ui執行緒post一個runnable, runnable的作用是對tick進行自增操作，然後watch執行緒sleep 5s（值可以調整）, 5s後讀取tick的值，如果tick=x則說明5s內ui執行緒都沒有完成自增操作，發生了Block，如果tick=x+1則ui執行緒沒有發生block, 10s後可以再次讀取tick的值
ANR-UI執行緒Block檢測.png
-
另一種利用訊息機制的方式原理上更加簡單。ui執行緒的looper在分發訊息前後都會列印日誌，給ui執行緒的looper設定一個Printer後，通過計算列印日誌的時間差得到處理訊息的時間，進而判斷是否發生了Block。
public static void loop() {
...
for (;;) {
...
// This must be in a local variable, in case a UI event sets the logger
final Printer logging = me.mLogging;
if (logging != null) {
logging.println(">>>>> Dispatching to " + msg.target + " " +
msg.callback + ": " + msg.what);
}
...
try {
msg.target.dispatchMessage(msg);
end = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
} finally {
if (traceTag != 0) {
Trace.traceEnd(traceTag);
}
}
...
if (logging != null) {
logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
}
...
}
}
5.2 收集資訊
發生ANR時需要收集兩種資訊，trace檔案和logcat日誌
可以利用FileObserver來監聽trace檔案，當發生ANR並生成trace檔案後可以在FileObserver的回撥中做檔案的解析和上報。上報日誌的粒度需要權衡，一般的ANR問題，拿到發生ANR程序的執行緒棧資訊就可以定位原因，但對於一些複雜詭異ANR，如果能拿到其他程序的資訊分析時會多一些線索，拿到的現場日誌越多，分析就越接近客觀和準確。但上傳更多的日誌要考慮對傳輸和儲存的影響。
logcat日誌可以通過List<ProcessErrorStateInfo> ActivityManager#getProcessesInErrorState獲取發生ANR時的Logcat日誌，
android.app.ActivityManager.ProcessErrorStateInfo#shortMsg: Logcat日誌中的Reason，
android.app.ActivityManager.ProcessErrorStateInfo#longMsg: Logcat日誌，
Logcat裡CPU相關的日誌也可用通過讀取cpu相關的檔案獲取。
5.3 初步分析
對於客戶端上報的ANR日誌，服務端可以做初步的聚類分析，合併同類問題，降低人工篩選歸類的成本。分析時可以利用trace檔案和logcat日誌的格式。
5.4 分配工單
初步分析後可以建立工單，根據一定的匹配規則把問題分配給對應的RD進行進一步的處理。