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超時的直接原因，最重要的是能還原出問題發生的場景。