轉(zhuǎn)自：https://duanqz.github.io/2015-10-12-Watchdog-Analysis

1. 概覽

Watchdog的中文的“看門狗”，有保護(hù)的意思。最早引入Watchdog是在單片機(jī)系統(tǒng)中，由于單片機(jī)的工作環(huán)境容易受到外界磁場的干擾，導(dǎo)致程序“跑飛”，造成整個系統(tǒng)無法正常工作，因此，引入了一個“看門狗”，對單片機(jī)的運(yùn)行狀態(tài)進(jìn)行實(shí)時監(jiān)測，針對運(yùn)行故障做一些保護(hù)處理，譬如讓系統(tǒng)重啟。這種Watchdog屬于硬件層面，必須有硬件電路的支持。

Linux也引入了Watchdog，在Linux內(nèi)核下，當(dāng)Watchdog啟動后，便設(shè)定了一個定時器，如果在超時時間內(nèi)沒有對/dev/Watchdog進(jìn)行寫操作，則會導(dǎo)致系統(tǒng)重啟。通過定時器實(shí)現(xiàn)的Watchdog屬于軟件層面。

Android設(shè)計了一個軟件層面Watchdog，用于保護(hù)一些重要的系統(tǒng)服務(wù)，當(dāng)出現(xiàn)故障時，通常會讓Android系統(tǒng)重啟。由于這種機(jī)制的存在，就經(jīng)常會出現(xiàn)一些system_server進(jìn)程被Watchdog殺掉而發(fā)生手機(jī)重啟的問題。

本文期望回答以下問題：

Watchdog是怎么工作的？這涉及到Watchdog的工作機(jī)制。

遇到Watchdog的問題該怎么辦？這涉及到分析Watchdog問題的慣用方法。

2. Watchdog機(jī)制

我們以frameworks/base/services/core/java/com/android/server/Watchdog.java為藍(lán)本，分析Watchdog的實(shí)現(xiàn)邏輯。為了描述方便，ActivityManagerService， PackageManagerService， WindowManagerService會分別簡稱為AMS, PKMS, WMS。

2.1 Watchdog的初始化

Android的Watchdog是一個單例線程，在System Server時就會初始化Watchdog。Watchdog在初始化時，會構(gòu)建很多HandlerChecker，大致可以分為兩類：

Monitor Checker，用于檢查是Monitor對象可能發(fā)生的死鎖, AMS, PKMS, WMS等核心的系統(tǒng)服務(wù)都是Monitor對象。
Looper Checker，用于檢查線程的消息隊列是否長時間處于工作狀態(tài)。Watchdog自身的消息隊列，Ui, Io, Display這些全局的消息隊列都是被檢查的對象。此外，一些重要的線程的消息隊列，也會加入到Looper Checker中，譬如AMS, PKMS，這些是在對應(yīng)的對象初始化時加入的。

private Watchdog() {
    ....
    mMonitorChecker = new HandlerChecker(FgThread.getHandler(),
                "foreground thread", DEFAULT_TIMEOUT);
    mHandlerCheckers.add(mMonitorChecker);
    mHandlerCheckers.add(new HandlerChecker(new Handler(Looper.getMainLooper()),
                "main thread", DEFAULT_TIMEOUT));
    mHandlerCheckers.add(new HandlerChecker(UiThread.getHandler(),
                "ui thread", DEFAULT_TIMEOUT));
    mHandlerCheckers.add(new HandlerChecker(IoThread.getHandler(),
                "i/o thread", DEFAULT_TIMEOUT));
    mHandlerCheckers.add(new HandlerChecker(DisplayThread.getHandler(),
                "display thread", DEFAULT_TIMEOUT));
    ...
}

兩類HandlerChecker的側(cè)重點(diǎn)不同，Monitor Checker預(yù)警我們不能長時間持有核心系統(tǒng)服務(wù)的對象鎖，否則會阻塞很多函數(shù)的運(yùn)行; Looper Checker預(yù)警我們不能長時間的霸占消息隊列，否則其他消息將得不到處理。這兩類都會導(dǎo)致系統(tǒng)卡住(System Not Responding)。

2.2 添加Watchdog監(jiān)測對象

Watchdog初始化以后，就可以作為system_server進(jìn)程中的一個單獨(dú)的線程運(yùn)行了。但這個時候，還不能觸發(fā)Watchdog的運(yùn)行，因?yàn)锳MS, PKMS等系統(tǒng)服務(wù)還沒有加入到Watchdog的監(jiān)測集。所謂監(jiān)測集，就是需要Watchdog關(guān)注的對象，Android中有成千上萬的消息隊列在同時運(yùn)行，然而，Watchdog畢竟是系統(tǒng)層面的東西，它只會關(guān)注一些核心的系統(tǒng)服務(wù)。

Watchdog提供兩個方法，分別用于添加Monitor Checker對象和Looper Checker對象:

public void addMonitor(Monitor monitor) {
    // 將monitor對象添加到Monitor Checker中，
    // 在Watchdog初始化時，可以看到Monitor Checker本身也是一個HandlerChecker對象
    mMonitors.add(monitor);
}

