开机时启动客户定制服务，概率性导致开机非常缓慢，正常开机50秒左右，异常开机达到2~4分钟
记录问题分析过程。
废话不多说，直接上日志，定位到异常日志位置
12-27 17:26:02.864 4469 4806 I Process : Sending signal. PID: 4469 SIG: 3 12-27 17:26:02.864 4469 4472 I art : Thread[2,tid=4472,WaitingInMainSignalCatcherLoop,Thread*=0x9b9a3800,peer=0x12c010d0,"Signal Catcher"]: reacting to signal 3 12-27 17:26:02.864 4469 4472 I art : 12-27 17:26:03.290 4469 4737 E WifiHAL : Error polling socket 12-27 17:26:03.374 4469 4472 I art : Wrote stack traces to '/data/anr/traces.txt' 12-27 17:26:03.375 4469 4806 I Process : Sending signal. PID: 4858 SIG: 3 12-27 17:26:03.375 4858 4878 I art : Thread[3,tid=4878,WaitingInMainSignalCatcherLoop,Thread*=0x9b9a3d00,peer=0x12c20280,"Signal Catcher"]: reacting to signal 3 12-27 17:26:03.375 4858 4878 I art : 12-27 17:26:03.568 4858 4878 I art : Wrote stack traces to '/data/anr/traces.txt' 12-27 17:26:03.584 260 260 W : debuggerd: handling request: pid=486 uid=1000 gid=1003 tid=486 12-27 17:26:03.725 260 260 W : debuggerd: resuming target 486 12-27 17:26:03.727 260 260 W : debuggerd: handling request: pid=603 uid=1041 gid=1005 tid=603 12-27 17:26:03.858 260 260 W : debuggerd: resuming target 603 12-27 17:26:03.859 260 260 W : debuggerd: handling request: pid=607 uid=1047 gid=1005 tid=607 12-27 17:26:03.916 260 260 W : debuggerd: resuming target 607 12-27 17:26:03.917 260 260 W : debuggerd: handling request: pid=620 uid=1019 gid=1019 tid=620 12-27 17:26:03.948 260 260 W : debuggerd: resuming target 620 12-27 17:26:03.950 260 260 W : debuggerd: handling request: pid=633 uid=1046 gid=1006 tid=633 12-27 17:26:04.002 260 260 W : debuggerd: resuming target 633 12-27 17:26:04.004 260 260 W : debuggerd: handling request: pid=637 uid=1013 gid=1031 tid=637 12-27 17:26:04.034 260 260 W : debuggerd: resuming target 637 12-27 17:26:04.036 260 260 W : debuggerd: handling request: pid=638 uid=1040 gid=1026 tid=638 12-27 17:26:04.092 260 260 W : debuggerd: resuming target 638 12-27 17:26:04.093 260 260 W : debuggerd: handling request: pid=642 uid=1013 gid=1005 tid=642 12-27 17:26:04.153 260 260 W : debuggerd: resuming target 642 12-27 17:26:04.155 260 260 W : debuggerd: handling request: pid=4555 uid=1002 gid=1002 tid=4555 12-27 17:26:05.991 260 260 W : debuggerd: resuming target 4555 12-27 17:26:05.992 260 260 W : debuggerd: handling request: pid=4631 uid=1023 gid=1023 tid=4631 12-27 17:26:06.022 260 260 W : debuggerd: resuming target 4631 12-27 17:26:06.023 260 260 W : debuggerd: handling request: pid=4833 uid=1023 gid=1023 tid=4833 12-27 17:26:06.052 260 260 W : debuggerd: resuming target 4833 12-27 17:26:06.185 1133 1293 W XTCC-5.1.0.19-d: [CS-RIL-LISTENER] timerCallback fired for ril update registering, re-register 12-27 17:26:08.053 4469 4806 I Watchdog_N: dumpKernelStacks 12-27 17:26:08.134 4469 4806 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.am.ActivityManagerService on foreground thread (android.fg), Blocked in handler on main thread (main), Blocked in handler on ui thread (android.ui), Blocked in handler on display thread (android.display), Blocked in handler on ActivityManager (ActivityManager) 12-27 17:26:08.134 4469 4806 W Watchdog: foreground thread stack trace: 12-27 17:26:08.134 4469 4806 W Watchdog: at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:22432) 12-27 17:26:08.134 4469 4806 W Watchdog: at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:184) 12-27 17:26:08.134 4469 4806 W Watchdog: at android.os.Handler.handleCallback(Handler.java:751) 12-27 17:26:08.134 4469 4806 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:95) 12-27 17:26:08.134 4469 4806 W Watchdog: at android.os.Looper.loop(Looper.java:154) 12-27 17:26:08.134 4469 4806 W Watchdog: at android.os.HandlerThread.run(HandlerThread.java:61) 12-27 17:26:08.134 4469 4806 W Watchdog: at com.android.server.ServiceThread.run(ServiceThread.java:46) 12-27 17:26:08.134 4469 4806 W Watchdog: main thread stack trace: 12-27 17:26:08.135 4469 4806 W Watchdog: at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:19267) 12-27 17:26:08.135 4469 4806 W Watchdog: at android.app.ActivityManagerNative.broadcastStickyIntent(ActivityManagerNative.java:111) 12-27 17:26:08.135 4469 4806 W Watchdog: at android.app.ActivityManagerNative.broadcastStickyIntent(ActivityManagerNative.java:101) 12-27 17:26:08.135 4469 4806 W Watchdog: at com.android.server.BatteryService.run(BatteryService.java:670) 12-27 17:26:08.135 4469 4806 W Watchdog: at android.os.Handler.handleCallback(Handler.java:751) 12-27 17:26:08.135 4469 4806 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:95) 12-27 17:26:08.135 4469 4806 W Watchdog: at android.os.Looper.loop(Looper.java:154) 12-27 17:26:08.135 4469 4806 W Watchdog: at com.android.server.SystemServer.run(SystemServer.java:363) 12-27 17:26:08.135 4469 4806 W Watchdog: at com.android.server.SystemServer.main(SystemServer.java:230) 12-27 17:26:08.135 4469 4806 W Watchdog: at java.lang.reflect.Method.invoke(Native Method) 12-27 17:26:08.135 4469 4806 W Watchdog: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:889) 12-27 17:26:08.135 4469 4806 W Watchdog: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:779) 12-27 17:26:08.135 4469 4806 W Watchdog: ui thread stack trace: 12-27 17:26:08.136 4469 4806 W Watchdog: at com.android.server.am.ActivityManagerService$UiHandler.handleMessage(ActivityManagerService.java:1764) 12-27 17:26:08.136 4469 4806 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:102) 12-27 17:26:08.136 4469 4806 W Watchdog: at android.os.Looper.loop(Looper.java:154) 12-27 17:26:08.136 4469 4806 W Watchdog: at android.os.HandlerThread.run(HandlerThread.java:61) 12-27 17:26:08.136 4469 4806 W Watchdog: at com.android.server.ServiceThread.run(ServiceThread.java:46) 12-27 17:26:08.136 4469 4806 W Watchdog: display thread stack trace: 12-27 17:26:08.136 4469 4806 W Watchdog: at com.android.server.am.ActivityManagerService.startService(ActivityManagerService.java:17866) 12-27 17:26:08.136 4469 4806 W Watchdog: at android.app.ContextImpl.startServiceCommon(ContextImpl.java:1377) 12-27 17:26:08.136 4469 4806 W Watchdog: at android.app.ContextImpl.startService(ContextImpl.java:1359) 12-27 17:26:08.136 4469 4806 W Watchdog: at com.android.server.wm.WindowManagerService.startMyCoreService(WindowManagerService.java:6247) 12-27 17:26:08.137 4469 4806 W Watchdog: at com.android.server.wm.WindowManagerService.performEnableScreen(WindowManagerService.java:6329) 12-27 17:26:08.137 4469 4806 W Watchdog: at com.android.server.wm.WindowManagerService$H.handleMessage(WindowManagerService.java:8954) 12-27 17:26:08.137 4469 4806 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:102) 12-27 17:26:08.137 4469 4806 W Watchdog: at android.os.Looper.loop(Looper.java:154) 12-27 17:26:08.137 4469 4806 W Watchdog: at android.os.HandlerThread.run(HandlerThread.java:61) 12-27 17:26:08.137 4469 4806 W Watchdog: at com.android.server.ServiceThread.run(ServiceThread.java:46) 12-27 17:26:08.137 4469 4806 W Watchdog: ActivityManager stack trace: 12-27 17:26:08.137 4469 4806 W Watchdog: at com.android.server.am.BroadcastQueue.processNextBroadcast(BroadcastQueue.java:762) 12-27 17:26:08.137 4469 4806 W Watchdog: at com.android.server.am.BroadcastQueue$BroadcastHandler.handleMessage(BroadcastQueue.java:172) 12-27 17:26:08.137 4469 4806 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:102) 12-27 17:26:08.137 4469 4806 W Watchdog: at android.os.Looper.loop(Looper.java:154) 12-27 17:26:08.137 4469 4806 W Watchdog: at android.os.HandlerThread.run(HandlerThread.java:61) 12-27 17:26:08.137 4469 4806 W Watchdog: at com.android.server.ServiceThread.run(ServiceThread.java:46) 12-27 17:26:08.137 4469 4806 W Watchdog: *** GOODBYE! 12-27 17:26:08.137 4469 4806 I Process : Sending signal. PID: 4469 SIG: 9 12-27 17:26:08.233 4586 4892 W Sensors : sensorservice died [0x9bfc2cc0] 12-27 17:26:08.234 485 485 I ServiceManager: service 'telecom' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'graphicsstats' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'print' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'restrictions' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'media_session' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'shortcut' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'launcherapps' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'media_projection' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'imms' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'trust' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'media_router' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'bluetooth_manager' died 12-27 17:26:08.234 4586 4586 D AndroidRuntime: Shutting down VM 12-27 17:26:08.234 485 485 I ServiceManager: service 'connectivity_metrics_logger' died 12-27 17:26:08.234 485 485 I ServiceManager: service 'connmetrics' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'netd_listener' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'contexthub_service' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'package' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'otadexopt' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'user' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'activity' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'procstats' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'meminfo' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'gfxinfo' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'dbinfo' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'cpuinfo' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'permission' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'processinfo' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'sensorservice' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'battery' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'usagestats' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'webviewupdate' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'scheduling_policy' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'telephony.registry' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'media.camera.proxy' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'account' died 12-27 17:26:08.235 485 485 I ServiceManager: service 'content' died
从ServiceManager的日志可以看到，系统服务都挂掉了，然后system_server重新启动，如此往复最后导致开始缓慢。
接着看一下日志的开头，Wrote stack traces to '/data/anr/traces.txt’字样，妥妥的ANR无疑了
stack trace信息里面，还能看到客制化的方法startMyCoreService()，自己挖的坑，还是得自己填…
这里贴一下startSMyCoreService()方法的代码，仅仅只是启动客户的服务，没想到导致这么严重的问题
private void startSMyCoreService(Context context){
Intent intent = new Intent("my.action.system.FIRMWARE_SERVER");
intent.setPackage("com.my.system.sdk");
context.startService(intent);
}
不多说，把/data/anr/traces.txt导出来分析一下，查找startMyCoreService字段，找到如下信息：
"android.display" prio=5 tid=18 Blocked | group="main" sCount=1 dsCount=0 obj=0x12cb2ba0 self=0x97b0b900 | sysTid=4445 nice=-4 cgrp=default sched=0/0 handle=0x97297920 | state=S schedstat=( 439854791 240361668 556 ) utm=35 stm=8 core=3 HZ=100 | stack=0x97195000-0x97197000 stackSize=1038KB | held mutexes= at com.android.server.am.ActivityManagerService.startService(ActivityManagerService.java:17866) - waiting to lock <0x02e6d8e0> (a com.android.server.am.ActivityManagerService) held by thread 9 at android.app.ContextImpl.startServiceCommon(ContextImpl.java:1377) at android.app.ContextImpl.startService(ContextImpl.java:1359) at com.android.server.wm.WindowManagerService.startMyCoreService(WindowManagerService.java:6247) at com.android.server.wm.WindowManagerService.performEnableScreen(WindowManagerService.java:6329) - locked <0x0f9ec799> (a java.util.HashMap) at com.android.server.wm.WindowManagerService$H.handleMessage(WindowManagerService.java:8954) at android.os.Handler.dispatchMessage(Handler.java:102) at android.os.Looper.loop(Looper.java:154) at android.os.HandlerThread.run(HandlerThread.java:61) at com.android.server.ServiceThread.run(ServiceThread.java:46)
当代码运行到locked <0x0f9ec799>时，持有了锁<0x0f9ec799>（锁A）
继续向下运行，到waiting to lock <0x02e6d8e0>，等待锁<0x02e6d8e0>（锁B）释放
继续在日志里面搜索0x02e6d8e0字段，找到如下信息：
"Binder:4414_2" prio=5 tid=9 Blocked | group="main" sCount=1 dsCount=0 obj=0x12c01790 self=0xa09a5b00 | sysTid=4427 nice=-2 cgrp=default sched=0/0 handle=0x97cb1920 | state=S schedstat=( 375727911 379066966 1202 ) utm=20 stm=17 core=0 HZ=100 | stack=0x97bb5000-0x97bb7000 stackSize=1014KB | held mutexes= at com.android.server.wm.WindowManagerService.deferSurfaceLayout(WindowManagerService.java:5575) - waiting to lock <0x0f9ec799> (a java.util.HashMap) held by thread 18 at com.android.server.am.ActivityManagerService.updateConfigurationLocked(ActivityManagerService.java:19709) at com.android.server.am.ActivityManagerService.updateConfigurationLocked(ActivityManagerService.java:19687) at com.android.server.am.ActivityManagerService.updateConfigurationLocked(ActivityManagerService.java:19681) at com.android.server.am.ActivityManagerService.updateConfiguration(ActivityManagerService.java:19667) - locked <0x02e6d8e0> (a com.android.server.am.ActivityManagerService) at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:1224) at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2972) at android.os.Binder.execTransact(Binder.java:565)
可以看到代码运行到locked <0x02e6d8e0>，持有了锁<0x02e6d8e0>（锁B）
继续运行到waiting to lock <0x0f9ec799>时，等到锁<0x0f9ec799>（锁A）释放
简而言之就是：
Binder:4414_2持有锁B，等待锁A释放 android.display持有锁A，等待锁B释放
这样导致了死锁。
解决方案这里就不贴详细解决方案，只需调整客制化服务启动的时间点，根据客户具体需求定制，测试没问题即可。
欢迎分享，转载请注明来源：内存溢出
微信扫一扫
支付宝扫一扫
评论列表（0条）