Android App 启动过程分析
Harttle
通过分析和修改Android 源码,分析 Android App 启动过程的时间消耗及性能瓶颈。
本文包括源码编译与运行、源码修改与调试、数据收集与分析。分析了 App 启动过程中， Activity Manager Service 、Binder、Launcher和MainActivity扮演的角色以及消耗的时间。
源码编译与运行
环境配置
环境要求可以在从 文档 查询得到。以下在Arch Linux中进行Android Source Building的环境配置。
安装依赖
# x86
yaourt -S --needed gcc git gnupg flex bison gperf sdl wxgtk squashfs-tools curl ncurses zlib schedtool perl-switch zip unzip libxslt
# x64
yaourt -S --needed gcc-multilib lib32-zlib lib32-ncurses lib32-readline
# Android 工具
yaourt -S android-sdk android-sdk-platform-tools android-sdk-build-tools android-studio
增加交换空间，加 RAM 应达到 16G (另外，还需要 30G 的大小写敏感文件系统可用空间)
su
swapoff /swapfile && rm /swapfile
dd if=/dev/zero of=/swapfile bs=512M count=32
mkswap /swapfile && swapon /swapfile
安装对应版本的工具软件：
# make 3.81-3.82
yaourt -S make-3.81
# python2
cd /usr/bin && sudo ln -sf python python2
# java SE 1.6
yaourt -S jdk6-compat
环境变量配置：
#!/bin/bash
# file: env.sh
# cache
export USE_CCACHE=1
export CCACHE_DIR=~/.ccache
# output
export OUT_DIR_COMMON_BASE=~/code/androidcore/output
# alias
alias make='make-3.81'
# java6
export JAVA_HOME=/opt/java6
export PATH=/opt/java6/bin:$PATH
配置USB访问权限：
# file: /etc/udev/rules.d/51-android.rules
# adb protocol on passion (Nexus One)
SUBSYSTEM=="usb", ATTR{idVendor}=="18d1", ATTR{idProduct}=="4e12", MODE="0600", OWNER="<username>"
# fastboot protocol on passion (Nexus One)
SUBSYSTEM=="usb", ATTR{idVendor}=="0bb4", ATTR{idProduct}=="0fff", MODE="0600", OWNER="<username>"
# ...
最终环境
Linux acer 3.13.7-1-ARCH #1 SMP PREEMPT Mon Mar 24 20:06:08 CET 2014 x86_64 GNU/Linux
Python 2.7.6 (default, Feb 26 2014, 12:07:17)
gcc 版本 4.9.0 20140507 (prerelease) (GCC)
GNU Make 3.81
java SE 1.6
编译Android Source
参照 文档 ，下载Android4.2源码。
# 导入环境
. ../env.sh
. build/envsetup.sh
# 设置缓存大小
prebuilts/misc/linux-x86/ccache/ccache -M 50G
# 选择目标
lunch
# 并行编译
make -j4
启动Emulator
# 加载环境
lunch
# 启动
emulator
启动成功，Android版本为4.2.1：
源码修改与调试
考虑从Launcher启动应用程序时，ActivityManagerService，Launcher，MainActivity之间的执行与通信序列如下图。在源码中相应的过程调用或进程通信处加入日志信息，用于分析启动时各部分的耗时。
Android源码修改
以下列出所有需要更改的源码。注释中给出了文件路径、类名、函数名，与添加的语句。添加日志输出（Level为Info，Tag为"PKU"）。
说明：文件ApplicationThreadNative没有引入Log类。添加import andriod.util.Log会发生运行时错误，可能是因为该文件的在类层次中的特殊性。所以我们将在try catch语句中指明命名空间并进行调用。我们关心的是整个系统启动后的 App启动过程，所以直接吞掉这个在早期才会产生的异常。
/////////////////////////////////////////////////////////////////////////
// file: packages/apps/Launcher2/src/com/android/launcher2/Launcher.java
// 0 Launcher.onClick
Log.i("PKU", "0 shortcut clicked");
/////////////////////////////////////////////////////////////////////////
// file: frameworks/base/core/java/android/app/ActivityManagerNative.java
// 1 ActivityManagerProxy.startActivity
Log.i("PKU","1 START_ACTIVITY_TRANSACTION begin");
Log.i("PKU","1 START_ACTIVITY_TRANSACTION end");
// 5 ActivityManagerProxy.activityPaused
Log.i("PKU","5 ACTIVITY_PAUSED_TRANSACTION begin");
Log.i("PKU","5 ACTIVITY_PAUSED_TRANSACTION end");
// 9 ActivityManagerProxy.attachApplication
Log.i("PKU","9 ATTACH_APPLICATION_TRANSACTION begin");
Log.i("PKU","9 ATTACH_APPLICATION_TRANSACTION end");
/////////////////////////////////////////////////////////////////////////
// file: frameworks/base/services/java/com/android/server/am/ActivityManagerService.java
// 2 ActivityManagerService.startActivity
Log.i("PKU","2 on START_ACTIVITY_TRANSACTION");
// 6 ActivityManagerService.activityPaused
Log.i("PKU","6 on ACTIVITY_PAUSED_TRANSACTION");
// 7 ActivityManagerService.startProcessLocked
Log.i("PKU","7 process starting");
Log.i("PKU","7 process started");
// 10 ActivityManagerService.attachApplication
Log.i("PKU","10 on ATTACH_APPLICATION_TRANSACTION");
/////////////////////////////////////////////////////////////////////////
// file: frameworks/base/core/java/android/app/ApplicationThreadNative.java
// 3 ApplicationThreadProxy.schedulePauseActivity
try{
android.util.Log.i("PKU","3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION begin");
}catch(Exception e){}
try{
android.util.Log.i("PKU","3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION end");
}catch(Exception e){}
// 11 ApplicationThreadProxy.scheduleLaunchActivity
try{
android.util.Log.i("PKU","11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION begin");
}catch(Exception e){}
try{
android.util.Log.i("PKU","11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION end");
}catch(Exception e){}
/////////////////////////////////////////////////////////////////////////
// file: frameworks/base/core/java/android/app/ActivityThread.java
// 4 ApplicationThread.schedulePauseActivity
Log.i("PKU","4 on SCHEDULE_PAUSE_ACTIVITY_TRANSACTION");
// 8 ActivityThread.main
Log.i("PKU","8 main entered");
// 12 ApplicationThread.scheduleLaunchActivity
Log.i("PKU","12 on SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION");
App源码修改
/////////////////////////////////////////////////////////////////////////
// file: src/com/example/android/searchabledict/SearchableDictionary.java
import android.util.Log;
// SearchableDictionary.onCreate
Log.i("PKU", "searchabledictionary oncreate");
// SearchableDictionary.handleIntent
Log.i("PKU", "item clicked");
/////////////////////////////////////////////////////////////////////////
// file: src/com/example/android/searchabledict/SearchableDictionary.java
import android.util.Log;
// WordActivity.onCreate
Log.i("PKU", "wordactivity oncreate");
重新编译
重新编译Android Source
. ../env.sh
. build/envsetup.sh
prebuilts/misc/linux-x86/ccache/ccache -M 50G
lunch
make -j4
运行模拟器
emulator&
安装测试应用：SearchableDictionary
# 拷贝Sample
cp -r /opt/android-sdk/samples/android-19/legacy/SearchableDictionary/ .
# 创建Project
android update project -t 1 -n searchabledict -p ./SearchableDictionary
# 编译
cd SearchableDictionary && ant debug
# 查看正在运行的设备
adb devices
# 安装到指定设备
adb -s emulator-5554 install bin/searchabledict-debug.apk
安装后在应用程序列表中出现SearchableDictionary：
数据采集与分析
数据采集
首先运行模拟器，在设置中更改 "background process limit" 为0，勾选"don't keep activities"。这样每次点击Home即可结束应用进程。
然后监视日志并重定向到文件：
# 清空日志
adb -s emulator-5554 logcat -c
# 开始过滤
adb -s emulator-5554 logcat -v time PKU:I *:S | tee pku.log
现在，我们来获得10组启动过程的日志数据：
- 启动SearchableDictionary；
- 点击搜索，随机搜索一个单词并打开；
- 点击Home按键（因为我们只关心启动过程）；
- 重复1-3；
- 结束
logcat，得到pku.log，文件46行为一个周期，10次测试共460行，前46行如下：
1 06-01 05:08:57.111 I/PKU ( 399): 0 shortcut clicked
2 06-01 05:08:57.111 I/PKU ( 399): 1 START_ACTIVITY_TRANSACTION begin
3 06-01 05:08:57.121 I/PKU ( 276): 2 on START_ACTIVITY_TRANSACTION
4 06-01 05:08:57.151 I/PKU ( 276): 3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION begin
5 06-01 05:08:57.151 I/PKU ( 399): 4 on SCHEDULE_PAUSE_ACTIVITY_TRANSACTION
6 06-01 05:08:57.151 I/PKU ( 276): 3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION end
7 06-01 05:08:57.171 I/PKU ( 399): 1 START_ACTIVITY_TRANSACTION end
8 06-01 05:08:57.171 I/PKU ( 399): 5 ACTIVITY_PAUSED_TRANSACTION begin
9 06-01 05:08:57.171 I/PKU ( 276): 6 on ACTIVITY_PAUSED_TRANSACTION
10 06-01 05:08:57.171 I/PKU ( 276): 7 process starting
11 06-01 05:08:57.191 I/PKU ( 276): 7 process started
12 06-01 05:08:57.211 I/PKU ( 399): 5 ACTIVITY_PAUSED_TRANSACTION end
13 06-01 05:08:57.361 I/PKU ( 1005): 8 main entered
14 06-01 05:08:57.371 I/PKU ( 1005): 9 ATTACH_APPLICATION_TRANSACTION begin
15 06-01 05:08:57.371 I/PKU ( 276): 10 on ATTACH_APPLICATION_TRANSACTION
16 06-01 05:08:57.391 I/PKU ( 276): 11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION begin
17 06-01 05:08:57.391 I/PKU ( 276): 11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION end
18 06-01 05:08:57.391 I/PKU ( 1005): 12 on SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION
19 06-01 05:08:57.461 I/PKU ( 1005): 9 ATTACH_APPLICATION_TRANSACTION end
20 06-01 05:08:57.711 I/PKU ( 1005): searchabledictionary oncreate
21 06-01 05:09:03.791 I/PKU ( 1005): 1 START_ACTIVITY_TRANSACTION begin
22 06-01 05:09:03.801 I/PKU ( 276): 2 on START_ACTIVITY_TRANSACTION
23 06-01 05:09:03.812 I/PKU ( 1005): 1 START_ACTIVITY_TRANSACTION end
24 06-01 05:09:03.981 I/PKU ( 1005): item clicked
25 06-01 05:09:03.981 I/PKU ( 1005): 1 START_ACTIVITY_TRANSACTION begin
26 06-01 05:09:04.001 I/PKU ( 276): 2 on START_ACTIVITY_TRANSACTION
27 06-01 05:09:04.001 I/PKU ( 276): 3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION begin
28 06-01 05:09:04.001 I/PKU ( 1005): 4 on SCHEDULE_PAUSE_ACTIVITY_TRANSACTION
29 06-01 05:09:04.001 I/PKU ( 276): 3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION end
30 06-01 05:09:04.011 I/PKU ( 1005): 1 START_ACTIVITY_TRANSACTION end
31 06-01 05:09:04.041 I/PKU ( 1005): 5 ACTIVITY_PAUSED_TRANSACTION begin
32 06-01 05:09:04.041 I/PKU ( 276): 6 on ACTIVITY_PAUSED_TRANSACTION
33 06-01 05:09:04.051 I/PKU ( 276): 11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION begin
34 06-01 05:09:04.051 I/PKU ( 1005): 12 on SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION
35 06-01 05:09:04.051 I/PKU ( 276): 11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION end
36 06-01 05:09:04.091 I/PKU ( 1005): 5 ACTIVITY_PAUSED_TRANSACTION end
37 06-01 05:09:04.171 I/PKU ( 1005): wordactivity oncreate
38 06-01 05:09:09.201 I/PKU ( 276): 3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION begin
39 06-01 05:09:09.201 I/PKU ( 1005): 4 on SCHEDULE_PAUSE_ACTIVITY_TRANSACTION
40 06-01 05:09:09.211 I/PKU ( 1005): 5 ACTIVITY_PAUSED_TRANSACTION begin
41 06-01 05:09:09.211 I/PKU ( 276): 6 on ACTIVITY_PAUSED_TRANSACTION
42 06-01 05:09:09.211 I/PKU ( 276): 3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION end
43 06-01 05:09:09.241 I/PKU ( 276): 11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION begin
44 06-01 05:09:09.251 I/PKU ( 399): 12 on SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION
45 06-01 05:09:09.251 I/PKU ( 276): 11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION end
46 06-01 05:09:09.311 I/PKU ( 1005): 5 ACTIVITY_PAUSED_TRANSACTION end
- 1-20行：点击Launcher图标（Launcher.onClick）到Activity启动完毕（SearchableDictionary.onCreate）；
- 21-23行：点击搜索提示列表中的某一项到生成隐式Intent；
- 24-37行：调用StartActivity（SearchableDictionary.handleIntent）到WordActivity启动完毕（WordActivity.onCreate）；
- 38-46行：点击Home键直到应用程序进程结束（这一段不在我们关心的范围内）。
可以看到到
begin与end之间总会有on，即transaction类似远程过程调用，该过程是同步的。
数据分析
利用脚本pku_analyzer.sh，计算日志文件pku.log相邻事件之间的时间差，最终结果(即 10 次测试的平均值)记录在r.txt文件:
# Actor Time Event
1 0 0 shortcut clicked
2 L 0 1 START_ACTIVITY_TRANSACTION begin
3 B 5 2 on START_ACTIVITY_TRANSACTION
4 A 23 3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION begin
5 B 1 4 on SCHEDULE_PAUSE_ACTIVITY_TRANSACTION
6 L 2.9 3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION end
7 A 30.1 1 START_ACTIVITY_TRANSACTION end
8 L 6.9 5 ACTIVITY_PAUSED_TRANSACTION begin
9 B 1 6 on ACTIVITY_PAUSED_TRANSACTION
10 A 2 7 process starting
11 B 25.9 7 process started
12 AM 11.1 5 ACTIVITY_PAUSED_TRANSACTION end
13 M 214.9 8 main entered
14 M 22 9 ATTACH_APPLICATION_TRANSACTION begin
15 B 0 10 on ATTACH_APPLICATION_TRANSACTION
16 A 19 11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION begin
17 B 1 12 on SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION
18 M 2 11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION end
19 A 75.9 9 ATTACH_APPLICATION_TRANSACTION end
20 M 232.6 searchabledictionary oncreate
24 161 item clicked
25 L 5 1 START_ACTIVITY_TRANSACTION begin
26 B 15.9 2 on START_ACTIVITY_TRANSACTION
27 A 6 3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION begin
28 B 0 4 on SCHEDULE_PAUSE_ACTIVITY_TRANSACTION
29 L 2 3 SCHEDULE_PAUSE_ACTIVITY_TRANSACTION end
30 A 15 1 START_ACTIVITY_TRANSACTION end
31 L 34 5 ACTIVITY_PAUSED_TRANSACTION begin
32 B 1 6 on ACTIVITY_PAUSED_TRANSACTION
33 A 6 11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION begin
34 B 2 12 on SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION
35 M 3 11 SCHEDULE_LAUNCH_ACTIVITY_TRANSACTION end
36 A 36.9 5 ACTIVITY_PAUSED_TRANSACTION end
37 M 58.8 wordactivity oncreate
说明:
- Time 为当前事件与上一事件的间隔,Actor 为消耗这段时间的主体。A:
AMS;B:Binder;L:Launcher;M:MainActivity。 - 方便起见，请求启动子Activity的对象同样被标记为
Launcher。 Process.start的执行时间归于Binder，而该函数返回直到ActivityThread.main的时间归于MainActivity。- 在
Process.start后AMS与MainActivity并发执行,时间为 11.1ms，为便于统计这段重合时间归于AMS。 - 脚本完成了绝大部分计算，仍有部分是手工计算的(这些结果包括行 1-2、行 19-20、行 36-37 之间的间隔)。
- 相同时间的 Log 可能会出现乱序(Log 并非原子操作,但时间的正确的)，最终结果对这种情况进行了手工纠正。
对这四个主体消耗的时间进行加和,可得到如下时间分布图:
图1：主Activity 启动时间分布(合计:674.3ms)
图2：子Activity 启动时间分布(合计:185.6ms)
由图1可以看出，主Activity 启动过程中，主要的性能瓶颈由 MainActivity 的创建和切换产生，Binder 消费的时间非常少。
在图2中，各部分消费时间相差较小,以AMS和MainActivity耗时为主,Binder所占时间仍是最少的。
在图2中，子Activity启动时间相对主Activity来讲已经大大减少。此外,这个过程的时间波动可能与子Activity 的具体类型高度相关。
在图2中，Launcher的时间有所增加。注意这里的Launcher是发出启动子Activity请求的对象,即主Activity。这说明系统的Launcher程序是有所优化的(响应时间减少了76.1%)。
综上，
Binder机制是一种高效的进程间通信机制。它在提供高可靠性和扩展性的同时，并未引入过多的时间开销。AMS提供将Activity与进程分离的机制,其时间也小于MainActivity本身,这样的开销是值得的。- 系统的
Launcher启动Activity的速度要高于普通的主Activity。
本文采用 知识共享署名 4.0 国际许可协议（CC-BY 4.0）进行许可，转载注明来源即可： https://harttle.land/2014/05/27/android-appstartup.html。如有疏漏、谬误、侵权请通过评论或 邮件 指出。