public void addThread(Handler thread, long timeoutMillis) {
    synchronized (this) {
        if (isAlive()) {
            throw new RuntimeException("Threads can't be added once the Watchdog is running");
        }
        final String name = thread.getLooper().getThread().getName();
        // 為Handler構(gòu)建一個HandlerChecker對象，其實(shí)就是**Looper Checker**
        mHandlerCheckers.add(new HandlerChecker(thread, name, timeoutMillis));
    }
}

被Watchdog監(jiān)測的對象，都需要將自己添加到Watchdog的監(jiān)測集中。以下是AMS的類定義和構(gòu)造器的代碼片段：

public final class ActivityManagerService extends ActivityManagerNative
        implements Watchdog.Monitor, BatteryStatsImpl.BatteryCallback {

    public ActivityManagerService(Context systemContext) {
        ...
        Watchdog.getInstance().addMonitor(this);
        Watchdog.getInstance().addThread(mHandler);
    }

    public void monitor() {
        synchronized (this) { }
    }
}

AMS實(shí)現(xiàn)了Watchdog.Monitor接口，這個接口只有一個方法，就是monitor()，它的作用后文會再解釋。這里可以看到在AMS的構(gòu)造器中，將自己添加到Monitor Checker對象中，然后將自己的handler添加到Looper Checker對象中。其他重要的系統(tǒng)服務(wù)添加到Watchdog的代碼邏輯都與AMS差不多。

整個Android系統(tǒng)中，被monitor的對象并不多，十個手指頭就能數(shù)出來Watchdog.Monitor的實(shí)現(xiàn)類的個數(shù)。

2.3 Watchdog的監(jiān)測機(jī)制

Watchdog本身是一個線程，它的run()方法實(shí)現(xiàn)如下：

@Override
public void run() {
    boolean waitedHalf = false;
    while (true) {
        ...
        synchronized (this) {
            ...
            // 1\. 調(diào)度所有的HandlerChecker
            for (int i=0; i<mHandlerCheckers.size(); i++) {
                HandlerChecker hc = mHandlerCheckers.get(i);
                hc.scheduleCheckLocked();
            }
            ...
            // 2\. 開始定期檢查
            long start = SystemClock.uptimeMillis();
            while (timeout > 0) {
                ...
                try {
                    wait(timeout);
                } catch (InterruptedException e) {
                    Log.wtf(TAG, e);
                }
                ...
                timeout = CHECK_INTERVAL - (SystemClock.uptimeMillis() - start);
            }

            // 3\. 檢查HandlerChecker的完成狀態(tài)
            final int waitState = evaluateCheckerCompletionLocked();
            if (waitState == COMPLETED) {
                ...
                continue;
            } else if (waitState == WAITING) {
                ...
                continue;
            } else if (waitState == WAITED_HALF) {
                ...
                continue;
            }

            // 4\. 存在超時的HandlerChecker
            blockedCheckers = getBlockedCheckersLocked();
            subject = describeCheckersLocked(blockedCheckers);
            allowRestart = mAllowRestart;
        }
        ...
        // 5\. 保存日志，判斷是否需要?dú)⒌粝到y(tǒng)進(jìn)程
        Slog.w(TAG, "*** GOODBYE!");
        Process.killProcess(Process.myPid());
        System.exit(10);
    } // end of while (true)

}

以上代碼片段主要的運(yùn)行邏輯如下：

Watchdog運(yùn)行后，便開始無限循環(huán)，依次調(diào)用每一個HandlerChecker的scheduleCheckLocked()方法
調(diào)度完HandlerChecker之后，便開始定期檢查是否超時，每一次檢查的間隔時間由CHECK_INTERVAL常量設(shè)定，為30秒
每一次檢查都會調(diào)用evaluateCheckerCompletionLocked()方法來評估一下HandlerChecker的完成狀態(tài)：
- COMPLETED表示已經(jīng)完成
- WAITING和WAITED_HALF表示還在等待，但未超時
- OVERDUE表示已經(jīng)超時。默認(rèn)情況下，timeout是1分鐘，但監(jiān)測對象可以通過傳參自行設(shè)定，譬如PKMS的Handler Checker的超時是10分鐘
如果超時時間到了，還有HandlerChecker處于未完成的狀態(tài)(OVERDUE)，則通過getBlockedCheckersLocked()方法，獲取阻塞的HandlerChecker，生成一些描述信息
保存日志，包括一些運(yùn)行時的堆棧信息，這些日志是我們解決Watchdog問題的重要依據(jù)。如果判斷需要?dú)⒌魋ystem_server進(jìn)程，則給當(dāng)前進(jìn)程(system_server)發(fā)送signal 9

只要Watchdog沒有發(fā)現(xiàn)超時的任務(wù)，HandlerChecker就會被不停的調(diào)度，那HandlerChecker具體做一些什么檢查呢？直接上代碼：

public final class HandlerChecker implements Runnable {

    public void scheduleCheckLocked() {
        // Looper Checker中是不包含monitor對象的，判斷消息隊列是否處于空閑
        if (mMonitors.size() == 0 && mHandler.getLooper().isIdling()) {
            mCompleted = true;
            return;
        }
        ...
        // 將Monitor Checker的對象置于消息隊列之前，優(yōu)先運(yùn)行
        mHandler.postAtFrontOfQueue(this);
    }

