Android system_server中watchdog机制介绍（下）

[TOC]

回顾： 从上篇文章中，我们主要从问题角度描述了我们system_server中watchdog的原理，粒度是很粗糙的。简单可以概况为下面三点：

• 关键服务对象锁不能被某线程异常长时间占用——问题1

• 系统关键线程不能长时间只执行一个单一逻辑，避免后面的消息阻塞——问题2

• 当监测到上面异常时，我们根据异常时间长短来决策是否重启手机，并且根据异常时间我们针对性的输出日志，让程序员根据log解决异常。

  本篇文章，我们再进一步将上述三点内容，进一步细化以及列举一些常见的案例。

1. 关键线程异常

system_server中的众多模块功能，离不开system_server中各个线程的执行，system_server中线程组成如下：

如上虚线框内的线程中我们主要关注关键线程（绿色部分线程），他们的职能如同名字一样，服务模块如果处理例如io，显示等职能事务，可以将事务专门交给这些关键线程。而不是将所有事务都交给模块线程来处理。这些关键线程就像我们生活中的公共交通工具火车、地铁、公交一样在system_server中扮演着重要的作用。

1.1 关键线程具体有哪些?

我们通过系统源码查看可以查看，我们主要监测着下面表格中这些线程：

关键线程名	作用
main	主线程（优先级：-2）
android.ui	处理系统进程UI相关的事务（优先级：-2）
android.io	文件读写相关的事务（优先级：0）
android.display	处理系统显示事务相关（优先级：-3）
android.anim	处理系统动画相关的事务（优先级：-4）
android.anim.lf	处理系统动画相关和Vsync相关（优先级：-4）
android.fg	前台公共线程（优先级：0）
android.bg	后台公共线程（优先级：10）
watchdog.monitor	用来check关键服务锁情况（优先级：0）
服务模块线程	服务模块逻辑线程
ActivityManager:starter	AMS进程创建相关线程
RollbackManagerServiceHandler	回滚相关线程
PermissionManager	权限管理线程
PowerManagerService	电量/源管理服务线程
PackageManagerService	包管理服务线程
可根据问题自主添加

1.2 watchdog中添加线程监控方法：

模块代码中使用 Watchdog.getInstance().addThread(..)

2. 关键服务异常

具体的监测服务如下，100多个服务为什么选择这几个服务呢？这里我们不得而知，但是可想而知的是，随之系统的迭代以及项目的不断开发，系统中会遇到各种各样的问题，会根据问题的分类，增加新的监测模块。

• StorageManagerService
• MediaProjectionManagerService
• MediaRouterService
• InputManagerService
• PowerManagerService
• WindowManagerService
• ActivityManagerService
• BatteryStatsService
• BinderThreadMonitor(补充) 目前系统中监测的服务为上面的这些服务，当然如果我们往system_server中添加新的重要服务，我们也可以将该服务添加到监控中去。

2.1 监控关键服务的方法：

我们添加重要的模块/服务到system_server中，可以通过以下方法添加到watchdog监控中去。

1. 实现Watchdog.Monitor接口中的 monitor() 方法，方法中实现本模块认为异常的监测逻辑。
2. 模块代码调用 Watchdog.getInstance().addMonitor(this)。

2.2 Binder线程监测补充

在system_server中Binder线程（下图橙色部分）作为应用进程和system_server交互的桥梁，并且system_server作为整个Android系统中Binder线程数量最多的进程，Binder线程资源多并且十分重要。

问题：会不会出现所有Binder线程都阻塞到某个逻辑，导致其他应用进程访问system_server却没有Binder线程处理事务？

是会这样的，所有要对这种异常情况进行监控。我们就可以使用上面的 2.1 中方法添加到watchdog监控中去。

