從技術(shù)的角度看帝簇，ANR對用戶體驗的傷害僅次于Crash贬芥。多年的開發(fā)實踐過程中遇到過不少ANR問題笑诅，有兩次印象比較深调缨，都是App冷啟動后卡死在廣告頁進(jìn)不了主頁導(dǎo)致應(yīng)用市場審核不通過疮鲫。
在發(fā)版審核這種關(guān)鍵節(jié)點吆你，分析原因解決問題的速度很重要，而速度取決于分析問題的思路俊犯，相關(guān)技術(shù)的日掣径啵總結(jié)以及對業(yè)務(wù)和代碼的熟悉度。下面先從一個實際例子開始燕侠。

1 實際案例

這是一次ANR后者祖，分析trace文件得到的線程等待關(guān)系圖

ANR-線程關(guān)系圖.png

圖中UI線程(tid=1)和另外兩個Rx調(diào)度線程(tid=55,tid=96)都在等待鎖 <0x33199586> *Provider，鎖<0x33199586> *Provider被另一個Rx調(diào)度線程（tid=49）持有绢彤，線程49持有鎖<0x33199586> *Provider后七问，又調(diào)用了一個同步方法持有了鎖<0x14818fd3> Object（被線程84等待），這個同步方法內(nèi)部在執(zhí)行網(wǎng)絡(luò)請求導(dǎo)致UI線程長時間Block進(jìn)而造成了ANR茫舶。

UI線程參與并發(fā)很容易造成ANR, 并發(fā)一般涉及到鎖械巡，如果UI線程等待鎖的時間過長都會發(fā)生ANR。圖中如果不是線程49，而是線程55或線程96先持有了鎖<0x33199586> *Provider并去執(zhí)行一段很耗時代碼也會造成ANR讥耗。

UI線程長時間Block會造成ANR, 網(wǎng)絡(luò)線程長時間Block有時也會造成嚴(yán)重的問題有勾。開發(fā)中遇到過鎖競爭造成網(wǎng)絡(luò)線程Block導(dǎo)致進(jìn)首頁后長時間loading的case，Block的原因是發(fā)送請求時在攔截器里需要添加一個公參古程，獲取公參的方法有鎖相關(guān)的邏輯蔼卡。圖中線程55和線程96都是網(wǎng)絡(luò)線程，即使UI線程沒有參與鎖競爭造成ANR挣磨，這兩個網(wǎng)絡(luò)線程也會因為Block造成端到端（從客戶端發(fā)出請求到客戶端收到響應(yīng)）時間過長雇逞。

定位到原因后問題就迎刃而解了，UI線程使用不會Block的api趋急，同時消除網(wǎng)絡(luò)線程之間的鎖競爭就可以快速解決這個問題喝峦。

2 分析方法

至今還記得剛?cè)胄械谝淮斡龅紸NR時自己完全沒有思路的情形。不知道看哪些日志呜达，面對海量日志不知道怎么快速分析提取有效信息谣蠢，更不清楚系統(tǒng)檢測ANR的機(jī)制。只是大概知道UI線程執(zhí)行耗時操作超過一定閾值時會被系統(tǒng)檢測到查近，然后彈FC對話框眉踱。這段重點從實操的角度說下分析ANR的方法。

2.1 分析Trace文件

Trace文件記錄了發(fā)生ANR時的進(jìn)程和線程信息霜威，分析過程主要分3步

找到trace文件并導(dǎo)出
trace文件一般都在/data/anr/目錄下谈喳，trace文件名有的不帶包名，有的帶包名戈泼，有的既帶包名又帶日期
系統(tǒng)存儲ANR文件的位置可以通過 adb shell getprop 得到婿禽，[dalvik.vm.stack-trace-file]:[/data/anr/traces.txt]

shell@PD1415BA:/data/anr $ ls -al
-rw-rw-rw- system   system          0 2018-09-12 15:20 packages-fail.txt
-rw-rw-rw- system   system     615759 2017-02-16 15:47 traces_com.*.*.txt
-rw-rw-rw- system   system     642303 2018-09-11 16:12 traces_com.*.*.txt
-rw-rw-rw- system   system     475820 2018-02-01 19:44 traces_com.omottec.demoapp.txt

系統(tǒng)還有個存儲ANR歷史文件的地方

