android 7.1 刷机后第一次开机概率性缓慢（2~4分钟）--ANR
2024-05-27 05:16:25
引言
开机时启动客户定制服务，概率性导致开机非常缓慢，正常开机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 9at 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 18at 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释放
这样导致了死锁。
解决方案
这里就不贴详细解决方案，只需调整客制化服务启动的时间点，根据客户具体需求定制，测试没问题即可。
android 7.1 刷机后第一次开机概率性缓慢（2~4分钟）--ANR相关推荐
- Android系统刷机后第一次启动很慢的原因
转自:Android系统刷机后第一次启动很慢的原因 - 走看看 在做Android内核开发的过程中,我们会发现,每次编译完系统源码,烧录到设备/手机中后,第一次启动都会很慢很慢,要好几分钟甚至十几分钟 ...
- 小米一直显示在android,小米三刷机失败！开机一直显示power by android
满意答案 siemf12165 推荐于 2016.11.04 采纳率:51% 等级:7 已帮助:410人 小米三刷机失败后开机一直显示power by android可以通过重新升级固件的方法解 ...
- Android内核开发：为什么刷机后系统第一次启动会很慢？
转自:http://ticktick.blog.51cto.com/823160/1677216 在做Android内核开发的过程中,我们会发现,每次编译完系统源码,烧录到设备/手机中后,第一次启动都 ...
- android htc G13刷机初探
很多朋友对刷机都是一头雾水,每天都在听说刷机刷机,但就是不知道刷机是什么,自己也想尝试一下,但又不知道该如何操作,其实不要把它想的多复杂,只要你按照下面的步骤来做,你也能给自己的android手机刷个 ...
- android电脑不识别手机号码,安卓手机刷机后电脑不识别怎么办 如何让电脑重新识别手机...
安卓手机刷机后电脑不识别应该怎么办? 刷机就是通过软件技术手段获得较高的管理权限及较好的使用体验,或者更改或替换了手机原版系统中固有的一些语言.图片.铃声和软件版本或者操作系统,以达到系统的优化或自己 ...
- android 刷机 备份,安卓刷机后如何还原以前ROM和系统备份
核心提示:本教程为大家介绍刷机后如何还原到以前的ROM和系统备份. 很多人,看到了好多新的rom,包括测试版的新rom,心里痒痒的.想刷一刷.尝尝鲜,结果刷完.感觉新的rom 还没有我现在用的rom好 ...
- 刷机命令android手机刷机后，wifi无法使用的解决方法
刷机命令android手机刷机后,wifi无法使用的解决方法 https://blog.csdn.net/wxz1179503422/article/details/83031909
- android 刷机后熄屏断网
情况说明 我的黑鲨1代刷机后,部署了Linux系统,但是只要熄屏后过一会儿就无法访问网络了.尝试了修改电量管理.关闭省电模式等,均无效. 经过很久很久的测试,终于找到了原因.Android6.0或更高 ...
- 小米android手机怎么刷机,刷机如此简单 小米手机四种刷机方法
完整包刷机 完整包刷机适用于MIUI的升级.降级,开发版与稳定版的互刷,甚至是刷原生系统或者点心OS,是最灵活也是大家最想得到的刷机方式,这种升级 方式没有其他厂商提供,而用户在其他品牌上选择这种刷机 ...
最新文章
- 理解神经网络，从简单的例子开始（2）使用python建立多层神经网络
- Android 调试 Release 包(debuggable)
- LeetCode 145 ——二叉树的后序遍历
- QT信号和槽函数学习笔记
- python spider怎么用_python爬虫入门（七）Scrapy框架之Spider类
- 34 年了，“杀”不死的 Perl！
- Error loading WebappClassLoader解决方法
- 主程序与子程序不在同一程序模块中_数控车床子程序M98、M99编程实例！
- 操作系统--内存管理超详细整理！
- 简易图解N合1集成安装光盘制作教程
- Android实现头像上传至数据库与保存 简易新闻（十七 下）
- 【数据科学家学习小组】之统计学（第二期）第一周（20191028-20191103)-momi
- 液晶面板价格持续上涨，中国面板企业迎来赶超韩国面板企业的机会
- 建“数字风洞”，永信至诚开启安全测试评估专业赛道
- 史上最全的python的web开发和网络编程【附属详细解释+案例】
- linux装好了启动不了系统,Linux系统不能启动怎么办
- 贾小伟—Web前端开发工程师（作品集）
- 机器学习从入门到创业手记-2.1.2 逻辑回归与选择恐惧症
- java程序在运行时，总是出现冲突的错误的解决办法。
- 总结：java.lang包