我们可以根据2.1的步骤可以看一下代码：

 //frameworks/base/services/core/java/com/android/server/Watchdog.java
    1. 现Watchdog.Monitor接口中的 `monitor()` 方法，方法中实现本模块认为异常的监测逻辑
    private static final class BinderThreadMonitor implements Watchdog.Monitor {
        @Override
        public void monitor() {
            Binder.blockUntilThreadAvailable();
        }
    }
	2. 模块代码调用  `Watchdog.getInstance().addMonitor(this)`
	addMonitor(new BinderThreadMonitor())

monitor方法具体实现： 如果所有Binder线程都在阻塞（正常来说不可能所有Binder线程都长时间阻塞的），那么打印异常日志并且一直等待阻塞，阻塞将会被watchdog监测到，持续异常将触发重启。

void IPCThreadState::blockUntilThreadAvailable()
{
   pthread_mutex_lock(&mProcess->mThreadCountLock);
   mProcess->mWaitingForThreads++;
   while (mProcess->mExecutingThreadsCount >= mProcess->mMaxThreads) {
       ALOGW("Waiting for thread to be free. mExecutingThreadsCount=%lu mMaxThreads=%lu\n",
               static_cast<unsigned long>(mProcess->mExecutingThreadsCount),
               static_cast<unsigned long>(mProcess->mMaxThreads));
       pthread_cond_wait(&mProcess->mThreadCountDecrement, &mProcess->mThreadCountLock);
   }
   mProcess->mWaitingForThreads--;
   pthread_mutex_unlock(&mProcess->mThreadCountLock);
}

3. 异常监测的衡量

在对于问题1、2的详细阐述后我们可以得到下面这个图片：

watchdog线程给各个关键线程发送一条消息，各个关键线程在规定时间内处理完该消息，那么watchdog线程认为系统正常。如果规定时间内无法处理完该消息，那么认为系统异常。 问题： 那么这个规定时间是多少呢？

答案是：30s，每隔30s发送一条消息，如果超过30s各个关键线程没有处理完消息，系统将会打印对应的日志。

问题：假如system_server异常后不能长时间卡住，用户无法忍受，如何处理？

超过第二个30s（即一分钟），消息还未被处理完成，重启系统，让用户能恢复手机使用。

当然有人会问为什么是30s？这里无从考证，个人猜测一方面可能是用户的体验不能卡住太久，另一方面是时间一分钟=60s=两个30s，便于编码。

经过第三点的补充后我们得到了下面完整的框架图片：

图片解读:

1. system_server中watchdog线程每隔30s给各个关键线程发送一条消息，消息内容：设置一个标志位，代表处理完成。
2. Binder线程是否空余，以及各个关键服务的对象锁是否被异常持有，由watchdog.monitor线程进行检测，检测方式：逐一调用各个模块实现的monitor方法即可，monitor接口是否阻塞则决定各个模块是否异常。
3. 如果>30s 存在消息没有被处理完，watchdog线程要输出log，将异常点体现在日志中。
4. 如果>60s 存在消息没有被处理完，watchdog线程要输出log，将异常点体现在日志中，并且重启system_server进程。

4. 日志的输出

在超时30s消息没有被处理完，在 events log 我们能看到下面这条log：

07-26 09:31:29.795 1453 1578 I Watchdog: WAITED_UNTIL_PRE_WATCHDOG

在在超时60s消息没有被处理完，在 events log 我们能看到下面这条相似的log：

07-26 09:32:15.586  1453  1578 E Watchdog: **SWT happen **Blocked in monitor com.android.server.am.ActivityManagerService on monitor thread (watchdog.monitor) for 60s

光凭借这点log我们程序员可无法准确的定位出问题，我们的目的只有一个:输出log要能让程序员定位到问题。

4.1 问题： 我们还需要输出哪些log？

4.1.1 system_server 自身堆栈信息

system_server 中存在的问题很可能就是上图的情况，可能还比上图更为杂乱，各个线程间相互等待，相互等锁等等，我们最直观能看到问题点就是将system_server中各个的线程的堆栈dump出来，通过堆栈找出问题点。

