聊一聊binder driver导致的系统重启问题

2022-06-25 01:30:34

问题现象

这个问题最早是由接电话重启的现象暴露出来的，当时看到异常信息是Native crash，栈如下：

Build fingerprint: 'Xiaomi/scorpio/scorpio:6.0.1/MXB48T/6.10.8:user/release-keys'
Revision: '0'
ABI: 'arm64'
pid: 1383, tid: 1400, name: Binder_1 >>> system_server <<<
signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr --------
x0 0000000000000000 x1 0000000000000578 x2 0000000000000006 x3 0000000000000000
x4 0000000000000000 x5 0000000000000001 x6 0000000000000000 x7 0000000000000000
x8 0000000000000083 x9 0000007fa146e012 x10 0000000000000000 x11 0000007fa146d000
x12 0000007fa1458090 x13 0000000000000001 x14 0000007f9f8e8e28 x15 0000000000000000
x16 0000007fa45c3568 x17 0000007fa455637c x18 0000007fa146d000 x19 0000007f9f8e9500
x20 0000007f9f8e9440 x21 0000000000000009 x22 0000000000000006 x23 0000007f9f8e9380
x24 0000007f9ab9f598 x25 0000007f963ee100 x26 0000007fa4552000 x27 0000007fe86ec7c8
x28 0000000000001000 x29 0000007f9f8e9220 x30 0000007fa4553b18
sp 0000007f9f8e9220 pc 0000007fa4556384 pstate 0000000020000000
v0 00000000000000000000000000000000 v1 000003f5000000000000000000000000
v2 00000000000000000000000000000000 v3 0000007f9f8ea5900000007f9f8ea590
v4 00000000000000000000007900740069 v5 0000000000000000006e0061002e006d
v6 0000000000000000006e0069002e0064 v7 7078656e752064656e72757465722029
v8 00000000000000000000000000000000 v9 00000000000000000000007fe86ed050
v10 00000000000000000000007fe86ed020 v11 00000000000000000000007fe86ed208
v12 00000000000000000000005594ebc2b8 v13 00000000000000000000007fe86ed3a8
v14 00000000000000000000000000000004 v15 00000000000000000000000000000000
v16 40100401401004014010040140100401 v17 80008000000000008080000000000040
v18 80000000800000000000000000000000 v19 b6e84b3dea35f4e9df19793977b4475e
v20 12ed3b001320ac4070b97e9070b98908 v21 000000000000000000000000ebad8085
v22 000000000000000000000000ebad8086 v23 000000000000000000000000ebad8087
v24 000000000000000000000000ebad8088 v25 000000000000000000000000ebad8089
v26 000000000000000000000000ebad808a v27 000000000000000000000000ebad808b
v28 000000000000000000000000ebad808c v29 000000000000000000000000ebad808d
v30 000000000000000000000000ebad808e v31 00000000000000000000000000000000
fpsr 00000010 fpcr 00000000
backtrace:
#00 pc 0000000000069384 /system/lib64/libc.so (tgkill+8)
#01 pc 0000000000066b14 /system/lib64/libc.so (pthread_kill+68)
#02 pc 0000000000023a78 /system/lib64/libc.so (raise+28)
#03 pc 000000000001e218 /system/lib64/libc.so (abort+60)
#04 pc 000000000002df80 /system/lib64/libbinder.so (_ZN7android14IPCThreadState14joinThreadPoolEb+216)
#05 pc 00000000000369e8 /system/lib64/libbinder.so
#06 pc 00000000000167b4 /system/lib64/libutils.so (_ZN7android6Thread11_threadLoopEPv+208)
#07 pc 00000000000905ac /system/lib64/libandroid_runtime.so (_ZN7android14AndroidRuntime15javaThreadShellEPv+96)
#08 pc 0000000000016004 /system/lib64/libutils.so
#09 pc 0000000000065f64 /system/lib64/libc.so (ZL15_pthread_startPv+52)
#10 pc 000000000001edc4 /system/lib64/libc.so (__start_thread+16)

问题结论

问题的根本原因是binder driver的协议处理对于BC_FREE_BUFFER的处理没有考虑到同步binder call嵌套异步binder call的情况，导致协议处理紊乱，最终解决方案如下，将BC_FREE_BUFFER时move async transaction的操作，由当前线程的todo list更改为进程的todo list，保证嵌套binder call的情况下也能正确处理，并且达到负载均衡，提升吞吐量的目的：

