Android开机启动时间优化及bootchart工具使用

做性能优化绕不开开机启动时间的优化,用户往往都希望自己的机器能够快速的启动,这种强烈的需求覆盖各种电子设备,本篇主要简单的介绍Android设备启动时间的计时工具——bootchart以及简单的优化。

1. bootchart工具的使用

Bootchart是一个用于Linux启动过程性能分析的开源软件工具,以可视化的方式对GUN/Linux的开机启动过程进行性能分析,包括资源的使用(如CPU,磁盘等),各进程的执行时间信息等。根据分析结果,确定系统启动的性能瓶颈,制定相应的优化策略。由于Android系统是基于Linux的,所以我们可以使用Bootchart来分析开机性能。实际上在Android中已经集成了Bootchart这一开源工具供我们使用,只是在Android5.1之前默认是没有编译进系统的,需要我们手动编译进去使用,这里不再赘述在Android5.1以下系统如何使用Bootchart,从Android6.0开始,Google已经在Android系统中默认集成了Bootchart,adb shell命令进入设备后,可以看到有一个/data/bootchart目录。因为bootchart本身会影响性能,所以默认没有打开Bootchart开关,/data/bootchart目录下什么东西都没有。下面介绍在Android O中的使用方法:

  • adb shell touch /data/bootchart/enabled

  • 重新启动设备,启动后会发现在/data/bootchart/目录下生成了如下文件:

    1
    2
    3
    4
    5
    6
    7
    adb shell ls -l data/bootchart/
    total 4792
    -rw-rw-rw- 1 root root 0 2018-03-13 10:58 enabled
    -rw-rw-rw- 1 root root 1115 1970-02-02 00:32 header
    -rw-rw-rw- 1 root root 180357 2018-03-13 11:18 proc_diskstats.log
    -rw-rw-rw- 1 root root 4635657 2018-03-13 11:18 proc_ps.log
    -rw-rw-rw- 1 root root 80531 2018-03-13 11:18 proc_stat.log

  • 电脑连接手机,执行android源码中的脚本:./system/core/init/grab-bootchart.sh,随后就会在执行命令的目录下生成bootchart.png

1.1 grab-bootchart.sh

先来看一下脚本内容:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
#!/bin/sh
#
# This script is used to retrieve a bootchart log generated by init.
# All options are passed to adb, for better or for worse.
# See the readme in this directory for more on bootcharting.

TMPDIR=/tmp/android-bootchart
rm -rf $TMPDIR
mkdir -p $TMPDIR

LOGROOT=/data/bootchart
TARBALL=bootchart.tgz

FILES="header proc_stat.log proc_ps.log proc_diskstats.log"

for f in $FILES; do
# 把手机中/data/bootchart生成的文件pull到电脑/tmp/android-bootchart目录
adb "${@}" pull $LOGROOT/$f $TMPDIR/$f 2>&1 > /dev/null
done
# 进入/tmp/android-bootchart目录,并把pull到此目录的文件打包成bootchart.tgz
(cd $TMPDIR && tar -czf $TARBALL $FILES)
# 执行命令使用bootchart工具生成bootchart.png
bootchart ${TMPDIR}/${TARBALL}
gnome-open ${TARBALL%.tgz}.png
# 清空/tmp/android-bootchart目录
echo "Clean up ${TMPDIR}/ and ./${TARBALL%.tgz}.png when done"

由于现在使用的开发环境ubuntu为远程主机,无法连接手机,所以直接把/data/bootchart/目录下生成的文件打包成bootchart.tgz,然后copy到ubuntu机器,直接使用bootchart /tmp/android-bootchart/bootchart.tgz命令生成bootchart.png。

如果ubuntu机器中的bootchart无法执行,或者没有安装其他工具,可使用如下命令安装:

1
2
3
sudo apt-get install bootchart
sudo apt-get install pybootchartgui
sudo apt-get install gnome-open
1.2 compare-bootcharts.py

Google还给我们提供了一个比较脚本/system/core/init/compare-bootcharts.py用来比较两次开机的数据。需要将两次打包得到的两个压缩包bootchart.tgz分别保存在base_bootchart_dir和exp_bootchart_dir目录中,然后运行下面的命令来执行脚本:

1
2
3
4
5
6
7
8
9
10
11
root@ubuntu:~/work/Ored $ ./system/core/init/compare-bootcharts.py base_bootchart_dir exp_bootchart_dir
process: baseline experiment (delta)
- Unit is ms (a jiffy is 8 ms on the system)
------------------------------------
/init: 0 0 (+0)
/system/bin/surfaceflinger: 3736 3736 (+0)
/system/bin/bootanimation: 4304 4304 (+0)
zygote64: 5960 5960 (+0)
zygote: 5960 5960 (+0)
system_server: 8008 8008 (+0)
bootanimation ends at: 12888 12888 (+0)

这个脚本中只比较了几个重要的核心进程(init、surfacefliger、bootanimation、zygote64、zygote、system_server、bootanimation)的启动时间。

1.3 bootchart.png

生成的bootchart.png如下图所示:

看不到图点这里bootchart

