手把手教你高效监控ANR

1.前言

ANR比较棘手在于,没有崩溃日志,定位问题比较困难,而且ANR是必须要解决的问题。

Android对ANR的监控机制
Android应用程序是通过消息来驱动的,Android某种意义上也可以说成是一个以消息驱动的系统,UI、事件、生命周期都和消息处理机制息息相关。Android的ANR监测方案也是一样,大部分就是利用了Android的消息机制。

 

anr.png

2.主流的ANR监控方案

主流的ANR监控方案:FileObserver,WatchDog,Looper.loop。它们都各有优缺点,无法覆盖所有情况,所以在线上使用的时候可以结合这几种方案一起使用。

2.1 FileObserver实现ANR监控

当ANR发生的时候,我们是可以通过监听该文件目录data/anr/的写入情况来判断是否发生了ANR,看起来这是一个不错的时机。需要注意的是,所有应用发生ANR的时候都会进行回调,因此需要做一些过滤与判断,如包名、进程号等。

优点:

  1. 基于原生接口调用,时机和内容准确
  2. 无性能问题实现简单

缺点:
最大的困难是兼容性问题,这个方案受限于Android系统的SELinux机制,5.0以后基本已经使低权限应用无法监听到trace文件了,但是可以在开发内测阶段通过root手机进行监控。

2.2 ANR-WatchDog实现ANR监控

ANR-WatchDog是参考Android WatchDog机制(com.android.server.WatchDog.java)起个单独线程向主线程发送一个变量+1操作的消息,然后自我休眠sleep 自定义ANR的阈值一般是5s,休眠过后判断变量是否+1完成,如果未完成则告警。

 

watchdog.png

优点:

  1. 兼容性好,各个机型版本通用
  2. 无需修改APP逻辑代码,非侵入式
  3. 逻辑简单,性能影响不大

缺点:
无法保证能捕捉所有ANR,对阈值的设置直接影响捕获概率.比如如果设置了5s就无法捕获10s的Receiver和20s的service 引起的ANR。

2.3 Looper.loop实现ANR监控

巧妙的利用了Android原生Looper.loop中的一个log打印逻辑。
这个log打印逻辑正是在Message消息分发前后,大部分的性能卡顿问题都是在这里发生的,监控这两个逻辑之间的时间差就可以得到当前主线程的卡顿状态,如果超时则获取trace信息并上报。

实现原理:开启子线程执行,会消耗cpu资源,谨慎开启,开发中一般针对部分用户下发开关:

  1. 设置Looper.setPrinter(自定义printer)实现println方法;
  2. 在消息执行前后,Looper会调用
    Looper.mPriter.pritlin(“>>>>> dispatch msg.target msg.callBack,msg.what”)//子线程开启收集线程堆栈信息
    Looper.mPriter.pritlin(“<<<<<< finish msg.target msg.callBack,msg.what”)//子线程结束收集线程堆栈信息
  3. 首先需要判断msg.target的Looper是否等于主线程的Looper.
  4. 其次计算这两个函数前后时间差是否超过200ms超过的话就上报堆栈调用信息。

优点:

  1. 灵活配置可监控常见APP应用性能也可作为一部分场景的ANR监测,并且可以准确定位ANR和耗时调用栈。

  2. 谷歌已经明确标注This must be in a local variable, in case a UI event sets the logger这个looger对象是可以被更改的,已经有开发者遇到在使用WebView时logger被set为Null导致,进而造成监控失败。

3.如果dispatchMessage消息执行的非常久是无法触发监控的逻辑。

4.无法监控CPU资源紧张造成系统卡顿,无法响应的ANR

2.4 注册信号函数

使用注册信号函数机制监听SINGAL_QUIT信号,可以监听ANR和Crash触发逻辑。可以作为FileObserver在5.0以后因权限问题无法监测data/anr目录的使用。
因为当应用发生crash和ANR的时候,系统会向目标进程发送SIGNAL_QUIT信号,应用虚拟机捕获到信号以后会收集系统信息输出到日志文件中(data/anr/trace.txt)然后kill掉目标进程。trace文件中数据过大,可以根据当前时间节点和进程id进行信息过滤。详情参考:让Native Crash 与ANR无处发泄

3.总结

ANR监控方案各有优劣,开发中一般组合多个共同使用。
Crash,ANR,卡顿最难的是异常信息的收集上传,收集到信息后可以根据日志进行分析进而解决问题。信息(一般是将日志保存在本地,有效期限是七天)上传一般都是通过开关动态下发的,目的是为了节省带宽和服务端的存储压力。千万级的用户数据量会很大。

在灰度期间重点观察指标是否正常,如果正常扩大灰度继续观察,不正常的话就停止灰度。然后定位问题是升级还是采用热修复。

工程实践举例:

ANR监控是一个非常有年代感的话题了,但是市面上的ANR监控工具,或者并非真正意义上的ANR的监控(而是5秒卡顿监控);或者并不完善,监控不到到所有的ANR。而想要得到一个完善的ANR监控工具,必须要先了解系统整个ANR的流程。本文分析了ANR的主要流程,给出了一个完善的ANR监控方案。该方案已经在Android微信客户端上经过全量验证,稳定地运行了一年多的时间。

我们知道ANR流程基本都是在system_server系统进程完成的,系统进程的行为我们很难监控和改变,想要监控ANR就必须找到系统进程跟我们自己的应用进程是否有交互,如果有,两者交互的边界在哪里,边界上应用一端的行为,才是我们比较容易能监控到的,想要要找到这个边界,我们就必须要了解ANR的流程。