https://android-review.googlesource.com/#/c/305049/
聊一聊binder driver导致的系统重启问题

初步分析

咋一看Native Crash的调用栈让人有点摸不着头脑，好好的binder thread怎么自己abort掉了？先看看对应的代码：
聊一聊binder driver导致的系统重启问题
可以看到是getAndExecuteCommand();的返回值有问题，再继续看看里面影响返回值的地方：
聊一聊binder driver导致的系统重启问题
有两个地方会影响这个返回值，分别是result = talkWithDriver();和result = executeCommand(cmd);
通过log和coredump确认是在result = executeCommand(cmd);里面出了问题，因为打debug log还提交了两个AOSP change修正一些原生打log时的问题，有兴趣的同学可以看一下：

https://android-review.googlesource.com/#/c/291187/

https://android-review.googlesource.com/#/c/294368/
聊一聊binder driver导致的系统重启问题
具体出错时的cmd是BR_TRANSACTION_COMPLETE，这里引出第一个一疑问，为什么会从driver里面拿回来一个单独的BR_TRANSACTION_COMPLETE？

背景知识

想要理解出错的场景，我们需要先知道binder call的协议及其执行流程：

1、binder协议分两种，命令协议（BinderDriverCommandProtocol）和返回协议（BinderDriverReturnProtocol）
我们先看一下这些协议的定义：

enum BinderDriverReturnProtocol {
    BR_ERROR = _IOR('r', 0, int),
    /*
     * int: error code
     */
BR_OK = _IO('r', 1),
    /* No parameters! */
BR_TRANSACTION = _IOR('r', 2, struct binder_transaction_data),
    BR_REPLY = _IOR('r', 3, struct binder_transaction_data),
    /*
     * binder_transaction_data: the received command.
     */
BR_ACQUIRE_RESULT = _IOR('r', 4, int),
    /*
     * not currently supported
     * int: 0 if the last bcATTEMPT_ACQUIRE was not successful.
     * Else the remote object has acquired a primary reference.
     */
BR_DEAD_REPLY = _IO('r', 5),
    /*
     * The target of the last transaction (either a bcTRANSACTION or
     * a bcATTEMPT_ACQUIRE) is no longer with us.  No parameters.
     */
BR_TRANSACTION_COMPLETE = _IO('r', 6),
    /*
     * No parameters... always refers to the last transaction requested
     * (including replies).  Note that this will be sent even for
     * asynchronous transactions.
     */
BR_INCREFS = _IOR('r', 7, struct binder_ptr_cookie),
    BR_ACQUIRE = _IOR('r', 8, struct binder_ptr_cookie),
    BR_RELEASE = _IOR('r', 9, struct binder_ptr_cookie),
    BR_DECREFS = _IOR('r', 10, struct binder_ptr_cookie),
    /*
     * void *:  ptr to binder
     * void *: cookie for binder
     */
BR_ATTEMPT_ACQUIRE = _IOR('r', 11, struct binder_pri_ptr_cookie),
    /*
     * not currently supported
     * int: priority
     * void *: ptr to binder
     * void *: cookie for binder
     */
BR_NOOP = _IO('r', 12),
    /*
     * No parameters.  Do nothing and examine the next command.  It exists
     * primarily so that we can replace it with a BR_SPAWN_LOOPER command.
     */
BR_SPAWN_LOOPER = _IO('r', 13),
    /*
     * No parameters.  The driver has determined that a process has no
     * threads waiting to service incomming transactions.  When a process
     * receives this command, it must spawn a new service thread and
     * register it via bcENTER_LOOPER.
     */
BR_FINISHED = _IO('r', 14),
    /*
     * not currently supported
     * stop threadpool thread
     */
BR_DEAD_BINDER = _IOR('r', 15, void *),
    /*
     * void *: cookie
     */
    BR_CLEAR_DEATH_NOTIFICATION_DONE = _IOR('r', 16, void *),
    /*
     * void *: cookie
     */
BR_FAILED_REPLY = _IO('r', 17),
    /*
     * The the last transaction (either a bcTRANSACTION or
     * a bcATTEMPT_ACQUIRE) failed (e.g. out of memory).  No parameters.
     */
};
enum BinderDriverCommandProtocol {
    BC_TRANSACTION = _IOW('c', 0, struct binder_transaction_data),
    BC_REPLY = _IOW('c', 1, struct binder_transaction_data),
    /*
     * binder_transaction_data: the sent command.
     */
BC_ACQUIRE_RESULT = _IOW('c', 2, int),
    /*
     * not currently supported
     * int:  0 if the last BR_ATTEMPT_ACQUIRE was not successful.
     * Else you have acquired a primary reference on the object.
     */
BC_FREE_BUFFER = _IOW('c', 3, int),
    /*
     * void *: ptr to transaction data received on a read
     */
BC_INCREFS = _IOW('c', 4, int),
    BC_ACQUIRE = _IOW('c', 5, int),
    BC_RELEASE = _IOW('c', 6, int),
    BC_DECREFS = _IOW('c', 7, int),
    /*
     * int: descriptor
     */
BC_INCREFS_DONE = _IOW('c', 8, struct binder_ptr_cookie),
    BC_ACQUIRE_DONE = _IOW('c', 9, struct binder_ptr_cookie),
    /*
     * void *: ptr to binder
     * void *: cookie for binder
     */
BC_ATTEMPT_ACQUIRE = _IOW('c', 10, struct binder_pri_desc),
    /*
     * not currently supported
     * int: priority
     * int: descriptor
     */
BC_REGISTER_LOOPER = _IO('c', 11),
    /*
     * No parameters.
     * Register a spawned looper thread with the device.
     */
BC_ENTER_LOOPER = _IO('c', 12),
    BC_EXIT_LOOPER = _IO('c', 13),
    /*
     * No parameters.
     * These two commands are sent as an application-level thread
     * enters and exits the binder loop, respectively.  They are
     * used so the binder can have an accurate count of the number
     * of looping threads it has available.
     */
BC_REQUEST_DEATH_NOTIFICATION = _IOW('c', 14, struct binder_ptr_cookie),
    /*
     * void *: ptr to binder
     * void *: cookie
     */
BC_CLEAR_DEATH_NOTIFICATION = _IOW('c', 15, struct binder_ptr_cookie),
    /*
     * void *: ptr to binder
     * void *: cookie
     */
BC_DEAD_BINDER_DONE = _IOW('c', 16, void *),
    /*
     * void *: cookie
     */
};