• 输出日志：dump出 system_server中各个线程的堆栈信息

4.1.2 system_server 关联进程堆栈信息

对于system_server进程而言，除了自身进程之外，system_server进程还会和其他进程交互，这里尤其指的是服务模块进程，万一我们system_server中的线程阻塞在这些其他进程上怎么办？

所以我们需要dump出和system_server交互频繁的这些服务进程的线程堆栈。native 层服务进程，以及hal层服务进程，以及Java层的匿名Binder服务进程等等：

• 例如：native/hal层服务进程 : SF、Netd、audio模块、sensor模块等。

• 例如：Java层匿名Binder服务进程: com.android.phone、com.google.android.providers.media.module等。

• 输出日志： dump出和system_server交互频繁的服务进程的线程堆栈

我们能从watchdog代码中看到下面的这些需要dump的进程的信息：

这里的信息也是随着项目产品不断迭代，出现问题后，不断往上添加的一个过程。例如你在项目中遇到问题指向某个服务进程并且排查问题时候这个服务进程没有被dump出来，你就可以在上面代码中添加。

4.1.3 kernel异常进程信息

上面我们主要dump的都是用户态的堆栈信息，但是我们还需要想一个点——问题：内核模块会不会异常？

会的，我们还是从上上个图中来看，底层的一些重要的服务是依赖于kernel中的一些驱动模块的，除了我们常知道内存、cpu、gpu等还有tp/屏显/sensor等等一些内核模块，也是会出现异常的进而间接会影响到system_server中的模块。所以我们需要dump出内核模块中异常的堆栈信息。

但是怎么判断内核异常模块进程呢？

• TASK_UNINTERRUPTIBLE：不可中断休眠，长时间的不可中断休眠状态的线程则很容易出现阻塞问题，进而引发SWT问题
• 进程状态：D状态

不可中断休眠状态进程的特点：

• 不接受中断（软/硬）signal信号等，只等待想等待的事情完成。
• 常见场景：有 Swap 读数据、信号量机制、mutex 锁、内存慢路径回收等场景。 (参考：elixir.bootlin.com/linux/v6.16…)

dump方式：echo w > /proc/sysrq-trigger 类似：

4.1.4 小结

上述就是我们需要dump出来的log信息，但是还缺一样log，在Android系统中服务进程间通信方式使用的的是Binder通信，所以我们要知道A进程中的A1线程和B进程中B1线程是否存在通信的关系，我们需要dump Binder通信的log信息。 位置：/dev/binderfs/binder_logs/transactions或者/sys/kernel/debug/binder目录下。 所需的日志如下：

• system_server自身线程堆栈信息
• 与system_server关联其他服务端进程信息
• kernel异常状态进程堆栈信息
• Binder进程间交互信息

如下图：

4.2 日志解读

我们在分析SWT 问题时候，通常来说是按照下面的log进行分析的：

• 红色部分日志：先从events system 这些log中确定system_server中遭遇了哪类问题？是问题一还是问题二。
• 蓝色部分日志：进而从dump的堆栈信息（不管是kernel还是用户态其他进程）分析异常模块。
• 绿色日志：Binder交互信息作为辅助，借助交互信息可以得知各个阻塞模块的联系。

4.2.1 events system 日志解读

events log中下面两条log分别是在异常大于30s，大于60s两个时间节点输出

07-26 09:31:29.795  1453  1578 I Watchdog: WAITED_UNTIL_PRE_WATCHDOG
07-26 09:32:15.586  1453  1578 E Watchdog: **SWT happen **Blocked in monitor com.android.server.am.ActivityManagerService on monitor thread (watchdog.monitor) for 60s

第二条log会直接指出出现的异常是那种类型，也就是我们之前分析的问题一或者问题二，当前的log表明，watchdog.monitor 线程想要去获取ActivityManagerService的对象锁，很遗憾超过60s都没有获取到，说明问题点是：AMS这个模块中的对象锁被某个线程异常长时间持有，有可能是线程逻辑阻塞，也有可能是线程死锁。

