偶现来电时手机操作出现重启

问题描述：偶现来电时手机操作出现重启

问题分析：从系统Log看

09-06 10:22:44.791829 1400 1425 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in handler on main thread (main)
09-06 10:22:44.794133 1400 1425 W Watchdog: main annotated stack trace:
09-06 10:22:44.794535 1400 1425 W Watchdog: at com.android.server.telecom.SystemStateHelper$1.onReceive(SystemStateHelper.java:80)
09-06 10:22:44.794992 1400 1425 W Watchdog: - waiting to lock <0x000060ed> (a com.android.server.telecom.TelecomSystem$1)
09-06 10:22:44.795265 1400 1425 W Watchdog: at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$getRunnable$0$android-app-LoadedApk$ReceiverDispatcher$Args(LoadedApk.java:1809)
09-06 10:22:44.795402 1400 1425 W Watchdog: at android.app.LoadedApk$ReceiverDispatcher$Args$$ExternalSyntheticLambda0.run(Unknown Source:2)
09-06 10:22:44.795508 1400 1425 W Watchdog: at android.os.Handler.handleCallback(Handler.java:942)
09-06 10:22:44.795605 1400 1425 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:99)
09-06 10:22:44.795740 1400 1425 W Watchdog: at android.os.Looper.loopOnce(Looper.java:204)
09-06 10:22:44.795843 1400 1425 W Watchdog: at android.os.Looper.loop(Looper.java:291)
09-06 10:22:44.795940 1400 1425 W Watchdog: at com.android.server.SystemServer.run(SystemServer.java:1020)
09-06 10:22:44.796036 1400 1425 W Watchdog: at com.android.server.SystemServer.main(SystemServer.java:692)
09-06 10:22:44.796127 1400 1425 W Watchdog: at java.lang.reflect.Method.invoke(Native Method)
09-06 10:22:44.796247 1400 1425 W Watchdog: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:601)
09-06 10:22:44.796398 1400 1425 W Watchdog: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1114)
09-06 10:22:44.796527 1400 1425 W Watchdog: *** GOODBYE!

从Log看，而Telecom一直等待如下锁 waiting to lock <0x000060ed>，引发WatchDog

Telecom的系统进程为1400

Trace 分析如下：

Telecom 1400主线程一直waiting to lock <0x000060ed>

"main" prio=5 tid=1 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x713e81b8 self=0xf0242a10
| sysTid=1400 nice=-2 cgrp=default sched=1073741824/0 handle=0xf752b470
| state=S schedstat=( 17127376404 10774636406 33180 ) utm=1285 stm=427 core=7 HZ=100
| stack=0xff605000-0xff607000 stackSize=8188KB
| held mutexes=
at com.android.server.telecom.SystemStateHelper$1.onReceive(SystemStateHelper.java:80)
- waiting to lock <0x000060ed> (a com.android.server.telecom.TelecomSystem$1) held by thread 68
at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$getRunnable$0$android-app-LoadedApk$ReceiverDispatcher$Args(LoadedApk.java:1809)
at android.app.LoadedApk$ReceiverDispatcher$Args$$ExternalSyntheticLambda0.run(unavailable:2)
at android.os.Handler.handleCallback(Handler.java:942)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loopOnce(Looper.java:204)
at android.os.Looper.loop(Looper.java:291)
at com.android.server.SystemServer.run(SystemServer.java:1020)
at com.android.server.SystemServer.main(SystemServer.java:692)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:601)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1114)

1、1400:1400等待1400:1487

该锁又被 1400:1487所持有

