做什么软件做网站效率最好,网站公司建设都招聘那些职位,网站的标题与关键词,苏州建设银行网站首页文章目录 1. 介绍2 watchdog 机制2.1 初始化2.2 添加Watchdog监测对象2.3 监测机制 3 问题分析3.1 日志分类3.2 定位3.3 场景还原 4. 实例分析5. 总结 1. 介绍
最早引入Watchdog是在单片机系统中#xff0c;由于单片机的工作环境容易受到外界磁场的干扰#xff0c;导致程序“… 文章目录 1. 介绍2 watchdog 机制2.1 初始化2.2 添加Watchdog监测对象2.3 监测机制 3 问题分析3.1 日志分类3.2 定位3.3 场景还原 4. 实例分析5. 总结 1. 介绍
最早引入Watchdog是在单片机系统中由于单片机的工作环境容易受到外界磁场的干扰导致程序“跑飞”造成整个系统无法正常工作因此引入了一个“看门狗”对单片机的运行状态进行实时监测针对运行故障做一些保护处理譬如让系统重启。这种Watchdog属于硬件层面必须有硬件电路的支持。Linux也引入了Watchdog在Linux内核下当Watchdog启动后便设定了一个定时器如果在超时时间内没有对/dev/Watchdog进行写操作则会导致系统重启。通过定时器实现的Watchdog属于软件层面Android设计了一个软件层面Watchdog用于保护一些重要的系统服务当出现故障时通常会让Android系统重启。由于这种机制的存在就经常会出现一些system_server进程被Watchdog杀掉而发生手机重启的问题
2 watchdog 机制
2.1 初始化
注意英文注释 private Watchdog() {mThread new Thread(this::run, watchdog);// Initialize handler checkers for each common thread we want to check. Note// that we are not currently checking the background thread, since it can// potentially hold longer running operations with no guarantees about the timeliness// of operations there.// The shared foreground thread is the main checker. It is where we// will also dispatch monitor checks and do other work.mMonitorChecker new HandlerChecker(FgThread.getHandler(),foreground thread, DEFAULT_TIMEOUT);mHandlerCheckers.add(mMonitorChecker);// Add checker for main thread. We only do a quick check since there// can be UI running on the thread.mHandlerCheckers.add(new HandlerChecker(new Handler(Looper.getMainLooper()),main thread, DEFAULT_TIMEOUT));。。。。。。。。。。。// Initialize monitor for Binder threads.addMonitor(new BinderThreadMonitor());mInterestingJavaPids.add(Process.myPid());// See the notes on DEFAULT_TIMEOUT.assert DB ||DEFAULT_TIMEOUT ZygoteConnectionConstants.WRAPPED_PID_TIMEOUT_MILLIS;mTraceErrorLogger new TraceErrorLogger();}初始化时会构建很多HandlerChecker大致分为两类
Monitor Checker用于检查是Monitor对象可能发生的死锁, AMS, PKMS, WMS等核心的系统服务都是Monitor对象Looper Checker用于检查线程的消息队列是否长时间处于工作状态。Watchdog自身的消息队列Ui, Io, Display这些全局的消息队列都是被检查的对象。此外一些重要的线程的消息队列也会加入到Looper Checker中譬如AMS, PKMS这些是在对应的对象初始化时加入的
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) {synchronized (mLock) {mMonitorChecker.addMonitorLocked(monitor);}
}
void addMonitorLocked(Monitor monitor) {// We dont want to update mMonitors when the Handler is in the middle of checking// all monitors. We will update mMonitors on the next schedule if it is safemMonitorQueue.add(monitor);
}//HandlerChecker
public void addThread(Handler thread) {addThread(thread, DEFAULT_TIMEOUT);
}
public void addThread(Handler thread, long timeoutMillis) {synchronized (mLock) {final String name thread.getLooper().getThread().getName();mHandlerCheckers.add(new HandlerChecker(thread, name, timeoutMillis));}
}2.3 监测机制
Override
public void run() {boolean waitedHalf false;while (true) {...synchronized (this) {long timeout CHECK_INTERVAL;...// 1. 调度所有的HandlerCheckerfor (int i0; imHandlerCheckers.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. 存在超时的HandlerCheckerblockedCheckers getBlockedCheckersLocked();subject describeCheckersLocked(blockedCheckers);allowRestart mAllowRestart;}...// 5. 保存日志判断是否需要杀掉系统进程Slog.w(TAG, *** GOODBYE!);Process.killProcess(Process.myPid());System.exit(10);} // end of while (true)}以上代码片段主要的运行逻辑如下 Watchdog运行后便开始无限循环依次调用每一个HandlerChecker的scheduleCheckLocked()方法 调度完HandlerChecker之后便开始定期检查是否超时每一次检查的间隔时间由CHECK_INTERVAL常量设定为30秒 每一次检查都会调用evaluateCheckerCompletionLocked()方法来评估一下HandlerChecker的完成状态 COMPLETED表示已经完成WAITING和WAITED_HALF表示还在等待但未超时OVERDUE表示已经超时。默认情况下timeout是1分钟但监测对象可以通过传参自行设定譬如PKMS的Handler Checker的超时是10分钟 如果超时时间到了还有HandlerChecker处于未完成的状态(OVERDUE)则通过getBlockedCheckersLocked()方法获取阻塞的HandlerChecker生成一些描述信息 保存日志包括一些运行时的堆栈信息这些日志是我们解决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);}Overridepublic 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定时检查一些重要的系统服务举报长时间阻塞的事件甚至杀掉system_server进程让Android系统重启。
3 问题分析
3.1 日志分类
设备厂商和应用开发者都会在AOSP的基础上增加很多日志
logcat 通过adb logcat命令输出Android的一些当前运行日志可以通过logcat的 -b 参数指定要输出的日志缓冲区缓冲区对应着logcat的一种日志类型。 高版本的logcat可以使用 -b all 获取到所有缓冲区的日志 event 通过android.util.EventLog工具类打印的日志一些重要的系统事件会使用此类日志main 通过android.util.Log工具类打印的日志应用程序尤其是基于SDK的应用程序会使用此类日志system 通过android.util.Slog工具类打印的日志系统相关的日志一般都是使用此类日志譬如SystemServerradio 通过android.util.Rlog工具类打印的日志通信模块相关的日志一般都是使用此类日志譬如RIL dumpsys 通过adb dumpsys命令输出一些重要的系统服务信息譬如内存、电源、磁盘等traces 该文件记录了一个时间段的函数调用栈信息通常在应用发生ANR(Application Not Responding)时会触发打印各进程的函数调用栈。 站在Linux的角度其实就是向进程发送SIGNAL_QUIT(3)请求譬如我们可以通过adb shell kill -3 命令打印指定进程的的trace。 SIGNAL_QUIT(3)表面意思有一点误导它其实并不会导致进程退出。输出一般在 /data/anr/traces.txt 文件中当然这是可以灵活配置的 Android提供的系统属性dalvik.vm.stack-trace-file可以用来配置生成traces文件的位置。binder 通过Binder跨进程调用的日志可以通过adb shell cat命令从 /proc/binder 下取出对应的日志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()方法被阻塞了。这里隐含了两层意思
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 prio5 tid25 Blocked| groupmain sCount1 dsCount0 obj0x12eef900 self0x7f7a8b1000| sysTid973 nice0 cgrpdefault sched0/0 handle0x7f644e9000| stateS schedstat( 3181688530 2206454929 8991 ) utm251 stm67 core1 HZ100| stack0x7f643e7000-0x7f643e9000 stackSize1036KB| held mutexesat com.android.server.wm.WindowManagerService.monitor(WindowManagerService.java:13125)- waiting to lock 0x126dccb8 (a java.util.HashMap) held by thread 91at 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()方法中在等锁0x126dccb8held by thread 91 这个锁被编号为91的线程持有需要进一步观察91号线程的状态。
题外话每一个进程都会对自己所辖的线程编号从1开始。1号线程通常就是我们所说的主线程。 线程在Linux系统中还有一个全局的编号由sysTid表示。我们在logcat等日志中看到的一般是线程的全局编号。 譬如本例中android.fg线程在system_server进程中的编号是25系统全局编号是973。
可以在traces.txt文件中检索 tid91 来快速找到91号线程的函数调用栈信息
91号线程的名字是Binder_C它的函数调用栈告诉我们几个关键信息
Binder_C prio5 tid91 Native| groupmain sCount1 dsCount0 obj0x12e540a0 self0x7f63289000| sysTid1736 nice0 cgrpdefault sched0/0 handle0x7f6127c000| stateS schedstat( 96931835222 49673449591 260122 ) utm7046 stm2647 core2 HZ100| stack0x7f5ffbc000-0x7f5ffbe000 stackSize1008KB| held mutexesat 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 addr0x134c4910 (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)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 场景还原
我们经历了两个关键步骤
通过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_to0x74/0x8c
kernel: pipe_wait0x60/0x9c
kernel: pipe_write0x278/0x5cc
kernel: do_sync_write0x90/0xcc
kernel: vfs_write0xa4/0x194
kernel: SyS_write0x40/0x8c
kernel: cpu_switch_to0x48/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. 实例分析
在上面介绍Watchdog问题分析方法的时候我们其实已经举了一个例子。通常比较容易定位导致Watchdog出现的直接原因(Direct Cause)但很难找到更深层次的原因(Root Cause)。 这个小节我们再介绍一个实例来分析Watchdog出现的另一种场景。诚然仅凭几个例子远不够涵盖Watchdog的所有问题我们的章法还是按照一定的方法论来深究问题。
回顾一下解决问题三部曲
日志获取。日志种类繁多分析Watchdog问题宁滥毋缺问题定位。从logcat中锁定watchdog的出现从traces锁定直接原因场景还原。结合各类日志不断假设验证
以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 prio5 tid17 TimedWaiting| groupmain sCount1 dsCount0 obj0x12c0e6d0 self0x7f84caf000| sysTid938 nice-2 cgrpdefault sched0/0 handle0x7f7d887000| stateS schedstat( 107864628645 628257779012 60356 ) utm7799 stm2987 core2 HZ100| stack0x7f6e68f000-0x7f6e691000 stackSize1036KB| held mutexesat 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, time27097912
10-14 17:10:04.215 892 938 E ANRManager: Reason: Broadcast of Intent { actandroid.intent.action.TIME_TICK flg0x50000114 (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超时的直接原因最重要的是能还原出问题发生的场景。