上述的第二条log信息是比较重要的，直接为为我们指明了排查方向，第二条log还有其他好几种形式，但是log的模板基本上只有两种，因为我们要检测的问题基本上就两个：

• Blocked in handler on 关键线程名 thread (关键线程)——问题2
• Blocked in monitor 关键服务对象 on monitor thread (watchdog.monitor)——问题1

关键线程名	关键服务对象
线程名	关键服务对象
main	StorageManagerService
android.ui	MediaRouterService
android.io	InputManagerService
android.display	WindowManagerService
android.anim	ActivityManagerService
android.anim.lf	BatteryStatsService
android.fg	BinderThreadMonitor
android.bg	...
watchdog.monitor
ActivityManager:starter，RollbackManagerServiceHandler，PermissionManager，PowerManagerService，PackageManagerService

打印的log只是上面表格中列出来的一种或者多种组合。 例如：下面的日志中所有问题都囊括了

• 关键服务AMS服务的对象锁被异常持有。
• 关键线程 android.fg、main、android.io、android.display、android.anim阻塞
• 没有空闲Binder线程。

排查的时候我们使用一条线索往下排查就行，往往是各个问题相互杂糅相互影响的（目前没有遇到过几个问题点是分开的这种问题）。

在system log 中会打印下面这样的log：

W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.am.ActivityManagerService on monitor thread (watchdog.monitor) for 60s
W Watchdog: watchdog.monitor annotated stack trace:
W Watchdog:     at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:18216)
W Watchdog:     - waiting to lock <0x0bcefae9> (a com.android.server.am.ActivityManagerService)
W Watchdog:     at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:398)
W Watchdog:     at android.os.Handler.handleCallback(Handler.java:959)
W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:100)
W Watchdog:     at android.os.Looper.loopOnce(Looper.java:232)
W Watchdog:     at android.os.Looper.loop(Looper.java:317)
W Watchdog:     at android.os.HandlerThread.run(HandlerThread.java:85)
W Watchdog:     at com.android.server.ServiceThread.run(ServiceThread.java:46)
W Watchdog: *** GOODBYE!

log会打印出阻塞的关键线程的堆栈信息（有时候受负载影响可能不准，但是可以作为参考），如上能看到AMS对象锁的地址，会打印出GOODBYE关键字。

除此之外在system log中还会打印出现SWT先后dump两次trace文件的名称，给我们指明下一步排查的文件的位置（这里比较关键，有的伙伴分析问题直接就随便点开一个anr_xx就开始排查，可能看的trace文件都不对，这会影响问题的分析结果）。

ActivityManager: Dumping to /data/anr/anr_2025-07-26-09-32-16-000 （可以在system log中检索Dumping to 这个关键字，anr问题的分析也是如此）。

4.2.2 trace 文件概要解读

SWT以及ANR问题都会将进程的线程堆栈信息dump出来，文件保存到data/anr目录下面。区别在于SWT问题trace文件dump的进程较多，ANR问题dump的trace文件进程较少（通常只是ANR进程本身以及system_server进程）。 通常来说trace文件主要包括以下几部分内容：

Subject: Blocked in monitor com.android.server.am.ActivityManagerService on monitor thread (watchdog.monitor) for 15s
--- CriticalEventLog ---
capacity: 20
timestamp_ms: 1753493489805
window_ms: 300000

----- dumping pid: 1453 at 156092124
proc 1453
context binder
  thread 2538: l 01 need_return 0 tr 0
    incoming transaction 8113988: 0000000000000000 from 16729:16729 to 1453:2538 code 5f434d44 flags 10 pri 0:120 r1 elapsed 29819ms node 5247 size 148:40 offset 0
  buffer 8113988: 0 size 148:40:0 active

