开机性能优化时间对比法-通过events日志部分实战

背景：

在很多同学做开启时间性能优化相关工作时候，经常用的比较多的方法肯定是抓取开机的perfetto或者systrace方法，这种方法当然是比较准确，一般抓取这个时候都是开始准备比较细微的局部优化。这个开机perfetto抓取方法已经在前面blog有进行介绍
性能优化：官方文档抓取开机trace给perfetto分析–Recording traces on Android boot
今天来给大家介绍另一种开机启动根据event日志log来进行粗略的瓶颈定位和检验优化成果指标的方式。

log日志查看开机过程实战：

涉及开机流程核心log如下

    'boot_progress_start',
    'boot_progress_preload_start',
    'boot_progress_preload_end',
    'boot_progress_system_run',
    'boot_progress_pms_start',
    'boot_progress_pms_system_scan_start',
    'boot_progress_pms_data_scan_start',
    'boot_progress_pms_scan_end',
    'boot_progress_pms_ready',
    'boot_progress_ams_ready',
    'boot_progress_enable_screen',
    'sf_stop_bootanim',
    'wm_boot_animation_done',

抓取方式：
需要使用adb logcat -b all或者-b events来抓取所有日志才可以

adb logcat -b all | grep -E "boot_p|sf_stop|wm_boot" 
adb logcat -b events | grep -E "boot_p|sf_stop|wm_boot"

使用后结果如下：

adb logcat -b all | grep -E "boot_p|sf_stop|wm_boot" 
03-29 05:23:06.836   903   903 I boot_progress_start: 11143
03-29 05:23:08.586   903   903 I boot_progress_preload_start: 12894
03-29 05:23:13.004   903   903 I boot_progress_preload_end: 17311
03-29 05:23:14.077  1700  1700 I boot_progress_system_run: 18384
03-29 05:23:15.547  1700  1700 I boot_progress_pms_start: 19854
03-29 05:23:16.374  1700  1700 I boot_progress_pms_system_scan_start: 20681
03-29 05:23:19.149  1700  1700 I boot_progress_pms_data_scan_start: 23456
03-29 05:23:19.198  1700  1700 I boot_progress_pms_scan_end: 23505
03-29 05:23:19.531  1700  1700 I boot_progress_pms_ready: 23838
03-09 15:55:58.370  1700  1700 I boot_progress_ams_ready: 27043
03-09 15:56:00.644  1700  1773 I boot_progress_enable_screen: 29318
03-09 15:56:08.079   998  1327 I sf_stop_bootanim: 36753
03-09 15:56:08.080  1700  1773 I wm_boot_animation_done: 36754

上面都是毫秒为单位，有了这个时间指标就可以拿来作为优化前后对比，或者各个机器之间的䶏。

它们分别代表各个阶段意义如下：

boot_progress_start

代表着Android屏幕点亮，开始显示启动动画，标志着kernel启动完成，本例中可以看出kernel启动耗时

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。

sf_stop_bootanim
SF设置service.bootanim.exit属性值为1，标志系统要结束开机动画了，可以用来跟踪开机动画结尾部分消耗的时间

wm_boot_animation_done
开机动画结束，这一步用户能直观感受到开机结束

以上log可能过多，这里进行一下相关分类

Kernel part : boot_progress_start
Zygote time : boot_progress_preload_end - boot_progress_preload_start
/system Scan time : boot_progress_pms_data_scan_start - boot_progress_pms_system_scan_start
/data Scan time : boot_progress_pms_scan_end- boot_progress_pms_data_scan_start
Home activity start time : boot_progress_enable_screen- boot_progress_ams_ready

日志来源的源码：

有时候想要了解上面日志具体是在哪个时候进统计打印的时间，需要查询相关的源码，那么一般如何查找boot_progress_*相关日志打印的代码呢？

这里有个技巧哈，因为是events日志打印出来的，所以可以直接代码中进行查找，但是查找如果自己grep这个日志的tag会有如下结果：

grep boot_progress_enable_screen ./ -rn

./base/services/core/java/com/android/server/am/EventLogTags.logtags:11:3050 boot_progress_enable_screen (time|2|3)

发现只是找到了EventLogTags，所以要进行一下转换，转换方式如下：

boot_progress_enable_screen去除下划线"_"而且首字母大写，变成如下：
BootProgressEnableScreen
然后使用这个字符进行grep既可以。

grep BootProgressEnableScreen ./ -rn
./base/services/art-wear-profile:6289:PLcom/android/server/am/EventLogTags;->writeBootProgressEnableScreen(J)V
./base/services/core/java/com/android/server/wm/ActivityTaskManagerService.java:97:import static com.android.server.am.EventLogTags.writeBootProgressEnableScreen;
./base/services/core/java/com/android/server/wm/ActivityTaskManagerService.java:6337:            writeBootProgressEnableScreen(SystemClock.uptimeMillis());

可以看看ActivityTaskManagerService.java:6337行

更多framework实战开发干货，请关注下面“千里马学框架”