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

目錄

• 1. 概覽
• 2. Watchdog機(jī)制
  • 2.1 Watchdog的初始化
  • 2.2 添加Watchdog監(jiān)測(cè)對(duì)象
  • 2.3 Watchdog的監(jiān)測(cè)機(jī)制
• 3. 問(wèn)題分析方法
  • 3.1 日志獲取
  • 3.2 問(wèn)題定位
  • 3.3 場(chǎng)景還原
• 4. 實(shí)例分析
• 5. 總結(jié)

請(qǐng)尊重原創(chuàng)版權(quán)挪哄，轉(zhuǎn)載注明出處虑鼎。

<article style="box-sizing: border-box; display: block; color: rgb(51, 51, 51); font-family: Menlo, Monaco, Consolas, "Courier New", monospace, Helvetica, Tahoma, Arial, "WenQuanYi Micro Hei", 文泉驛微米黑, STXihei, 華文細(xì)黑, "Microsoft YaHei", 微軟雅黑, SimSun, 宋體, Heiti, 黑體, sans-serif; font-size: 17px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: 400; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial;">

1. 概覽

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

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

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

本文期望回答以下問(wèn)題：

1. Watchdog是怎么工作的纱扭？這涉及到Watchdog的工作機(jī)制牍帚。

2. 遇到Watchdog的問(wèn)題該怎么辦？這涉及到分析Watchdog問(wèn)題的慣用方法乳蛾。

2. Watchdog機(jī)制

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

2.1 Watchdog的初始化

Android的Watchdog是一個(gè)單例線程，在System Server時(shí)就會(huì)初始化Watchdog详幽。Watchdog在初始化時(shí)筛欢，會(huì)構(gòu)建很多HandlerChecker浸锨，大致可以分為兩類：

• Monitor Checker，用于檢查是Monitor對(duì)象可能發(fā)生的死鎖, AMS, PKMS, WMS等核心的系統(tǒng)服務(wù)都是Monitor對(duì)象版姑。

• Looper Checker柱搜，用于檢查線程的消息隊(duì)列是否長(zhǎng)時(shí)間處于工作狀態(tài)。Watchdog自身的消息隊(duì)列剥险，Ui, Io, Display這些全局的消息隊(duì)列都是被檢查的對(duì)象聪蘸。此外，一些重要的線程的消息隊(duì)列表制，也會(huì)加入到Looper Checker中健爬，譬如AMS, PKMS，這些是在對(duì)應(yīng)的對(duì)象初始化時(shí)加入的么介。

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ù)警我們不能長(zhǎng)時(shí)間持有核心系統(tǒng)服務(wù)的對(duì)象鎖，否則會(huì)阻塞很多函數(shù)的運(yùn)行; Looper Checker預(yù)警我們不能長(zhǎng)時(shí)間的霸占消息隊(duì)列壤短，否則其他消息將得不到處理设拟。這兩類都會(huì)導(dǎo)致系統(tǒng)卡住(System Not Responding)。

2.2 添加Watchdog監(jiān)測(cè)對(duì)象

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

Watchdog提供兩個(gè)方法，分別用于添加Monitor Checker對(duì)象和Looper Checker對(duì)象:

public void addMonitor(Monitor monitor) {
    // 將monitor對(duì)象添加到Monitor Checker中婆赠，
    // 在Watchdog初始化時(shí)绵脯，可以看到Monitor Checker本身也是一個(gè)HandlerChecker對(duì)象
    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)建一個(gè)HandlerChecker對(duì)象，其實(shí)就是**Looper Checker**
        mHandlerCheckers.add(new HandlerChecker(thread, name, timeoutMillis));
    }
}

被Watchdog監(jiān)測(cè)的對(duì)象休里，都需要將自己添加到Watchdog的監(jiān)測(cè)集中蛆挫。以下是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接口，這個(gè)接口只有一個(gè)方法妙黍，就是monitor()悴侵，它的作用后文會(huì)再解釋。這里可以看到在AMS的構(gòu)造器中拭嫁，將自己添加到Monitor Checker對(duì)象中可免，然后將自己的handler添加到Looper Checker對(duì)象中抓于。 其他重要的系統(tǒng)服務(wù)添加到Watchdog的代碼邏輯都與AMS差不多。