----- pid 1453 at 2025-07-26 09:31:33.233489611+0800 -----
Cmd line: system_server
Build fingerprint: xxxx
ABI: 'arm64'
Build type: optimized
Debug Store: 1,0,156092154::
suspend all histogram:	Sum: 64.207ms 99% C.I. 3us-7449.600us Avg: 369.005us Max: 22931us
DALVIK THREADS (226):
"watchdog.monitor" prio=5 tid=12 Blocked
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x2016da8 self=0x8b0000598a4b8000
  | sysTid=1570 nice=-2 cgrp=foreground sched=0/0 handle=0x7001af0730
  | state=S schedstat=( 14628587427 2412564438 42408 ) utm=581 stm=880 core=0 HZ=100
  | stack=0x70019ed000-0x70019ef000 stackSize=1037KB
  | held mutexes=
  at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:18216)
  - waiting to lock <0x0bcefae9> (a com.android.server.am.ActivityManagerService) held by thread 57
  at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:398)
  at android.os.Handler.handleCallback(Handler.java:959)
  at android.os.Handler.dispatchMessage(Handler.java:100)
  at android.os.Looper.loopOnce(Looper.java:232)
  at android.os.Looper.loop(Looper.java:317)
  at android.os.HandlerThread.run(HandlerThread.java:85)
  at com.android.server.ServiceThread.run(ServiceThread.java:46)
DumpLatencyMs: 102.166

anr_XXX.txt 包含log	含义、作用
Subject:XXX	当前的这个anr_xx.txt是什么原因被dump出来
CriticalEventLog	记录在此之前发生过的关键性异常事件（anr等）
dumping pid XX（关键）	binder交互信息（/dev/binderfs/binder_logs/transactions）
Cmd line: 进程名 （关键）	对应进程的各个线程的堆栈信息
Waiting Channels: pid XX	XX进程各线程的内核函数接口
等等

分析问题时我们主要关注Binder 交互信息以及各进程的各线程的堆栈信息。

4.2.3 trace 文件解读-线程堆栈信息

"ReferenceQueueDaemon" daemon prio=5 tid=6 Waiting
  | group="system" sCount=1 ucsCount=0 flags=1 obj=0x20030b8 self=0x730000598a472000
  | sysTid=1557 nice=4 cgrp=foreground sched=0/0 handle=0x70496d0730
  | state=S schedstat=( 1359509621 111263835 448 ) utm=110 stm=25 core=6 HZ=100
  | stack=0x70495cd000-0x70495cf000 stackSize=1037KB
  | held mutexes=
  at java.lang.Object.wait(Native method)
  - waiting on <0x0e053311> (a java.lang.Class<java.lang.ref.ReferenceQueue>)
  at java.lang.Object.wait(Object.java:405)
  at java.lang.Object.wait(Object.java:543)
  at java.lang.Daemons$ReferenceQueueDaemon.runInternal(Daemons.java:260)
  - locked <0x0e053311> (a java.lang.Class<java.lang.ref.ReferenceQueue>)
  at java.lang.Daemons$Daemon.run(Daemons.java:132)
  at java.lang.Thread.run(Thread.java:1119)
DumpLatencyMs: 90.8357

• 第1行：
  • 线程名：ReferenceQueueDaemon
  • daemon：有此则代表守护线程（生命周期和进程的生命周期一样长）
  • prio：（Priority）线程优先级
  • tid：线程在进程内的序号（主线程tid=1，其他线程依次递增）
  • Waiting：线程状态（Java层面）常见还有Native、TimedWaiting、Sleeping、Blocked、Runnable。
• 第2行：
  • group：线程所属的线程组，Java代码遗漏下来的，没有什么实际作用。
  • sCount：Suspend Count 线程挂起次数（这里是art runtime 垃圾回收中的概念：GC时，要将线程挂起，执行GC操作）。
  • ucsCount：用户主动使用代码导致线程挂起的次数（区别于sCount，这里主动调用代码挂起，前者是ART机制）。
  • obj：保存着当前线程关联Java线程的对象地址（在虚拟机中从线程是以native的形式c++层thread存在，native线程要想访问java对象必须先保存Java线程对象的地址）。
  • self：当前线程的地址