shell@PD1415BA:/data/system/dropbox $ ls -al
-rw------- system   system        316 2018-09-10 03:31 SYSTEM_BOOT@1536521506856.txt
-rw-r--r-- system   system      49681 2018-09-11 16:13 data_app_anr@1536653591215.txt.gz

找到發(fā)生ANR的進(jìn)程和UI線程
Trace文件里的第一個進(jìn)程一般就是發(fā)生ANR的進(jìn)程(和系統(tǒng)寫ANR日志文件的邏輯有關(guān))，進(jìn)程下的第一個線程一般就是UI線程大猛，UI線程更準(zhǔn)確的判斷方法是看sysTid和pid是否相等扭倾，相等的就是UI線程，tid是創(chuàng)建線程時的序號挽绩。

----- pid 13178 at 2018-05-03 00:54:42 -----
Cmd line: com.*.*
...
DALVIK THREADS (97):
// "線程名" prio=優(yōu)先級 tid=線程創(chuàng)建序號 線程N(yùn)ative層的狀態(tài)
"main" prio=5 tid=1 Blocked
    // group=線程組名 sCount=掛起次數(shù)(suspend count) dsCount=調(diào)試被掛起次數(shù)(debug suspend count) obj=線程的Java對象地址 self=線程N(yùn)ative對象地址
  | group="main" sCount=1 dsCount=0 obj=0x74240c30 self=0xf5027800
  // sysTid=內(nèi)核線程id nice=調(diào)度優(yōu)先級 cgrp=調(diào)度屬組 sched=線程調(diào)度策略/優(yōu)先級 handle=線程處理函數(shù)地址  
  | sysTid=13178 nice=0 cgrp=default sched=0/0 handle=0xf7753bec
  // state=調(diào)度狀態(tài) schedstat=(線程執(zhí)行時間 線程等待時間 線程執(zhí)行的時間片長度) utm=用戶態(tài)時間 stm=內(nèi)核態(tài)時間 core=最后執(zhí)行線程的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線程, 搜索的結(jié)果可能有很多處膛壹，因為很多線程所屬線程組的name為main，要注意和name為main的UI線程區(qū)分開唉堪。

分析UI線程和相關(guān)線程的狀態(tài)
trace文件里的線程狀態(tài)和Java里面java.lang.Thread.State枚舉表示的線程狀態(tài)不是一個概念模聋，有個映射關(guān)系。trace文件里的線程狀態(tài)是native層的線程狀態(tài)唠亚，理解線程狀態(tài)可以幫助更好的分析問題链方，映射關(guān)系如下，在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狀態(tài), 在等待monitor鎖暂题，線程49處于Native狀態(tài)移剪，在執(zhí)行一個Native方法，具體調(diào)用棧如下

"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@framework@boot.oat (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線程參與鎖競爭薪者，梳理一張線程之間的關(guān)系圖可以讓原因一目了然纵苛。

2.2 分析Logcat日志

發(fā)生ANR時logcat會打印很多信息，下面ANR in指向的Activity和trace日志中UI線程發(fā)生Block時的Activity一致, Reason給出了輸入事件分發(fā)超時的原因言津。

// 發(fā)生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
// 有應(yīng)用但沒有焦點窗口來處理輸入事件
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平均負(fù)載
05-03 00:54:46.888 2479 2504 E ActivityManager: Load: 8.41 / 7.82 / 7.5
// ANR發(fā)生前各進(jìn)程的CPU使用率攻人，每個進(jìn)程的使用率又分為用戶態(tài)和內(nèi)核態(tài)
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
// 發(fā)生ANR進(jìn)程的CPU使用率 / 缺頁錯誤次數(shù)
05-03 00:54:46.888 2479 2504 E ActivityManager: 66% 13178/com.*.*: 50% user + 16% kernel / faults: 30732 minor 11 major
...
// +表示進(jìn)程是在ANR發(fā)生前后的兩個采樣時間段內(nèi)新建的
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發(fā)生后各進(jìn)程的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負(fù)載可以理解為正在使用和等待使用CPU的活動進(jìn)程數(shù)，對一段時間內(nèi)的多個時間點采樣可以得到這一段時間的平均負(fù)載悬槽，由于ANR的超時限制基本都在1分鐘以內(nèi)怀吻，所以最近1分鐘的平均負(fù)載參考價值更大，也可以通過 /proc/loadavg 文件查看CPU負(fù)載初婆。如果CPU負(fù)載過高導(dǎo)致當(dāng)前進(jìn)程的UI線程分配不到充足的CPU時間片也會導(dǎo)致ANR蓬坡。

