1. 程式人生 > >Watchdog機制以及問題分析

Watchdog機制以及問題分析

轉載連結:http://duanqz.github.io/2015-10-12-Watchdog-Analysis#section-1

1. 概覽

Watchdog的中文的“看門狗”,有保護的意思。最早引入Watchdog是在微控制器系統中,由於微控制器的工作環境容易受到外界磁場的干擾,導致程式“跑飛”,造成整個系統無法正常工作,因此,引入了一個“看門狗”,對微控制器的執行狀態進行實時監測,針對執行故障做一些保護處理,譬如讓系統重啟。這種Watchdog屬於硬體層面,必須有硬體電路的支援。

Linux也引入了Watchdog,在Linux核心下,當Watchdog啟動後,便設定了一個定時器,如果在超時時間內沒有對/dev/Watchdog進行寫操作,則會導致系統重啟。通過定時器實現的Watchdog屬於軟體層面。

Android設計了一個軟體層面Watchdog,用於保護一些重要的系統服務,當出現故障時,通常會讓Android系統重啟。由於這種機制的存在,就經常會出現一些system_server程序被Watchdog殺掉而發生手機重啟的問題。

本文期望回答以下問題:

  1. Watchdog是怎麼工作的?這涉及到Watchdog的工作機制。
  2. 遇到Watchdog的問題該怎麼辦?這涉及到分析Watchdog問題的慣用方法。

2. Watchdog機制

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

2.1 Watchdog的初始化

Android的Watchdog是一個單例執行緒,在System Server時就會初始化Watchdog。Watchdog在初始化時,會構建很多HandlerChecker,大致可以分為兩類:

  • Monitor Checker,用於檢查是Monitor物件可能發生的死鎖, AMS, PKMS, WMS等核心的系統服務都是Monitor物件。

  • Looper Checker,用於檢查執行緒的訊息佇列是否長時間處於工作狀態。Watchdog自身的訊息佇列,Ui, Io, Display這些全域性的訊息佇列都是被檢查的物件。此外,一些重要的執行緒的訊息佇列,也會加入到Looper Checker

    中,譬如AMS, PKMS,這些是在對應的物件初始化時加入的。

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的側重點不同,Monitor Checker預警我們不能長時間持有核心繫統服務的物件鎖,否則會阻塞很多函式的執行; Looper Checker預警我們不能長時間的霸佔訊息佇列,否則其他訊息將得不到處理。這兩類都會導致系統卡住(System Not Responding)。

2.2 新增Watchdog監測物件

Watchdog初始化以後,就可以作為system_server程序中的一個單獨的執行緒運行了。但這個時候,還不能觸發Watchdog的執行,因為AMS, PKMS等系統服務還沒有加入到Watchdog的監測集。 所謂監測集,就是需要Watchdog關注的物件,Android中有成千上萬的訊息佇列在同時執行,然而,Watchdog畢竟是系統層面的東西,它只會關注一些核心的系統服務。

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構建一個HandlerChecker物件,其實就是**Looper Checker**
        mHandlerCheckers.add(new HandlerChecker(thread, name, timeoutMillis));
    }
}

被Watchdog監測的物件,都需要將自己新增到Watchdog的監測集中。以下是AMS的類定義和構造器的程式碼片段:

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實現了Watchdog.Monitor介面,這個介面只有一個方法,就是monitor(),它的作用後文會再解釋。這裡可以看到在AMS的構造器中,將自己新增到Monitor Checker物件中,然後將自己的handler新增到Looper Checker物件中。 其他重要的系統服務新增到Watchdog的程式碼邏輯都與AMS差不多。

整個Android系統中,被monitor的物件並不多,十個手指頭就能數出來Watchdog.Monitor的實現類的個數。

2.3 Watchdog的監測機制

Watchdog本身是一個執行緒,它的run()方法實現如下:

