Watchdog问题实例分析

时间 2019-12-12

标签 watchdog 问题实例分析繁體版

原文原文链接

1.日志获取html

Watchdog相关的问题甚至须要如下全部的日志：java

logcat 经过adb logcat命令输出Android的一些当前运行日志，能够经过logcat的 -b 参数指定要输出的日志缓冲区，缓冲区对应着logcat的一种日志类型。高版本的logcat可使用 -b all 获取到全部缓冲区的日志android
- event 经过android.util.EventLog工具类打印的日志，一些重要的系统事件会使用此类日志
- main 经过android.util.Log工具类打印的日志，应用程序，尤为是基于SDK的应用程序，会使用此类日志
- system 经过android.util.Slog工具类打印的日志，系统相关的日志通常都是使用此类日志，譬如SystemServer
- radio 经过android.util.Rlog工具类打印的日志，通讯模块相关的日志通常都是使用此类日志，譬如RIL
dumpsys 经过adb dumpsys命令输出一些重要的系统服务信息，譬如内存、电源、磁盘等.git
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文件的位置。github
binder 经过Binder跨进程调用的日志，能够经过adb shell cat命令从 /proc/binder 下取出对应的日志shell
- failed_transaction_log
- transaction_log
- transactions
- stats
dropbox 为了记录历史的logcat日志，Android引入了Dropbox，将历史日志持久化到磁盘中(/data/system/dropbox)。 logcat的缓冲区大小毕竟是有限的，因此须要循环利用，这样历史的日志信息就会被冲掉。在一些自动化测试的场景下，譬如Monkey须要长时间的运行，就须要把历史的日志全都保存下来。app
tombstone tombstone错误通常由Dalvik错误、native层的代码问题致使的。当系统发生tombstone时，内核会上报一个严重的警告信号，上层收到后，把当前的调用栈信息持久化到磁盘中(/data/tombstone)函数
bugreport 经过adb bugreport命令输出，日志内容多到爆，logcat, traces, dmesg, dumpsys, binder的日志都包含在其中。因为输出bugreport的时间很长，当系统发生错误时，咱们再执行bugreport每每就来不及了(此时，系统可能都已经重启了)，因此，要动用bugreport就须要结合一些其余机制，譬如在杀掉system_server进程以前，先让bugreport运行完。工具

2.问题定位oop

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()方法被阻塞了。这里隐含了两层意思：

WindowManagerService实现了Watchdog.Monitor这个接口，并将本身做为Monitor Checker的对象加入到了Watchdog的监测集中
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.场景还原

咱们经历了两个关键步骤：

经过event或system类型的日志，发现了Watchdog杀掉system_server致使系统重启
经过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超时的直接缘由，最重要的是能还原出问题发生的场景。