logcat一般會打印ANR發(fā)生前后兩段時間的CPU使用率，有時候是ANR發(fā)生之后的兩段時間磅叛，也可以通過/proc/pid/stat, /proc/pid/task/tid/stat 文件查看CPU使用率屑咳。如果當(dāng)前進(jìn)程的其他線程或其他進(jìn)程的CPU使用率過高導(dǎo)致當(dāng)前進(jìn)程的UI線程分配不到充足的CPU時間片也會導(dǎo)致ANR。

faults: *** minor *** major
minor指Minor Page Fault(次要頁錯誤)和major指Major Page Fault(主要頁錯誤)弊琴，內(nèi)核讀數(shù)據(jù)時會先后查找CPU的高速緩存和物理內(nèi)存兆龙，如果如果找不到會發(fā)出一個MPF信息，請求將數(shù)據(jù)加載到內(nèi)存敲董，數(shù)據(jù)被加載到內(nèi)存后紫皇，內(nèi)核再次讀取時，會發(fā)出一個MnPF信息腋寨。所以minor可以理解為進(jìn)程在訪問內(nèi)存聪铺，major可以理解為進(jìn)程在做磁盤io，分析問題需要注意MPF過多精置，iowait CPU占用過高的信息计寇。

3 系統(tǒng)檢測和報告ANR的機(jī)制

3.1 檢測機(jī)制

3.1.1 InputEvent超時檢測

linux底層識別到按鍵锣杂，觸屏這些物理輸入時會把他們抽象轉(zhuǎn)換成Android系統(tǒng)可以處理的輸入事件脂倦。system_server進(jìn)程的InputDispatcherThread線程中InputDispatcher負(fù)責(zé)分發(fā)輸入事件，等待分發(fā)的輸入事件都會進(jìn)入outboundQueue排隊元莫，InputDispatcher分發(fā)事件時會尋找接收輸入事件的焦點窗口并判斷窗口是否準(zhǔn)備好處理更多的輸入事件赖阻，如果窗口可以處理就會通過IPC機(jī)制（InputChanel）把輸入事件發(fā)送給應(yīng)用進(jìn)程的窗口，發(fā)送成功后輸入事件會從outboundQueue轉(zhuǎn)移到waitQueue踱蠢，窗口一般會把接收到的輸入事件傳遞給View樹處理并通過IPC機(jī)制通知InputDispatcher把成功分發(fā)的事件從waitQueue中移除火欧，開發(fā)分發(fā)新事件棋电。
如果沒有焦點窗口或窗口無法處理更多輸入事件導(dǎo)致等待超時，會觸發(fā)AMS報告ANR并丟棄當(dāng)前事件開始分發(fā)其他事件苇侵。

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在尋找焦點應(yīng)用和窗口時發(fā)現(xiàn)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進(jìn)程的ActivityManager線程所綁定的MessageQueue中發(fā)送一個用于檢測超時的消息榆浓。如果應(yīng)用進(jìn)程的UI線程上Service的生命周期方法在限定的時間內(nèi)執(zhí)行完于未，會調(diào)用AMS的serviceDoneExecuting方法移除這個消息，使AMS不再處理這個消息陡鹃。如果限定時間內(nèi)烘浦，Service的生命周期方法未執(zhí)行完，AMS就會處理這個消息萍鲸，進(jìn)而報告ANR

ANR-Service檢測.png

3.1.3 Broadcast超時檢測

Broadcast超時檢測的機(jī)制和Service類似也是利用了消息機(jī)制闷叉，廣播分為并行廣播和串行廣播，只有串行廣播會發(fā)生ANR脊阴。systerm_server進(jìn)程中的BroadcastQueue每次分發(fā)廣播時會檢測廣播總的處理時間是否超過了2×time×num握侧，time是單個接收器處理廣播的超時時間，num是接收器的數(shù)量嘿期。如果超過了會進(jìn)入一個超時判斷藕咏，如果未超過會開始分發(fā)廣播，分發(fā)廣播給第一個接收器時會給AMS線程發(fā)送一個定時消息BROADCAST_TIMEOUT_MSG秽五，
每次處理定時消息時也會進(jìn)入一個超時判斷孽查，如果發(fā)生了超時則會丟棄當(dāng)前廣播，報告ANR坦喘，并開始分發(fā)新廣播盲再。定時消息只有在串行廣播被所有接收器處理完后才會移除。