    @Override
    public void run() {
        // 依次調(diào)用Monitor對象的monitor()方法
        for (int i = 0 ; i < size ; i++) {
            synchronized (Watchdog.this) {
                mCurrentMonitor = mMonitors.get(i);
            }
            mCurrentMonitor.monitor();
        }
        ...
    }
}

對于Looper Checker而言，會判斷線程的消息隊列是否處于空閑狀態(tài)。如果被監(jiān)測的消息隊列一直閑不下來，則說明可能已經(jīng)阻塞等待了很長時間
對于Monitor Checker而言，會調(diào)用實(shí)現(xiàn)類的monitor方法，譬如上文中提到的AMS.monitor()方法，方法實(shí)現(xiàn)一般很簡單，就是獲取當(dāng)前類的對象鎖，如果當(dāng)前對象鎖已經(jīng)被持有，則monitor()會一直處于wait狀態(tài)，直到超時，這種情況下，很可能是線程發(fā)生了死鎖

至此，我們已經(jīng)分析了Watchdog的工作機(jī)制，回答了我們提出的第一個問題：

Watchdog定時檢查一些重要的系統(tǒng)服務(wù)，舉報長時間阻塞的事件，甚至殺掉system_server進(jìn)程，讓Android系統(tǒng)重啟。

3. 問題分析方法

3.1 日志獲取

Andriod的日志門類繁多，而且，為了調(diào)試的需要，設(shè)備廠商和應(yīng)用開發(fā)者都會在AOSP的基礎(chǔ)上增加很多日志。面對如此龐大復(fù)雜的日志系統(tǒng)，通常只有對應(yīng)領(lǐng)域的專家才能看懂其透露的細(xì)節(jié)信息，就像去醫(yī)院就診，醫(yī)生一看檢查報告就知道患者身體出了什么問題，而外行對這些診斷信息往往是束手無策的。

解決Watchdog相關(guān)的問題，對日志的要求比較高，有些問題與當(dāng)時的系統(tǒng)環(huán)境相關(guān)，僅僅憑借單一的日志并不能定位問題。以下羅列出獲取Android日志的一些重要手段，部分場景下，Watchdog相關(guān)的問題甚至需要以下所有的日志：

logcat 通過adb logcat命令輸出Android的一些當(dāng)前運(yùn)行日志，可以通過logcat的 -b 參數(shù)指定要輸出的日志緩沖區(qū)，緩沖區(qū)對應(yīng)著logcat的一種日志類型。高版本的logcat可以使用 -b all 獲取到所有緩沖區(qū)的日志
- event 通過android.util.EventLog工具類打印的日志，一些重要的系統(tǒng)事件會使用此類日志
- main 通過android.util.Log工具類打印的日志，應(yīng)用程序，尤其是基于SDK的應(yīng)用程序，會使用此類日志
- system 通過android.util.Slog工具類打印的日志，系統(tǒng)相關(guān)的日志一般都是使用此類日志，譬如SystemServer
- radio 通過android.util.Rlog工具類打印的日志，通信模塊相關(guān)的日志一般都是使用此類日志，譬如RIL
dumpsys 通過adb dumpsys命令輸出一些重要的系統(tǒng)服務(wù)信息，譬如內(nèi)存、電源、磁盤等，工作原理可以查閱dumpsys介紹一文
traces 該文件記錄了一個時間段的函數(shù)調(diào)用棧信息，通常在應(yīng)用發(fā)生ANR(Application Not Responding)時，會觸發(fā)打印各進(jìn)程的函數(shù)調(diào)用棧。站在Linux的角度，其實(shí)就是向進(jìn)程發(fā)送SIGNAL_QUIT(3)請求，譬如，我們可以通過adb shell kill -3 <pid>命令，打印指定進(jìn)程<pid style="box-sizing: border-box;">的的trace。 SIGNAL_QUIT(3)表面意思有一點(diǎn)誤導(dǎo)，它其實(shí)并不會導(dǎo)致進(jìn)程退出。輸出一般在 /data/anr/traces.txt 文件中，當(dāng)然，這是可以靈活配置的， Android提供的系統(tǒng)屬性dalvik.vm.stack-trace-file可以用來配置生成traces文件的位置。</pid>
binder 通過Binder跨進(jìn)程調(diào)用的日志，可以通過adb shell cat命令從 /proc/binder 下取出對應(yīng)的日志
- failed_transaction_log
- transaction_log
- transactions
- stats
dropbox 為了記錄歷史的logcat日志，Android引入了Dropbox，將歷史日志持久化到磁盤中(/data/system/dropbox)。 logcat的緩沖區(qū)大小畢竟是有限的，所以需要循環(huán)利用，這樣歷史的日志信息就會被沖掉。在一些自動化測試的場景下，譬如Monkey需要長時間的運(yùn)行，就需要把歷史的日志全都保存下來。
tombstone tombstone錯誤一般由Dalvik錯誤、native層的代碼問題導(dǎo)致的。當(dāng)系統(tǒng)發(fā)生tombstone時，內(nèi)核會上報一個嚴(yán)重的警告信號，上層收到后，把當(dāng)前的調(diào)用棧信息持久化到磁盤中(/data/tombstone)
bugreport 通過adb bugreport命令輸出，日志內(nèi)容多到爆，logcat, traces, dmesg, dumpsys, binder的日志都包含在其中。由于輸出bugreport的時間很長，當(dāng)系統(tǒng)發(fā)生錯誤時，我們再執(zhí)行bugreport往往就來不及了(此時，系統(tǒng)可能都已經(jīng)重啟了)，所以，要動用bugreport就需要結(jié)合一些其他機(jī)制，譬如在殺掉system_server進(jìn)程之前，先讓bugreport運(yùn)行完。

