Android 平台侧性能优化之应用启动[问题已解决]

上一篇文章Android 平台侧性能优化之应用启动采用多个命令分析了平台的cpu/memory等方面对Email启动慢照成的影响。很遗憾花了许多精力,但依然没有找出问题所在,这个坑终于填平了。手动撒花_
回头看来,问题其实很简单,一开始走错方向,导致花了许多精力,不过这个过程也同样积累了不少知识。
本篇文章记录填坑的过程,重新换个角度分析。

曙光出现:

同事在分析另外一个I/O读取慢的问题时发现我们的设备是被加密的,得知这个消息后,我的内心是激动的。一度以为找到了问题的root cause.

adb shell getprop ro.crypto.state

用上述命令查看问题机的加密状态,返回encrypted,果然是已经默认加密了。感觉曙光出现了,我们的设备加密时将/data分区也进行了加密,而应用启动的文件正是放在/data分区下的。按理来讲加密后的/data分区读写速度肯定弱于未加密状态。问题会不会跟此相关呢?
我们采用的是高通8909平台芯片,找到对应的fstab.qcom文件。修改如下:


- /dev/block/bootdevice/by-name/userdata       /data        ext4    nosuid,nodev,barrier=1,noauto_da_alloc,discard      wait,check,forceencrypt=footer
+ /dev/block/bootdevice/by-name/userdata       /data        ext4    nosuid,nodev,barrier=1,noauto_da_alloc,discard      wait,check,encryptable=footer

关键就是修改这一句forceencrypt=footer===>encryptable=footer
forceencrypt表示强制加密,我们改成encryptable意味着加密是让用户主动去选择的。

怀着胸有成竹的心情验证修改后的版本。发现根本没有起任何作用。whats's the fuck!说不过去啊。
满以为找到突破口了,结果希望的火焰还是被无情的浇灭了。

还是IO速度

自己写了一个test apk,专门测试平台emcc的读写速度。测试问题机Log如下:

03-24 20:05:52.126 30578 30727 D Sunny-Test: start call writeData--->
03-24 20:05:52.144 30578 30727 D Sunny-Test-Utils: befWriteTime=93676689579157
03-24 20:05:52.144 30578 30727 D Sunny-Test-Utils: NewBufTime use time--->392292
03-24 20:06:12.656 30578 30727 D Sunny-Test-Utils: initBufData use time--->20512314888
03-24 20:06:12.656 30578 30727 D Sunny-Test-Utils: total create BufData use time--->20512707180
03-24 20:06:12.695 30578 30727 D Sunny-Test-Utils: aftWriteTime=93697240995816
03-24 20:06:12.695 30578 30727 D Sunny-Test-Utils: delta=20551416659
03-24 20:06:12.696 30578 30727 D Sunny-Test: start call writeData--->
03-24 20:06:12.710 30578 30727 D Sunny-Test-Utils: befWriteTime=93697255657795
03-24 20:06:12.710 30578 30727 D Sunny-Test-Utils: NewBufTime use time--->551198
03-24 20:06:33.188 30578 30727 D Sunny-Test-Utils: initBufData use time--->20477974992
03-24 20:06:33.188 30578 30727 D Sunny-Test-Utils: total create BufData use time--->20478526190
03-24 20:06:33.227 30578 30727 D Sunny-Test-Utils: aftWriteTime=93717772564923
03-24 20:06:33.227 30578 30727 D Sunny-Test-Utils: delta=20516907128

在测试参考机Log如下:

03-24 06:03:42.766 18541 18576 D Sunny-Test: start call writeData--->
03-24 06:03:42.780 18541 18576 D Sunny-Test-Utils: befWriteTime=7136372545141
03-24 06:03:42.787 18541 18576 D Sunny-Test-Utils: NewBufTime use time--->6635938
03-24 06:03:45.272 18541 18576 D Sunny-Test-Utils: initBufData use time--->2485714686
03-24 06:03:45.272 18541 18576 D Sunny-Test-Utils: total create BufData use time--->2492350624
03-24 06:03:45.359 18541 18576 D Sunny-Test-Utils: aftWriteTime=7138951725036
03-24 06:03:45.359 18541 18576 D Sunny-Test-Utils: delta=2579179895
03-24 06:03:45.360 18541 18576 D Sunny-Test: start call writeData--->
03-24 06:03:45.371 18541 18576 D Sunny-Test-Utils: befWriteTime=7138963657484
03-24 06:03:45.371 18541 18576 D Sunny-Test-Utils: NewBufTime use time--->387188
03-24 06:03:47.898 18541 18576 D Sunny-Test-Utils: initBufData use time--->2526351301
03-24 06:03:47.898 18541 18576 D Sunny-Test-Utils: total create BufData use time--->2526738489
03-24 06:03:47.983 18541 18576 D Sunny-Test-Utils: aftWriteTime=7141575492639
03-24 06:03:47.983 18541 18576 D Sunny-Test-Utils: delta=2611835155

可以看到
问题机写入耗时:Sunny-Test-Utils: delta=20516907128
参考机写入耗时:Sunny-Test-Utils: delta=2611835155
参考机比问题机写入速度快了一个数量级。再用其他的工具测试I/O读写速度,同样发现参考机比问题机快。但知道这个还是没有办法解决问题,也没法量化I/O差异到底会对Email的启动速度影响多大。
问题到这一度陷入窘境,迷失了分析方向。是时候祭出systrace工具了。

插播 systrace 使用简介

systrace位于<sdk>/platform-tools/systrace目录下。
我们主要分析Email的性能问题,因此可以用命令:

python systrace.py --app=com.tct.email gfx view sched dalvik -o email_launch.html

