Android开机阶段log分析

标签（空格分隔）：开关机流程

Android开机阶段log分析
- bootchart工具查看开机过程
- 打印开机过程各阶段的时间
- kernel
- Init进程
- Zygote进程
- SystemServer进程
- 开机动画log

bootchart工具查看开机过程

Android版本：7.0
平台：高通和MTK
输出：

局部放大图：

使用方法：
1.修改代码

1) /system/core/init/Android.mk
Remove the lines in Android.mk
LOCAL_SANITIZE := integer
2)build boot.img and system.img, flash into device

如果没有此步骤，将导致手机不断重启，无法开机。
2.抓取log

adb shell 'echo 120 > /data/bootchart/start'

数据采集完之后再将/data/bootchart/start删除，否则每次开机都会抓取log。
3.数据采集与分析
关机和开机（120S）后，采集的数据信息会自动收集到/data/bootchart目录下，包含如下5个文件：
header，kernel_pacct，proc_diskstats.log，proc_ps.log，proc_stat.log

$ system/core/init/grab-bootchart.sh

grap-bootchart.sh调用bootchart工具解析生成的压缩包，生成图片，最后又用命令将图片打开（user版本也可以）。

打印开机过程各阶段的时间

工具：system/core/init/perfboot.py
作用：打印开机过程各阶段的时间
命令：

./perfboot.py --iterations=1 -v --output=data.tsv

备注：工程需要先lunch一下，否则有可能出现ImportError: No module named adb
示例：

Event log recorded: boot_progress_start (616) - 20409 ms
Event log recorded: boot_progress_preload_start (616) - 22764 ms
Event log recorded: boot_progress_preload_start (656) - 22780 ms
Event log recorded: boot_progress_preload_end (616) - 25649 ms
Event log recorded: boot_progress_preload_end (656) - 25776 ms
Event log recorded: boot_progress_system_run (1351) - 25990 ms
Event log recorded: boot_progress_pms_start (1351) - 26744 ms
Event log recorded: boot_progress_pms_system_scan_start (1351) - 27309 ms
Event log recorded: boot_progress_pms_data_scan_start (1351) - 30620 ms
Event log recorded: boot_progress_pms_scan_end (1351) - 30677 ms
Event log recorded: boot_progress_pms_ready (1351) - 32772 ms
Event log recorded: boot_progress_ams_ready (1351) - 36251 ms
Event log recorded: boot_progress_enable_screen (1351) - 39129 ms
Event log recorded: sf_stop_bootanim (475) - 40908 ms
Event log recorded: wm_boot_animation_done (1351) - 46139 ms
mean:  46139.0
median: 46139
standard deviation: 0.0
Wrote: data.tsv

释义：

name	description
boot_progress_start	代表着Android屏幕点亮，开始显示启动动画，标志着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	开机动画结束，这一步用户能直观感受到开机结束

Android系统启动的log分为Linux内核的log和Android Logger系统的log，

抓取的方法如下：

$ adb shell dmesg > dmesg.txt
$ adb logcat -d -v time -b "main"   >  main.txt
$ adb logcat -d -v time -b "system" >  system.txt
$ adb logcat -d -v time -b "events" >  events.txt

kernel

这里提下如何看kernel的log，
开机后用命令：adb shell dmesg > dmesg.txt抓取Log
log里面搜关键字”Bootloader start count”–>LK 启动
“Bootloader end count”–>LK 结束
“Kernel MPM timestamp”–>bootloader运行完成

Linux内核启动完成，一般都有如下的标准输出信息

[    3.980460]  (1)[1:swapper/0]Freeing initrd memory: 2500K (ffffffc003600000 - ffffffc003871000)

合并kernel config
工具：kernel/msm-3.18/scripts/kconfig/msm-3./merge_config.sh
方法：单独编译下kernel(make kernel -j8 PROJECT_NAME=cas_tr)，然后去out目录下查看out/target/product/v11bnlite/obj/KERNEL_OBJ文件

Init进程

Init程序的log信息也位于dmesg.txt文件中，我们可以通过检索“init”找到该程序的打印消息。

通过检索“init starting”，我们可以找到init进程启动了哪些本地服务，如：