ANR-Broadcast檢測.png

判斷超時的邏輯比較巧妙

final void broadcastTimeoutLocked(boolean fromMsg) {
        ...
        long now = SystemClock.uptimeMillis();
        BroadcastRecord r = mOrderedBroadcasts.get(0);
        if (fromMsg) {
            ...
             // r.receiverTime是 當(dāng)前接收器 接收廣播的時間瓣铣，這個值會動態(tài)更新
             // 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));
        }
    }

假設(shè)一條串行廣播有2個接收器答朋，在時間點t1給第一個接收器發(fā)送了廣播，則r.receiverTime的初始值為t1, AMS線程在t1+x（x為超時時間）的時間點會處理這個消息棠笑，如果這段時間內(nèi)第一個接收器處理完了廣播并通知了BroadcastQueue廣播已處理梦碗，BroadcastQueue會在時間點t2給第二個接收器發(fā)送廣播，此時r.receiverTime=t2蓖救，這樣在第一次處理超時消息時 timeoutTime = r.receiverTime + mTimeoutPeriod = t2 + x > now = t1 + x洪规，這樣就不會走下面分發(fā)新廣播和報告ANR的邏輯了，并且會再發(fā)送一個超時消息循捺，在時間點t2+x檢測第二個接收器是否處理完了廣播斩例，如果在t2到t2+x期間第二個接收器處理完了廣播，則會移除t2+x時間點的超時消息从橘，不再檢測ANR, 并開始下一個串行廣播的分發(fā)念赶。

ANR-廣播檢測定時消息.png

三種檢測機(jī)制中InputEvent的檢測利用了Native層的超時機(jī)制础钠，Service, Broadcast的檢測利用了Java層的消息機(jī)制。這里用于檢測超時的消息機(jī)制運(yùn)行在system_server進(jìn)程中叉谜，注意和應(yīng)用進(jìn)程中處理應(yīng)用邏輯的消息機(jī)制區(qū)分開旗吁。系統(tǒng)檢測ANR的機(jī)制側(cè)重于講解整體流程和基本原理，更多細(xì)節(jié)可以參考相關(guān)鏈接里的源碼分析停局。

3.2 報告機(jī)制

無論是哪種類型的ANR阵漏，最終都會調(diào)AppErrors的appNotResponding方法，方法內(nèi)部的主要邏輯就是寫trace文件翻具，打印logcat日志履怯，寫dropbox文件，彈ANR對話框裆泳。