整個(gè)Android系統(tǒng)中浇借，被monitor的對(duì)象并不多捉撮，十個(gè)手指頭就能數(shù)出來(lái)Watchdog.Monitor的實(shí)現(xiàn)類的個(gè)數(shù)。

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

Watchdog本身是一個(gè)線程妇垢，它的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\. 存在超時(shí)的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)行邏輯如下：

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

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

public final class HandlerChecker implements Runnable {

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

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

• 對(duì)于Looper Checker而言确沸，會(huì)判斷線程的消息隊(duì)列是否處于空閑狀態(tài)。 如果被監(jiān)測(cè)的消息隊(duì)列一直閑不下來(lái)俘陷，則說(shuō)明可能已經(jīng)阻塞等待了很長(zhǎng)時(shí)間

• 對(duì)于Monitor Checker而言罗捎，會(huì)調(diào)用實(shí)現(xiàn)類的monitor方法，譬如上文中提到的AMS.monitor()方法拉盾， 方法實(shí)現(xiàn)一般很簡(jiǎn)單桨菜，就是獲取當(dāng)前類的對(duì)象鎖，如果當(dāng)前對(duì)象鎖已經(jīng)被持有捉偏，則monitor()會(huì)一直處于wait狀態(tài)雷激，直到超時(shí)替蔬，這種情況下告私，很可能是線程發(fā)生了死鎖

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

Watchdog定時(shí)檢查一些重要的系統(tǒng)服務(wù)驻粟，舉報(bào)長(zhǎng)時(shí)間阻塞的事件根悼，甚至殺掉system_server進(jìn)程，讓Android系統(tǒng)重啟蜀撑。

3. 問(wèn)題分析方法

3.1 日志獲取

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

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

• logcat 通過(guò)adb logcat命令輸出Android的一些當(dāng)前運(yùn)行日志舷暮，可以通過(guò)logcat的 -b 參數(shù)指定要輸出的日志緩沖區(qū)，緩沖區(qū)對(duì)應(yīng)著logcat的一種日志類型噩茄。 高版本的logcat可以使用 -b all 獲取到所有緩沖區(qū)的日志

  • event 通過(guò)android.util.EventLog工具類打印的日志下面，一些重要的系統(tǒng)事件會(huì)使用此類日志
  • main 通過(guò)android.util.Log工具類打印的日志，應(yīng)用程序巢墅，尤其是基于SDK的應(yīng)用程序诸狭，會(huì)使用此類日志
  • system 通過(guò)android.util.Slog工具類打印的日志，系統(tǒng)相關(guān)的日志一般都是使用此類日志君纫，譬如SystemServer
  • radio 通過(guò)android.util.Rlog工具類打印的日志驯遇，通信模塊相關(guān)的日志一般都是使用此類日志，譬如RIL

• dumpsys 通過(guò)adb dumpsys命令輸出一些重要的系統(tǒng)服務(wù)信息蓄髓，譬如內(nèi)存叉庐、電源、磁盤等会喝， 工作原理可以查閱dumpsys介紹一文

• traces 該文件記錄了一個(gè)時(shí)間段的函數(shù)調(diào)用棧信息陡叠，通常在應(yīng)用發(fā)生ANR(Application Not Responding)時(shí)玩郊，會(huì)觸發(fā)打印各進(jìn)程的函數(shù)調(diào)用棧。 站在Linux的角度枉阵，其實(shí)就是向進(jìn)程發(fā)送SIGNAL_QUIT(3)請(qǐng)求译红，譬如，我們可以通過(guò)adb shell kill -3 <pid>命令兴溜，打印指定進(jìn)程<pid style="box-sizing: border-box;">的的trace侦厚。 SIGNAL_QUIT(3)表面意思有一點(diǎn)誤導(dǎo)，它其實(shí)并不會(huì)導(dǎo)致進(jìn)程退出拙徽。輸出一般在 /data/anr/traces.txt 文件中刨沦，當(dāng)然，這是可以靈活配置的膘怕， Android提供的系統(tǒng)屬性dalvik.vm.stack-trace-file可以用來(lái)配置生成traces文件的位置想诅。</pid>

• binder 通過(guò)Binder跨進(jìn)程調(diào)用的日志，可以通過(guò)adb shell cat命令從 /proc/binder 下取出對(duì)應(yīng)的日志