@Override
public void run() {
    boolean waitedHalf = false;
    while (true) {
        ...
        synchronized (this) {
            ...
            // 1. 排程所有的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的完成狀態
            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. 儲存日誌,判斷是否需要殺掉系統程序
        Slog.w(TAG, "*** GOODBYE!");
        Process.killProcess(Process.myPid());
        System.exit(10);
    } // end of while (true)

}

以上程式碼片段主要的執行邏輯如下:

  1. Watchdog執行後,便開始無限迴圈,依次呼叫每一個HandlerChecker的scheduleCheckLocked()方法
  2. 排程完HandlerChecker之後,便開始定期檢查是否超時,每一次檢查的間隔時間由CHECK_INTERVAL常量設定,為30秒
  3. 每一次檢查都會呼叫evaluateCheckerCompletionLocked()方法來評估一下HandlerChecker的完成狀態:
    • COMPLETED表示已經完成
    • WAITING和WAITED_HALF表示還在等待,但未超時
    • OVERDUE表示已經超時。預設情況下,timeout是1分鐘,但監測物件可以通過傳參自行設定,譬如PKMS的Handler Checker的超時是10分鐘
  4. 如果超時時間到了,還有HandlerChecker處於未完成的狀態(OVERDUE),則通過getBlockedCheckersLocked()方法,獲取阻塞的HandlerChecker,生成一些描述資訊
  5. 儲存日誌,包括一些執行時的堆疊資訊,這些日誌是我們解決Watchdog問題的重要依據。如果判斷需要殺掉system_server程序,則給當前程序(system_server)傳送signal 9

只要Watchdog沒有發現超時的任務,HandlerChecker就會被不停的排程,那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的物件置於訊息佇列之前,優先執行
        mHandler.postAtFrontOfQueue(this);
    }

    @Override
    public void run() {
        // 依次呼叫Monitor物件的monitor()方法
        for (int i = 0 ; i < size ; i++) {
            synchronized (Watchdog.this) {
                mCurrentMonitor = mMonitors.get(i);
            }
            mCurrentMonitor.monitor();
        }
        ...
    }
}
  • 對於Looper Checker而言,會判斷執行緒的訊息佇列是否處於空閒狀態。 如果被監測的訊息佇列一直閒不下來,則說明可能已經阻塞等待了很長時間

  • 對於Monitor Checker而言,會呼叫實現類的monitor方法,譬如上文中提到的AMS.monitor()方法, 方法實現一般很簡單,就是獲取當前類的物件鎖,如果當前物件鎖已經被持有,則monitor()會一直處於wait狀態,直到超時,這種情況下,很可能是執行緒發生了死鎖

至此,我們已經分析了Watchdog的工作機制,回答了我們提出的第一個問題:

Watchdog定時檢查一些重要的系統服務,舉報長時間阻塞的事件,甚至殺掉system_server程序,讓Android系統重啟。

3. 問題分析方法

3.1 日誌獲取

Andriod的日誌門類繁多,而且,為了除錯的需要,裝置廠商和應用開發者都會在AOSP的基礎上增加很多日誌。 面對如此龐大複雜的日誌系統,通常只有對應領域的專家才能看懂其透露的細節資訊,就像去醫院就診,醫生一看檢查報告就知道患者身體出了什麼問題,而外行對這些診斷資訊往往是束手無策的。