1008:[   10.630620]  (0)[1:init]init: Starting service 'ueventd'...
1122:[   13.371655]  (3)[1:init]init: Starting service 'logd'...
1142:[   14.824560]  (1)[1:init]init: Starting service 'debuggerd'...
1143:[   14.831413]  (1)[1:init]init: Starting service 'debuggerd64'...
1144:[   14.839197]  (2)[1:init]init: Starting service 'vold'...
1149:[   15.135726]  (3)[1:init]init: Starting service 'exec 1 (/system/bin/tzdatacheck)'...
1151:[   15.233418]  (2)[1:init]init: Starting service 'perfd'...
1154:[   15.288520]  (2)[1:init]init: Starting service 'carrier_switcher'...
1156:[   15.448583]  (3)[1:init]init: Starting service 'logd-reinit'...
1167:[   15.833831]  (0)[1:init]init: Starting service 'exec 2 (/init.qcom.early_boot.sh)'...
1238:[   16.640513]  (1)[1:init]init: Starting service 'healthd'...
1239:[   16.647123]  (1)[1:init]init: Starting service 'qcom-c_core-sh'...
1240:[   16.654727]  (1)[1:init]init: Starting service 'irsc_util'...
1242:[   16.669672]  (1)[1:init]init: Starting service 'rmt_storage'...
1244:[   16.687135]  (1)[1:init]init: Starting service 'tftp_server'...

Zygote进程

Zygote进程所输出的log信息被放到/dev/log/main文件中了，因此，我们需要检索main.txt得到Zygote的log信息。

zygote进程是在init进程中启动的，因此，我们从上面init进程的输出log中，检索”zygote”就可以找到zygote进程何时启动的，如图所示：

[   17.696441]  (0)[1:init]init: Starting service 'zygote'...

Android系统为了提高应用程序的启动速度，会在Zygote进程初始化过程中加载一些常用的java class和资源文件到进程的内存中，从而共享常用的class和resourse资源。这个过程我们可以通过检索”preload”标签得到这个过程所消耗的时间，如图所示：

./APLog_2017_0103_063308/main_log.boot:2894:01-03 06:32:18.105987   280   280 I Zygote  : ...preloaded 4161 classes in 1457ms.
./APLog_2017_0103_063308/main_log.boot:3008:01-03 06:32:19.234774   280   280 I Zygote  : ...preloaded 114 resources in 629ms.
./APLog_2017_0103_063308/main_log.boot:3024:01-03 06:32:19.301479   280   280 I Zygote  : ...preloaded 41 resources in 67ms.

SystemServer进程

Zygote完成了初始化工作后就启动SystemServer进程了，SystemServer进程的log信息被放到了/dev/log/system文件中了，因此，我们需要检索system.txt文件得到SystemServer的log信息，如图所示：

./APLog_2017_0103_063308/sys_log.boot:459:01-03 06:32:19.821505   879   879 I SystemServer: Entered the Android system server!
./APLog_2017_0103_063308/sys_log.boot:489:01-03 06:32:20.744765   879   879 I SystemServer: StartPackageManagerService
./APLog_2017_0103_063308/sys_log.boot:1334:01-03 06:32:28.256673   879   879 I SystemServer: StartOtaDexOptService
./APLog_2017_0103_063308/sys_log.boot:1335:01-03 06:32:28.258833   879   879 I SystemServer: StartUserManagerService
./APLog_2017_0103_063308/sys_log.boot:1343:01-03 06:32:28.344933   879   879 I SystemServer: Reading configuration...
./APLog_2017_0103_063308/sys_log.boot:1344:01-03 06:32:28.345094   879   879 I SystemServer: StartSchedulingPolicyService
./APLog_2017_0103_063308/sys_log.boot:1346:01-03 06:32:28.349108   879   879 I SystemServer: StartTelephonyRegistry
./APLog_2017_0103_063308/sys_log.boot:1347:01-03 06:32:28.358208   879   879 I SystemServer: StartEntropyMixer
./APLog_2017_0103_063308/sys_log.boot:1349:01-03 06:32:28.375747   879   879 I SystemServer: Camera Service

开机动画log

// 启动SurfaceFlinger服务：合成图像并显示到屏幕。启动该服务过程中会触发init启动一个bootanimation进程，其会开始启动动画显示，也就是我们看到的带“android”字样的启动动画
02-11 20:10:53.143   473   473 I SurfaceFlinger: SurfaceFlinger is starting
02-11 20:10:53.145   473   473 I SurfaceFlinger: SurfaceFlinger's main thread ready to run. Initializing graphics H/W...// 开机动画开始
387:SurfaceFlinger:]BOOTPROF:      7072.487169:BOOT_Animation:START// 开机动画结束
./APLog_2017_0103_063308/bootprof:92:     36704.968241 :  486-Binder:247_1    : BOOT_Animation:END