看了上面一堆的协议定义，让人有点害怕，不过不用担心，这次我们只讨论正常binder call的几个关键协议，其他初始化的，增加binder线程的，死亡通知的，对象生命周期管理的，错误相关的都先不讨论，另外需要说明一点，BinderDriverCommandProtocol的所有协议都是发给binder driver的，BinderDriverReturnProtocol 的所有协议都是binder driver发给交互线程的。

下面我们先切入一个正常同步binder call的执行流程：
聊一聊binder driver导致的系统重启问题
然后再看一个正常的异步binder call的执行流程，异步binder call就是ONE WAY的，不需要等待reply：
聊一聊binder driver导致的系统重启问题
相对于同步的binder call，异步的简单多了，接下来再看一下异步binder call触发同步binder call的执行流程，这个稍微复杂点：
聊一聊binder driver导致的系统重启问题
看完这个图有些同学可能会问，时序图中每次TRANSACTION或者REPLY结束之后都有一个BC_FREE_BUFFER，它的作用是什么？

答案是每次的BR_TRANSACTION或者BR_REPLY binder driver都会为它们找一块内核缓冲区承载binder通信的数据，并通过更新页表的方式与之前mmap的内存地址对应上，所以接受BR_TRANSACTION或者BR_REPLY的线程需要在每次处理完之后告诉binder driver释放这块区域。

看完异步触发同步的流程之后我们再看一个正常的连续两个异步触发一个同步和一个异步的执行流程，看到这的同学不用害怕，后面不会再看更复杂的了：
聊一聊binder driver导致的系统重启问题

初步推论

有了上面的储备知识之后，我们就可以反推出问题时多一个BR_TRANSACTION_COMPLETED的的场景了，如下是最早的推论流程：