解決Watchdog相關的問題,對日誌的要求比較高,有些問題與當時的系統環境相關,僅僅憑藉單一的日誌並不能定位問題。 以下羅列出獲取Android日誌的一些重要手段,部分場景下,Watchdog相關的問題甚至需要以下所有的日誌:

  • logcat 通過adb logcat命令輸出Android的一些當前執行日誌,可以通過logcat的 -b 引數指定要輸出的日誌緩衝區,緩衝區對應著logcat的一種日誌型別。 高版本的logcat可以使用 -b all 獲取到所有緩衝區的日誌

    • event 通過android.util.EventLog工具類列印的日誌,一些重要的系統事件會使用此類日誌
    • main 通過android.util.Log工具類列印的日誌,應用程式,尤其是基於SDK的應用程式,會使用此類日誌
    • system 通過android.util.Slog工具類列印的日誌,系統相關的日誌一般都是使用此類日誌,譬如SystemServer
    • radio 通過android.util.Rlog工具類列印的日誌,通訊模組相關的日誌一般都是使用此類日誌,譬如RIL
  • dumpsys 通過adb dumpsys命令輸出一些重要的系統服務資訊,譬如記憶體、電源、磁碟等, 工作原理可以查閱dumpsys介紹一文

  • traces 該檔案記錄了一個時間段的函式呼叫棧資訊,通常在應用發生ANR(Application Not Responding)時,會觸發列印各程序的函式呼叫棧。 站在Linux的角度,其實就是向程序傳送SIGNAL_QUIT(3)請求,譬如,我們可以通過adb shell kill -3 <pid>命令,列印指定程序的的trace。 SIGNAL_QUIT(3)表面意思有一點誤導,它其實並不會導致程序退出。輸出一般在 */data/anr/traces.txt* 檔案中,當然,這是可以靈活配置的, Android提供的系統屬性dalvik.vm.stack-trace-file可以用來配置生成traces檔案的位置。

  • binder 通過Binder跨程序呼叫的日誌,可以通過adb shell cat命令從 /proc/binder 下取出對應的日誌

    • failed_transaction_log
    • transaction_log
    • transactions
    • stats
  • dropbox 為了記錄歷史的logcat日誌,Android引入了Dropbox,將歷史日誌持久化到磁碟中(/data/system/dropbox)。 logcat的緩衝區大小畢竟是有限的,所以需要迴圈利用,這樣歷史的日誌資訊就會被沖掉。在一些自動化測試的場景下,譬如Monkey需要長時間的執行, 就需要把歷史的日誌全都儲存下來。

  • tombstone tombstone錯誤一般由Dalvik錯誤、native層的程式碼問題導致的。當系統發生tombstone時,核心會上報一個嚴重的警告訊號, 上層收到後,把當前的呼叫棧資訊持久化到磁碟中(/data/tombstone)

  • bugreport 通過adb bugreport命令輸出,日誌內容多到爆,logcat, traces, dmesg, dumpsys, binder的日誌都包含在其中。 由於輸出bugreport的時間很長,當系統發生錯誤時,我們再執行bugreport往往就來不及了(此時,系統可能都已經重啟了),所以,要動用bugreport就需要結合一些其他機制, 譬如在殺掉system_server程序之前,先讓bugreport執行完。

3.2 問題定位

Watchdog出現的日誌很明顯,logcat中的event, system中都會有體現,要定位問題,可以從檢索日誌中的watchdog關鍵字開始。

發生Watchdog檢測超時這麼重要的系統事件,Android會列印一個EventLog:

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

Watchdog是執行在system_server程序中,會列印一些System型別的日誌。在手機處於非除錯狀態時,伴隨Watchdog出現的往往是system_server程序被殺,從而系統重啟。 當Watchdog要主動殺掉system_server程序時,以下關鍵字就會出現在SystemLog中:

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

當我們在日誌中檢索到上述兩類關鍵資訊時,說明“Watchdog顯靈”了,從另一個角度來理解,就是“System Not Responding”了。 接下來,我們需要進一步定位在watchdog出現之前,system_server程序在幹什麼,處於一個什麼狀態。 這與排除”Application Not Responding“問題差不多,我們需要程序的traces資訊、當前系統的CPU執行資訊、IO資訊。

找到Watchddog出現之前的traces.txt檔案,這個時間差最好不要太大,因為Watchdog預設的超時時間是1分鐘,太久以前的traces並不能說明問題。 誘導Watchdong出現的直接原因其實就是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()方法被阻塞了。這裡隱含了兩層意思:

  1. WindowManagerService實現了Watchdog.Monitor這個介面,並將自己作為Monitor Checker的物件加入到了Watchdog的監測集中

  2. monitor()方法是執行在android.fg執行緒中的。Android將android.fg設計為一個全域性共享的執行緒,意味著它的訊息佇列可以被其他執行緒共享, Watchdog的Monitor Checker就是使用的android.fg執行緒的訊息佇列。因此,出現Monitor Checker的超時,肯定是android.fg執行緒阻塞在monitor()方法上。

我們開啟system_server程序的traces,檢索 android.fg 可以快速定位到該執行緒的函式呼叫棧:

