由Monkey测试引发的跨多个进程的Android系统死锁问题分析

一、问题现象

1、界面定住，没有任何刷新，所有输入事件无效，包括power key

2、adb shell可以连接并操作手机

3、手机的data和sdcard存储空间已满

4、watchdog没有重启system server

二、解决方案

通过初步分析、深入分析（具体分析过程和关键代码及log在下面）我们知道了问题的原因：

1、monkey测试的过程中起了bugreport，并将bugreport输出到stdout的log通过同步pipe循环读取出来然后write到sdcard的文件中，但是由于sdcard空间满了，write的时候发生了IO error导致monkey异常跳出了读取同步pipe的流程，由于bugreport还没有将log输出完毕所以会一直等待，而monkey则继续运行。

2、bugreport起来之后通过set property的方式触发了dumpstate去获取log，然后通过同步local socket（以下为了描述方便简短起见简称socket）与dumpstate建立连接，将dumpstate通过socket输出的log读取出来写到stdout。

3、dumpstate起来之后会首先将与bugreport的socket通过dup2重定向到stdout，然后执行一系列的抓取log信息的动作，包括cat proc节点、执行dumpsys batterystats等，这些动作都是通过run command的方式起的即fork一个进程，然后执行execvp，fork会继承dumpstate的文件描述符，所以起dumpsys batterystats之后dumpsys中的stdout就是与bugreport通信的socket，dumpsys batterystats会将stdout 文件描述符通过binder传递到system server中。

4、binder driver负责在system server进程中重新分配一个文件描述符来指向与bugreport通信的socket，system server收到dump batterystats的请求后开始把信息输出到bugreport的socket，由于bugreport被write block，导致system server输出的log无法被读取，从而引起system server的dump thread拿着batterystats的一个lock而block了进程内多个其他thread。

5、monkey继续运行向system server发起了dumpsys meminfo的请求，由于dump batterystats的线程拿着一个关键的lock没有释放，导致dumpsys meminfo一直无法得到执行而block了monkey主线程。

6、watchdog线程检测到system server被block之后开始执行相关逻辑，其中就有调用IActivityController的systemNotResponding方法，这个IActivityController是monkey注册的，所有就会跨进程调用到了monkey端，monkey的binder thread收到这个请求之后开始执行，但是执行的过程中需要monkey主线dump完需要的信息后notify它，由于monkey主线程dumpsys meminfo的过程中block，所以导致watchdog线程也被block而无法kill system server。

针对问题的原因，给出以下解决方案：
解开死锁问题的根本死结，当monkey向sdcard写log的时候，如果发生IO error，我们捕获它并继续将monkey起的bugreport的输出读完，从而使system server的dump线程释放持有的lock，使其他线程继续正常工作，dumpsys、dumpstate、cat、bugreport等都能完成自己的同步输入输出，monkey主线程也会恢复，整个系统恢复正常。

patch已同步提交给AOSP review，https://android-review.googlesource.com/#/c/234141/

三、初步分析

1、查看system server的traces发现多线程互锁，主线程需要的锁在thread 33手里

"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x74869fb8 self=0x5588e4e100
  | sysTid=3230 nice=-2 cgrp=default sched=0/0 handle=0x7fa92efe80
  | state=S schedstat=( 153835271056 66149983041 217214 ) utm=9061 stm=6322 core=4 HZ=100
  | stack=0x7ff873d000-0x7ff873f000 stackSize=8MB
  | held mutexes=
  at com.android.server.AlarmManagerService$ResultReceiver.onSendFinished(AlarmManagerService.java:2266)
  - waiting to lock <0x2310f49f> (a java.lang.Object) held by thread 33
  at android.app.PendingIntent$FinishedDispatcher.run(PendingIntent.java:219)
  at android.os.Handler.handleCallback(Handler.java:739)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:135)
  at com.android.server.SystemServer.run(SystemServer.java:296)
  at com.android.server.SystemServer.main(SystemServer.java:188)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:908)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:703)

2、thread 33需要的锁在thread 86手里

"AlarmManager" prio=5 tid=33 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x132f14c0 self=0x7f92814780
  | sysTid=3773 nice=0 cgrp=default sched=0/0 handle=0x7f93cb7d50
  | state=S schedstat=( 7677732166 3315508747 11830 ) utm=569 stm=198 core=5 HZ=100
  | stack=0x7f9233f000-0x7f92341000 stackSize=1036KB
  | held mutexes=
  at com.android.server.power.PowerManagerService.acquireWakeLockInternal(PowerManagerService.java:753)
  - waiting to lock <0x012c60c0> (a java.lang.Object) held by thread 86
  at com.android.server.power.PowerManagerService.access$3300(PowerManagerService.java:87)
  at com.android.server.power.PowerManagerService$BinderService.acquireWakeLock(PowerManagerService.java:2990)
  at android.os.PowerManager$WakeLock.acquireLocked(PowerManager.java:986)
  at android.os.PowerManager$WakeLock.acquire(PowerManager.java:954)
  - locked <@addr=0x1300b8a0> (a android.os.Binder)
  at com.android.server.AlarmManagerService.deliverAlarmsLocked(AlarmManagerService.java:1820)
  at com.android.server.AlarmManagerService$AlarmThread.run(AlarmManagerService.java:1981)
  - locked <0x2310f49f> (a java.lang.Object)

3、thread 86需要的锁在thread 84手里

"Binder_E" prio=5 tid=86 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x141230a0 self=0x7f8b096630
  | sysTid=5467 nice=0 cgrp=default sched=0/0 handle=0x7f8b0960e0
  | state=S schedstat=( 169694491361 86744323304 358303 ) utm=11590 stm=5379 core=5 HZ=100
  | stack=0x7f8ada5000-0x7f8ada7000 stackSize=1012KB
  | held mutexes=
  at com.android.server.am.BatteryStatsService.noteStartWakelock(BatteryStatsService.java:253)
  - waiting to lock <0x052efb00> (a com.android.internal.os.BatteryStatsImpl) held by thread 84
  at com.android.server.power.Notifier.onWakeLockAcquired(Notifier.java:158)
  at com.android.server.power.PowerManagerService.notifyWakeLockAcquiredLocked(PowerManagerService.java:963)
  at com.android