  • failed_transaction_log
  • transaction_log
  • transactions
  • stats

• dropbox 為了記錄歷史的logcat日志岛心，Android引入了Dropbox来破，將歷史日志持久化到磁盤中(/data/system/dropbox)。 logcat的緩沖區(qū)大小畢竟是有限的鹉梨，所以需要循環(huán)利用讳癌，這樣歷史的日志信息就會(huì)被沖掉。在一些自動(dòng)化測(cè)試的場(chǎng)景下存皂，譬如Monkey需要長(zhǎng)時(shí)間的運(yùn)行晌坤， 就需要把歷史的日志全都保存下來(lái)。

• tombstone tombstone錯(cuò)誤一般由Dalvik錯(cuò)誤旦袋、native層的代碼問(wèn)題導(dǎo)致的骤菠。當(dāng)系統(tǒng)發(fā)生tombstone時(shí)，內(nèi)核會(huì)上報(bào)一個(gè)嚴(yán)重的警告信號(hào)疤孕， 上層收到后商乎，把當(dāng)前的調(diào)用棧信息持久化到磁盤中(/data/tombstone)

• bugreport 通過(guò)adb bugreport命令輸出矢腻，日志內(nèi)容多到爆寂曹，logcat, traces, dmesg, dumpsys, binder的日志都包含在其中。 由于輸出bugreport的時(shí)間很長(zhǎng)师幕，當(dāng)系統(tǒng)發(fā)生錯(cuò)誤時(shí)专控，我們?cè)賵?zhí)行bugreport往往就來(lái)不及了(此時(shí)抹凳，系統(tǒng)可能都已經(jīng)重啟了)，所以伦腐，要?jiǎng)佑胋ugreport就需要結(jié)合一些其他機(jī)制赢底， 譬如在殺掉system_server進(jìn)程之前，先讓bugreport運(yùn)行完。

3.2 問(wèn)題定位

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

發(fā)生Watchdog檢測(cè)超時(shí)這么重要的系統(tǒng)事件庞溜，Android會(huì)打印一個(gè)EventLog：

watchdog: Blocked in handler XXX    # 表示HandlerChecker超時(shí)了
watchdog: Blocked in monitor XXX    # 表示MonitorChecker超時(shí)了

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

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

當(dāng)我們?cè)谌罩局袡z索到上述兩類關(guān)鍵信息時(shí)赏胚，說(shuō)明“Watchdog顯靈”了访娶，從另一個(gè)角度來(lái)理解，就是“System Not Responding”了觉阅。 接下來(lái)崖疤，我們需要進(jìn)一步定位在watchdog出現(xiàn)之前，system_server進(jìn)程在干什么典勇，處于一個(gè)什么狀態(tài)劫哼。 這與排除”Application Not Responding“問(wèn)題差不多，我們需要進(jìn)程的traces信息割笙、當(dāng)前系統(tǒng)的CPU運(yùn)行信息权烧、IO信息。

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

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

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

1. WindowManagerService實(shí)現(xiàn)了Watchdog.Monitor這個(gè)接口伏伯，并將自己作為Monitor Checker的對(duì)象加入到了Watchdog的監(jiān)測(cè)集中

2. monitor()方法是運(yùn)行在android.fg線程中的橘洞。Android將android.fg設(shè)計(jì)為一個(gè)全局共享的線程，意味著它的消息隊(duì)列可以被其他線程共享舵鳞， Watchdog的Monitor Checker就是使用的android.fg線程的消息隊(duì)列震檩。因此，出現(xiàn)Monitor Checker的超時(shí)，肯定是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)用棧告訴我們幾個(gè)關(guān)鍵的信息：

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