"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執行緒呼叫棧告訴我們幾個關鍵的資訊:

  • 這個執行緒當前的狀態是Blocked,阻塞
  • 由Watchdog發起呼叫monitor(),這是一個Watchdog檢查,阻塞已經超時
  • waiting to lock <0x126dccb8>: 阻塞的原因是monitor()方法中在等鎖<0x126dccb8>
  • held by thread 91: 這個鎖被編號為91的執行緒持有,需要進一步觀察91號執行緒的狀態。

題外話:每一個程序都會對自己所轄的執行緒編號,從1開始。1號執行緒通常就是我們所說的主執行緒。 執行緒在Linux系統中還有一個全域性的編號,由sysTid表示。我們在logcat等日誌中看到的一般是執行緒的全域性編號。 譬如,本例中android.fg執行緒在system_server程序中的編號是25,系統全域性編號是973。

可以在traces.txt檔案中檢索 tid=91 來快速找到91號執行緒的函式呼叫棧資訊:

"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,它的函式呼叫棧告訴我們幾個關鍵資訊:

  • Native,表示執行緒處於執行狀態(RUNNING),並且正在執行JNI方法
  • 在WindowManagerService.dump()方法申請了鎖<0x126dccb8>,這個鎖正是android.fg執行緒所等待的
  • FileOutputStream.write()表示Binder_C執行緒在執行IO寫操作,正式因為這個寫操作一直在阻塞,導致執行緒持有的鎖不能釋放

題外話:關於Binder執行緒。當Android程序啟動時,就會建立一個執行緒池,專門處理Binder事務。執行緒池中會根據當前的binder執行緒計數器的值來構造新建立的binder執行緒, 執行緒名”Binder_%X”,X是十六進位制。當然,執行緒池的執行緒數也有上限,預設情況下為16,所以,可以看到 Binder_1 ~ Binder_F 這樣的執行緒命名。

聰明的你看到這或許已經能夠想到解決辦法了,在這個IO寫操作上加一個超時機制,並且這個超時小於Watchdog的超時,不就可以讓執行緒釋放它所佔有的鎖了嗎? 是的,這確實可以作為一個臨時解決方案(Workaround),或者說一個保護機制。但我們可以再往深處想一想,這個IO寫操作為什麼會阻塞:

  • 是不是IO緩衝區滿了,導致寫阻塞呢?
  • 是不是寫操作有什麼鎖,導致這個write方法在等鎖呢?
  • 是不是當前系統的IO負載過於高,導致寫操作效率很低呢?

這都需要我們再進一步從日誌中去找原因。如果已有的日誌不全,找不到論據,我們還需要設計場景來驗證假設,解決問題的難度陡然上升。

3.3 場景還原

我們經歷了兩個關鍵步驟:

  1. 通過event或system型別的日誌,發現了Watchdog殺掉system_server導致系統重啟
  2. 通過traces日誌,發了導致Watchdog出現的具體執行緒操作

這兩個過程基本就涵蓋了Watchdog的執行機制了,但這並沒有解決問題啊。我們需要找到執行緒阻塞的原因是什麼,然而,執行緒阻塞的原因就千奇百怪了。 如果有問題出現的現場,並且問題可以重現,那麼我們可以通過除錯的手段來分析問題產生的原因。 如果問題只是偶然出現,甚至只有一堆日誌,我們就需要從日誌中來還原問題出現的場景,這一步才是真正考驗大家Android/Linux功底的地方。

繼續以上述問題為例,我們來進一步還原問題出現的場景,從Java層的函式呼叫棧來看:

  • 首先,跨程序發起了Binder.dump()方法的呼叫:at android.os.Binder.dump(Binder.java:324)
  • 然後,進入了WMS的dump():at com.android.server.wm.WindowManagerService.dump(WindowManagerService.java:12654)
  • 接著,發生了寫檔案操作:at java.io.FileOutputStream.write(FileOutputStream.java:186)
  • 最後,呼叫了JNI方法:at libcore.io.Posix.writeBytes(Native method)

Binder_C執行緒要出現這種函式呼叫棧,我們可以初步確定是Android接受了如下命令 (dumpsys原理請查閱dumpsys介紹一文):

$ adb shell dumpsys window

當通過命令列執行以上命令時,客戶端(PC)的adb server會向服