3.2 問題定位

Watchdog出現(xiàn)的日志很明顯，logcat中的event, system中都會有體現(xiàn)，要定位問題，可以從檢索日志中的watchdog關(guān)鍵字開始。

發(fā)生Watchdog檢測超時這么重要的系統(tǒng)事件，Android會打印一個EventLog：

watchdog: Blocked in handler XXX    # 表示HandlerChecker超時了
watchdog: Blocked in monitor XXX    # 表示MonitorChecker超時了

Watchdog是運(yùn)行在system_server進(jìn)程中，會打印一些System類型的日志。在手機(jī)處于非調(diào)試狀態(tài)時，伴隨Watchdog出現(xiàn)的往往是system_server進(jìn)程被殺，從而系統(tǒng)重啟。當(dāng)Watchdog要主動殺掉system_server進(jìn)程時，以下關(guān)鍵字就會出現(xiàn)在SystemLog中：

Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: XXX
Watchdog: XXX
Watchdog: "*** GOODBYE!

當(dāng)我們在日志中檢索到上述兩類關(guān)鍵信息時，說明“Watchdog顯靈”了，從另一個角度來理解，就是“System Not Responding”了。接下來，我們需要進(jìn)一步定位在watchdog出現(xiàn)之前，system_server進(jìn)程在干什么，處于一個什么狀態(tài)。這與排除”Application Not Responding“問題差不多，我們需要進(jìn)程的traces信息、當(dāng)前系統(tǒng)的CPU運(yùn)行信息、IO信息。

找到Watchddog出現(xiàn)之前的traces.txt文件，這個時間差最好不要太大，因?yàn)閃atchdog默認(rèn)的超時時間是1分鐘，太久以前的traces并不能說明問題。誘導(dǎo)Watchdong出現(xiàn)的直接原因其實(shí)就是system_server中某個線程被阻塞了，這個信息在event和system的log中清晰可見。我們以一個systemLog為例：

W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.wm.WindowManagerService on foreground thread (android.fg)

Watchdog告訴我們Monitor Checker超時了，具體在哪呢？名為android.fg的線程在WindowManagerService的monitor()方法被阻塞了。這里隱含了兩層意思：

WindowManagerService實(shí)現(xiàn)了Watchdog.Monitor這個接口，并將自己作為Monitor Checker的對象加入到了Watchdog的監(jiān)測集中
monitor()方法是運(yùn)行在android.fg線程中的。Android將android.fg設(shè)計為一個全局共享的線程，意味著它的消息隊列可以被其他線程共享， Watchdog的Monitor Checker就是使用的android.fg線程的消息隊列。因此，出現(xiàn)Monitor Checker的超時，肯定是android.fg線程阻塞在monitor()方法上。

我們打開system_server進(jìn)程的traces，檢索 android.fg 可以快速定位到該線程的函數(shù)調(diào)用棧：

"android.fg" prio=5 tid=25 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x12eef900 self=0x7f7a8b1000
  | sysTid=973 nice=0 cgrp=default sched=0/0 handle=0x7f644e9000
  | state=S schedstat=( 3181688530 2206454929 8991 ) utm=251 stm=67 core=1 HZ=100
  | stack=0x7f643e7000-0x7f643e9000 stackSize=1036KB
  | held mutexes=
  at com.android.server.wm.WindowManagerService.monitor(WindowManagerService.java:13125)
  - waiting to lock <0x126dccb8> (a java.util.HashMap) held by thread 91
  at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:204)
  at android.os.Handler.handleCallback(Handler.java:815)
  at android.os.Handler.dispatchMessage(Handler.java:104)
  at android.os.Looper.loop(Looper.java:194)
  at android.os.HandlerThread.run(HandlerThread.java:61)
  at com.android.server.ServiceThread.run(ServiceThread.java:46)

android.fg線程調(diào)用棧告訴我們幾個關(guān)鍵的信息：

這個線程當(dāng)前的狀態(tài)是Blocked，阻塞
由Watchdog發(fā)起調(diào)用monitor()，這是一個Watchdog檢查，阻塞已經(jīng)超時
waiting to lock <0x126dccb8>：阻塞的原因是monitor()方法中在等鎖<0x126dccb8>
held by thread 91：這個鎖被編號為91的線程持有，需要進(jìn)一步觀察91號線程的狀態(tài)。

題外話：每一個進(jìn)程都會對自己所轄的線程編號，從1開始。1號線程通常就是我們所說的主線程。線程在Linux系統(tǒng)中還有一個全局的編號，由sysTid表示。我們在logcat等日志中看到的一般是線程的全局編號。譬如，本例中android.fg線程在system_server進(jìn)程中的編號是25，系統(tǒng)全局編號是973。

可以在traces.txt文件中檢索 tid=91 來快速找到91號線程的函數(shù)調(diào)用棧信息：