題外話：每一個(gè)進(jìn)程都會(huì)對(duì)自己所轄的線程編號(hào)峰髓，從1開始。1號(hào)線程通常就是我們所說(shuō)的主線程息尺。 線程在Linux系統(tǒng)中還有一個(gè)全局的編號(hào)携兵，由sysTid表示。我們?cè)趌ogcat等日志中看到的一般是線程的全局編號(hào)搂誉。 譬如徐紧，本例中android.fg線程在system_server進(jìn)程中的編號(hào)是25，系統(tǒng)全局編號(hào)是973炭懊。

可以在traces.txt文件中檢索 tid=91 來(lái)快速找到91號(hào)線程的函數(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號(hào)線程的名字是Binder_C并级，它的函數(shù)調(diào)用棧告訴我們幾個(gè)關(guān)鍵信息：

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

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

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

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

這都需要我們?cè)龠M(jìn)一步從日志中去找原因揪垄。如果已有的日志不全，找不到論據(jù)逻翁，我們還需要設(shè)計(jì)場(chǎng)景來(lái)驗(yàn)證假設(shè)饥努，解決問(wèn)題的難度陡然上升。

3.3 場(chǎng)景還原

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

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

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

繼續(xù)以上述問(wèn)題為例邦投，我們來(lái)進(jìn)一步還原問(wèn)題出現(xiàn)的場(chǎng)景伤锚，從Java層的函數(shù)調(diào)用棧來(lái)看：

• 首先，跨進(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原理請(qǐng)查閱dumpsys介紹一文)：

$ adb shell dumpsys window

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

僅憑這個(gè)還是分析不出問(wèn)題所在庐橙，我們需要啟用內(nèi)核的日志了。當(dāng)調(diào)用JNI方法libcore.io.Posix.writeBytes()時(shí)借嗽，會(huì)觸發(fā)系統(tǒng)調(diào)用态鳖， Linux會(huì)從用戶態(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卻打開了一個(gè)管道兆蕉，最終阻塞在了pipe_wait()方法。 什么場(chǎng)景下會(huì)打開一個(gè)管道缤沦，而且管道會(huì)阻塞呢虎韵？一系列的猜想和驗(yàn)證過(guò)程接踵而至。

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

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

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

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

• 管道掛起的案例

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

  結(jié)合到例子中的場(chǎng)景缺谴，system_server進(jìn)程無(wú)法往管道中寫數(shù)據(jù)但惶，很可能是dumpsys進(jìn)程一直忙碌來(lái)不及處理新的數(shù)據(jù)。

接下來(lái)瓣赂，需要再?gòu)娜罩局袑ふ襠umpsys進(jìn)程的運(yùn)行狀態(tài)了：

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

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

小伙伴們可以看到碉钠，場(chǎng)景還原涉及到的知識(shí)點(diǎn)非常之寬泛纲缓，而且有一定的深度。在沒有現(xiàn)場(chǎng)的情況下喊废，伴隨一系列的假設(shè)和驗(yàn)證過(guò)程祝高，充滿了不確定性和發(fā)現(xiàn)問(wèn)題的喜悅。 正所謂污筷，同問(wèn)題做斗爭(zhēng)工闺，其樂無(wú)窮！

至此瓣蛀，我們分析Watchdog問(wèn)題的慣用方法陆蟆，回答前面提出來(lái)的第二個(gè)問(wèn)題：

通過(guò)event或system類型的logcat日志，檢索Watchdog出現(xiàn)的關(guān)鍵信息惋增；通過(guò)traces叠殷，分析出導(dǎo)致Watchdog檢查超時(shí)的直接原因；通過(guò)其他日志诈皿，還原出問(wèn)題出現(xiàn)的場(chǎng)景林束。

4. 實(shí)例分析

