性能优化-Android中如何通过adb start命令和添加Log方式统计APP启动时间
前言
鉴于最近这段时间在做APP的性能优化方面的工作，其中一个小项是需要提高APP的启动速度，最好做到秒开的地步；做这个的时候需要经常去观察和统计APP启动到底需要多长时间，所以本篇文章就记录下这方面的经历，也希望能给后来者一些帮助
本文所含代码随时更新，可从这里下载最新代码
传送门
启动时间
说到启动时间我们需要重新理一下应用启动时间到底怎么定义？或者说站在谁的角度定义？
APP是做给用户使用的，一切的优化都是为了给用户更好的体验，所以应该站在用户的角度来定义这个启动时间：即冷启动中（冷启动大概意思就是手机中不存在该APP的进程，然后启动这种情况），从用户点击屏幕上的Logo开始到用户看到APP第一个页面展现在他眼前的这段时间，也就是尽快让用户看到应用页面
adb start 命令
在进行开发调试和上线前的测试工作时可以通过adb命令进行统计，如下
adb shell am start -S -R 5 -W com.mango.datasave/.SplashActivity
- S表示每次启动前先强制杀死应用进程，达到每次都是冷启动，一定要大写
- R表示重复次数，一定要大写
- W表示是否等待输出日志信息，一定要大写
- 后面接包名加Activity名称，别忘记点号了；要启动的Activity一定要有< intent-filter>标签或者android:exported="true"属性，否则会报SecurityException: Permission Denial异常
接下来看下执行结果，这里只截取一次
Starting: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10000000 cmp=com.mango.datasave/.SplashActivity }
Status: ok
Activity: com.mango.datasave/.SplashActivity
ThisTime: 947
TotalTime: 947
WaitTime: 976
Complete
可以看到这里有显示时间的三个字段ThisTime，TotalTime，WaitTime；那这三个时间指的是什么呢？这时候我们就要找到它们是怎么计算出来的，这样才能搞明白自己到底需要哪个
这句adb命令的实现是在
frameworks\base\cmds\am\src\com\android\commands\am\Am.java
本文基于API24
AM.onRun
private IActivityManager mAm;
private IPackageManager mPm;
@Override
public void onRun() throws Exception {
mAm = ActivityManagerNative.getDefault();
if (mAm == null) {
throw new AndroidException("Can't connect to activity manager; is the system running?");
}
mPm = IPackageManager.Stub.asInterface(ServiceManager.getService("package"));
if (mPm == null) {
throw new AndroidException("Can't connect to package manager; is the system running?");
}
String op = nextArgRequired();
if (op.equals("start")) {
runStart();
} else {
showError("Error: unknown command '" + op + "'");
}
}
这个方法里其实还有很多命令的解析，比如startservice，stopservice，broadcast，dumpheap等，大家如果有兴趣可以去研究；我们这里就只看start这个命令
AM.runStart
private void runStart() throws Exception {
//根据命令构建Intent
Intent intent = makeIntent(UserHandle.USER_CURRENT);
if (mUserId == UserHandle.USER_ALL) {
System.err.println("Error: Can't start service with user 'all'");
return;
}
String mimeType = intent.getType();
if (mimeType == null && intent.getData() != null
&& "content".equals(intent.getData().getScheme())) {
mimeType = mAm.getProviderMimeType(intent.getData(), mUserId);
}
do {
//强制关闭应用
if (mStopOption) {
String packageName;
if (intent.getComponent() != null) {
packageName = intent.getComponent().getPackageName();
} else {
List<ResolveInfo> activities = mPm.queryIntentActivities(intent, mimeType, 0,
mUserId).getList();
if (activities == null || activities.size() <= 0) {
System.err.println("Error: Intent does not match any activities: "
+ intent);
return;
} else if (activities.size() > 1) {
System.err.println("Error: Intent matches multiple activities; can't stop: "
+ intent);
return;
}
packageName = activities.get(0).activityInfo.packageName;
}
System.out.println("Stopping: " + packageName);
mAm.forceStopPackage(packageName, mUserId);
Thread.sleep(250);
}
System.out.println("Starting: " + intent);
intent.addFlags(Intent.FLAG_ACTIVITY_NEW_TASK);
......
IActivityManager.WaitResult result = null;
int res;
final long startTime = SystemClock.uptimeMillis();
ActivityOptions options = null;
if (mStackId != INVALID_STACK_ID) {
options = ActivityOptions.makeBasic();
options.setLaunchStackId(mStackId);
}
//通过Binder机制通知AMS启动Activity
if (mWaitOption) {
result = mAm.startActivityAndWait(null, null, intent, mimeType,
null, null, 0, mStartFlags, profilerInfo,
options != null ? options.toBundle() : null, mUserId);
res = result.result;
} else {
res = mAm.startActivityAsUser(null, null, intent, mimeType,
null, null, 0, mStartFlags, profilerInfo,
options != null ? options.toBundle() : null, mUserId);
}
final long endTime = SystemClock.uptimeMillis();
PrintStream out = mWaitOption ? System.out : System.err;
boolean launched = false;
switch (res) {
case ActivityManager.START_SUCCESS:
launched = true;
break;
}
//输出日志信息
if (mWaitOption && launched) {
if (result == null) {
result = new IActivityManager.WaitResult();
result.who = intent.getComponent();
}
System.out.println("Status: " + (result.timeout ? "timeout" : "ok"));
if (result.who != null) {
System.out.println("Activity: " + result.who.flattenToShortString());
}
if (result.thisTime >= 0) {
System.out.println("ThisTime: " + result.thisTime);
}
if (result.totalTime >= 0) {
System.out.println("TotalTime: " + result.totalTime);
}
System.out.println("WaitTime: " + (endTime-startTime));
System.out.println("Complete");
}
//重复执行
mRepeat--;
if (mRepeat > 1) {
mAm.unhandledBack();
}
} while (mRepeat > 1);
}
private Intent makeIntent(int defUser) throws URISyntaxException {
mStartFlags = 0;
mWaitOption = false;
mStopOption = false;
mRepeat = 0;
mProfileFile = null;
mSamplingInterval = 0;
mAutoStop = false;
mUserId = defUser;
mStackId = INVALID_STACK_ID;
return Intent.parseCommandArgs(mArgs, new Intent.CommandOptionHandler() {
@Override
public boolean handleOption(String opt, ShellCommand cmd) {
if (opt.equals("-D")) {
mStartFlags |= ActivityManager.START_FLAG_DEBUG;
} else if (opt.equals("-N")) {
mStartFlags |= ActivityManager.START_FLAG_NATIVE_DEBUGGING;
} else if (opt.equals("-W")) {
mWaitOption = true;
} else if (opt.equals("-P")) {
mProfileFile = nextArgRequired();
mAutoStop = true;
} else if (opt.equals("--start-profiler")) {
mProfileFile = nextArgRequired();
mAutoStop = false;
} else if (opt.equals("--sampling")) {
mSamplingInterval = Integer.parseInt(nextArgRequired());
} else if (opt.equals("-R")) {
mRepeat = Integer.parseInt(nextArgRequired());
} else if (opt.equals("-S")) {
mStopOption = true;
} else if (opt.equals("--track-allocation")) {
mStartFlags |= ActivityManager.START_FLAG_TRACK_ALLOCATION;
} else if (opt.equals("--user")) {
mUserId = parseUserArg(nextArgRequired());
} else if (opt.equals("--receiver-permission")) {
mReceiverPermission = nextArgRequired();
} else if (opt.equals("--stack")) {
mStackId = Integer.parseInt(nextArgRequired());
} else {
return false;
}
return true;
}
});
}
从这个方法就能清楚的看到是通过Binder机制通知ActivityManagerService（以下简称AMS）去启动Activity；调用流程可以参考从源码解析-Android中Activity启动流程包含AIDL使用案例和APP启动闪屏的缘由；这里就不探讨这些知识了
时间计算
从AM.runStart方法可以看出来，WaitTime是(endTime-startTime)的结果，startTime记录startActivityAndWait刚调用的时间，endTime是startActivityAndWait调用结束的时间，所以WaitTime就是startActivityAndWait所消耗的时间；而thisTime和totalTime是WaitResult 对象带回来的，它们在如下类中计算
frameworks\base\services\core\java\com\android\server\am\ActivityRecord.java
//计算时间
private void reportLaunchTimeLocked(final long curTime) {
final ActivityStack stack = task.stack;
if (stack == null) {
return;
}
final long thisTime = curTime - displayStartTime;
final long totalTime = stack.mLaunchStartTime != 0
? (curTime - stack.mLaunchStartTime) : thisTime;
if (SHOW_ACTIVITY_START_TIME) {
StringBuilder sb = service.mStringBuilder;
sb.setLength(0);
sb.append("Displayed ");
sb.append(shortComponentName);
sb.append(": ");
TimeUtils.formatDuration(thisTime, sb);
if (thisTime != totalTime) {
sb.append(" (total ");
TimeUtils.formatDuration(totalTime, sb);
sb.append(")");
}
}
mStackSupervisor.reportActivityLaunchedLocked(false, this, thisTime, totalTime);
displayStartTime = 0;
stack.mLaunchStartTime = 0;
}
//记录时间信息
void reportActivityLaunchedLocked(boolean timeout, ActivityRecord r,
long thisTime, long totalTime) {
boolean changed = false;
for (int i = mWaitingActivityLaunched.size() - 1; i >= 0; i--) {
WaitResult w = mWaitingActivityLaunched.remove(i);
if (w.who == null) {
changed = true;
w.timeout = timeout;
if (r != null) {
w.who = new ComponentName(r.info.packageName, r.info.name);
}
w.thisTime = thisTime;
w.totalTime = totalTime;
}
}
if (changed) {
mService.notifyAll();
}
}
这里的thisTime和totalTime和adb命令获取的是相同的，它们是根据curTime、displayStartTime、mLaunchStartTime三个时间变量计算
- curTime表示reportLaunchTimeLocked函数调用的时间点，也就是最终Activity完整显示的时间点
- displayStartTime表示一连串启动Activity中的最后一个Activity的启动时间点
- mLaunchStartTime表示一连串启动Activity中第一个Activity的启动时间点
注意：那我们需要以哪个时间为准呢，其实不同需求要参考不同的时间，比如有的公司注重于用户点击APP尽快看到第一个Activity，像我这里就是这个目的；有的公司APP注重于尽快看到主页Activity，这种情况下就会经过一个广告页或者说欢迎页Activity，然后再到主页Activity，会有两个Activity；那我们就分两种情况讨论
- 启动单个Activity
我们这里的情况是点击桌面Logo启动应用，直到看到第一个Activity为止，所以displayStartTime和mLaunchStartTime是同一个值，所以根据上面的计算公式
thisTime = curTime - displayStartTime
totalTime = stack.mLaunchStartTime != 0 ? (curTime - stack.mLaunchStartTime) : thisTime;
可以得出thisTime = totalTime
- 启动多个Activity
如果是连续启动多个Activity，displayStartTime就表示最后一个Activity开始启动时间点，mLaunchStartTime 表示第一个Activity启动时间点；这样根据上面公式计算thisTime < totalTime
总结
可能你会有疑问，reportLaunchTimeLocked函数的参数curTime是什么时候的时间？前面说过，在onResume方法回调之后，Activity窗口才会添加到WMS中，然后进行绘制，窗口绘制完成后通知WMS，WMS在合适的时机控制界面开始显示(夹杂了界面切换动画逻辑)；显示出来后，WMS才调用reportLaunchTimeLocked()通知AMS Activity启动完成；所以这个curTime是最终完成时间；接下来就可以得出三个时间代表什么了
- thisTime就是最后一个Activity启动所消耗的时间
- totalTime就是冷启动中一个新应用启动所消耗的时间，它包括进程创建，Application创建和Activity启动
- WaitTime就是总的时间，它还包括前一个Activity的pause方法耗时（这里就是桌面应用Activity pause方法耗时）
所以我们如果只关注自己Activity冷启动所消耗的时间，只用关注totalTime就行了，这也是自己应用真正启动的耗时；如果只关注最后一个Activity的耗时，那关注thisTime；如果还需要考虑系统消耗，那就关注WaitTime
注意：WaitTime比totalTime多了一个桌面应用LuncherActivity的pause方法耗时，但是这个我们开发者操作不了，所以就关注totalTime就行了
Log日志
当APP上线被用户使用后，使用adb命令肯定行不通了，这时候我们就得通过Log日志来将应用启动时间上报到服务器；但是问题来了，日志该添加到哪里呢？毕竟添加的位置直接决定启动时间统计是否准确，同样也会影响启动速度优化效果的判断；这时候就需要你熟知应用的启动流程和Activity的启动流程
-
由博主前面的文章可以知道一个APP被用户启动后，第一件事就是创建它的进程，然后加载ActivityThread类，在它的main方法做经过一系列的调用，其中第一件事就是创建应用的Application实例，这个是在所有Activity加载前做的事，所以Log起点就可以在Application里加；但是加在它哪个方法呢？幸运的是这个类的构造方法是public修饰的，我们可以将起点加在构造方法中；但是我们由于一些因素一般不用这个构造方法，这时候可以看到实例创建后立即调用的第一个方法是attach方法，但是它是final修饰，我们不能重写，好在是attach方法里调用了attachBaseContext方法，这个方法是可以被重写的，这样我们就可以将Log起点加在attachBaseContext方法中
-
Log起始点有了，那就需要结束点；我们的目的是统计到第一个Activity页面显示出来的时间，那是不是加到第一个Activity的onResume方法呢？看到网上很多博客说当一个Activity的onResume方法回调之后，你就能看到Activity的页面内容了，这其实是错的，这个时候内容并没有绘制出来，当你结合上面分析和这篇文章
从源码解析-结合Activity加载流程深入理解ActivityThrad的工作逻辑，你就知道Activity的onCreate方法在回调过程中做了目标Activity类的加载，进行Activity一些初始化操作，比如完成Window的创建并建立自己和Window的关联；还有主题设置，View树的建立（这里View还没有绘制，只是inflate而已）等这些事情；onStart，onResume方法在回调之后才会将窗口添加到WMS，绘制显示完后WMS通知AMS Activity启动完成，同时Activity的onWindowFocusChanged方法会被回调；所以我们可以重写这个方法然后加Log；但是要注意该方法在 Activity 焦点发生变化时就会触发，所以要做好判断，去掉不需要的情况
这样我们可以写个工具类统计时间并提交到服务端
/**
* @Description TODO(时间辅助类)
* @author cxy
* @Date 2018/11/27 16:27
*/
public class TimeTools {
private static String TAG = TimeTools.class.getSimpleName();
private static Map<String,Long> mStartTime = new HashMap<>();
private static String TIME_BEGIN = "begin";
private static String TIME_PART = "part";
/**
* 保存应用创建的时间点
*/
public static void saveBeginTime(){
long time = System.currentTimeMillis();
mStartTime.put(TIME_BEGIN,time);
}
/**
* 保存应用冷启动到第一个Activity完整显示所消耗的时间
*/
public static void savePartTime(){
//判断是不是冷启动
if (!mStartTime.containsKey(TIME_BEGIN) || mStartTime.get(TIME_BEGIN) <= 0l) {
return;
}
long timePart = System.currentTimeMillis() - mStartTime.get(TIME_BEGIN);
mStartTime.put(TIME_PART,timePart);
mStartTime.remove(TIME_BEGIN);
}
/**
* 将启动时间提交到服务端
*/
public static void commitTime2Server(){
if (!mStartTime.containsKey(TIME_PART) || mStartTime.get(TIME_PART) <= 0) {
return;
}
LocalThreadPools.getInstance().execute(new Runnable() {
@Override
public void run() {
long time = mStartTime.get(TIME_PART);
mStartTime.remove(TIME_PART);
}
});
}
}
然后在Application里
@Override
protected void attachBaseContext(Context base) {
super.attachBaseContext(base);
TimeTools.saveBeginTime();
}
在第一个Activity里这样
@Override
public void onWindowFocusChanged(boolean hasFocus) {
if (hasFocus) {
TimeTools.savePartTime();
TimeTools.commitTime2Server();
}
}
完结
通过Log统计出来Demo的启动时间是778ms左右，比上面的adb命令获取的TotalTime: 947ms时间要少，因为TotalTime还包括进程创建时间，但是进程创建这部分作为开发者来说能做的有限；所以这个778ms就可以看做是应用冷启动消耗的时间，包括Application创建所消耗时间和Activity完全显示所消耗时间
所以你要想优加快APP启动速度，可以从这两个方面入手
参考文章
https://www.zhihu.com/question/35487841/answer/63011462