[工具篇]Android系统首次开机分析-----BootChart工具

以开发的android设备W机器为参考分析,该机器是基于高通平台Android 7.0开发,User版本开机时间平均约为85S左右。

这里记录下个人最近对android系统开机时间的分析手段以及开机流程理解。

BootChart工具

Bootchart是一个用于linux启动过程性能分析的开源软件工具,在系统启动过程自动收集CPU占用率、进程等信息,并以图形方式显示分析结果,可用作指导优化系统启动过程。Android5.1之前已自带bootchart,但缺省时不被编译,需要显式指定编译。5.1之后的不用编译boot.img,该工具默认已经编入系统中。

Android系统中已有一份bootchart的c实现,位于system/core/init/bootchart.cpp中,入口函数为bootchart_init();如果在该方法执行前设定了采样时间,则会记录android开机的各个进程的启动时间。

bootchart_init()函数是在init.rc脚本中调用,代码如下:

on post-fs-data       ---------------------/data分区挂载后触发

................

    # Start bootcharting as soon as possible after the data partition is

    # mounted to collect more data.

    mkdir /data/bootchart 0755 shell shell

    bootchart_init

系统默认是不会设置采样时间的,用户可以通过adb shell 'echo 240 > /data/bootchart/start'命令设定,写入start节点值为240(即采样时间为240s,可以自行选择时间数值),just for example.

设定采样时间

列出工具使用中几个坑

    坑1、由于bootchart程序运行时是通过读取/data/bootchart/start这个节点值来确定采样时间,在系统进行恢复出厂设置时,设备会清除data分区,前面方式设置的时间节点“/data/bootchart/start”同样是会被清理的,so 如果按照这样的常规设置,我们是无法通过该工具记录恢复出厂设置的开机时间的。

    坑2、想使用该工具获取首次开机时间,毫不犹豫,我修改init.rc脚本,如下:

on post-fs-data

................

    # Start bootcharting as soon as possible after the data partition is

    # mounted to collect more data.

    mkdir /data/bootchart 0755 shell shell

+ write/data/bootchart/start 240

    bootchart_init

      然后使用命令make bootimage重新编译boot,将生成的boot.image成功flash到机器中,so easy,以为可以获取到首次开机时间图,但是确实空空如也,需要查看代码分析。

忽略N个过程,这里需要关注的是,android系统在首次开机时或者进行reset恢复出厂设置时,是会首先进行全盘加密,即FDE(full-disk encryption.)操作,可以查看链接全盘加密(https://source.android.com/security/encryption/)。在这个过程中,vold会将vold.decrypt设为trigger_restart_min_framework,装载tmpfs临时分区,并且会执行class_start main,即重启main组内的服务,当加密成功后,会装载/data

然后,vold会将vold.decrypt属性设为trigger_restart_framework。这会使init.rc再次启动main类中的服务,并启动late_start类中的服务(这是设备启动后首次启动这些服务)。这个启动过程中post-fs-data会触发两次,bootchart_init()函数触发两次,initj进程一直占用/data/bootchart/proc_stat.log,进程kill失败,会导致开机一直进入不到launcher界面,开机失败问题。

经过前面的分析,为了能使bootchart正常工作,可以在/data正常挂载后,触发trigger_restart_framework。这时写入采样时间并且调用bootchart_init()。代码修改如下:

on post-fs-data

................

    # Start bootcharting as soon as possible after the data partition is

    # mounted to collect more data.

    mkdir /data/bootchart 0755 shell shell

    #bootchart_init

.......................

on property:vold.decrypt=trigger_restart_framework

    # A/B update verifier that marks a successful boot.

    exec - root cache -- /system/bin/update_verifier trigger_restart_framework

+  write /data/bootchart/start 360

+  bootchart_init

    class_start main

    class_start late_start

这种修改方式在userdebug版本中测试正常。


数据采集与分析

     开机后,采集的数据信息会自动收集到/data/bootchart目录下,包含如下5个文件:

header,kernel_pacct,proc_diskstats.log,proc_ps.log,proc_stat.log

接着,可以将以上文件打包放到pc机上,以便利用bootchart工具分析采集到的数据(其中codebase为自己源码所在根目录):

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



 在6.0中Google更加贴心了,grap-bootchart.sh在5.1的基础上又调用bootchart工具解析生成的压缩包,生成图片,最后又用命令将图片打开。我们在userdebug时可能感觉不到grap-bootchart.sh的好处,因为我们可以手动pull文件,压缩,解析,查看图片。但是如果在user版本上,我们虽然可以在data/bootchart下新建文件,如果你要想用命令将里面的文件pull出来,就报出文件夹不存在的命令,这时如果使用该脚本就没有问题,最终生成开机图片。

最后生成的分析结果如下(请放大查看),截图是以userdebug版本实验的,可以清晰看到每个进程的执行时间:


对比正常开机的时间,这是机器开机后,按电源键reboot重启后抓取的时间,这次启动完成大约在75s左右


对比两个bootchart图

android 7.0代码还添加了新功能,执行compare-bootcharts.py脚本可以对比获取的两个bootchart的进程启动结束时间点,从而得到对应进程之间的耗时差距.

当我们使用grab-bootchart.sh脚本获取对应的bootcahrt图时,会在PC的/tmp/android-bootchart目录下留下bootchart.tgz压缩包.然后将所要比较的两个bootchart的压缩包放在两个不同的目录base_bootchart_dir,

exp_bootchart_dir.执行如下命令:

system/core/init/compare-bootcharts.py base_bootchart_dir exp_bootchart_dir

就可以得到如下信息:


可以看到zygote进程在首次开机时间和之后的正常开机相比启动时间延迟了38s,即android上层启动晚了38s时间,这是需要抓取event log来同时分析延迟原因。搜索boot_progress关键字:


前面已经分析过,在机器首次开机时,是会首先进行全盘加密,即FDE(full-disk encryption.)操作,这个过程是会先后触发trigger_restart_min_framework和trigger_restart_framework,即 

  class_start main的服务会启动两次,zygote属于main类服务,可以查看init.zygote32.rc脚本,

service zygote /system/bin/app_process -Xzygote /system/bin --zygote --start-system-server

    class main

而通过bootchart工具得到的zygote进程开始时间点,是第二次启动的时间,因为第一次zygote启动后,进程后来是会被kill掉,重新启动,此时能找到的zygote进程pid只是第二次的。

    但是可以参考第一次启动时间为boot_progress_start大约为51s,boot_progress_pms_ready时间为81s,由于是采集的userdebug版本,该时间可以说是开机速度不慢了。

     这里,自己用秒表采集过W机器的user版本首次开机时间,记录大约是80s左右,应该说速度相对不慢。

这里主要介绍了最近对bootchart工具的使用,已便于分析系统启动过程的耗时点,为优化启动过程提供指导意义.

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 204,053评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,527评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,779评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,685评论 1 276
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,699评论 5 366
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,609评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,989评论 3 396
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,654评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,890评论 1 298
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,634评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,716评论 1 330
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,394评论 4 319
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,976评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,950评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,191评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 44,849评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,458评论 2 342

推荐阅读更多精彩内容