Android开机日志解读

干过优化开机时间这个苦逼活的同学都知道开机日志，动则上万行日志不足为奇。特别对于第一次看开机日志的同学来说，简直就是一本天书。根本找不到重点。这篇文章就聊聊开机日志这本天书的章节要领，以及分析的工具bootchart。让大家阅读万行开机日志有如庖丁解牛游刃有余。当然，不管是日志，还是分析工具bootchart，这些都只是寻找或者说发现问题的手段，正真要分析问题的原因和解决问题还是需要去熟悉系统。这些首先声明，因为水平有限我这里说的开机日志主要是Zygote以及它之后系统吐出的日志。

1 开机日志的获取：(开机日志当然是越全越好，方便分析各种问题)

adb logcat -b main -b system -b radio -b events -v time > bootLog.log

2 Zygote进程预加载相关日志：

在优化开机时间这个问题上，经常会提到Zygote预加载资源着一块是比较耗时的。网上也流传这各种优化方法，比如说启动线程专门预加载资源，删除一些加载时间比较长的Class等等。(这里后面我会专门写一篇文章，google是按照怎样一个策略来决定一个类是不是需要预加载的，启动线程加载资源是不是合理)

这里主要是贴出日志，量化这个zygote在预加载资源的耗时时间。(下面贴出的日志只是一个Zygote进程的日志，其实AndroidL64位系统中为了兼容32位APP存在两个Zygote进程)

01-01 08:00:20.288 I/boot_progress_preload_start( 2035): 20288

01-01 08:00:20.288 D/Zygote ( 2035): begin preload

01-01 08:00:20.340 I/Zygote ( 2035): Preloading classes...

01-01 08:00:22.500 I/Zygote ( 2035): ...preloaded 3831 classes in 2160ms.

01-01 08:00:22.702 I/Zygote ( 2035): Preloading resources...

01-01 08:00:23.021 I/Zygote ( 2035): ...preloaded 342 resources in 319ms.

01-01 08:00:23.025 I/Zygote ( 2035): ...preloaded 41 resources in 4ms.

01-01 08:00:23.060 I/Zygote ( 2035): Preloading shared libraries...

01-01 08:00:23.357 D/Zygote ( 2035): end preload

3 PackageMangerService扫描APk耗时：

这也是开机过程中一个非常耗时的点，PMS需要扫描系统中的应用，解析AndroidManifest.xml文件，检查更新，检查签名等等。

下面是具体的日志：

01-01 08:00:24.780 I/boot_progress_pms_start( 2510): 24780

01-01 08:00:28.215 I/boot_progress_pms_scan_end( 2510): 28215

01-01 08:00:28.215 I/PackageManager( 2510): Time to scan packages: 3.309 seconds

4 其他日志：

启动Launcher：

Start proc 3079:com.android.home/u0a14 for activity com.android.home/.Launcher

5 启动Launcher花费的时间：

01-01 08:00:35.882 I/ActivityManager( 2488): Displayed com.android.home/.Launcher: +3s308ms

6 请求关闭开机动画显示Launcher以及从开机到现在花费的时间：

01-01 08:00:40.561 I/boot_progress_enable_screen( 2488): 40561

7 如果开机动画是因为超时关闭的日志：

01-01 08:01:10.591 W/WindowManager( 2488): ***** BOOT TIMEOUT: forcing display enabled

8 通知SurfaceFlinger关闭开机动画：

01-01 08:01:10.592 I/WindowManager( 2488): ******* TELLING SURFACE FLINGER WE ARE BOOTED!

9 开机动画关闭：(自己加的为了验证，通知SurfaceFlinger关闭开机动画后，到开机动画应用关闭中间有多长时间的耗时)

01-01 08:01:10.602 E/BootAnimation( 2205): nio_zhangyw, checkExit, requestExit()--------------exiting...

10 总结说明：

其实日志是系统对外的一个窗口，如果你够熟悉这个系统，你就能透过日志这个窗口，看到系统内心想要表达而又不好意思表达的更深层次的意思。

比如说第5步日志,他表示的意思是Home的启动所话费的时间，但是实际上也表达另外一个意思，那就是现在Home中启动的Activity(也就是桌面)，对应在WMS中的WindowState是一个准备显示的状态(Readytoshow).那么就可以这样理解，如果现在关闭开机动画，就能看到Home了。但是呢？

我们看第6条日志，请求关闭开机动画日志却在将近5S之后才打印出来？为什么要拖延这么长时间？其实只要我们研究这个日志6,是满足一个什么条件打印出来，再去查为什么这个条件没有满足？就能解决这个5S的耗时。这里卖关子了：日志6要打印出来，是Home应用进程进如空闲后，会出发请求触发打印出日志6.也就是说，因为Home进程一直忙，所以拖延了将近5S的开机时间。(详细分析我以后会用一篇文章单独分析这些开机动画关闭的条件)

