问题描述
开机时间相对参考机过慢,大约慢15s左右。Android 系统7.0。
问题分析
开机问题涉及的层次较多,大致有bootloader–>kernel–>Zygote–>PMS–>AMS–>Launcher
可以借助bootchart来分析,也可以直接通过log分析。不幸的是本项目机器因未知原因导致无法抓取到bootchart。
幸好在我浏览源码时发现了一个神器perfboot工具。具体在system/core/init/perfboot.py。
运行该命令需要在源码编译环境下。详细请参考源码文件,此处不做过多介绍。
使用命令:
./perfboot.py --iterations=5 --interval=30 -v --output=boot_time.tsv
获取问题机与参考机的开机数据。生成下图
上图X轴是开机启动过程中的一些重要节点。Y轴是开机时间。
详细说明下X轴上各个节点表征的含义。
boot_progress_start | 系统进入用户空间,标志着kernel启动完成,本例中可以看出kernel启动耗时30s左右 |
---|---|
boot_progress_preload_start | Zygote启动 |
boot_progress_preload_end | Zygote结束 |
boot_progress_system_run | SystemServer ready,开始启动Android系统服务,如PMS,APMS等 |
boot_progress_pms_start | PMS开始扫描安装的应用 |
boot_progress_pms_system_scan_start | PMS先行扫描/system目录下的安装包 |
boot_progress_pms_data_scan_start | PMS扫描/data目录下的安装包 |
boot_progress_pms_scan_end | PMS扫描结束 |
boot_progress_pms_ready | PMS就绪 |
boot_progress_ams_ready | AMS就绪 |
boot_progress_enable_screen | AMS启动完成后开始激活屏幕,从此以后屏幕才能响应用户的触摸,它在WindowManagerService发出退出开机动画的时间节点之前,而真正退出开机动画还会花费少许时间,具体依赖animation zip 包中的desc.txt。wm_boot_animation_done才是用户感知到的动画结束时间节点 |
sf_stop_bootanim | SF设置service.bootanim.exit属性值为1,标志系统要结束开机动画了,可以用来跟踪开机动画结尾部分消耗的时间 |
wm_boot_animation_done | 开机动画结束,这一步用户能直观感受到开机结束 |
通过上图可以直观的看到问题机在进入boot_progress_start节点之前相对参考机耗时较多。而这之前主要涉及bootloader和kernel。
bootloader 优化
这一块没有接触过,交给底层同事优化。大概说下抓取log的方式.
adb shell cat /proc/bootmsg > bootmsg.txt.
从log里底层同事发现是bootimg签名有问题,更详细的分析,自己对这块真心不懂,总结不出帮助性的意见。
kernel层优化
kernel的优化先check一遍config的配置,kernel中config的配置种类繁多,就算是工作几年的kernel工程师也不一定能清楚每一个config值的作用。Android提供了一个基础配置表。
可以用脚本:kernel/scripts/kconfig/merge_config.sh来生成一份config文件。具体用法戳这
拿生成的config文件和当前项目中的config做对比,同时也对比参考机的config文件。对比的时候可以用一个现成的工具kernel/scripts/diffconfig来比较。
综合比较后的结果,本地一点点调试,查找资料。最终去掉了如下config:
CONFIG_MTD_TESTS=m ----> m改为n
CONFIG_SERIAL_MSM_HSL=y ----> y改为n
CONFIG_SERIAL_MSM_HSL_CONSOLE=y ----> y改为n
CONFIG_MMC_BLOCK_TEST=m ---->注释掉
CONFIG_MMC_TEST=m ---->注释掉
CONFIG_SERIAL_MSM_HSL=y ----> y改为n
CONFIG_SERIAL_MSM_HSL_CONSOLE=y ----> y改为n
CONFIG_MSM_SMD_DEBUG=y ---->注释掉
CONFIG_CGROUP_DEBUG=y ---->注释掉
CONFIG_RELAY=y ---->注释掉
CONFIG_RMNET_DATA_DEBUG_PKT=y ---->注释掉
CONFIG_DEBUG_GPIO=y ---->注释掉
CONFIG_CORESIGHT=y ---->注释掉
CONFIG_CORESIGHT_EVENT=y ---->注释掉
CONFIG_CORESIGHT_FUSE=y ---->注释掉
CONFIG_CORESIGHT_CTI=y ---->注释掉
CONFIG_CORESIGHT_TMC=y ---->注释掉
CONFIG_CORESIGHT_TPIU=y ---->注释掉
CONFIG_CORESIGHT_FUNNEL=y ---->注释掉
CONFIG_CORESIGHT_REPLICATOR=y ---->注释掉
CONFIG_CORESIGHT_STM=y ---->注释掉
CONFIG_CORESIGHT_HWEVENT=y ---->注释掉
CONFIG_DEBUG_MEMORY_INIT=y ---->注释掉
CONFIG_DYNAMIC_DEBUG=y ---->注释掉
//以下也全部注释掉
CONFIG_SCHED_DEBUG
CONFIG_DEBUG_KMEMLEAK
CONFIG_DEBUG_KMEMLEAK_EARLY_LOG_SIZE=400
CONFIG_DEBUG_KMEMLEAK_DEFAULT_OFF
CONFIG_DEBUG_SPINLOCK
CONFIG_DEBUG_MUTEXES
CONFIG_DEBUG_ATOMIC_SLEEP
CONFIG_DEBUG_STACK_USAGE
CONFIG_DEBUG_LIST
CONFIG_FAULT_INJECTION_DEBUG_FS
CONFIG_LOCKUP_DETECTOR
CONFIG_DEBUG_PAGEALLOC
CONFIG_PAGE_POISONING
CONFIG_RMNET_DATA_DEBUG_PKT
CONFIG_MMC_PERF_PROFILING
CONFIG_DEBUG_BUS_VOTER
CONFIG_SLUB_DEBUG
CONFIG_DEBUG_BUGVERBOSE
CONFIG_ALLOC_BUFFERS_IN_4K_CHUNK
CONFIG_SERIAL_CORE
CONFIG_SERIAL_CORE_CONSOLE
CONFIG_SERIAL_MSM_HSL
CONFIG_SERIAL_MSM_HSL_CONSOLE
CONFIG_MSM_TZ_LOG
CONFIG_DYNAMIC_DEBUG
这里说下config的配置有y,n,m,m表示编译成模块,不编译进内核。不配置的话相当于n。
CONFIG_DEBUG_INFO 不能去掉, 会引起CTS不过。由于config的的各项值可能散落在kernel的不同文件中,我们可以单独编译下kernel,然后去out目录下查看obj/KERNEL_OBJ/.config 文件,这里面的配置项是完全的。
kernel关闭掉一些debug开关后。在新版本上复测结果如下:
这里提下如何看kernel的log,
开机后用命令:adb shell dmesg > dmesg.txt抓取Log
log里面搜关键字”Bootloader start count”–>LK 启动
“Bootloader end count”–>LK 结束
“Kernel MPM timestamp”–>bootloader运行完成
通过对bootloader和kernel的优化,直接减少了14s左右的开机时间,可以看到优化的效果还是比较明显的。
frameworks层优化
用命令: adb logcat -b events|grep boot
我们过滤出启动阶段的主要事件。
01-01 13:38:52.139 391 391 I boot_progress_start: 15452
01-01 13:38:53.329 391 391 I boot_progress_preload_start: 16641
01-01 13:38:56.675 391 391 I boot_progress_preload_end: 19989
01-01 13:38:57.020 1729 1729 I boot_progress_system_run: 20333
01-01 13:38:57.824 1729 1729 I boot_progress_pms_start: 21137
01-01 13:38:58.865 1729 1729 I boot_progress_pms_system_scan_start: 22179
01-01 13:39:08.852 1729 1729 I boot_progress_pms_data_scan_start: 32166
01-01 13:39:08.907 1729 1729 I boot_progress_pms_scan_end: 32221
01-01 13:39:10.109 1729 1729 I boot_progress_pms_ready: 33422
01-01 13:39:12.557 1729 1729 I boot_progress_ams_ready: 35871
01-01 13:39:15.189 1729 1782 I boot_progress_enable_screen: 38503
01-01 13:39:17.973 290 321 I sf_stop_bootanim: 41287
01-01 13:39:18.887 1729 1961 I wm_boot_animation_done: 42201
结合对比图看,boot_progress_enable_screen之前问题机跟对比机各个节点耗时相差不大。在这里说明下,Android M上启动阶段到boot_progress_enable_screen就结束了,而Android N上还多了sf_stop_bootanim和wm_boot_animation_done两个事件。这也就是图-优化kernel后棕红色的线条到boot_progress_enable_screen就没有延生的原因,因为它表示的参考机,而参考机正好是Android M系统。
从log的时间戳可以看出:
boot_progress_enable_screen—>花费2s左右的时间到达sf_stop_bootanim—>花费1s多时间到达wm_boot_animation_done。多出来的两个过程总共多花接近4s的时间。
我们要重点看下这个过程发生了什么,为什么会多出来这近4s时间。
1.先看下boot_progress_enable_screen出现的位置。
它在frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
void enableScreenAfterBoot() {
EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_ENABLE_SCREEN,
SystemClock.uptimeMillis());
mWindowManager.enableScreenA