• 第3行：
  • sysTid：线程号
  • nice：调度优先级
  • cgrp=foreground：cgroup中进程所属调度组(常见有：foreground、top-app等)
  • sched=0/0：调度策略（0 ：SCHED_NORMAL（也叫 SCHED_OTHER，普通时间共享，最常见）1 ：SCHED_FIFO（实时，先入先出）2 ：SCHED_RR（实时，轮询）3 ：SCHED_BATCH（批量）5 ：SCHED_IDLE（空闲线程）6 ：SCHED_DEADLINE（实时 deadline））。
  • handle：native线程句柄
• 第4行：
  • state=S ：线程内核级别的调度状态（区别于运行时的线程状态，常见：Z：僵尸、D：不可中断休眠、S：可中断休眠、R：运行、T：停止）。
  • schedstat=( 1359509621 111263835 448 )：CPU调度时间统计（Running运行时间、Runable等待调度时间、SwitchCPU调度切换次数）， 见proc/[pid]/task/[tid]/schedstat.。在分析两份trace文件堆栈前后是否一致，是否卡死到同一位置，我们可以拿这几个值作为参考。
  • utm=110 ：线程在用户态所执行的时间
  • stm=25 ：线程在内核态所执行的时间
  • core=6 ：线程最后运行所在CPU的核
  • HZ=100：时钟频率
• 第5行：
  • stack=0x70495cd000-0x70495cf000：线程栈的地址空间
  • stackSize=1037KB：栈大小
• 第6行：held mutexes：线程持有的mutexes
• 第7行：往下就是线程的调用堆栈：

从问题排查的角度我们第一眼主要看到的是线程的状态（运行时）

• Native：运行native层代码
• Waiting：线程等待
• TimedWaiting：线程定时等待
• Sleeping：线程主动Sleep
• Blocked：等待锁资源释放
• ...

根据状态再看线程的调用栈，来确认是否是该线程中执行的代码逻辑有问题。

线程的调用堆栈反应线程此时在执行什么代码，那么在一个良好运作的系统中，线程的调用堆栈是什么样的呢？ 在Android系统中和线程图中描述的一样并没有那么复杂,有一些基础功能的线程,有Binder线程,有普通的线程池线程。总体来说，除了一些基础功能的守护线程之外，其他线程模型主要有两种：

• 通过epoll机制监测fd封装的线程模型。
• Binder线程循环通过系统调用ioctl不断从Binder驱动读取消息线程模型。
• 其他

//epoll 机制线程模型--正常等待新消息的到来
  native: #00 pc 000b5ff8  /apex/com.android.runtime/lib64/bionic/libc.so (__epoll_pwait+8) 
  native: #01 pc 00018c2c  /system/lib64/libutils.so (android::Looper::pollInner+188)
  native: #02 pc 00018b0c  /system/lib64/libutils.so (android::Looper::pollOnce+124) 
  native: #03 pc 0018b67c  /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce+44) 
  at android.os.MessageQueue.nativePollOnce(Native method)
  at android.os.MessageQueue.next(MessageQueue.java:335)
  at android.os.Looper.loopOnce(Looper.java:194)
  at android.os.Looper.loop(Looper.java:338)
  at android.os.HandlerThread.run(HandlerThread.java:67)
 //Binder 线程模型--正常读取Binder驱动消息
  native: #00 pc 000b5038  /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+8)
  native: #01 pc 000670ac  /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156)
  native: #02 pc 0005f4e4  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver+292) 
  native: #03 pc 000600c8  /system/lib64/libbinder.so (android::IPCThreadState::getAndExecuteCommand+24) 
  native: #04 pc 00060cfc  /system/lib64/libbinder.so (android::IPCThreadState::joinThreadPool+732) 
  native: #05 pc 0006ae08  /system/lib64/libbinder.so (android::PoolThread::threadLoop+24) 
  native: #06 pc 000144dc  /system/lib64/libutils.so (android::Thread::_threadLoop+284) 
  native: #07 pc 000ec29c  /system/lib64/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell+140)
  native: #08 pc 000c9fd0  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start+208)
  native: #09 pc 0005dd90  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64) 
  