"binder:1400_4" prio=5 tid=68 Native
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x16a80eb0 self=0xf0271010
| sysTid=1487 nice=0 cgrp=default sched=1073741824/0 handle=0xba4c11c0
| state=S schedstat=( 6412454401 8041460075 15557 ) utm=477 stm=163 core=2 HZ=100
| stack=0xba3c6000-0xba3c8000 stackSize=1004KB
| held mutexes=
native: #00 pc 000744ac /apex/com.android.runtime/lib/bionic/libc.so (__ioctl+8) (BuildId: 25891ab1dc6076962f6709f412e9da4e)
native: #01 pc 000404c7 /apex/com.android.runtime/lib/bionic/libc.so (ioctl+26) (BuildId: 25891ab1dc6076962f6709f412e9da4e)
native: #02 pc 00040827 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+206) (BuildId: 4e1f7dff9859f87a85bf606ccf092d4e)
native: #03 pc 00041a17 /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+78) (BuildId: 4e1f7dff9859f87a85bf606ccf092d4e)
native: #04 pc 0004179b /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+134) (BuildId: 4e1f7dff9859f87a85bf606ccf092d4e)
native: #05 pc 0003b92f /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+118) (BuildId: 4e1f7dff9859f87a85bf606ccf092d4e)
native: #06 pc 000fd4e9 /system/lib/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+84) (BuildId: f8da374b10c090ef6df2144d297bf32f)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(BinderProxy.java:602)
at com.android.internal.telephony.ISms$Stub$Proxy.sendTextForSubscriber(ISms.java:1481)
at android.telephony.SmsManager$1.onSuccess(SmsManager.java:639)
at android.telephony.SmsManager.sendResolverResult(SmsManager.java:1651)
at android.telephony.SmsManager.resolveSubscriptionForOperation(SmsManager.java:1612)
at android.telephony.SmsManager.sendTextMessageInternal(SmsManager.java:634)
at android.telephony.SmsManager.sendMultipartTextMessageInternal(SmsManager.java:1076)
at android.telephony.SmsManager.sendMultipartTextMessage(SmsManager.java:1003)
at com.android.server.telecom.RespondViaSmsManager.rejectCallWithMessage(RespondViaSmsManager.java:217)
at com.android.server.telecom.RespondViaSmsManager.onIncomingCallRejected(RespondViaSmsManager.java:147)
at com.android.server.telecom.CallsManager.rejectCall(CallsManager.java:2901)
at com.android.server.telecom.InCallAdapter.rejectCall(InCallAdapter.java:128)
- locked <0x000060ed> (a com.android.server.telecom.TelecomSystem$1)
at com.android.internal.telecom.IInCallAdapter$Stub.onTransact(IInCallAdapter.java:350)
at android.os.Binder.execTransactInternal(Binder.java:1286)
at android.os.Binder.execTransact(Binder.java:1245)

为啥1400:1487一直不到释放锁呢，从Trace log中看到1400:1487与1793:2325进行交互

context binder
thread 1793: l 10 need_return 0 tr 0
outgoing transaction 899363: 0000000000000000 from 1793:1793 to 1400:3633 code 5 flags 10 pri 0:120 r1
transaction complete
thread 2325: l 01 need_return 0 tr 0
incoming transaction 898886: 0000000000000000 from 1400:1487 to 1793:2325 code 5 flags 10 pri 0:120 r1 node 39006 size 272:8 data 0000000000000000
buffer 898886: 0000000000000000 size 272:8:0 active
buffer 899156: 0000000000000000 size 12:0:0 delivered

2、1400:1487等待1793:2325

我们在看1793:2325的堆栈，它在处理什么呢

"binder:1793_8" prio=5 tid=74 Waiting
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x15dc3c70 self=0xc2482a10
| sysTid=2325 nice=0 cgrp=default sched=1073741824/0 handle=0xc1afb1c0
| state=S schedstat=( 934387147 1124625611 3593 ) utm=63 stm=30 core=2 HZ=100
| stack=0xc1a00000-0xc1a02000 stackSize=1004KB
| held mutexes=
at jdk.internal.misc.Unsafe.park(Native method)
- waiting on an unknown object
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1772)
at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3129)
at java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1799)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1974)
at com.android.internal.telephony.ims.ImsResolver.getConfiguredImsServicePackageName(ImsResolver.java:1040)
at com.android.internal.telephony.CarrierSmsUtils.getImsRcsPackage(CarrierSmsUtils.java:85)
at com.android.internal.telephony.CarrierSmsUtils.getImsRcsPackageForIntent(CarrierSmsUtils.java:50)
at com.android.internal.telephony.SMSDispatcher.getCarrierAppPackageName(SMSDispatcher.java:2801)
at com.android.internal.telephony.SMSDispatcher.sendSmsByCarrierApp(SMSDispatcher.java:1355)
at com.android.internal.telephony.SMSDispatcher.sendText(SMSDispatcher.java:1318)
at com.android.internal.telephony.SmsDispatchersController.sendText(SmsDispatchersController.java:809)
at com.android.internal.telephony.IccSmsInterfaceManager.sendTextInternal(IccSmsInterfaceManager.java:561)
at com.mediatek.internal.telephony.MtkIccSmsInterfaceManager.sendTextInternal(MtkIccSmsInterfaceManager.java:417)
at com.android.internal.telephony.IccSmsInterfaceManager.sendText(IccSmsInterfaceManager.java:474)
at com.android.internal.telephony.SmsController.sendIccText(SmsController.java:239)
at com.android.internal.telephony.SmsController.sendTextForSubscriber(SmsController.java:216)
at com.android.internal.telephony.ISms$Stub.onTransact(ISms.java:874)
at android.os.Binder.execTransactInternal(Binder.java:1286)
at android.os.Binder.execTransact(Binder.java:1245)

1793:2325相关线程处于waiting状态，此处需要看代码