"Binder_C" prio=5 tid=91 Native
  | group="main" sCount=1 dsCount=0 obj=0x12e540a0 self=0x7f63289000
  | sysTid=1736 nice=0 cgrp=default sched=0/0 handle=0x7f6127c000
  | state=S schedstat=( 96931835222 49673449591 260122 ) utm=7046 stm=2647 core=2 HZ=100
  | stack=0x7f5ffbc000-0x7f5ffbe000 stackSize=1008KB
  | held mutexes=
  at libcore.io.Posix.writeBytes(Native method)
  at libcore.io.Posix.write(Posix.java:258)
  at libcore.io.BlockGuardOs.write(BlockGuardOs.java:313)
  at libcore.io.IoBridge.write(IoBridge.java:537)
  at java.io.FileOutputStream.write(FileOutputStream.java:186)
  at com.android.internal.util.FastPrintWriter.flushBytesLocked(FastPrintWriter.java:334)
  at com.android.internal.util.FastPrintWriter.flushLocked(FastPrintWriter.java:355)
  at com.android.internal.util.FastPrintWriter.appendLocked(FastPrintWriter.java:303)
  at com.android.internal.util.FastPrintWriter.print(FastPrintWriter.java:466)
  - locked <@addr=0x134c4910> (a com.android.internal.util.FastPrintWriter$DummyWriter)
  at com.android.server.wm.WindowState.dump(WindowState.java:1510)
  at com.android.server.wm.WindowManagerService.dumpWindowsNoHeaderLocked(WindowManagerService.java:12279)
  at com.android.server.wm.WindowManagerService.dumpWindowsLocked(WindowManagerService.java:12266)
  at com.android.server.wm.WindowManagerService.dump(WindowManagerService.java:12654)
  - locked <0x126dccb8> (a java.util.HashMap)
  at android.os.Binder.dump(Binder.java:324)
  at android.os.Binder.onTransact(Binder.java:290)

91號線程的名字是Binder_C，它的函數(shù)調(diào)用棧告訴我們幾個關(guān)鍵信息：

Native，表示線程處于運(yùn)行狀態(tài)(RUNNING)，并且正在執(zhí)行JNI方法
在WindowManagerService.dump()方法申請了鎖<0x126dccb8>，這個鎖正是android.fg線程所等待的
FileOutputStream.write()表示Binder_C線程在執(zhí)行IO寫操作，正式因?yàn)檫@個寫操作一直在阻塞，導(dǎo)致線程持有的鎖不能釋放

題外話：關(guān)于Binder線程。當(dāng)Android進(jìn)程啟動時，就會創(chuàng)建一個線程池，專門處理Binder事務(wù)。線程池中會根據(jù)當(dāng)前的binder線程計數(shù)器的值來構(gòu)造新創(chuàng)建的binder線程, 線程名”Binder_%X”，X是十六進(jìn)制。當(dāng)然，線程池的線程數(shù)也有上限，默認(rèn)情況下為16，所以，可以看到 Binder_1 ~ Binder_F 這樣的線程命名。

聰明的你看到這或許已經(jīng)能夠想到解決辦法了，在這個IO寫操作上加一個超時機(jī)制，并且這個超時小于Watchdog的超時，不就可以讓線程釋放它所占有的鎖了嗎？是的，這確實(shí)可以作為一個臨時解決方案(Workaround)，或者說一個保護(hù)機(jī)制。但我們可以再往深處想一想，這個IO寫操作為什么會阻塞：

是不是IO緩沖區(qū)滿了，導(dǎo)致寫阻塞呢？
是不是寫操作有什么鎖，導(dǎo)致這個write方法在等鎖呢？
是不是當(dāng)前系統(tǒng)的IO負(fù)載過于高，導(dǎo)致寫操作效率很低呢？

這都需要我們再進(jìn)一步從日志中去找原因。如果已有的日志不全，找不到論據(jù)，我們還需要設(shè)計場景來驗(yàn)證假設(shè)，解決問題的難度陡然上升。

3.3 場景還原

我們經(jīng)歷了兩個關(guān)鍵步驟：

通過event或system類型的日志，發(fā)現(xiàn)了Watchdog殺掉system_server導(dǎo)致系統(tǒng)重啟
通過traces日志，發(fā)了導(dǎo)致Watchdog出現(xiàn)的具體線程操作

這兩個過程基本就涵蓋了Watchdog的運(yùn)行機(jī)制了，但這并沒有解決問題啊。我們需要找到線程阻塞的原因是什么，然而，線程阻塞的原因就千奇百怪了。如果有問題出現(xiàn)的現(xiàn)場，并且問題可以重現(xiàn)，那么我們可以通過調(diào)試的手段來分析問題產(chǎn)生的原因。如果問題只是偶然出現(xiàn)，甚至只有一堆日志，我們就需要從日志中來還原問題出現(xiàn)的場景，這一步才是真正考驗(yàn)大家Android/Linux功底的地方。

繼續(xù)以上述問題為例，我們來進(jìn)一步還原問題出現(xiàn)的場景，從Java層的函數(shù)調(diào)用棧來看：

