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超时的直接原因，最重要的是能还原出问题发生的场景。

posted @ 2019-01-03 15:13  Leo的银弹  阅读(2830)  评论(0)  编辑  收藏  举报