来抓取trace log分析启动过程。systrace 支持的trace类型可以通过:

python systrace.py -l

查看,用Android N下的systrace工具输出结果如下:

systrace.py -l 输出结果

输入上述命令,然后启动Email,待主界面展示出来后,根据提示输入回车键,此时systrace工具开始生成报告。

生成systrace过程

Tips:
systrace.py位于SDK/platform-tools/systrace目录下。抓取时最好用系统对应的SDK工具抓取。同时如果有源码,也可以用源码的external/chromium-trace/catapult/systrace/systrace/systrace.py 抓取。同样注意抓取systrace的手机跟源码版本一直。

然后打开chrome,在地址栏里输入

chrome://tracing/

load systrace界面

点击Load 按钮,载入email_launch.html文件。显示入下图:

systrace 主界面

查看systrace主要用到4个快捷键:

W 放大视图
S 缩小视图
A 右移视图
D 左移视图

systrace 报告分析

为了排除apk版本差异的干扰,将同版本的apk分别安装到问题机跟参考机上。然后对比systrace报告。
先用TestActivityLaunchTime.py测试问题机以及参考机的启动时间。脚本获取地址:https://github.com/guanglixiang/Android_Performance/blob/master/TestActivityLaunchTime.py
问题机:

**************************************************
Test APK version info is:
versionCode=317022801 minSdk=17 targetSdk=24
    versionName=v7.0.4.1.0312.0_0228
**************************************************
1 lunch time is 875
2 lunch time is 884
3 lunch time is 897
4 lunch time is 873
5 lunch time is 862
5 launch time average is 878

参考机:

**************************************************
Test APK version info is:
versionCode=317022801 targetSdk=24
    versionName=v7.0.4.1.0312.0_0228
    versionCode=216030401 targetSdk=23
    versionName=v5.2.10.3.0214.0
**************************************************
1 lunch time is 806
2 lunch time is 773
3 lunch time is 782
4 lunch time is 777
5 lunch time is 835
5 launch time average is 794

这里看差距貌似不大,但多次测试总是发现参考机就是比问题机快那么一点点。从配置上来将问题机跟参考机配置差不多,并且问题机的内存还比参考机大。为什么就是慢那么一点点呢。
下面尝试通过systrace文件去找原因。
这里我用命令:

./systrace.py gfx input view wm am sm app res dalvik bionic pm database sched freq idle disk mmc load -t 5 -o vJ5E-no-encrypt-no-net_emailv7.html

分别抓取参考机和问题机的systrace。终于发现了问题所在。

参考机systrace
问题机systrace

从systrace对比非常明显的看到参考机没有bindApplication的过程,而问题机却在这个过程中消耗了0.226s。
我们知道冷启动应用都是需要走bindApplication过程的。
bindApplication过程会:
1.创建应用进程
2.加载应用dex执行文件
3.获取应用资源文件
4.makeApplication,初始化JavaContextClassLoader。
相应的热启动是不需要走上述过程的。

为了验证上述分析。可以有个简单的方法,只要先启动Email,然后点击menu清除最近的应用,最后通过ps命令查看email进程是否还存在。

清理应用结果

透过上面的分析可以确定参考机的Email应用一直都在后台运行。而测试测冷启动case时只是点击menu键,然后清除所有应用,在去启动Email。参考机的Email逃过了这一劫,清除的过程中,进程并没有被杀死。而问题机的Email就没那么幸运了,直接被杀的它妈都不认识它了。

解决办法

由于参考机将Email配置成了后台一直运行,相当于拿问题机的冷启动耗时对比参考机的热启动应用耗时。想要达到参考机的启动速度,在平台侧可以也可以效仿参考机将Email配置成后台一直运行。
修改方法:
在frameworks/base/services/core/java/com/android/server/am/ProcessRecord.java

void kill(String reason, boolean noisy) {
    if("com.tct.email".equals(processName) 
        && !KILL_APP_REASON_PERMISSIONS_REVOKED.equals(reason)) {
                return;
    }
    //忽略其他code
}

但这种做法需要项目上根据需求做权衡。Email应用本身会定时去check邮件列表,发起网络请求,属于高耗电程序。一直在后台运行会消耗电量。

写在最后

Email问题陆陆续续的分析了两周多,最开始一心要去从I/O速度上去分析个结果出来。没有去想其它的可能。中间一度想放弃,打算将问题归结到I/O,抛给底层同事去check。但心里始终不安,有空了就去想该问题。其实一开始也抓取过systrace,只是重点放在了分析I/O上,没有跟参考机做对比。没有对比就带来了伤害啊TT

systrace是个好东西,有空打算专门写篇针对该工具的文章。

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

推荐阅读更多精彩内容

  • 写在前面 最近工作转到Android 性能优化方向,刚转过来,相关经验缺乏,纪录一个目前让人恼火的问题。非常遗憾,...
    小草凡阅读 2,593评论 6 4
  • Spring Cloud为开发人员提供了快速构建分布式系统中一些常见模式的工具(例如配置管理,服务发现,断路器,智...
    卡卡罗2017阅读 134,579评论 18 139
  • 原文: http://www.cnblogs.com/yezhennan/p/5442031.html UI性能测...
    vb12阅读 4,251评论 0 9
  • 请保持淡定,分析代码,记住:性能很重要。 启动时间优化 毫无疑问,应用的启动速度越快越好。 本文可以帮助你优化应用...
    Mupceet阅读 11,365评论 5 19
  • 前天晚上我一回到家,就看到屋里有好多大包。我们的东西有好多都收起来了,我很纳闷,因为太困了就迷迷糊糊地睡着了。第二...
    任曦说日记阅读 214评论 0 0