首先，跨進(jìn)程發(fā)起了Binder.dump()方法的調(diào)用：at android.os.Binder.dump(Binder.java:324)
然后，進(jìn)入了WMS的dump()：at com.android.server.wm.WindowManagerService.dump(WindowManagerService.java:12654)
接著，發(fā)生了寫文件操作：at java.io.FileOutputStream.write(FileOutputStream.java:186)
最后，調(diào)用了JNI方法：at libcore.io.Posix.writeBytes(Native method)

Binder_C線程要出現(xiàn)這種函數(shù)調(diào)用棧，我們可以初步確定是Android接受了如下命令 (dumpsys原理請查閱dumpsys介紹一文)：

$ adb shell dumpsys window

當(dāng)通過命令行運(yùn)行以上命令時，客戶端(PC)的adb server會向服務(wù)端(手機(jī))的adbd發(fā)送指令， adbd進(jìn)程會fork出一個叫做dumpsys的子進(jìn)程，dumpsys進(jìn)程再利用Binder機(jī)制和system_server通信 (adb的實(shí)現(xiàn)原理可以查閱adb介紹一文)。

僅憑這個還是分析不出問題所在，我們需要啟用內(nèi)核的日志了。當(dāng)調(diào)用JNI方法libcore.io.Posix.writeBytes()時，會觸發(fā)系統(tǒng)調(diào)用， Linux會從用戶態(tài)切換到內(nèi)核態(tài)，內(nèi)核的函數(shù)調(diào)用棧也可以從traces中找到：

kernel: __switch_to+0x74/0x8c
kernel: pipe_wait+0x60/0x9c
kernel: pipe_write+0x278/0x5cc
kernel: do_sync_write+0x90/0xcc
kernel: vfs_write+0xa4/0x194
kernel: SyS_write+0x40/0x8c
kernel: cpu_switch_to+0x48/0x4c

在Java層，明確指明要寫文件(FileOutputStream)，正常情況下，系統(tǒng)調(diào)用write()就完事了，但Kernel卻打開了一個管道，最終阻塞在了pipe_wait()方法。什么場景下會打開一個管道，而且管道會阻塞呢？一系列的猜想和驗(yàn)證過程接踵而至。

這里有必要先補(bǔ)充一些基礎(chǔ)知識了：

Linux進(jìn)程間通信之管道(pipe)

Linux的管道實(shí)現(xiàn)借助了文件系統(tǒng)的file結(jié)構(gòu)和VFS(Virtual File System)，通過將兩個file結(jié)構(gòu)指向同一個臨時的VFS索引節(jié)點(diǎn)，而這個VFS索引節(jié)點(diǎn)又指向一個物理頁面時，實(shí)際上就建立了一個管道。

這就解釋了為什么發(fā)起系統(tǒng)調(diào)用write的時候，打開了一個管道。因?yàn)閐umpsys和system_server進(jìn)程，將自己的file結(jié)構(gòu)指向了同一個VFS索引節(jié)點(diǎn)。
管道掛起的案例

管道是一個生產(chǎn)者-消費(fèi)者模型，當(dāng)緩沖區(qū)滿時，則生產(chǎn)者不能往管道中再寫數(shù)據(jù)了，需等到消費(fèi)者讀數(shù)據(jù)。如果消費(fèi)者來不及處理緩沖區(qū)的數(shù)據(jù)，或者鎖定緩沖區(qū)，則生產(chǎn)者就掛起了。

結(jié)合到例子中的場景，system_server進(jìn)程無法往管道中寫數(shù)據(jù)，很可能是dumpsys進(jìn)程一直忙碌來不及處理新的數(shù)據(jù)。

接下來，需要再從日志中尋找dumpsys進(jìn)程的運(yùn)行狀態(tài)了：

是不是dumpsys進(jìn)程的負(fù)載太高？
是不是dumpsys進(jìn)程死掉了，導(dǎo)致一直沒有處理緩沖區(qū)數(shù)據(jù)？
是不是dumpsys進(jìn)程有死鎖？

接下來的分析過程已經(jīng)偏離Watchdog機(jī)制越來越遠(yuǎn)了，我們點(diǎn)到為止。

小伙伴們可以看到，場景還原涉及到的知識點(diǎn)非常之寬泛，而且有一定的深度。在沒有現(xiàn)場的情況下，伴隨一系列的假設(shè)和驗(yàn)證過程，充滿了不確定性和發(fā)現(xiàn)問題的喜悅。正所謂，同問題做斗爭，其樂無窮！

至此，我們分析Watchdog問題的慣用方法，回答前面提出來的第二個問題：

通過event或system類型的logcat日志，檢索Watchdog出現(xiàn)的關(guān)鍵信息；通過traces，分析出導(dǎo)致Watchdog檢查超時的直接原因；通過其他日志，還原出問題出現(xiàn)的場景。

4. 實(shí)例分析

在上面介紹Watchdog問題分析方法的時候，我們其實(shí)已經(jīng)舉了一個例子。通常，比較容易定位導(dǎo)致Watchdog出現(xiàn)的直接原因(Direct Cause)，但很難找到更深層次的原因(Root Cause)。這個小節(jié)，我們再介紹一個實(shí)例，來分析Watchdog出現(xiàn)的另一種場景。誠然，僅憑幾個例子，遠(yuǎn)不夠涵蓋Watchdog的所有問題，我們的章法還是按照一定的方法論來深究問題。