一、ANR流程

无论ANR的来源是哪里,最终都会走到ProcessRecord中的appNotResponding,这个方法包括了ANR的主要流程,所以也比较长,我们找出一些关键的逻辑来分析:frameworks/base/services/core/java/com/android/server/am/ProcessRecord.java:

void appNotResponding(String activityShortComponentName, ApplicationInfo aInfo,

先是一长串if else,给出了几种比较极端的情况,会直接return,而不会产生一个ANR,这些情况包括:进程正在处于正在关闭的状态,正在crash的状态,被kill的状态,或者相同进程已经处在ANR的流程中。

另外很重要的一个逻辑就是判断当前ANR是否是一个SilentAnr,所谓“沉默的ANR”,其实就是后台ANR,后台ANR跟前台ANR会有不同的表现:前台ANR会弹无响应的Dialog,后台ANR会直接杀死进程。前后台ANR的判断的原则是:如果发生ANR的进程对用户来说是有感知的,就会被认为是前台ANR,否则是后台ANR。另外,如果在开发者选项中勾选了“显示后台ANR”,那么全部ANR都会被认为是前台ANR。

我们继续分析这个方法:

if (!isSilentAnr && !onlyDumpSelf) {

发生ANR后,为了能让开发者知道ANR的原因,方便定位问题,会dump很多信息到ANR Trace文件里,上面的逻辑就是选择需要dump的进程。ANR Trace文件是包含许多进程的Trace信息的,因为产生ANR的原因有可能是其他的进程抢占了太多资源,或者IPC到其他进程(尤其是系统进程)的时候卡住导致的。

选择需要dump的进程是一段挺有意思逻辑,我们稍微分析下:需要被dump的进程被分为了firstPids、nativePids以及extraPids三类:

  • firstPIds:firstPids是需要首先dump的重要进程,发生ANR的进程无论如何是一定要被dump的,也是首先被dump的,所以第一个被加到firstPids中。如果是SilentAnr(即后台ANR),不用再加入任何其他的进程。如果不是,需要进一步添加其他的进程:如果发生ANR的进程不是system_server进程的话,需要添加system_server进程;接下来轮询AMS维护的一个LRU的进程List,如果最近访问的进程包含了persistent的进程,或者带有BIND_TREAT_LIKE_ACTVITY标签的进程,都添加到firstPids中。
  • extraPids:LRU进程List中的其他进程,都会首先添加到lastPids中,然后lastPids会进一步被选出最近CPU使用率高的进程,进一步组成extraPids;
  • nativePids:nativePids最为简单,是一些固定的native的系统进程,定义在WatchDog.java中。

拿到需要dump的所有进程的pid后,AMS开始按照firstPids、nativePids、extraPids的顺序dump这些进程的堆栈:

File tracesFile = ActivityManagerService.dumpStackTraces(firstPids,

这里也是我们需要重点分析的地方,我们继续看这里做了什么,跟到AMS里面,

frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java

public static Pair<Long, Long> dumpStackTraces(String tracesFile, ArrayList<Integer> firstPids,

我们首先关注到remainingTime,这是一个重要的变量,规定了我们dump所有进程的最长时间,因为dump进程所有线程的堆栈,本身就是一个重操作,何况是要dump许多进程,所以规定了发生ANR之后,dump全部进程的总时间不能超过20秒,如果超过了,马上返回,确保ANR弹窗可以及时的弹出(或者被kill掉)。我们继续跟到dumpJavaTracesTombstoned

private static long dumpJavaTracesTombstoned(int pid, String fileName, long timeoutMs) {

再一路追到native层负责dump堆栈的system/core/debuggerd/client/debuggerd_client.cpp

bool debuggerd_trigger_dump(pid_t tid, DebuggerdDumpType dump_type, unsigned int timeout_ms, unique_fd output_fd) {

来了来了!之前说的交互边界终于找到了!这里会通过sigqueue向需要dump堆栈的进程发送SIGQUIT信号,也就是signal 3信号,而发生ANR的进程是一定会被dump的,也是第一个被dump的。这就意味着,只要我们能监控到系统发送的SIGQUIT信号,也许就能够监控到发生了ANR。

每一个应用进程都会有一个SignalCatcher线程,专门处理SIGQUIT,来到art/runtime/http://signal_catcher.cc

void* SignalCatcher::Run(void* arg) {

WaitForSignal方法调用了sigwait方法,这是一个阻塞方法。这里的死循环,就会一直不断的等待监听SIGQUIT和SIGUSR1这两个信号的到来。

整理一下ANR的过程:当应用发生ANR之后,系统会收集许多进程,来dump堆栈,从而生成ANR Trace文件,收集的第一个,也是一定会被收集到的进程,就是发生ANR的进程,接着系统开始向这些应用进程发送SIGQUIT信号,应用进程收到SIGQUIT后开始dump堆栈。来简单画个示意图:


图片

所以,事实上进程发生ANR的整个流程,也只有dump堆栈的行为会在发生ANR的进程中执行。这个过程从收到SIGQUIT开始(圈1),到使用socket写Trace(圈2)结束,然后再继续回到server进程完成剩余的ANR流程。我们就在这两个边界上做做文章。

首先我们肯定会想到,我们能否监听到syste_server发送给我们的SIGQUIT信号呢?如果可以,我们就成功了一半。

二、监控SIGQUIT信号

Linux系统提供了两种监听信号的方法,一种是SignalCatcher线程使用的sigwait方法进行同步、阻塞地监听,另一种是使用sigaction方法注册signal handler进行异步监听,我们都来试试。

2.1. sigwait

我们首先尝试前一种方法,模仿SignalCatcher线程,做一模一样的事情,通过一个死循环sigwait,一直监听SIGQUIT:

static void *mySigQuitCatcher(void* args) {

这个时候就有了两个不同的线程sigwait同一个SIGQUIT,具体会走到哪个呢,我们在sigwait的文档中找到了这样的描述(sigwait方法是由sigwaitinfo方法实现的):

原来当有两个线程通过sigwait方法监听同一个信号时,具体是哪一个线程收到信号时不能确定的**。不确定可不行,当然不满足我们的需求。

3.2. Signal Handler

那我们再试下另一种方法是否可行,我们通过可以sigaction方法,建立一个Signal Handler:

void signalHandler(int sig, siginfo_t* info, void* uc) {

建立了Signal Handler之后,我们发现在同时有sigwait和signal handler的情况下,信号没有走到我们的signal handler而是依然被系统的Signal Catcher线程捕获到了,这是什么原因呢?

原来是Android默认把SIGQUIT设置成了BLOCKED,所以只会响应sigwait而不会进入到我们设置的handler方法中。我们通过pthread_sigmask或者sigprocmask把SIGQUIT设置为UNBLOCK,那么再次收到SIGQUIT时,就一定会进入到我们的handler方法中。需要这样设置:

sigset_t sigSet;

最后需要注意,我们通过Signal Handler抢到了SIGQUIT后,原本的Signal Catcher线程中的sigwait就不再能收到SIGQUIT了,原本的dump堆栈的逻辑就无法完成了,我们为了ANR的整个逻辑和流程跟原来完全一致,需要在Signal Handler里面重新向Signal Catcher线程发送一个SIGQUIT

int tid = getSignalCatcherThreadId(); //遍历/proc/[pid]目录,找到SignalCatcher线程的tid

(如果缺少了重新向SignalCatcher发送SIGQUIT的步骤,AMS就一直等不到ANR进程写堆栈,直到20秒超时后,才会被迫中断,而继续之后的流程。直接的表现就是ANR弹窗非常慢(20秒超时时间),并且/data/anr目录下无法正常生成完整的 ANR Trace文件。)

以上就得到了一个不改变系统行为的前提下,比较完善的监控SIGQUIT信号的机制,这也是我们监控ANR的基础。

三、完善的ANR监控方案

监控到SIGQUIT信号并不等于就监控到了ANR。

3.1. 误报

充分非必要条件1:发生ANR的进程一定会收到SIGQUIT信号;但是收到SIGQUIT信号的进程并不一定发生了ANR。

考虑下面两种情况:

  • 其他进程的ANR:上面提到过,发生ANR之后,发生ANR的进程并不是唯一需要dump堆栈的进程,系统会收集许多其他的进程进行dump,也就是说当一个应用发生ANR的时候,其他的应用也有可能收到SIGQUIT信号。进一步,我们监控到SIGQUIT时,可能是监听到了其他进程产生的ANR****,从而产生误报。
  • 非ANR发送SIGQUIT:发送SIGQUIT信号其实是很容易的一件事情,开发者和厂商都可以很容易的发送一个SIGQUIT(java层调用android.os.Process.sendSignal方法;Native层调用kill或者tgkill方法),所以我们可能会收到非ANR流程发送的SIGQUIT信号,从而产生误报。

怎么解决这些误报的问题呢,我重新回到ANR流程开始的地方:

void appNotResponding(String activityShortComponentName, ApplicationInfo aInfo,

在ANR弹窗前,会执行到makeAppNotRespondingLocked方法中,在这里会给发生ANR进程标记一个NOT_RESPONDING的flag。而这个flag我们可以通过ActivityManager来获取:

private static boolean checkErrorState() {

监控到SIGQUIT后,我们在20秒内(20秒是ANR dump的timeout时间)不断轮询自己是否有NOT_RESPONDING对flag,一旦发现有这个flag,那么马上就可以认定发生了一次ANR。

(你可能会想,有这么方便的方法,监控SIGQUIT信号不是多余的吗?直接一个死循环,不断轮训这个flag不就完事了?是的,理论上确实能这么做,但是这么做过于的低效、耗电和不环保外,更关键的是,下面漏报的问题依然无法解决)

另外,Signal Handler回调的第二个参数siginfo_t,也包含了一些有用的信息,该结构体的第三个字段si_code表示该信号被发送的方法,SI_USER表示信号是通过kill发送的,SI_QUEUE表示信号是通过sigqueue发送的。但在Android的ANR流程中,高版本使用的是sigqueue发送的信号,某些低版本使用的是kill发送的信号,并不统一。

而第五个字段(极少数机型上是第四个字段)si_pid表示的是发送该信号的进程的pid,这里适用几乎所有Android版本和机型的一个条件是:如果发送信号的进程是自己的进程,那么一定不是一个ANR。可以通过这个条件排除自己发送SIGQUIT,而导致误报的情况。

3.2. 漏报

充分非必要条件2:进程处于NOT_RESPONDING的状态可以确认该进程发生了ANR。但是发生ANR的进程并不一定会被设置为NOT_RESPONDING状态。

考虑下面两种情况:

  • 后台ANR(SilentAnr):之前分析ANR流程我们可以知道,如果ANR被标记为了后台ANR(即SilentAnr),那么杀死进程后就会直接return,并不会走到产生进程错误状态的逻辑。这就意味着,后台ANR没办法捕捉到,而后台ANR的量同样非常大,并且后台ANR会直接杀死进程,对用户的体验也是非常负面的,这么大一部分ANR监控不到,当然是无法接受的。
  • 闪退ANR:除此之外,我们还发现相当一部分机型(例如OPPO、VIVO两家的高Android版本的机型)修改了ANR的流程,即使是发生在前台的ANR,也并不会弹窗,而是直接杀死进程,即闪退。这部分的机型覆盖的用户量也非常大。并且,确定两家今后的新设备会一直维持这个机制。

所以我们需要一种方法,在收到SIGQUIT信号后,能够非常快速的侦查出自己是不是已处于ANR的状态,进行快速的dump和上报。很容易想到,我们可以通过主线程是否处于卡顿状态来判断。那么怎么最快速的知道主线程是不是卡住了呢?上一篇文章中,分析Sync Barrier泄漏问题时,我们反射过主线程Looper的mMessage对象,该对象的when变量,表示的就是当前正在处理的消息入队的时间,我们可以通过when变量减去当前时间,得到的就是等待时间,如果等待时间过长,就说明主线程是处于卡住的状态,这时候收到SIGQUIT信号基本上就可以认为的确发生了一次ANR:

private static boolean isMainThreadStuck(){

我们通过上面几种机制来综合判断收到SIGQUIT信号后,是否真的发生了一次ANR,最大程度地减少误报和漏报,才是一个比较完善的监控方案。

3.3. 额外收获:获取ANR Trace

回到之前画的ANR流程示意图,Signal Catcher线程写Trace(圈2)也是一个边界,并且是通过socket的write方法来写Trace的,如果我们能够hook到这里的write,我们甚至就可以拿到系统dump的ANR Trace内容。这个内容非常全面,包括了所有线程的各种状态、锁和堆栈(包括native堆栈),对于我们排查问题十分有用,尤其是一些native问题和死锁等问题。Native Hook我们采用PLT Hook 方案,这种方案在微信上已经被验证了其稳定性是可控的。

int (*original_connect)(int __fd, const struct sockaddr* __addr, socklen_t __addr_length);

其中有几点需要注意:

  • 只Hook ANR流程:有些情况下,基础库中的connect/open/write方法可能调用的比较频繁,我们需要把hook的影响降到最低。所以我们只会在接收到SIGQUIT信号后(重新发送SIGQUIT信号给Signal Catcher前)进行hook,ANR流程结束后再unhook。
  • 只处理Signal Catcher线程open/connect后的第一次write:除了Signal Catcher线程中的dump trace的流程,其他地方调用的write方法我们并不关心,并不需要处理。例如,dump trace的流程会在在write方法前,系统会先使用connet方法链接一个path为“/dev/socket/tombstoned_java_trace”的socket,我们可以hook connect方法,拿到这个socket的name,我们只处理connect这个socket后,相同线程(即Signal Catcher线程)的第一次write,这次write的内容才是我们唯一关心的。
  • Hook点因API Level而不同:需要hook的write方法在不同的Android版本中,所在的so也不尽相同,不同API Level需要分别处理,hook不同的so和方法。目前这个方案在API 18以上都测试过可行。

这个Hook Trace的方案,不仅仅可以用来查ANR问题,任何时候我们都可以手动向自己发送一个SIGQUIT信号,从而hook到当时的Trace。Trace的内容对于我们排查线程死锁,线程异常,耗电等问题都非常有帮助

这样我们就得到了一个完善的ANR监控方案,这套方案在微信上平稳运行了很长一段时间,给我们评估和优化微信Android客户端的质量提供了非常重要根据和方向。

另外一个ANR 监控思路:

GitHub - idaretobe/ANR-WatchDog: A simple watchdog that detects Android ANR (Application Not Responding) error and throws a meaningful exception

Android中的Watchdog

  1. 在Android中,Watchdog是用来监测关键服务是否发生了死锁,如果发生了死锁就kill进程,重启SystemServer
  2. Android的Watchdog是在SystemServer中进行初始化的,所以Watchdog是运行在SystemServer进程中
  3. Watchdog是运行一个单独的线程中的,每次wait 30s之后就会发起一个监测行为,如果系统休眠了,那Watchdog的wait行为也会休眠,此时需要等待系统唤醒之后才会重新恢复监测
  4. 想要被Watchdog监测的对象需要实现Watchdog.Monitor接口的monitor()方法,然后调用addMonitor()方法
  5. 其实framework里面的Watchdog实现除了能监控线程死锁以外还能够监控线程卡顿,addMonitor()方法是监控线程死锁的,而addThread()方法是监控线程卡顿的

Watchdog线程死锁监控实现

Watchdog监控线程死锁需要被监控的对象实现Watchdog.Monitor接口的monitor()方法,然后再调用addMonitor()方法,例如ActivityManagerService:

public final class ActivityManagerService extends ActivityManagerNative
    implements Watchdog.Monitor, BatteryStatsImpl.BatteryCallback {

 public ActivityManagerService(Context systemContext) {
  Watchdog.getInstance().addMonitor(this);
 }

 public void monitor() {
    synchronized (this) { }
  }
// ...
}

如上是从ActivityManagerService提取出来关于Watchdog监控ActivityManagerService这个对象锁的相关代码,而监控的实现如下,Watchdog是一个线程对象,start这个线程之后就会每次wait 30s后检查一次,如此不断的循环检查:

public void addMonitor(Monitor monitor) {
    synchronized (this) {
      if (isAlive()) {
        throw new RuntimeException("Monitors can't be added once the Watchdog is running");
      }
      mMonitorChecker.addMonitor(monitor);
    }
  }

@Override
  public void run() {
    boolean waitedHalf = false;
    while (true) {
      final ArrayList<HandlerChecker> blockedCheckers;
      final String subject;
      final boolean allowRestart;
      int debuggerWasConnected = 0;
      synchronized (this) {
        long timeout = CHECK_INTERVAL;
        // Make sure we (re)spin the checkers that have become idle within
        // this wait-and-check interval
        for (int i=0; i<mHandlerCheckers.size(); i++) {
          HandlerChecker hc = mHandlerCheckers.get(i);
          hc.scheduleCheckLocked();
        }

        if (debuggerWasConnected > 0) {
          debuggerWasConnected--;
        }

        // NOTE: We use uptimeMillis() here because we do not want to increment the time we
        // wait while asleep. If the device is asleep then the thing that we are waiting
        // to timeout on is asleep as well and won't have a chance to run, causing a false
        // positive on when to kill things.
        long start = SystemClock.uptimeMillis();
        while (timeout > 0) {
          if (Debug.isDebuggerConnected()) {
            debuggerWasConnected = 2;
          }
          try {
            wait(timeout);
          } catch (InterruptedException e) {
            Log.wtf(TAG, e);
          }
          if (Debug.isDebuggerConnected()) {
            debuggerWasConnected = 2;
          }
          timeout = CHECK_INTERVAL - (SystemClock.uptimeMillis() - start);
        }

        final int waitState = evaluateCheckerCompletionLocked();
        if (waitState == COMPLETED) {
          // The monitors have returned; reset
          waitedHalf = false;
          continue;
        } else if (waitState == WAITING) {
          // still waiting but within their configured intervals; back off and recheck
          continue;
        } else if (waitState == WAITED_HALF) {
          if (!waitedHalf) {
            // We've waited half the deadlock-detection interval. Pull a stack
            // trace and wait another half.
            ArrayList<Integer> pids = new ArrayList<Integer>();
            pids.add(Process.myPid());
            ActivityManagerService.dumpStackTraces(true, pids, null, null,
                NATIVE_STACKS_OF_INTEREST);
            waitedHalf = true;
          }
          continue;
        }

        // something is overdue!
        blockedCheckers = getBlockedCheckersLocked();
        subject = describeCheckersLocked(blockedCheckers);
        allowRestart = mAllowRestart;
      }

      // If we got here, that means that the system is most likely hung.
      // First collect stack traces from all threads of the system process.
      // Then kill this process so that the system will restart.
      EventLog.writeEvent(EventLogTags.WATCHDOG, subject);

      ArrayList<Integer> pids = new ArrayList<Integer>();
      pids.add(Process.myPid());
      if (mPhonePid > 0) pids.add(mPhonePid);
      // Pass !waitedHalf so that just in case we somehow wind up here without having
      // dumped the halfway stacks, we properly re-initialize the trace file.
      final File stack = ActivityManagerService.dumpStackTraces(
          !waitedHalf, pids, null, null, NATIVE_STACKS_OF_INTEREST);

      // Give some extra time to make sure the stack traces get written.
      // The system's been hanging for a minute, another second or two won't hurt much.
      SystemClock.sleep(2000);

      // Pull our own kernel thread stacks as well if we're configured for that
      if (RECORD_KERNEL_THREADS) {
        dumpKernelStackTraces();
      }

      String tracesPath = SystemProperties.get("dalvik.vm.stack-trace-file", null);
      String traceFileNameAmendment = "_SystemServer_WDT" + mTraceDateFormat.format(new Date());

      if (tracesPath != null && tracesPath.length() != 0) {
        File traceRenameFile = new File(tracesPath);
        String newTracesPath;
        int lpos = tracesPath.lastIndexOf (".");
        if (-1 != lpos)
          newTracesPath = tracesPath.substring (0, lpos) + traceFileNameAmendment + tracesPath.substring (lpos);
        else
          newTracesPath = tracesPath + traceFileNameAmendment;
        traceRenameFile.renameTo(new File(newTracesPath));
        tracesPath = newTracesPath;
      }

      final File newFd = new File(tracesPath);

      // Try to add the error to the dropbox, but assuming that the ActivityManager
      // itself may be deadlocked. (which has happened, causing this statement to
      // deadlock and the watchdog as a whole to be ineffective)
      Thread dropboxThread = new Thread("watchdogWriteToDropbox") {
          public void run() {
            mActivity.addErrorToDropBox(
                "watchdog", null, "system_server", null, null,
                subject, null, newFd, null);
          }
        };
      dropboxThread.start();
      try {
        dropboxThread.join(2000); // wait up to 2 seconds for it to return.
      } catch (InterruptedException ignored) {}


      // At times, when user space watchdog traces don't give an indication on
      // which component held a lock, because of which other threads are blocked,
      // (thereby causing Watchdog), crash the device to analyze RAM dumps
      boolean crashOnWatchdog = SystemProperties
                    .getBoolean("persist.sys.crashOnWatchdog", false);
      if (crashOnWatchdog) {
        // Trigger the kernel to dump all blocked threads, and backtraces
        // on all CPUs to the kernel log
        Slog.e(TAG, "Triggering SysRq for system_server watchdog");
        doSysRq('w');
        doSysRq('l');

        // wait until the above blocked threads be dumped into kernel log
        SystemClock.sleep(3000);

        // now try to crash the target
        doSysRq('c');
      }

      IActivityController controller;
      synchronized (this) {
        controller = mController;
      }
      if (controller != null) {
        Slog.i(TAG, "Reporting stuck state to activity controller");
        try {
          Binder.setDumpDisabled("Service dumps disabled due to hung system process.");
          // 1 = keep waiting, -1 = kill system
          int res = controller.systemNotResponding(subject);
          if (res >= 0) {
            Slog.i(TAG, "Activity controller requested to coninue to wait");
            waitedHalf = false;
            continue;
          }
        } catch (RemoteException e) {
        }
      }

      // Only kill the process if the debugger is not attached.
      if (Debug.isDebuggerConnected()) {
        debuggerWasConnected = 2;
      }
      if (debuggerWasConnected >= 2) {
        Slog.w(TAG, "Debugger connected: Watchdog is *not* killing the system process");
      } else if (debuggerWasConnected > 0) {
        Slog.w(TAG, "Debugger was connected: Watchdog is *not* killing the system process");
      } else if (!allowRestart) {
        Slog.w(TAG, "Restart not allowed: Watchdog is *not* killing the system process");
      } else {
        Slog.w(TAG, "*** WATCHDOG KILLING SYSTEM PROCESS: " + subject);
        for (int i=0; i<blockedCheckers.size(); i++) {
          Slog.w(TAG, blockedCheckers.get(i).getName() + " stack trace:");
          StackTraceElement[] stackTrace
              = blockedCheckers.get(i).getThread().getStackTrace();
          for (StackTraceElement element: stackTrace) {
            Slog.w(TAG, "  at " + element);
          }
        }
        Slog.w(TAG, "*** GOODBYE!");
        Process.killProcess(Process.myPid());
        System.exit(10);
      }

      waitedHalf = false;
    }
  }

首先,ActivityManagerService调用addMonitor()方法把自己添加到了Watchdog的mMonitorChecker对象中,这是Watchdog的一个全局变量,这个全部变量在Watchdog的构造方法中已经事先初始化好并添加到mHandlerCheckers:ArrayList<HandlerChecker>这个监控对象列表中了,mMonitorChecker是一个HandlerChecker类的实例对象,代码如下:

public final class HandlerChecker implements Runnable {
    private final Handler mHandler;
    private final String mName;
    private final long mWaitMax;
    private final ArrayList<Monitor> mMonitors = new ArrayList<Monitor>();
    private boolean mCompleted;
    private Monitor mCurrentMonitor;
    private long mStartTime;

    HandlerChecker(Handler handler, String name, long waitMaxMillis) {
      mHandler = handler;
      mName = name;
      mWaitMax = waitMaxMillis;
      mCompleted = true;
    }

    public void addMonitor(Monitor monitor) {
      mMonitors.add(monitor);
    }

    public void scheduleCheckLocked() {
      if (mMonitors.size() == 0 && mHandler.getLooper().getQueue().isPolling()) {
        // If the target looper has recently been polling, then
        // there is no reason to enqueue our checker on it since that
        // is as good as it not being deadlocked. This avoid having
        // to do a context switch to check the thread. Note that we
        // only do this if mCheckReboot is false and we have no
        // monitors, since those would need to be executed at this point.
        mCompleted = true;
        return;
      }

      if (!mCompleted) {
        // we already have a check in flight, so no need
        return;
      }

      mCompleted = false;
      mCurrentMonitor = null;
      mStartTime = SystemClock.uptimeMillis();
      mHandler.postAtFrontOfQueue(this);
    }

    public boolean isOverdueLocked() {
      return (!mCompleted) && (SystemClock.uptimeMillis() > mStartTime + mWaitMax);
    }

    public int getCompletionStateLocked() {
      if (mCompleted) {
        return COMPLETED;
      } else {
        long latency = SystemClock.uptimeMillis() - mStartTime;
        if (latency < mWaitMax/2) {
          return WAITING;
        } else if (latency < mWaitMax) {
          return WAITED_HALF;
        }
      }
      return OVERDUE;
    }

    public Thread getThread() {
      return mHandler.getLooper().getThread();
    }

    public String getName() {
      return mName;
    }

    public String describeBlockedStateLocked() {
      if (mCurrentMonitor == null) {
        return "Blocked in handler on " + mName + " (" + getThread().getName() + ")";
      } else {
        return "Blocked in monitor " + mCurrentMonitor.getClass().getName()
            + " on " + mName + " (" + getThread().getName() + ")";
      }
    }

    @Override
    public void run() {
      final int size = mMonitors.size();
      for (int i = 0 ; i < size ; i++) {
        synchronized (Watchdog.this) {
          mCurrentMonitor = mMonitors.get(i);
        }
        mCurrentMonitor.monitor();
      }

      synchronized (Watchdog.this) {
        mCompleted = true;
        mCurrentMonitor = null;
      }
    }
  }

HandlerChecker类中的mMonitors也是监控对象列表,这里是监控所有实现了Watchdog.Monitor接口的监控对象,而那些没有实现Watchdog.Monitor接口的对象则会单独创建一个HandlerChecker类并add到Watchdog的mHandlerCheckers监控列表中,当Watchdog线程开始健康那个的时候就回去遍历mHandlerCheckers列表,并逐一的调用HandlerChecker的scheduleCheckLocked方法:

public void scheduleCheckLocked() {
      if (mMonitors.size() == 0 && mHandler.getLooper().getQueue().isPolling()) {
        // If the target looper has recently been polling, then
        // there is no reason to enqueue our checker on it since that
        // is as good as it not being deadlocked. This avoid having
        // to do a context switch to check the thread. Note that we
        // only do this if mCheckReboot is false and we have no
        // monitors, since those would need to be executed at this point.
        mCompleted = true;
        return;
      }

      if (!mCompleted) {
        // we already have a check in flight, so no need
        return;
      }

      mCompleted = false;
      mCurrentMonitor = null;
      mStartTime = SystemClock.uptimeMillis();
      mHandler.postAtFrontOfQueue(this);
    }

HandlerChecker这个类中有几个比较重要的标志,一个是mCompleted,标识着本次监控扫描是否在指定时间内完成,mStartTime标识本次开始扫描的时间mHandler,则是被监控的线程的handler,scheduleCheckLocked是开启本次对与改线程的监控,里面理所当然的会把mCompleted置为false并设置开始时间,可以看到,监控原理就是向被监控的线程的Handler的消息队列中post一个任务,也就是HandlerChecker本身,然后HandlerChecker这个任务就会在被监控的线程对应Handler维护的消息队列中被执行,如果消息队列因为某一个任务卡住,那么HandlerChecker这个任务就无法及时的执行到,超过了指定的时间后就会被认为当前被监控的这个线程发生了卡死(死锁造成的卡死或者执行耗时任务造成的卡死),在HandlerChecker这个任务中:

@Override
    public void run() {
      final int size = mMonitors.size();
      for (int i = 0 ; i < size ; i++) {
        synchronized (Watchdog.this) {
          mCurrentMonitor = mMonitors.get(i);
        }
        mCurrentMonitor.monitor();
      }

      synchronized (Watchdog.this) {
        mCompleted = true;
        mCurrentMonitor = null;
      }
    }

首先遍历mMonitors列表中的监控对象并调用monitor()方法来开启监控,通常在被监控对象实现的monitor()方法都是按照如下实现的:

public void monitor() {
    synchronized (this) { }
  }

即监控某一个死锁,然后就是本次监控完成,mCompleted设置为true,而当所有的scheduleCheckLocked都执行完了之后,Watchdog就开始wait,而且一定要wait for 30s,这里有一个实现细节:

long start = SystemClock.uptimeMillis();
        while (timeout > 0) {
          if (Debug.isDebuggerConnected()) {
            debuggerWasConnected = 2;
          }
          try {
            wait(timeout);
          } catch (InterruptedException e) {
            Log.wtf(TAG, e);
          }
          if (Debug.isDebuggerConnected()) {
            debuggerWasConnected = 2;
          }
          timeout = CHECK_INTERVAL - (SystemClock.uptimeMillis() - start);
        }

原先,我看到这段代码的时候,首先关注到SystemClock.uptimeMillis()在设备休眠的时候是不计时的,因此猜测会不会是因为设备休眠了,wait也停止了,Watchdog在wait到15s的时候设备休眠了,并且连续休眠30分钟后才又被唤醒,那么这时候wait会不会马上被唤醒,答案是:正常情况下wait会继续,知道直到剩下的15s也wait完成后才会唤醒,所以我疑惑了,于是查看下下Thread的wait()方法的接口文档,终于找到如下解释:

A thread can also wake up without being notified, interrupted, or
   * timing out, a so-called <i>spurious wakeup</i>. While this will rarely
   * occur in practice, applications must guard against it by testing for
   * the condition that should have caused the thread to be awakened, and
   * continuing to wait if the condition is not satisfied. In other words,
   * waits should always occur in loops, like this one:
   * <pre>
   *   synchronized (obj) {
   *     while (<condition does not hold>)
   *       obj.wait(timeout);
   *     ... // Perform action appropriate to condition
   *   }
   * </pre>

大致意思是说当Thread在wait的时候除了会被主动唤醒(notify或者notifyAll),中断(interrupt),或者wait的时间到期而唤醒,还有可能被假唤醒,而这种假唤醒在实践中发生的几率非常低,不过针对这种假唤醒,程序需要通过验证唤醒条件来区分线程是真的唤醒还是假的唤醒,如果是假的唤醒那么就继续wait直到真唤醒,事实上,在我们实际的开发过程中确实要注意这种微小的细节,可能99%的情况下不会发生,但是要是遇到1%的情况发生之后,那么这个问题将会是非常隐晦的,而且在查找问题的时候也会变得很困难,很奇怪,为什么线程好好的wait过程中突然被唤醒了呢,甚至可能怀疑我们以前对于线程wait在设备休眠状态下的执行情况?,废话就扯到这里,继续来研究Watchdog机制,在Watchdog等待30s之后会调用evaluateCheckerCompletionLocked()方法来检测被监控对象的运行情况:

private int evaluateCheckerCompletionLocked() {
    int state = COMPLETED;
    for (int i=0; i<mHandlerCheckers.size(); i++) {
      HandlerChecker hc = mHandlerCheckers.get(i);
      state = Math.max(state, hc.getCompletionStateLocked());
    }
    return state;
  }

通过调用HandlerChecker的getCompletionStateLocked来获取每一个HandlerChecker的监控状态:

public int getCompletionStateLocked() {
      if (mCompleted) {
        return COMPLETED;
      } else {
        long latency = SystemClock.uptimeMillis() - mStartTime;
        if (latency < mWaitMax/2) {
          return WAITING;
        } else if (latency < mWaitMax) {
          return WAITED_HALF;
        }
      }
      return OVERDUE;
    }

从这里,我们就看到了其实是通过mCompleted这个标志来区分30s之前和30s之后的不通状态,因为30s之前对被监控的线程对应的Handler的消息对了中post了一个HandlerChecker任务,然后mCompleted = false,等待了30s后,如果HandlerChecker被及时的执行了,那么mCompleted = true表示任务及时执行完毕,而如果发现mCompleted = false那就说明HandlerChecker依然未被执行,当mCompleted = false的时候,会继续检测HandlerChecker任务的执行时间,如果在唤醒状态下的执行时间小于30秒,那重新post监控等待,如果在30秒到60秒之间,那就会dump出一些堆栈信息,然后重新post监控等待,当等待时间已经超过60秒了,那就认为这是异常情况了(要么死锁,要么耗时任务太久),这时候就会搜集各种相关信息,例如代码堆栈信息,kernel信息,cpu信息等,生成trace文件,保存相关信息到dropbox文件夹下,然后杀死该进程,到这里监控就结束了

Watchdog线程卡顿监控实现

之前我们提到Watchdog监控的实现是通过post一个HandlerChecker到线程对应的Handler对的消息对了中的,而死锁的监控对象都是保存在HandlerChecker的mMonitors列表中的,所以外部调用addMonitor()方法,最终都会add到Watchdog的全局变量mMonitorChecker中的监控列表,一次所有线程的死锁监控都由mMonitorChecker来负责实现,那么对于线程耗时任务的监控,Watchdog是通过addThread()方法来实现的:

public void addThread(Handler thread) {
    addThread(thread, DEFAULT_TIMEOUT);
  }

  public void addThread(Handler thread, long timeoutMillis) {
    synchronized (this) {
      if (isAlive()) {
        throw new RuntimeException("Threads can't be added once the Watchdog is running");
      }
      final String name = thread.getLooper().getThread().getName();
      mHandlerCheckers.add(new HandlerChecker(thread, name, timeoutMillis));
    }
  }

addThread()方法实际上是创建了一个新的HandlerChecker对象,通过该对象来实现耗时任务的监控,而该HandlerChecker对象的mMonitors列表实际上是空的,因此在执行任务的时候并不会执行monitor()方法了,而是直接设置mCompleted标志位,所以可以这么解释:Watchdog监控者是HandlerChecker,而HandlerChecker实现了线程死锁监控和耗时任务监控,当有Monitor对象的时候就会同时监控线程死锁和耗时任务,而没有Monitor的时候就只是监控线程的耗时任务造成的卡顿

Watchdog监控流程

理解了Watchdog的监控流程,我们可以考虑是否把Watchdog机制运用到我们实际的项目中去实现监控在多线程场景中重要线程的死锁,以及实时监控主线程的anr的发生?当然是可以的,事实上,Watchdog的在framework中的重要作用就是监控主要的系统服务器是否发生死锁或者发生卡顿,例如监控ActivityManagerService,如果发生异常情况,那么Watchdog将会杀死进程重启,这样可以保证重要的系统服务遇到类似问题的时候可以通过重启来恢复,Watchdog实际上相当于一个最后的保障,及时的dump出异常信息,异常恢复进程运行环境

对于应用程序中,健康那个重要线程的死锁问题实现原理可以和Watchdog保持一致

对于监控应用的anr卡顿的实现原理可以从Watchdog中借鉴,具体实现稍微有点不一样,Activity是5秒发生anr,Broadcast是10秒,Service是20秒,但是实际四大组件都是运行在主线程中的,所以可以用像Watchdog一样,wait 30秒发起一次监控,通过设置mCompleted标志位来检测post到MessageQueue的任务是否被卡住并未及时的执行,通过mStartTime来计算出任务的执行时间,然后通过任务执行的时间来检测MessageQueue中其他的任务执行是否存在耗时操作,如果发现执行时间超过5秒,那么可以说明消息队列中存在耗时任务,这时候可能就有anr的风险,应该及时dump线程栈信息保存,然后通过大数据上报后台分析,记住这里一定是计算设备活跃的状态下的时间,如果是设备休眠,MessageQueue本来就会暂停运行,这时候其实并不是死锁或者卡顿

WatchDog机制的anr在线监控实现与demo

anrmonitor/anrmonitor at master · liuhongda/anrmonitor · GitHub

Watchdog机制总结

每一个线程都可以对应一个Looper,一个Looper对应一个MessageQueue,所以可以通过向MessageQueue中post检测任务来预测该检测任务是否被及时的执行,以此达到检测线程任务卡顿的效果,但是前提是该线程要先创建一个Looper

Watchdog必须独自运行在一个单独的线程中,这样才可以监控其他线程而不互相影响

使用Watchdog机制来实现在线的anr监控可能并不能百分百准确,比如5秒发生anr,在快到5秒的临界值的时候耗时任务正好执行完成了,这时候执行anr检测任务,在检测任务执行过程中,有可能Watchdog线程wait的时间也到了,这时候发现检测任务还没执行完于是就报了一个anr,这是不准确的;另一种情况可能是5秒anr已经发生了,但是Watchdog线程检测还没还是wait,也就是anr发生的时间和Watchdog线程wait的时间错开了,等到下一次Watchdog线程开始wait的时候,anr已经发生完了,主线程可能已经恢复正常,这时候就会漏掉这次发生的anr信息搜集,所以当anr卡顿的时间是Watchdog线程wait时间的两倍的时候,才能完整的扫描到anr并记录,也就是说Watchdog的wait时间为2.5秒,这个在实际应用中有点过于频繁了,如果设备不休眠,Watchdog相当于每间隔2.5秒就会运行一下,可能会有耗电风险

评论 1
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值