bootchart

通过图片中的时间线timeline上各个进程的启动、IO处理等,我们大致可以分析在开机过程中哪个部分比较耗时,我们能够大致清楚了从系统启动到Android启动完成后的主要时间,同时也能够简单的分析出kernel启动时间,zygote启动时间,sysetmserver启动时间,看出哪个部分比较耗时,待查找出后去重点优化,但是这个工具还是不能把Android 启动阶段毕竟清晰的展现出来,这个时候就需要使用到开机events log信息了。

2 系统启动架构图

系统启动架构图

点击查看大图

3. 如何debug

开机时间分为2部分,一个是内核空间,另一个是用户空间,需要关注的有如下几点:

  • Kernel config:在kernel/arch/arm64/configs/目录下有2个配置文件,分别是xxx_defconfig和xx-perf_defconfig;

    • xxx_defconfig:包含kernel的debug信息,性能差;
    • xxx-perf_defconfig:移除了kernel的debug信息,性能好;
  • 抓取log:包含kernel、events和adb log;

    • 1
      2
      3
      4
      5
      adb wait-for-device root
      adb wait-for-device
      adb shell dmesg > dmesg.txt // kernel log
      adb logcat -b events -d > logcat_events.txt // events log
      adb logcat -v time thread -d > logcat.txt // adb log
  • 如果以上log不能获取足够的信息,则抓取Ftrace log,抓取方法参考文档:点我下载 ,密码:iegy

4. log分析

4.1 kernel log

bootloader的时间

1
2
3
4
5
6
[    0.350199] KPI: Bootloader start count = 70361
[ 0.350204] KPI: Bootloader end count = 100035
[ 0.350208] KPI: Bootloader display count = 3623140379
[ 0.350212] KPI: Bootloader load kernel count = 5008
[ 0.350217] KPI: Kernel MPM timestamp = 119237
[ 0.350221] KPI: Kernel MPM Clock frequency = 32768

NHLOS time: A/D=70361/32768=2.15s
LK time: (B-A)/D=(100035-70361)/32768=0.91s
Boot loader :C/D-kmsg(C)=119237/32768-0.35=3.29s

驱动初始化耗时

1
2
3
4
5
6
7
8
01-29 20:39:54.040     0     0 I KPI     : Bootloader start count = 70361
01-29 20:39:54.040 0 0 I KPI : Bootloader end count = 100035
01-29 20:39:54.040 0 0 I KPI : Bootloader display count = 3623140379
01-29 20:39:54.040 0 0 I KPI : Bootloader load kernel count = 5008
01-29 20:39:54.040 0 0 I KPI : Kernel MPM timestamp = 119237
01-29 20:39:54.040 0 0 I KPI : Kernel MPM Clock frequency = 32768 // subsystem初始化开始
... ...
01-29 20:39:56.560 0 0 I init : init first stage started! // init进程第一阶段初始化开始

耗时大概为2.52s,使用如下修改打开调试开关,

1
2
3
4
5
6
7
8
9
10
11
12
13
// kernel/init/main.c
diff --git a/init/main.c b/init/main.c
index 7af2174..2d11927 100644
--- a/init/main.c
+++ b/init/main.c
@@ -785,7 +785,7 @@ int __init_or_module do_one_initcall(initcall_t fn)
if (initcall_blacklisted(fn))
return -EPERM;
- if (initcall_debug)
+ if (1)
ret = do_one_initcall_debug(fn);
else
ret = fn();

打开后可以看到初始化前后的log,从而对比哪个驱动模块耗时长。

Zygote启动前的command耗时

1
2
3
01-29 20:39:57.799     0     0 I init    : init second stage started! // init第二阶段初始化开始
... ...
01-29 20:40:03.619 0 0 I init : starting service 'zygote'... // zygote进程启动

耗时大概为5.82s,Init程序里默认对耗时超过50ms的command会打印log进行警告:

1
2
3
4
5
6
01-29 20:39:59.327     0     0 I init    : Command 'wait_for_coldboot_done' action=wait_for_coldboot_done (<Builtin Action>:0) returned 0 took 1472ms.
01-29 20:39:59.537 0 0 I init : Command 'mount_all /vendor/etc/fstab.qcom' action=fs (/vendor/etc/init/hw/init.target.rc:47) returned 2 took 190ms.
01-29 20:40:00.749 0 0 I init : Command 'insmod /vendor/lib/modules/msm_11ad_proxy.ko' action=boot (/vendor/etc/init/hw/init.qcom.rc:221) returned -1 took 104ms.
01-29 20:40:01.079 0 0 I init : Command 'insmod /vendor/lib/modules/qca_cld3/qca_cld3_wlan.ko' action=boot (/vendor/etc/init/hw/init.target.rc:111) returned 0 took 257ms.
01-29 20:40:03.604 0 0 I init : Command 'load_persist_props' action=vold.decrypt=trigger_load_persist_props (/init.rc:716) returned 0 took 141ms.
01-29 20:40:10.980 0 0 I init : Command 'mkdir /sys/kernel/debug/tracing/instances/wifi 711' action=sys.boot_completed=1 && sys.wifitracing.started=0 (/system/etc/init/wifi-events.rc:22) returned 0 took 59ms.