一、server binder thread todo list-》1、BR_TRANSACTION（异步）
二、processPendingDerefs-》BBinder对象析构函数-》同步binder call-》IPCThreadState::transact-》waitForResponse-》BC_TRANSACTION(同步调用)》server binder thread todo list》1、BR_TRANSACTION，2、BR_TRANSACTION_COMPLETE-》
三、在waitForResponse里面从todo里面读出来一个BR_TRANSACTION去工作-》executeCommand-》异步 binder call-》IPCThreadState::transact-》waitForResponse-》BC_TRANSACTION（异步调用）》server binder thread todo》1、BR_TRANSACTION_COMPLETE，2、BR_REPLY，3、BR_TRANSACTION_COMPLETE
四、在第二个异步调用的waitForResponse里面拿出来第一个BR_TRANSACTION_COMPLETE，退出waitForResponse，server binder thread todo-》1、BR_REPLY，2、BR_TRANSACTION_COMPLETE
五、回到第一个同步调用的waitForResponse，拿出来BR_REPLY，调用freebuffer，把BC_FREE_BUFFER写到out里面，退出waitForResponse，退出析构函数，退出processPendingDerefs，server binder thread todo-》1、BR_TRANSACTION_COMPLETE
六、继续调用getAndExecuteCommand，取出BR_TRANSACTION_COMPLETE，abort

但是这个推论有一个问题，如何让server binder thread todo list里面先有一个异步的BR_TRANSACTION？

正常情况下异步的BR_TRANSACTION是不会直接放到binder thread的todo list里的，如果是实体对象（target_node）的第一个BR_TRANSACTION，会先放到proc的todo list里，如果是第二个或者更多，会放到target_node的async_todo list里，所以这个问题分析到这里感觉有些走不通了，但是直觉告诉我上面的场景分析是靠谱的，一定还有其他路径可能执行到上面的问题场景，接下来就继续分析binder driver的源码，苦读之后终于发现了新大陆，原来BC_FREE_BUFFER除了会释放内核缓冲区，还有一个作用就是将同一个实体对象（target_node）的其他异步transaction放入当前binder thread的todo list中，使其free buffer之后就可以从自己的todo list中获取到异步transaction而直接返回到用户空间执行，好了到这里我们在逻辑上就能完全解释通上面出问题的场景了：
聊一聊binder driver导致的系统重启问题

这里对于同一个实体对象的连续异步transaction都绑定到了同一个处理线程，好处是连续异步transaction不会影响其他同步的transaction，减少一定的线程切换和唤醒，但这带来了一些潜在的问题，没有负载均衡，可能造成一个线程忙死，其他线程空闲，另外连续的异步transaction会降低后续同步transaction的吞吐量，除此之外还有一个最严重的问题就是无法处理同步嵌套异步的case。

验证推论

有了上面的一系列理论基础和推论，接下来就通过添加一些debug log来验证和确认这个问题，debug log的change参考如下链接：
http://git.xiaomi.com:8660/#/c/57748/

通过debug log获取到在processPendingDerefs里析构BBinder对象，并发起同步binder call的调用栈：

10-26 10:10:14.523 3060 3094 D IPCThreadState: #00 pc 0001f24b /system/lib/libbinder.so (_ZN7android14IPCThreadState8transactEijRKNS_6ParcelEPS1_j+178)
10-26 10:10:14.523 3060 3094 D IPCThreadState: #01 pc 0001a19b /system/lib/libbinder.so (_ZN7android8BpBinder8transactEjRKNS_6ParcelEPS1_j+30)
10-26 10:10:14.523 3060 3094 D IPCThreadState: #02 pc 00065cd1 /system/lib/libmedia.so
10-26 10:10:14.523 3060 3094 D IPCThreadState: #03 pc 0007200f /system/lib/libmedia.so (_ZN7android11AudioSystem21releaseAudioSessionIdEii+30)
10-26 10:10:14.523 3060 3094 D IPCThreadState: #04 pc 000750b5 /system/lib/libmedia.so (_ZN7android11MediaPlayerD2Ev+56)
10-26 10:10:14.523 3060 3094 D IPCThreadState: #05 pc 000752c3 /system/lib/libmedia.so (_ZN7android11MediaPlayerD0Ev+18)
10-26 10:10:14.523 3060 3094 D IPCThreadState: #06 pc 0000e71f /system/lib/libutils.so (_ZNK7android7RefBase9decStrongEPKv+50)
10-26 10:10:14.523 3060 3094 D IPCThreadState: #07 pc 0001e663 /system/lib/libbinder.so (_ZN7android14IPCThreadState20processPendingDerefsEv+82)
10-26 10:10:14.523 3060 3094 D IPCThreadState: #08 pc 0001efa3 /system/lib/libbinder.so (_ZN7android14IPCThreadState14joinThreadPoolEb+54)
10-26 10:10:14.523 3060 3094 D IPCThreadState: #09 pc 000239a5 /system/lib/libbinder.so
10-26 10:10:14.523 3060 3094 D IPCThreadState: #10 pc 00010075 /system/lib/libutils.so (_ZN7android6Thread11_threadLoopEPv+112)
10-26 10:10:14.523 3060 3094 D IPCThreadState: #11 pc 0005fd47 /system/lib/libandroid_runtime.so (_ZN7android14AndroidRuntime15javaThreadShellEPv+70)
10-26 10:10:14.523 3060 3094 D IPCThreadState: #12 pc 0003f557 /system/lib/libc.so (ZL15_pthread_startPv+30)
10-26 10:10:14.523 3060 3094 D IPCThreadState: #13 pc 00019c37 /system/lib/libc.so (__start_thread+6)

