Watchdog問題實例分析

1.日誌獲取

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命令輸出一些重要的系統服務信息，譬如內存、電源、磁盤等.

• 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運行完。

 

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.場景還原

咱們經歷了兩個關鍵步驟：

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會向服務端(手機)的adbd發送指令， adbd進程會fork出一個叫作dumpsys的子進程，dumpsys進程再利用Binder機制和system_server通訊 (adb的實現原理能夠查閱adb介紹一文)。

僅憑這個仍是分析不出問題所在，咱們須要啓用內核的日誌了。當調用JNI方法libcore.io.Posix.writeBytes()時，會觸發系統調用， Linux會從用戶態切換到內核態，內核的函數調用棧也能夠從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)，正常狀況下，系統調用write()就完事了，但Kernel卻打開了一個管道，最終阻塞在了pipe_wait()方法。 什麼場景下會打開一個管道，並且管道會阻塞呢？一系列的猜測和驗證過程接踵而至。

這裏有必要先補充一些基礎知識了：

• Linux進程間通訊之管道(pipe)

  Linux的管道實現藉助了文件系統的file結構和VFS(Virtual File System)，經過將兩個file結構指向同一個臨時的VFS索引節點，而這個VFS索引節點又指向一個物理頁面時， 實際上就創建了一個管道。

  這就解釋了爲何發起系統調用write的時候，打開了一個管道。由於dumpsys和system_server進程，將本身的file結構指向了同一個VFS索引節點。

• 管道掛起的案例

  管道是一個生產者-消費者模型，當緩衝區滿時，則生產者不能往管道中再寫數據了，需等到消費者讀數據。若是消費者來不及處理緩衝區的數據，或者鎖定緩衝區，則生產者就掛起了。

  結合到例子中的場景，system_server進程沒法往管道中寫數據，極可能是dumpsys進程一直忙碌來不及處理新的數據。

接下來，須要再從日誌中尋找dumpsys進程的運行狀態了：

• 是否是dumpsys進程的負載過高？
• 是否是dumpsys進程死掉了，致使一直沒有處理緩衝區數據？
• 是否是dumpsys進程有死鎖？

接下來的分析過程已經偏離Watchdog機制愈來愈遠了，咱們點到爲止。

小夥伴們能夠看到，場景還原涉及到的知識點很是之寬泛，並且有必定的深度。在沒有現場的狀況下，伴隨一系列的假設和驗證過程，充滿了不肯定性和發現問題的喜悅。 正所謂，同問題作鬥爭，其樂無窮！

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

經過event或system類型的logcat日誌，檢索Watchdog出現的關鍵信息；經過traces，分析出致使Watchdog檢查超時的直接緣由；經過其餘日誌，還原出問題出現的場景。

 

4.實例分析

以CPU佔用太高的場景爲例：

從sys_log中，檢索到了Watchdog的出現關鍵信息

TIPS: 在sys_log中搜索關鍵字」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這個線程一直處於忙碌狀態，致使Watchdog檢查超時。 Watchdog出現的時間是10-14 17:10:51.548左右，須要從traces.txt中找到這個時間段的system_server進程的函數調用棧信息， system_server的進程號是892。

從traces.txt中找到對應的函數調用棧

traces.txt包含不少進程在不一樣時間段的函數調用棧信息，爲了檢索的方便，首先能夠將traces.txt分塊。 筆者寫了一個工具，能夠從traces.txt文件中分割出指定進程號的函數調用棧信息。

TIPS: 在system_server的traces中(經過工具分割出的system_server_892_2015-10-14-17:09:06文件)搜索關鍵字」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線程實際上運行着AMS的消息隊列，這個函數調用棧的關鍵信息：

• 線程狀態爲TimedWaiting, 這表示當前線程阻塞在一個超時的wait()方法
• 正在處理廣播消息超時發生的ANR(Application Not Responding)，須要將當前的函數調用棧打印出來
• 最終在<0x264ff09d>等待，能夠從AMS的源碼 中找到這一處鎖的源碼，由於dumpStackTraces()會寫文件，因此AMS設計了一個200毫秒的超時鎖。

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

還原問題的場景

從ActivityManager這個線程的調用棧，咱們就會有一些疑惑：

• 是哪一個應用發生了ANR？爲何會發生ANR？
• 超時鎖只用200毫秒就釋放了，爲何會致使Watchdog檢查超時？(AMS的Looper默認超時是1分鐘)

帶着這些疑惑，咱們再回到日誌中：

從sys_log中，能夠檢索到Watchdog出現的時間點(17:10:51.548)以前，com.android.systemui發生了ANR，從而引起AMS打印函數調用棧:

TIPS: 在sys_log中檢索」ANR in」關鍵字或在event_log中檢索」anr」關鍵字

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

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

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

observer.wait(200)在調用後，便進入排隊等待喚醒狀態(Waiting)，在等待200毫秒後，便從新開始申請CPU資源，而此時，CPU資源一直被float_bessel佔着沒有釋放，因此該線程一直在等CPU資源。 等了1分鐘後，Watchdog跳出來講「不行，你已經等了1分鐘了，handler處理其餘消息了」。

在多核狀況下，CPU的使用率統計會累加多個核的使用率，因此會出現超過100%的狀況。那麼float_bessel到底是什麼呢？它是一個Linux的測試樣本，貝塞爾函數的計算，耗的就是CPU。

這樣，該問題的場景咱們就還原出來了：在壓力測試的環境下，CPU被float_bessel運算佔用，致使com.android.systemui進程發生ANR，從而引起AMS打印trace; 但因爲AMS一直等不到CPU資源，Watchdog檢測超時，殺掉system_server進程，系統重啓。

對於壓力測試而言，咱們通常會設定一個經過標準，在某些壓力狀況下，出現一些錯誤是容許的。對於Android實際用戶的使用場景而言，本例中的壓力一般是不存在的，因此在實際項目中，這種類型的Watchdog問題，咱們通常不解決。

5. 總結

Android中Watchdog用來看護system_server進程，system_server進程運行着系統最終要的服務，譬如AMS、PKMS、WMS等， 當這些服務不能正常運轉時，Watchdog可能會殺掉system_server，讓系統重啓。

Watchdog的實現利用了鎖和消息隊列機制。當system_server發生死鎖或消息隊列一直處於忙碌狀態時，則認爲系統已經沒有響應了(System Not Responding)。

在分析Watchdog問題的時候，首先要有詳盡的日誌，其次要能定位出致使Watchdog超時的直接緣由，最重要的是能還原出問題發生的場景。