Wait_for_coldboot_done由于是冷启动,需要等待sys必要节点创建完成,因此时间会比较长;

mount_all /vendor/etc/fstab.qcom 为需要解析fatab.qcom表内容以及挂载分区;

另外此阶段还有解析rc文件和prop文件,给文件和节点打selinux标签耗时,这部分耗时一般和硬件性能有关(CPU和emmc)。

1
2
3
4
5
6
7
8
9
10
11
01-29 20:39:57.807     0     0 I init    : Running restorecon... // 开始给文件和节点打selinux标签
01-29 20:39:57.814 0 0 E init : waitid failed: No child processes // 耗时结束:7ms
... ...
01-29 20:39:57.816 0 0 I init : Parsing file /init.rc... // 开始解析rc文件
01-29 20:39:57.818 0 0 I init : Parsing file /vendor/etc/init/hw/init.qcom.rc...
01-29 20:39:57.826 0 0 I init : Parsing file /vendor/etc/init/hw/init.target.rc...
... ...
01-29 20:39:57.851 0 0 I init : processing action (early-init) from (/init.rc:14)
... ...
01-29 20:39:57.854 0 0 I init : processing action (early-init) from (/vendor/etc/init/hw/init.qcom.rc:35)
01-29 20:39:57.854 0 0 I init : processing action (early-init) from (/vendor/etc/init/hw/init.target.rc:30) // 解析结束 耗时:38ms
4.2 events log
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
adb logcat -b events | grep boot_progress
01-29 20:40:03.450 1103 1103 I boot_progress_start: 10453
01-29 20:40:04.682 1103 1103 I boot_progress_preload_start: 11684
01-29 20:40:05.542 1103 1103 I boot_progress_preload_end: 12545
01-29 20:40:05.794 1934 1934 I boot_progress_system_run: 12796
01-29 20:40:06.099 1934 1934 I boot_progress_pms_start: 13101
01-29 20:40:06.253 1934 1934 I boot_progress_pms_system_scan_start: 13255
01-29 20:40:07.155 1934 1934 I boot_progress_pms_data_scan_start: 14157
01-29 20:40:07.161 1934 1934 I boot_progress_pms_scan_end: 14164
01-29 20:40:07.390 1934 1934 I boot_progress_pms_ready: 14392
01-29 20:40:08.150 1934 1934 I boot_progress_ams_ready: 15153
01-29 20:40:08.790 1934 1975 I boot_progress_enable_screen: 15792
...
01-29 20:40:10.151 743 818 I sf_stop_bootanim: 17153
01-29 20:40:10.152 1934 1985 I wm_boot_animation_done: 17155
启动阶段 时间点(ms) 花费时间(ms) 备注
boot_progress_start 10453 10453 Linux kernel启动到Zygote进程启动的时间,包含从kernel启动到Init启动Zygote的时间
boot_progress_preload_start 11684 1231 ART虚拟机启动耗时/Zygote开始启动
boot_progress_preload_end 12545 770 虚拟机资源装载耗时/Zygote启动结束
boot_progress_system_run 12796 251 System Server进程启动耗时
boot_progress_pms_start 13101 305 Android一些在PMS前需要启动服务的启动耗时,package scan开始
boot_progress_pms_system_scan_start 13255 154 system目录开始scan时间点
boot_progress_pms_data_scan_start 14157 902 data目录开始scan时间点/system目录扫描耗时
boot_progress_pms_scan_end 14164 7 扫描结束时间点/data目录扫描耗时
boot_progress_pms_ready 14392 1291 PMS启动扫描包耗时(pms_ready~pms_start)
boot_progress_ams_ready 15153 761 PMS后的系统服务启动时间
boot_progress_enable_screen 15792 639 AMS启动完成后开始激活屏幕
sf_stop_bootanim 17153 1361
wm_boot_animation_done 17155 2 从enable_screen到animation_done包含壁纸和keyguard的绘制时间

以上数据为优化后的数据,主要涉及到配置源码中/kernel/arch/arm64/config/xxx-perf_defconfig,关闭不必要的配置,尤其是串口log,以及camera驱动优化,TP优化等待,更多优化后续持续更新。

引用:

http://blog.csdn.net/ljp1205/article/details/78360701

http://blog.csdn.net/whurs/article/details/67062678

http://blog.csdn.net/fu_kevin0606/article/details/53928748

https://www.jianshu.com/p/6dba42c022a9

本文标题:Android开机启动时间优化及bootchart工具使用

文章作者:Ranger Zhou

发布时间:2018年03月13日 - 13:03

最后更新:2018年07月18日 - 21:07

原始链接:http://rangerzhou.top/2018/03/13/Android开机启动时间优化及bootchart工具使用/

许可协议: 署名-非商业性使用-禁止演绎 4.0 国际 转载请保留原文链接及作者。

Ranger Zhou wechat
欢迎您扫一扫上面的微信公众号,订阅我的博客!
坚持原创技术分享,您的支持将鼓励我继续创作!