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三个文件。

  • 发表于:
  • 原文链接:http://kuaibao.qq.com/s/20171211G00R5500?refer=cp_1026

扫码关注云+社区