再看第7调日志：这个日志是因为超时而强制关闭开机动画吐出的日志(30S超时)，你会发现日志6到日志7的时间间隔正好将近30S。也就是说日志6 请求关闭开机动画，但是实际并没关闭开机动画？那么关闭开机动画的条件具体有哪些呢？简单总结一下：除了前面Home进程要进入空闲状态，还需要当前WindowManagerService窗口列表中所有需要显示的窗口(WindowState)都必须是准备显示或者已经绘制的状态，同时如果墙纸服务打开的话，WindowManagerService中一定要存在准备绘制或者已经绘制状态窗口(WindowState)(详细分析我以后会用一篇文章单独分析这些开机动画关闭的条件)

11 开机过程中启动的进程：

我们说开机时间一般指的是：机器上电到关闭开机动画，用户看到Home应用的时间。也就就是说我们有必要知道从开机到Launcher启动完成，这个时间之内系统还启动了哪些进程。这些进程越多，自然也会延长开机时间。

如果获取开机过程中启动进程列表？

用关键字"Start proc"过滤开机日志就能看到了。

我这里对zygote起来之后到Home启动完成这段时间启动的进程，以及他们可能启动的原因做了一个大概的整理 （服务启动部分，有些是因为广播启动的）。为了方便排版，做了一个截图，放大看就好了。另外为了不暴露包名，我用了XXX替代了。

对于每一个在Home启动完成之前的进程问如下三个问题：

11.1 谁把他启动起来的？

11.2 为什么要这么早起来（它有什么依赖或者说时序的要求）？

11.3 能不能放到Home启动完成之后呢？

通常厂商都会定制化自己的系统应用，在开发的过程中，应用并不在意这些细节，都只是希望自己越早起来越好。各种加persistent属性，各种在系统服务里面就把自己启动起来，监听各种比较早的广播。

如果耐心去梳理着一块，还是有比较可观的优化空间。

12 开机分析工具BootChart：

bootchart的介绍如下:

Bootchart is a tool for performance analysis and visualization of the GNU/Linux boot process. Resource utilization and process information are collected during the boot process and are later rendered in aPNG,SVGorEPSencoded chart.

简单来说BootChart是Linux启动过程中性能分析和可视化的工具。

在Android系统中源码部分如下：

/system/core/init/bootchart.cpp

12.1 关于BootChart的启动：

开机过程中Init进程会解析init.rc文件，启动文件中定义的各种服务，比如说：SurfaceFlinger ，Zygote等等。其中Init.rc中有如下一行：

mkdir /data/bootchart 0755 shell shell

bootchart_init

/data/bootchart：主要用于给Bootchart来存放收集的日志文件。

bootchart_init: 当init进程解析到这个Command的时候是如何处理的呢？

12.2 bootchart_init关键字的定义：

在system/core/init/init_parser.cpp文件中有一个关于关键字数组的定义如下：

keyword_info结构体变量解释如下：

name:关键字的名称

func:函数指针，用于保存对应关键字需要执行的函数

nargs:该参数的个数，也就是函数指针的参数个数。

flags：该关键字的类型，这里分为如下三种：

#define SECTION 0x01 //主要用于on, import, service关键字

#define COMMAND 0x02 //命令，类是于mkdir chmod这样的

#define OPTION 0x04 //分类 该类型的关键字主要用于修饰service，比如说Class关键字，把service分为， core，main，late_start三种类型。

实际上，keyword_info数组的值都定义在keywords.h中。

下面是bootchart_init在keywords.h中的定义：

bootchart_init:是一个Command， 没有参数，该命令对应的处理函数是do_bootchart_init.

12.3 bootchart_init命令的处理。

回到12.1 当init进程解析init.rc文件中

mkdir /data/bootchart 0755 shell shell时回调用do_mkdir函数创建/data/bootchart目录。

在解析bootchart_init命令时，会执行do_bootchart_init函数

该函数位于/system/core/init/bootchart.cpp

具体的函数代码就不贴出来了，他主要作了如下事情：

12.3.1 从/data/bootchart/start 文件中读取bootchart采样日志的时间这个时间最多60S，如果这个文件不存在或者start文件没有内容或者为0则设置剩余采样时间为0,初始化过程结束。

12.3.2 如果start文件有时间的内容则创建如下文件用于保存日志：

12.4 BootChart开始采样数据：

在/system/core/init/init.cpp 的main函数中执行如下代码：

bootchart_sample(&timeout);

这里也不贴出该函数代码了，他主要做的事情就是，先检查剩余采样时间是否为0,如果为0直接就返回了。如果不为0就开始采样日志。

12.5 BootChart生成的日志如下：

12.6 生成图形文件

12.6.1 安装如下工具：

$sudo apt-get install bootchart

$sudo apt-get install pybootchartgui

12.6.2 打包日志生成bootchart.tgz

tar -czf bootchart.tgz header proc_stat.log proc_ps.log proc_diskstats.log kernel_pacct

最后执行如下命令：

bootchart bootchart.tgz

最后我这边生成的图片如下：

最后如果有人在Android5.0 中想使用BootChart分析Android启动时间相关的，就不要使用/data/bootchart/作为存放日志的目录了。建议修改为/dev。

另外如果发现生成图片的过程中出现异常参考如下文章：

https://groups.google.com/forum/#!topic/android-kernel/mdGQZzVODMQ

替换draw.py, parsing.py,samples.py三个文件。