packageNameFuture.get()，该函数卡在此处，为什么卡住呢？它需要等待mHandler post的那个runable 执行完毕后，等待才释放，而mHandler运行在主线程中，即1793

3、1793:2325等待1793:1793

1793:1793在干什么呢？导致一直不返回，从Trace中知道1793:1793与1400:3633进行binder交互

context binder
thread 1793: l 10 need_return 0 tr 0
outgoing transaction 899363: 0000000000000000 from 1793:1793 to 1400:3633 code 5 flags 10 pri 0:120 r1

"main" prio=5 tid=1 Native
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x713e81b8 self=0xf0242a10
| sysTid=1793 nice=0 cgrp=default sched=1073741824/0 handle=0xf752b470
| state=S schedstat=( 13556171224 13027625187 31126 ) utm=971 stm=383 core=1 HZ=100
| stack=0xff605000-0xff607000 stackSize=8188KB
| held mutexes=
native: #00 pc 000744ac /apex/com.android.runtime/lib/bionic/libc.so (__ioctl+8) (BuildId: 25891ab1dc6076962f6709f412e9da4e)
native: #01 pc 000404c7 /apex/com.android.runtime/lib/bionic/libc.so (ioctl+26) (BuildId: 25891ab1dc6076962f6709f412e9da4e)
native: #02 pc 00040827 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+206) (BuildId: 4e1f7dff9859f87a85bf606ccf092d4e)
native: #03 pc 000419f3 /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+42) (BuildId: 4e1f7dff9859f87a85bf606ccf092d4e)
native: #04 pc 0004179b /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+134) (BuildId: 4e1f7dff9859f87a85bf606ccf092d4e)
native: #05 pc 0003b92f /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+118) (BuildId: 4e1f7dff9859f87a85bf606ccf092d4e)
native: #06 pc 000fd4e9 /system/lib/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+84) (BuildId: f8da374b10c090ef6df2144d297bf32f)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(BinderProxy.java:602)
at com.android.internal.telecom.ITelecomService$Stub$Proxy.getCallCapablePhoneAccounts(ITelecomService.java:1583)
at android.telecom.TelecomManager.getCallCapablePhoneAccounts(TelecomManager.java:1368)
at android.telecom.TelecomManager.getCallCapablePhoneAccounts(TelecomManager.java:1291)
at com.android.phone.vvm.CarrierVvmPackageInstalledReceiver.onReceive(CarrierVvmPackageInstalledReceiver.java:78)
at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$getRunnable$0$android-app-LoadedApk$ReceiverDispatcher$Args(LoadedApk.java:1809)
at android.app.LoadedApk$ReceiverDispatcher$Args$$ExternalSyntheticLambda0.run(unavailable:2)
at android.os.Handler.handleCallback(Handler.java:942)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loopOnce(Looper.java:204)
at android.os.Looper.loop(Looper.java:291)
at android.app.ActivityThread.main(ActivityThread.java:8154)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:601)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1136)

1793:1793此时在收一个广播，而这个广播和Telecom进行交互

4、1793:1793等待1400:3633

我们需要看下1400:3633在做什么呢，为啥1793:1793的广播无法很快返回呢?

"binder:1400_E" prio=5 tid=257 Blocked
| group="main" sCount=1 ucsCount=0 flags=1 obj=0x1464b290 self=0xbc4e3010
| sysTid=3633 nice=0 cgrp=default sched=1073741824/0 handle=0xa953c1c0
| state=S schedstat=( 6045942672 7249409656 14813 ) utm=444 stm=160 core=7 HZ=100
| stack=0xa9441000-0xa9443000 stackSize=1004KB
| held mutexes=
at com.android.server.telecom.TelecomServiceImpl$1.getCallCapablePhoneAccounts(TelecomServiceImpl.java:230)
- waiting to lock <0x000060ed> (a com.android.server.telecom.TelecomSystem$1) held by thread 68
at com.android.internal.telecom.ITelecomService$Stub.onTransact(ITelecomService.java:776)
at android.os.Binder.execTransactInternal(Binder.java:1286)
at android.os.Binder.execTransact(Binder.java:1245)

从Trace看1400:3633也在等这个锁waiting to lock <0x000060ed>，这个锁谁持有呢？

从上面的分析知道1400:1487持有这个锁

5、1400:3633等待1400:1487

将这些锁归纳下：

1、1400:1400等待1400:1487

2、1400:1487等待1793:2325

3、1793:2325等待1793:1793

4、1793:1793等待1400:3633

5、1400:3633等待1400:1487

有发现什么规律吗？2-5两个进程不同线程之间形成了死锁状态

另外，1400 binder耗尽，且1400:1400处于Block状态