我们看到上面两种线程模型的堆栈信息，就是正常的运行形态。对于Binder线程来说，如果线程在等对端返回，通常在talkWithDriver往前的堆栈会调用到涉及对端的一些代码。 例如：

4.2.4 Binder日志解读

1.binder transaction信息 在我们查看Binder交互log中，我们经常看到的就是incoming transaction和outgoing transaction，他们的含义是什么呢？ 这其实内Binder驱动中Binder交互事务的描述。

• outgoing transaction--客户端保存，客户端向服务端发起的binder事务请求。
• incoming transaction--服务端保存，服务端返回给客户端的binder事情请求。

他们均指向一个binder_transaction，他们均能保存到线程指向的信息。 如下例子: 无论是outgoing transaction还是incoming transaction，他们都是指向7640493这个是kernel中binder_transaction的标识。

//客户端进程
proc 27226
context binder
  thread 27226: l 10 need_return 0 tr 0
    outgoing transaction 7640493: 0000000000000000 from 27226:27226 to 1467:3206 code 5f434d44 flags 10 pri 0:120 r1 elapsed 126772ms

//服务端进程
proc 1467
context binder
  thread 3206: l 01 need_return 0 tr 0
    incoming transaction 7640493: 0000000000000000 from 27226:27226 to 1467:3206 code 5f434d44 flags 10 pri 0:120 r1 elapsed 126772ms 

• from 27226:27226 to 1467:3206 --from:进程27226中线程27226作为客户端访问， to:服务端进程1467线程3206线程。
• elapsed: 访问阻塞时间。
• 还有很多其他信息，后面我们剖析Binder驱动再做说明。

2.kernel中的binder: release

从上面信息我们知道binder_transaction中保存着线程指向信息，那么拿到这个信息就可以知道线程指向。我们可以在kernel log中看到这样的打印，也能找到对端信息。 当客户端进程27226被kill后，binder驱动会将对应的binder_transaction释放掉，所以检索transaction的id(7640493)就能找到binder对端线程为: 1467_16即:sysTid=3206。

[147603.943970] [T1726663] kworker/7:2: binder: release 27226:27226 transaction 7640493 out, still active
[147603.949150] [T1003206] binder:1467_16: binder: send failed reply for transaction 7640493, target dead

"binder:1467_16" prio=5 tid=223 Native
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x3217730 self=0xb1000050bcbc4000
  | sysTid=3206 nice=0 cgrp=foreground sched=0/0 handle=0x729ebd3730
  | state=S schedstat=( 3960678864 3521264239 5438 ) utm=298 stm=97 core=0 HZ=100
  | stack=0x729eadc000-0x729eade000 stackSize=989KB
  | held mutexes=
....

以上就是输出log的一些解析。

5. 案例

以下是一些分析解决过的问题案例log。

5.1 system_server线程死锁

该例子中两次trace持锁情况如下，排查代码为客制化代码错误移到synchronized (mGlobalLock) {...}中导致。

lock	tid=203	tid=296
0x0ee759b0	waiting lock <0x0ee759b0>	locked <0x0ee759b0>
0x058d9a40	locked <0x058d9a40>	waiting lock <0x058d9a40>
上面表格锁的情况刚好形成一个死循环称为死锁。

5.2 system_server和phone进程死锁