回顧一下解決問題三部曲：

日志獲取。日志種類繁多，分析Watchdog問題，寧濫毋缺
問題定位。從logcat中鎖定watchdog的出現(xiàn)，從traces鎖定直接原因
場景還原。結(jié)合各類日志，不斷假設(shè)驗(yàn)證

以CPU占用過高的場景為例：下載該問題的全部日志

從sys_log中，檢索到了Watchdog的出現(xiàn)關(guān)鍵信息

TIPS: 在sys_log中搜索關(guān)鍵字”WATCHDOG KILLING SYSTEM PROCESS”

10-14 17:10:51.548   892  1403 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in handler on ActivityManager (ActivityManager)

這是一個Watchdog的Looper Checker超時，由于ActivityManager這個線程一直處于忙碌狀態(tài)，導(dǎo)致Watchdog檢查超時。 Watchdog出現(xiàn)的時間是10-14 17:10:51.548左右，需要從traces.txt中找到這個時間段的system_server進(jìn)程的函數(shù)調(diào)用棧信息， system_server的進(jìn)程號是892。

從traces.txt中找到對應(yīng)的函數(shù)調(diào)用棧

traces.txt包含很多進(jìn)程在不同時間段的函數(shù)調(diào)用棧信息，為了檢索的方便，首先可以將traces.txt分塊。筆者寫了一個工具，可以從traces.txt文件中分割出指定進(jìn)程號的函數(shù)調(diào)用棧信息。

TIPS: 在system_server的traces中(通過工具分割出的system_server_892_2015-10-14-17:09:06文件)搜索關(guān)鍵字”ActivityManager”

"ActivityManager" prio=5 tid=17 TimedWaiting
  | group="main" sCount=1 dsCount=0 obj=0x12c0e6d0 self=0x7f84caf000
  | sysTid=938 nice=-2 cgrp=default sched=0/0 handle=0x7f7d887000
  | state=S schedstat=( 107864628645 628257779012 60356 ) utm=7799 stm=2987 core=2 HZ=100
  | stack=0x7f6e68f000-0x7f6e691000 stackSize=1036KB
  | held mutexes=
  at java.lang.Object.wait!(Native method)
  - waiting on <0x264ff09d> (a com.android.server.am.ActivityManagerService$5)
  at java.lang.Object.wait(Object.java:422)
  at com.android.server.am.ActivityManagerService.dumpStackTraces(ActivityManagerService.java:5395)
  at com.android.server.am.ActivityManagerService.dumpStackTraces(ActivityManagerService.java:5282)
  at com.android.server.am.ActivityManagerService$AnrActivityManagerService.dumpStackTraces(ActivityManagerService.java:22676)
  at com.mediatek.anrmanager.ANRManager$AnrDumpMgr.dumpAnrDebugInfoLocked(SourceFile:1023)
  at com.mediatek.anrmanager.ANRManager$AnrDumpMgr.dumpAnrDebugInfo(SourceFile:881)
  at com.android.server.am.ActivityManagerService.appNotResponding(ActivityManagerService.java:6122)
  - locked <0x21c77912> (a com.mediatek.anrmanager.ANRManager$AnrDumpRecord)
  at com.android.server.am.BroadcastQueue$AppNotResponding.run(BroadcastQueue.java:228)
  at android.os.Handler.handleCallback(Handler.java:815)
  at android.os.Handler.dispatchMessage(Handler.java:104)
  at android.os.Looper.loop(Looper.java:192)
  at android.os.HandlerThread.run(HandlerThread.java:61)
  at com.android.server.ServiceThread.run(ServiceThread.java:46)

ActivityManager線程實(shí)際上運(yùn)行著AMS的消息隊列，這個函數(shù)調(diào)用棧的關(guān)鍵信息：

線程狀態(tài)為TimedWaiting, 這表示當(dāng)前線程阻塞在一個超時的wait()方法
正在處理廣播消息超時發(fā)生的ANR(Application Not Responding)，需要將當(dāng)前的函數(shù)調(diào)用棧打印出來
最終在<0x264ff09d>等待，可以從AMS的源碼中找到這一處鎖的源碼，因?yàn)閐umpStackTraces()會寫文件，所以AMS設(shè)計了一個200毫秒的超時鎖。

observer.wait(200);  // Wait for write-close, give up after 200msec

還原問題的場景

從ActivityManager這個線程的調(diào)用棧，我們就會有一些疑惑：

是哪個應(yīng)用發(fā)生了ANR？為什么會發(fā)生ANR？
超時鎖只用200毫秒就釋放了，為什么會導(dǎo)致Watchdog檢查超時？(AMS的Looper默認(rèn)超時是1分鐘)

帶著這些疑惑，我們再回到日志中：

從sys_log中，可以檢索到Watchdog出現(xiàn)的時間點(diǎn)(17:10:51.548)之前，com.android.systemui發(fā)生了ANR，從而引發(fā)AMS打印函數(shù)調(diào)用棧:

TIPS: 在sys_log中檢索”ANR in”關(guān)鍵字或在event_log中檢索”anr”關(guān)鍵字