/**
 * ProcessRecord app：發(fā)生ANR的進(jìn)程
 * ActivityRecord activity：發(fā)生ANR的Activity
 * String annotation：發(fā)生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 發(fā)生ANR的進(jìn)程號 at Date -----
Cmd line: 發(fā)生ANR的進(jìn)程名
內(nèi)存和GC信息
DALVIK THREADS (線程總數(shù)):
UI線程的調(diào)用棧
其他線程的調(diào)用棧
----- end 發(fā)生ANR的進(jìn)程號 -----
----- pid 其他進(jìn)程的進(jìn)程號 at Date -----
...
----- end 其他進(jìn)程的進(jìn)程號 -----
知道日志格式后分析動輒上萬行的ANR日志時心里也不會慌

4 避坑挖坑經(jīng)驗

了解了系統(tǒng)檢測ANR的機(jī)制后，在日常開發(fā)中要注意兩點：

不要在UI線程上寫可能導(dǎo)致超時的邏輯
- 耗時操作異步化工禾，可以利用AsyncTask, HandlerThread运提，AsyncQueryHandler，CursorLoader, IntentService, 注冊廣播時指定處理線程, RxJava及基于RxJava的擴(kuò)展庫等實現(xiàn)異步化
- 注意UI線程參與鎖競爭
- 注意UI性能的優(yōu)化
- 注意死循環(huán)
- 注意死鎖
非UI線程上如果有太耗CPU的操作要考慮對UI線程CPU使用率的影響

如果是做SDK的同學(xué)還應(yīng)該多注意兩點

盡量少寫同步邏輯闻葵，如果必須寫民泵，盡量縮小同步的范圍
public api盡量加上UiThread，WorkerThread槽畔，AnyThread這些Android支持庫的注解栈妆，防止業(yè)務(wù)同學(xué)誤用

開發(fā)中遇到過App冷啟動時十幾個庫的初始化和多處業(yè)務(wù)代碼都調(diào)用一個底層庫的api來獲取一個通用數(shù)據(jù)，這個api的內(nèi)部有多處鎖的邏輯導(dǎo)致啟動時發(fā)生了ANR厢钧。對于這種復(fù)雜case既需要考慮api內(nèi)部的設(shè)計鳞尔，也要考慮業(yè)務(wù)方對api的使用場景，最后的解決方案是業(yè)務(wù)方建立緩存早直，開一個單線程調(diào)可能導(dǎo)致block的api去獲取數(shù)據(jù)和寫緩存寥假，其他線程調(diào)不會導(dǎo)致block的方法去讀緩存，讀不到時給單線程提交獲取數(shù)據(jù)的任務(wù)（梳理各種庫和業(yè)務(wù)邏輯后發(fā)現(xiàn)第一次可以取不到）霞扬，緩存的讀寫邏輯用volatile保持可見性即可糕韧，不必使用比較重的鎖邏輯。

5 自動化監(jiān)控上報分析

除了日常開發(fā)中踐行良好的代碼實踐保證開發(fā)質(zhì)量喻圃，應(yīng)用上線后我們還需要一套自動化的機(jī)制來監(jiān)控上報分析每天線上發(fā)生的ANR萤彩。

ANR-自動化監(jiān)控方案.png

5.1 監(jiān)聽ANR及UI線程Block

5.1.1 監(jiān)聽ANR

主要原理是利用了系統(tǒng)報告ANR的機(jī)制和Java的FileObserver機(jī)制監(jiān)聽trace文件，如果監(jiān)聽到trace文件有寫操作則說明發(fā)生了ANR级及。

5.1.2 監(jiān)聽UI線程Block

這里介紹兩種監(jiān)聽UI線程Block的方式

利用消息機(jī)制監(jiān)聽UI線程是否有發(fā)生Block乒疏，可以創(chuàng)建一個watch線程额衙，在時間點t給一個int型變量tick賦值x即tick=x, 同時給ui線程post一個runnable, runnable的作用是對tick進(jìn)行自增操作饮焦，然后watch線程sleep 5s（值可以調(diào)整）, 5s后讀取tick的值怕吴，如果tick=x則說明5s內(nèi)ui線程都沒有完成自增操作，發(fā)生了Block县踢，如果tick=x+1則ui線程沒有發(fā)生block, 10s后可以再次讀取tick的值

ANR-UI線程Block檢測.png
另一種利用消息機(jī)制的方式原理上更加簡單转绷。ui線程的looper在分發(fā)消息前后都會打印日志，給ui線程的looper設(shè)置一個Printer后硼啤，通過計算打印日志的時間差得到處理消息的時間议经，進(jìn)而判斷是否發(fā)生了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 收集信息

發(fā)生ANR時需要收集兩種信息谴返，trace文件和logcat日志

可以利用FileObserver來監(jiān)聽trace文件煞肾，當(dāng)發(fā)生ANR并生成trace文件后可以在FileObserver的回調(diào)中做文件的解析和上報。上報日志的粒度需要權(quán)衡嗓袱，一般的ANR問題籍救，拿到發(fā)生ANR進(jìn)程的線程棧信息就可以定位原因，但對于一些復(fù)雜詭異ANR渠抹，如果能拿到其他進(jìn)程的信息分析時會多一些線索蝙昙，拿到的現(xiàn)場日志越多，分析就越接近客觀和準(zhǔn)確梧却。但上傳更多的日志要考慮對傳輸和存儲的影響奇颠。

logcat日志可以通過List<ProcessErrorStateInfo> ActivityManager#getProcessesInErrorState獲取發(fā)生ANR時的Logcat日志，
android.app.ActivityManager.ProcessErrorStateInfo#shortMsg: Logcat日志中的Reason放航，
android.app.ActivityManager.ProcessErrorStateInfo#longMsg: Logcat日志烈拒，
Logcat里CPU相關(guān)的日志也可用通過讀取cpu相關(guān)的文件獲取。

5.3 初步分析

對于客戶端上報的ANR日志广鳍，服務(wù)端可以做初步的聚類分析缺菌，合并同類問題，降低人工篩選歸類的成本搜锰。分析時可以利用trace文件和logcat日志的格式伴郁。

5.4 分配工單

初步分析后可以創(chuàng)建工單，根據(jù)一定的匹配規(guī)則把問題分配給對應(yīng)的RD進(jìn)行進(jìn)一步的處理蛋叼。

Android ANR那些事