//binder log
outgoing transaction 25633452: 0000000000000000 from 2937:2937 to 1937:5077 code 3a flags 10 pri 0:120 r1

binder: release 1937:3234 transaction 25632946 out, still active 
binder: release 2937:3605 transaction 25632946 in, still active 
binder: send failed reply for transaction 25632946, target dead

该例中两份trace文件均如此。

进程
system_server	binder:1937_16线程(sysTid=5077)	等待→	binder:1937_E线程(tid=290)sysTid=3234
	↑等待		↓等待
phone进程	main线程(sysTid=2937)	←等待	binder:2937_A线程(tid=70)sysTid=3605

5.3 audio进程和system_server进程间死锁

audio进程和system_server进程死锁导致Binder线程阻塞在其中出现Binder线程耗尽。

----------------------时间:20:21:45 system_server进程 binder线程不够用 ---最早出现的时间
10-17 20:21:45.931 1619 1805 W IPCThreadState: Waiting for thread to be free. mExecutingThreadsCount=32 mMaxThreads=31

排查发现trace中所有Binder线程均在等待WMS服务的锁:WindowManagerGlobalLock((蓝色部分)，对应4633线程持有该锁在访问Audio模块的 isStreamActive 方法。

[ 95.581437] [T600160] binder: release 855:984 transaction 93929 in, still active [ 95.581471] [T600160] binder: send failed reply for transaction 93929 to 1619:4633

进一步排查发现,audio发生了NE(在audio中有binder超时监测机制，当超时到达超时直接会直接NE，进程重启)。 在main log的audio打印中日志中发现audio进程中的984线程执行 isStreamActive 似乎在等锁 Mutex::Autolock _l(mLock)。

进一步我们发现main log中audio模块还有相关持有 Mutex::Autolock _l(mLock) 的堆栈信息,audio进程中的2945线程执行listAudioPorts 方法持锁 Mutex::Autolock _l(mLock) 并通过 mustAnonymizeBluetoothAddress 需要进一步访问system_server的权限管理服务。

上述流程存在audio和system_server进程间死锁情况。

5.4 堆栈看似相同实则不同,耗时异常

前后两次dump的trace文件阻塞点,粗略看一致(绿色部分)，仔细看堆栈不一致(其他颜色部分)， 客制化代码耗时导致。

5.5 三把锁导致的死锁

主线程tid=1等待线程378紫色的锁。

线程378等待线程369红色的锁。

线程369等待线程1蓝色的锁。

5.6 kernel模块异常

system_server中动画线程等待Binder对端返回,从代码来看对端未SF进程。

查看对应接口,发现SF线程1247等待主线程775。

SF主线程等待Binder对端返回对端为728线程,查看堆栈,发现未能dump出来。

最后查看kernellog中dump出来的kernel异常D状态进程信息,发现728存在D状态阻塞再模块A,需要模块A排查异常。

6. 总结

通过两篇文章，SWT问题中的watchdog原理我们基本上已经梳理清楚。文章开始围绕着system_server中存在的两个问题开始讲起，以及到后面的不断补充完善，提及输入的日志，分析了输出的日志信息，并且根据日志提供了遇到过的一些SWT案例分析日志来阐述system_server中的watchdog原理。总结为以下几点：

• 问题一细化
• 问题二细化
• 日志讲解
• 案例分析

最后再提出一个问题： system_server中存在的问题，使用一个watchdog线程来做监控，大家有没有想过万一watchdog线程异常了怎么办（虽然概率小，但还是存在）？watchdog线程监控功能不就失效了吗？手机还是会一直卡死。那么怎么解决这个新问题或者怎么监控这个问题？

难道我们我们再使用一个system_server中的线程A来监测吗？万一线程A又异常了怎么办？使用线程B...C... 虽然问题概率低，并且上面的方式不行，但是我们还是得监控。我们能否使用一个内核的进程/模块来监控它呢？ ——可行，MTK:Hang_detect机制、展锐：Native_Hang机制