引言
开机时启动客户定制服务,概率性导致开机非常缓慢,正常开机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$10.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释放
这样导致了死锁。
解决方案
这里就不贴详细解决方案,只需调整客制化服务启动的时间点,根据客户具体需求定制,测试没问题即可。