聊一聊binder driver导致的系统重启问题

processPendingDerefs过程中有向binder driver write BC_FREE_BUFFER，并且target_node->async_todo中有transaction等待处理，同时在processPendingDerefs中又发起同步的binder call来write BC_TRANSACTION，从而在处理BC_FREE_BUFFER的时候将target_node->async_todo中的transaction放入thread的todo中，如下是出问题之前free buffer的调用栈：

11-20 12:34:08.279 2892 2902 D IPCThreadState: #00 pc 0001e919 /system/lib/libbinder.so (_ZN7android14IPCThreadState10freeBufferEPNS_6ParcelEPKhjPKjjPv+60)
11-20 12:34:08.279 2892 2902 D IPCThreadState: #01 pc 00022477 /system/lib/libbinder.so (_ZN7android6Parcel14freeDataNoInitEv+22)
11-20 12:34:08.279 2892 2902 D IPCThreadState: #02 pc 000224d9 /system/lib/libbinder.so (_ZN7android6ParcelD1Ev+4)
11-20 12:34:08.279 2892 2902 D IPCThreadState: #03 pc 0001ee95 /system/lib/libbinder.so (_ZN7android14IPCThreadState14executeCommandEi+644)
11-20 12:34:08.279 2892 2902 D IPCThreadState: #04 pc 0001f19b /system/lib/libbinder.so (_ZN7android14IPCThreadState15waitForResponseEPNS_6ParcelEPi+262)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #05 pc 0001f327 /system/lib/libbinder.so (_ZN7android14IPCThreadState8transactEijRKNS_6ParcelEPS1_j+306)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #06 pc 0001a19b /system/lib/libbinder.so (_ZN7android8BpBinder8transactEjRKNS_6ParcelEPS1_j+30)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #07 pc 00065cd1 /system/lib/libmedia.so
11-20 12:34:08.280 2892 2902 D IPCThreadState: #08 pc 00072037 /system/lib/libmedia.so (_ZN7android11AudioSystem21releaseAudioSessionIdEii+30)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #09 pc 000750dd /system/lib/libmedia.so (_ZN7android11MediaPlayerD2Ev+56)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #10 pc 000752eb /system/lib/libmedia.so (_ZN7android11MediaPlayerD0Ev+18)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #11 pc 0000e8cf /system/lib/libutils.so (_ZNK7android7RefBase9decStrongEPKv+50)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #12 pc 0001e663 /system/lib/libbinder.so (_ZN7android14IPCThreadState20processPendingDerefsEv+82)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #13 pc 0001effb /system/lib/libbinder.so (_ZN7android14IPCThreadState14joinThreadPoolEb+54)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #14 pc 00023a09 /system/lib/libbinder.so
11-20 12:34:08.280 2892 2902 D IPCThreadState: #15 pc 00010225 /system/lib/libutils.so (_ZN7android6Thread11_threadLoopEPv+112)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #16 pc 0006145f /system/lib/libandroid_runtime.so (_ZN7android14AndroidRuntime15javaThreadShellEPv+70)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #17 pc 0003f557 /system/lib/libc.so (ZL15_pthread_startPv+30)
11-20 12:34:08.280 2892 2902 D IPCThreadState: #18 pc 00019c37 /system/lib/libc.so (__start_thread+6)

出问题时的调用栈和aborting log验证了前面的分析：
聊一聊binder driver导致的系统重启问题

最终出问题的执行流程如下，这是上面流程图的一个演化版：

聊一聊binder driver导致的系统重启问题

上一篇：OpenGL学习笔记：Console工程下如何不显示控制台黑窗口只显示Windows窗口


下一篇：μcGUI学习笔记之三文本显示与数值显示