10-14 17:10:04.215   892   938 E ANRManager: ANR in com.android.systemui, time=27097912
10-14 17:10:04.215   892   938 E ANRManager: Reason: Broadcast of Intent { act=android.intent.action.TIME_TICK flg=0x50000114 (has extras) }
10-14 17:10:04.215   892   938 E ANRManager: Load: 89.22 / 288.15 / 201.91
10-14 17:10:04.215   892   938 E ANRManager: Android time :[2015-10-14 17:10:04.14] [27280.396]
10-14 17:10:04.215   892   938 E ANRManager: CPU usage from 17016ms to 0ms ago:
10-14 17:10:04.215   892   938 E ANRManager:   358% 23682/float_bessel: 358% user + 0% kernel
10-14 17:10:04.215   892   938 E ANRManager:   57% 23604/debuggerd64: 3.8% user + 53% kernel / faults: 11369 minor
10-14 17:10:04.215   892   938 E ANRManager:   2% 892/system_server: 0.9% user + 1% kernel / faults: 136 minor

從這個日志信息中，我們兩個疑惑就釋然了：

發(fā)生ANR之前的CPU負(fù)載遠(yuǎn)高于正常情況好幾倍(Load： 89.22 / 288.15 / 201.91)，在這種CPU負(fù)載下，com.android.systemui進(jìn)程發(fā)生處理廣播消息超時(Reason: Broadcast of Intent)再正常不過了。在這之前CPU都被float_bessel這個進(jìn)程給占了，這貨僅憑一己之力就耗了358%的CPU資源。

observer.wait(200)在調(diào)用后，便進(jìn)入排隊等待喚醒狀態(tài)(Waiting)，在等待200毫秒后，便重新開始申請CPU資源，而此時，CPU資源一直被float_bessel占著沒有釋放，所以該線程一直在等CPU資源。等了1分鐘后，Watchdog跳出來說“不行，你已經(jīng)等了1分鐘了，handler處理其他消息了”。

在多核情況下，CPU的使用率統(tǒng)計會累加多個核的使用率，所以會出現(xiàn)超過100%的情況。那么float_bessel究竟是什么呢？它是一個Linux的測試樣本，貝塞爾函數(shù)的計算，耗的就是CPU。

這樣，該問題的場景我們就還原出來了：在壓力測試的環(huán)境下，CPU被float_bessel運(yùn)算占用，導(dǎo)致com.android.systemui進(jìn)程發(fā)生ANR，從而引發(fā)AMS打印trace; 但由于AMS一直等不到CPU資源，Watchdog檢測超時，殺掉system_server進(jìn)程，系統(tǒng)重啟。

對于壓力測試而言，我們一般會設(shè)定一個通過標(biāo)準(zhǔn)，在某些壓力情況下，出現(xiàn)一些錯誤是允許的。對于Android實(shí)際用戶的使用場景而言，本例中的壓力通常是不存在的，所以在實(shí)際項目中，這種類型的Watchdog問題，我們一般不解決。

5. 總結(jié)

Android中Watchdog用來看護(hù)system_server進(jìn)程，system_server進(jìn)程運(yùn)行著系統(tǒng)最終要的服務(wù)，譬如AMS、PKMS、WMS等，當(dāng)這些服務(wù)不能正常運(yùn)轉(zhuǎn)時，Watchdog可能會殺掉system_server，讓系統(tǒng)重啟。

Watchdog的實(shí)現(xiàn)利用了鎖和消息隊列機(jī)制。當(dāng)system_server發(fā)生死鎖或消息隊列一直處于忙碌狀態(tài)時，則認(rèn)為系統(tǒng)已經(jīng)沒有響應(yīng)了(System Not Responding)。

在分析Watchdog問題的時候，首先要有詳盡的日志，其次要能定位出導(dǎo)致Watchdog超時的直接原因，最重要的是能還原出問題發(fā)生的場景。

</article>

色偷偷精品伊人,欧洲久久精品,欧美综合婷婷骚逼,国产AV主播,国产最新探花在线,九色在线视频一区,伊人大交九欧美,1769亚洲,黄色成人av

Watchdog機(jī)制以及問題分析

Watchdog機(jī)制以及問題分析

1. 概覽

2. Watchdog機(jī)制

2.1 Watchdog的初始化

2.2 添加Watchdog監(jiān)測對象

2.3 Watchdog的監(jiān)測機(jī)制

3. 問題分析方法

3.1 日志獲取

3.2 問題定位

3.3 場景還原

4. 實(shí)例分析

5. 總結(jié)

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容

色偷偷精品伊人,欧洲久久精品,欧美综合婷婷骚逼,国产AV主播,国产最新探花在线,九色在线视频一区,伊人大交九 欧美,1769亚洲,黄色成人av

Watchdog機(jī)制以及問題分析

1. 概覽

2. Watchdog機(jī)制

2.1 Watchdog的初始化

2.2 添加Watchdog監(jiān)測對象

2.3 Watchdog的監(jiān)測機(jī)制

3. 問題分析方法

3.1 日志獲取

3.2 問題定位

3.3 場景還原

4. 實(shí)例分析

5. 總結(jié)

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容

色偷偷精品伊人,欧洲久久精品,欧美综合婷婷骚逼,国产AV主播,国产最新探花在线,九色在线视频一区,伊人大交九欧美,1769亚洲,黄色成人av