在上面介紹Watchdog問(wèn)題分析方法的時(shí)候，我們其實(shí)已經(jīng)舉了一個(gè)例子稽亏。通常壶冒，比較容易定位導(dǎo)致Watchdog出現(xiàn)的直接原因(Direct Cause)，但很難找到更深層次的原因(Root Cause)截歉。 這個(gè)小節(jié)依痊，我們?cè)俳榻B一個(gè)實(shí)例，來(lái)分析Watchdog出現(xiàn)的另一種場(chǎng)景怎披。誠(chéng)然，僅憑幾個(gè)例子瓶摆，遠(yuǎn)不夠涵蓋Watchdog的所有問(wèn)題凉逛，我們的章法還是按照一定的方法論來(lái)深究問(wèn)題。

回顧一下解決問(wèn)題三部曲：

1. 日志獲取群井。日志種類繁多状飞，分析Watchdog問(wèn)題，寧濫毋缺

2. 問(wèn)題定位书斜。從logcat中鎖定watchdog的出現(xiàn)诬辈，從traces鎖定直接原因

3. 場(chǎng)景還原。結(jié)合各類日志荐吉，不斷假設(shè)驗(yàn)證

以CPU占用過(guò)高的場(chǎng)景為例：下載該問(wèn)題的全部日志

從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)

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

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

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

TIPS: 在system_server的traces中(通過(guò)工具分割出的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的消息隊(duì)列瞬沦，這個(gè)函數(shù)調(diào)用棧的關(guān)鍵信息：

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

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

還原問(wèn)題的場(chǎng)景

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

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

帶著這些疑惑，我們?cè)倩氐饺罩局校?/p>

從sys_log中惩嘉，可以檢索到Watchdog出現(xiàn)的時(shí)間點(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

從這個(gè)日志信息中文黎，我們兩個(gè)疑惑就釋然了：

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

observer.wait(200)在調(diào)用后劳闹，便進(jìn)入排隊(duì)等待喚醒狀態(tài)(Waiting)院究，在等待200毫秒后，便重新開始申請(qǐng)CPU資源本涕，而此時(shí)业汰，CPU資源一直被float_bessel占著沒有釋放，所以該線程一直在等CPU資源菩颖。 等了1分鐘后样漆，Watchdog跳出來(lái)說(shuō)“不行，你已經(jīng)等了1分鐘了位他，handler處理其他消息了”氛濒。

在多核情況下产场，CPU的使用率統(tǒng)計(jì)會(huì)累加多個(gè)核的使用率，所以會(huì)出現(xiàn)超過(guò)100%的情況舞竿。那么float_bessel究竟是什么呢京景？它是一個(gè)Linux的測(cè)試樣本，貝塞爾函數(shù)的計(jì)算骗奖，耗的就是CPU确徙。

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

對(duì)于壓力測(cè)試而言错蝴，我們一般會(huì)設(shè)定一個(gè)通過(guò)標(biāo)準(zhǔn)，在某些壓力情況下颓芭，出現(xiàn)一些錯(cuò)誤是允許的顷锰。對(duì)于Android實(shí)際用戶的使用場(chǎng)景而言，本例中的壓力通常是不存在的亡问，所以在實(shí)際項(xiàng)目中官紫，這種類型的Watchdog問(wèn)題，我們一般不解決州藕。

5. 總結(jié)

Android中Watchdog用來(lái)看護(hù)system_server進(jìn)程束世，system_server進(jìn)程運(yùn)行著系統(tǒng)最終要的服務(wù)，譬如AMS床玻、PKMS良狈、WMS等， 當(dāng)這些服務(wù)不能正常運(yùn)轉(zhuǎn)時(shí)笨枯，Watchdog可能會(huì)殺掉system_server，讓系統(tǒng)重啟遇西。

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

在分析Watchdog問(wèn)題的時(shí)候洲敢，首先要有詳盡的日志，其次要能定位出導(dǎo)致Watchdog超時(shí)的直接原因茄蚯，最重要的是能還原出問(wèn)題發(fā)生的場(chǎng)景压彭。

</article>