文章目录
1. Watchdog是什么?2. Watchdog代码基本介绍3. 原因分析4. 实例分析例1:SystemServer Binder耗尽例2:IO阻塞例3:Thread.sleep阻塞
1. Watchdog是什么?
Android Watchdog主要是检测system server重要线程状态(main,android io,android display ,Activitymanager,android fg,android bg等线程 )的一种机制。发生Watchdog时会触发Android重启来使系统恢复。Watchdog是SystemServer的一个线程(class Watchdog extends Thread),检测system server重要线程的锁状态和消息是否阻塞,假如有线程block了60s那么就会触发watchdog timeout flow。
2. Watchdog代码基本介绍
可以在http://androidxref.com/搜索源码,看Watchdog.java文件
public class Watchdog extends Thread {
final ArrayList mHandlerCheckers = new ArrayList<>();
...
private Watchdog() {
super("watchdog");
//将前台线程加入队列
mMonitorChecker = new HandlerChecker(FgThread.getHandler(),
"foreground thread", DEFAULT_TIMEOUT);
mHandlerCheckers.add(mMonitorChecker);
//将主线程加入队列
mHandlerCheckers.add(new HandlerChecker(new Handler(Looper.getMainLooper()),
"main thread", DEFAULT_TIMEOUT));
//将ui线程加入队列
mHandlerCheckers.add(new HandlerChecker(UiThread.getHandler(),
"ui thread", DEFAULT_TIMEOUT));
//将i/o线程加入队列
mHandlerCheckers.add(new HandlerChecker(IoThread.getHandler(),
"i/o thread", DEFAULT_TIMEOUT));
//将display线程加入队列
mHandlerCheckers.add(new HandlerChecker(DisplayThread.getHandler(),
"display thread", DEFAULT_TIMEOUT));
addMonitor(new BinderThreadMonitor());
}
}
ActivityManagerService添加
@frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
3184 Watchdog.getInstance().addMonitor(this);
3185 Watchdog.getInstance().addThread(mHandler);
/** In this method we try to acquire our lock to make sure that we have not deadlocked */
public void monitor() {
synchronized (this) { }
}
Watchdog线程循环检测
@Override
public void run() {
boolean waitedHalf = false;
while (true) {
...
//java trace
final File stack = ActivityManagerService.dumpStackTraces(
!waitedHalf, pids, null, null, getInterestingNativePids());
//sysrq
// Trigger the kernel to dump all blocked threads, and backtraces on all CPUs to the kernel log
doSysRq('w');
doSysRq('l');
//dropbox
Thread dropboxThread = new Thread("watchdogWriteToDropbox") {
public void run() {
mActivity.addErrorToDropBox(
"watchdog", null, "system_server", null, null,
subject, null, stack, null);
}
};
dropboxThread.start();
try {
dropboxThread.join(2000); // wait up to 2 seconds for it to return.
} catch (InterruptedException ignored) {}
...
//打印LOG WATCHDOG KILLING SYSTEM PROCESS
} else {
Slog.w(TAG, "*** WATCHDOG KILLING SYSTEM PROCESS: " + subject);
WatchdogDiagnostics.diagnoseCheckers(blockedCheckers);
Slog.w(TAG, "*** GOODBYE!");
// kill自己(SystemServer)重启
Process.killProcess(Process.myPid());
System.exit(10);
}
waitedHalf = false;
}
}
private static final class BinderThreadMonitor implements Watchdog.Monitor {
@Override
public void monitor() {
Binder.blockUntilThreadAvailable();
}
}
BinderThread耗尽,就会Blocked在这里
void IPCThreadState::blockUntilThreadAvailable()
{
pthread_mutex_lock(&mProcess->mThreadCountLock);
while (mProcess->mExecutingThreadsCount >= mProcess->mMaxThreads) {
ALOGW("Waiting for thread to be free. mExecutingThreadsCount=%lu mMaxThreads=%lu\n",
static_cast(mProcess->mExecutingThreadsCount),
static_cast(mProcess->mMaxThreads));
pthread_cond_wait(&mProcess->mThreadCountDecrement, &mProcess->mThreadCountLock);
}
pthread_mutex_unlock(&mProcess->mThreadCountLock);
}
3. 原因分析
(1)手机性能影响主要一下:
cpu使用高 –查看cpu使用,看是否有问题
low memory –通过kernel log搜索lowmemorykiller看cache和free的内存是否够,是否有memory泄露
emmc问题(io文件)–block的trace应该在io操作时,可以kernellog搜索是否有emmc错误
dump log –在发生anr之前系统在dump log导致花费时间
object leakage –比如fd leak,window leakage,service leakage,receiver leakage,window leakage
(2)非性能影响,可能原因如下,看backtrace来分析
4. 实例分析
例1:SystemServer Binder耗尽
10-26 00:07:00.884 1000 17132 17312 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.Watchdog$BinderThreadMonitor on foreground thread (android.fg)
10-26 00:07:00.884 1000 17132 17312 W Watchdog: foreground thread stack trace:
10-26 00:07:00.885 1000 17132 17312 W Watchdog: at android.os.Binder.blockUntilThreadAvailable(Native Method)
10-26 00:07:00.885 1000 17132 17312 W Watchdog: at com.android.server.Watchdog$BinderThreadMonitor.monitor(Watchdog.java:381)
10-26 00:07:00.885 1000 17132 17312 W Watchdog: at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:353)
10-26 00:07:00.885 1000 17132 17312 W Watchdog: at android.os.Handler.handleCallback(Handler.java:873)
10-26 00:07:00.886 1000 17132 17312 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:99)
10-26 00:07:00.886 1000 17132 17312 W Watchdog: at android.os.Looper.loop(Looper.java:193)
10-26 00:07:00.886 1000 17132 17312 W Watchdog: at android.os.HandlerThread.run(HandlerThread.java:65)
10-26 00:07:00.886 1000 17132 17312 W Watchdog: at com.android.server.ServiceThread.run(ServiceThread.java:44)
10-26 00:07:00.886 1000 17132 17312 W Watchdog: *** GOODBYE!
例2:IO阻塞
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号线程的状态。
可以在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 (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写操作,正式因为这个写操作一直在阻塞,导致线程持有的锁不能释放
聪明的你看到这或许已经能够想到解决办法了,在这个IO写操作上加一个超时机制,并且这个超时小于Watchdog的超时,不就可以让线程释放它所占有的锁了吗? 是的,这确实可以作为一个临时解决方案(Workaround),或者说一个保护机制。但我们可以再往深处想一想,这个IO写操作为什么会阻塞:
是不是IO缓冲区满了,导致写阻塞呢?是不是写操作有什么锁,导致这个write方法在等锁呢?是不是当前系统的IO负载过于高,导致写操作效率很低呢?
这都需要我们再进一步从日志中去找原因。如果已有的日志不全,找不到论据,我们还需要设计场景来验证假设,解决问题的难度陡然上升。
例3:Thread.sleep阻塞
//watchdog half
08-17 02:59:46.824 906 1384 I Watchdog: WAITED_HALF
//dumpStackTraces half watchdog(data/anr)
08-17 02:59:46.949 906 1384 I ActivityManager: dumpStackTraces pids=null nativepids=[512, 658, 643, 819, 645, 646, 663, 828, 653, 510, 481, 508, 672, 797, 798, 806, 810, 811, 812, 815, 819, 828, 1504]
08-17 02:59:46.959 906 1384 I ActivityManager: Dumping to /data/anr/anr_2020-08-17-02-59-46-955
//发生watchdog
08-17 03:00:21.784 906 1384 I watchdog: Blocked in monitor com.android.server.am.ActivityManagerService on foreground thread (android.fg)
dumpStackTraces watchdog(data/anr)
08-17 03:00:21.876 906 1384 I ActivityManager: dumpStackTraces pids=null nativepids=[512, 658, 643, 819, 645, 646, 663, 828, 653, 510, 481, 508, 672, 797, 798, 806, 810, 811, 812, 815, 819, 828, 1504]
08-17 03:00:21.880 906 1384 I ActivityManager: Dumping to /data/anr/anr_2020-08-17-03-00-21-878
//dump sysrq(/proc/sysrq-trigger)
08-17 03:00:31.834 1384 1384 I SysRq : Show Blocked State
08-17 03:00:31.843 1384 1384 I SysRq : Show backtrace of all active CPUs
//dropbox (/data/system/dropbox/system_server_watchdog@xxx.txt)
08-17 03:00:31.902 906 3367 I DropBoxManagerService: add tag=system_server_watchdog isTagEnabled=true flags=0x2
@main/system log
08-17 03:00:31.966 906 1384 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.am.ActivityManagerService on foreground thread (android.fg)
08-17 03:00:31.968 906 1384 W Watchdog: android.fg annotated stack trace:
08-17 03:00:31.968 906 1384 W Watchdog: at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:17574)
08-17 03:00:31.968 906 1384 W Watchdog: - waiting to lock <0x05fe6da3> (a java.lang.Object)
08-17 03:00:31.968 906 1384 W Watchdog: at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:233)
08-17 03:00:31.968 906 1384 W Watchdog: at android.os.Handler.handleCallback(Handler.java:883)
08-17 03:00:31.969 906 1384 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:100)
08-17 03:00:31.969 906 1384 W Watchdog: at android.os.Looper.loop(Looper.java:214)
08-17 03:00:31.969 906 1384 W Watchdog: at android.os.HandlerThread.run(HandlerThread.java:67)
08-17 03:00:31.969 906 1384 W Watchdog: at com.android.server.ServiceThread.run(ServiceThread.java:44)
08-17 03:00:31.969 906 1384 W Watchdog: *** GOODBYE!
//kill self
08-17 03:00:31.969 906 1384 I Process : Sending signal. PID: 906 SIG: 9
//重启LOG
08-17 03:00:33.079 3407 3407 I boot_progress_start: 184709
08-17 03:00:33.635 3407 3407 I boot_progress_preload_start: 185266
08-17 03:00:34.376 3407 3407 I boot_progress_preload_end: 186006
08-17 03:00:34.682 3481 3481 I boot_progress_system_run: 186312
08-17 03:00:35.026 3481 3481 I boot_progress_pms_start: 186656
08-17 03:00:35.227 3481 3481 I boot_progress_pms_system_scan_start: 186857
08-17 03:00:36.049 3481 3481 I boot_progress_pms_data_scan_start: 187679
08-17 03:00:36.056 3481 3481 I boot_progress_pms_scan_end: 187687
08-17 03:00:36.165 3481 3481 I boot_progress_pms_ready: 187795
08-17 03:00:37.424 3481 3481 I boot_progress_ams_ready: 189054
08-17 03:00:38.361 3481 3503 I boot_progress_enable_screen: 189992
//watchdog half 和 watchdog trace表明是"Binder:906_F"线程sleep导致锁无法释放
//watchdog trace
----- pid 906 at 2020-08-17 03:00:21 -----
Cmd line: system_server
"android.fg" prio=5 tid=15 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x147812e8 self=0x7a0bb9cc00
| sysTid=1378 nice=0 cgrp=default sched=0/0 handle=0x791e0cbd50
| state=S schedstat=( 293867703 541217342 863 ) utm=23 stm=5 core=1 HZ=100
| stack=0x791dfc9000-0x791dfcb000 stackSize=1039KB
| held mutexes=
at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:17574)
- waiting to lock <0x05fe6da3> (a java.lang.Object) held by thread 117
at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:233)
//"Binder:906_F"线程(906:2913),sleep导致了Blocked
"Binder:906_F" prio=5 tid=117 Sleeping
| group="main" sCount=1 dsCount=0 flags=1 obj=0x13900728 self=0x797b178000
| sysTid=2913 nice=0 cgrp=default sched=0/0 handle=0x78c81e9d50
| state=S schedstat=( 227062849 166952101 637 ) utm=17 stm=4 core=2 HZ=100
| stack=0x78c80f3000-0x78c80f5000 stackSize=991KB
| held mutexes=
at java.lang.Thread.sleep(Native method)
- sleeping on <0x03e0cbb8> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:440)
- locked <0x03e0cbb8> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:356)
at com.android.server.am.ActivityManagerService.testWatchdog(ActivityManagerService.java:2916)
- locked <0x05fe6da3> (a java.lang.Object)
at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:4506)
at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2744)
at android.os.Binder.execTransactInternal(Binder.java:1021)
at android.os.Binder.execTransact(Binder.java:994)
//Binder Client端是TWatchdogTest(pid:3116 tid:3146)
08-17 03:00:32.208 3116 3146 W System.err: android.os.DeadObjectException
08-17 03:00:32.207 301 301 I binder : release 906:2913 transaction 53556 in, still active
08-17 03:00:32.207 301 301 I binder : send failed reply for transaction 53556 to 3116:3146
08-17 03:00:32.208 3116 3146 W System.err: at android.os.BinderProxy.transactNative(Native Method)
08-17 03:00:32.208 3116 3146 W System.err: at android.os.BinderProxy.transact(BinderProxy.java:510)
08-17 03:00:32.208 3116 3146 W System.err: at android.app.IActivityManager$Stub$Proxy.testWatchdog(IActivityManager.java:9331)
08-17 03:00:32.208 3116 3146 W System.err: at com.example.serviceclient.MainActivity$5.run(MainActivity.java:113)
08-17 03:00:32.208 3116 3146 W System.err: at java.lang.Thread.run(Thread.java:919)
08-17 02:58:58.155 3116 3146 D TWatchdogTest: startThread Client .
代码
明显是testWatchdog()sleep太久,导致mobj无法释放,超过60s,最后触发Watchdog @ActivityManagerService.java
private Object mobj = new Object();
@Override
public void testWatchdog() {
synchronized (mobj) {
Slog.d(TAG, "testWatchdog .");
try {
Thread.sleep(1000*1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
Slog.d(TAG, "startThread .");
}
}
//AMS monitor添加mobj锁检测
/** In this method we try to acquire our lock to make sure that we have not deadlocked */
public void monitor() {
synchronized (this) { }
synchronized (mobj) {
Slog.d(TAG, "testWatchdog monitor() .");
}
}
@core/java/android/app/IActivityManager.aidl
void testWatchdog();
//MainActivity
public void startThread(String name) {
Thread mThread = new Thread(new Runnable() {
@Override
public void run() {
Log.d(TAG, "startThread Client .");
try {
ActivityManager.getService().testWatchdog();
} catch (RemoteException e) {
e.printStackTrace();
}
}
});
mThread.setName(name);
mThread.start();
}