systemserver为啥很少同步跨进程调用app/DeadSystemException相关问题分析套路

news2024/11/24 22:24:45

背景：

有学员分享了一个问题，说monkey测试过程中有一系列问题属于同类的，具体看如下截图：
在这里插入图片描述
可以看到这里的有很多应用都进行了crash，而且crash原因居然都是写着
DeadSystemException: The system died; earlier logs will point to the root cause

即系统死了这种异常，但是提示也说明需要看更早的日志才可以找到根本原因，即注意这里说的DeadSystemException一般都是需要往前面分析日志找到根本原因

初步分析

一般DeadSystemException: The system died; earlier logs will point to the root cause
打印这类异常时候需要继续往前看日志，看看systemserver到底发生了什么。
往上看日志可以发现如下：

03-29 13:55:30.675   510   535 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.wm.WindowManagerService on foreground thread (android.fg)
03-29 13:55:30.676   510   535 W Watchdog: android.fg annotated stack trace:
03-29 13:55:30.676   510   535 W Watchdog:     at com.android.server.wm.WindowManagerService.monitor(WindowManagerService.java:6396)
03-29 13:55:30.677   510   535 W Watchdog:     - waiting to lock <0x048421d2> (a com.android.server.wm.WindowManagerGlobalLock)
03-29 13:55:30.677   510   535 W Watchdog:     at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:233)
03-29 13:55:30.678   510   535 W Watchdog:     at android.os.Handler.handleCallback(Handler.java:883)
03-29 13:55:30.678   510   535 W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:100)
03-29 13:55:30.678   510   535 W Watchdog:     at android.os.Looper.loop(Looper.java:214)
03-29 13:55:30.678   510   535 W Watchdog:     at android.os.HandlerThread.run(HandlerThread.java:67)
03-29 13:55:30.678   510   535 W Watchdog:     at com.android.server.ServiceThread.run(ServiceThread.java:44)
03-29 13:55:30.678   510   535 W Watchdog: *** GOODBYE!

明显可以看到确实这个时候系统都触发了watchdog，kill了system process，那么原因还是
waiting to lock <0x048421d2> (a com.android.server.wm.WindowManagerGlobalLock)
即在等待这把锁
这里再往上看可以看到有一个系统anr打印
03-29 13:52:19.196 510 535 I ActivityManager: Dumping to /data/anr/anr_2024-03-29-13-52-19-196

可以看看这个anr的dump日志

注意从上面可以看出watchdog信息可以看出是WindowManagerService的全局锁一直是获取不到，说明有地方长期占用了WindowManagerGlobalLock这个锁，可以在dump中搜一下Blocked关键字，结果如下：
在这里插入图片描述
点开一个查看详情

在这里插入图片描述

可以看到都是在等待同一个锁
lock <0x048421d2> (a com.android.server.wm.WindowManagerGlobalLock)

那么这个锁是被谁持有着不释放呢？
继续查看，查看方法可以搜thread 236，或者是搜索锁对象地址 0x048421d2
在这里插入图片描述

所以这个tid 236线程就是持有锁导致其他线程无法获取锁的根本
但是从堆栈来看看，明显这个是一个跨进程调用startActivity，systemserver在这个binder线程中居然还发起了同步的跨进程调用，即activityStarting，这个调用居然systemserver还是bp的角色。
android.app.IActivityController $St u b$ Proxy.activityStarting(IActivityController.java:273)

这里就奇怪了，systemserver一般自己作为bp时候的跨进程调用那都是oneway的异步调用，怎么会出现还有同步调用的情况，去aidl确认一下：

在这里插入图片描述
可以看到确实是没有oneway字样，正常其他跨进程调用都是有oneway的，比如如下IApplicationThread接口：

不过这个IActivityController接口正常情况都是无法使用的

/**
 * Testing interface to monitor what is happening in the activity manager
 * while tests are running.  Not for normal application development.
 * {@hide}
 */
interface IActivityController

可以看到只用于测试哈情况，其实这份日志本身是基于monkey测试的

总结直接问题点：
基于上面分析那就基本上明白了导致系统死锁的直接原因，那就是因为systemserver发起了个同步的跨进程调用，这个跨进程调用半天没有得到对方回应，导致systemserver一直卡在这个同步调用这里。

问题继续展望

上面虽然分析出来了一个直接原因，但是也没有找到根本原因，上面说的systemserver跨进程半天没有得到app层面回应，导致一直卡住，那么为啥会被一直卡住？正常跨进程调用应该很快才对，怎么能一直卡住呢？当前binder到底发生了什么呢？

需要进一步追踪根本原因，目前的日志和材料已经不够了，需要更多的日志，比如kernel日志，binder相关调用日志确认出到底是卡在了 app进程，它一直业务繁忙没处理完这个binder调用，还是说binder调用就是没到app进程等，最好还需要有app进程执行的一个线程情况和所有线程在出现问题时候执行的堆栈。

当然也不追查根本原因也可以有对应的规避方案：

可以考虑这个跨进程调用可能会存在长耗时，可以考虑改善这个跨进程调用为不获取锁等情况，修改可能较大，但是影响小一点，只会影响monkey进程业务

本文章更多详细代码和资料需要购买课程获取
hal+perfetto+surfaceflinger
https://mp.weixin.qq.com/s/LbVLnu1udqExHVKxd74ILg
在这里插入图片描述