Android启动优化之精确测量启动各个阶段的耗时

我们可以通过观察logcat日志查看Android应用启动耗时，过滤关键字"Displayed"：
ActivityTaskManager: Displayed com.peter.viewgrouptutorial/.activity.DashboardActivity: +797ms
启动时长(在这个例子中797ms)表示从启动App到系统认为App启动完成所花费的时间。

从用户点击桌面图标，到Activity启动并将界面第一帧绘制出来大概会经过以下几个阶段。

1. system_server展示starting window
2. Zygote fork Android 进程
3. ActivityThread handleBindApplication(这个阶段又细分为)
   • 加载程序代码和资源
   • 初始化ContentProvider
   • 执行Application.onCreate()
4. 启动Activity(执行 onCreate、onStart、onResume等方法)
5. ViewRootImpl执行doFrame()绘制View，计算出首帧绘制时长。
   流程图如下：
   
   我们可以看出：阶段1和2都是由系统控制的。App开发者对这两个阶段的耗时能做的优化甚微。
   

   3. 系统是如何测量启动时长的？

   
   本文源码基于android-30
   我们在cs.android.com源码阅读网站上全局搜索
   
   1.在ActivityMetricsLogger.logAppDisplayed()方法中发现了打印日志语句

private void logAppDisplayed(TransitionInfoSnapshot info
) {if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {return;}EventLog.writeEvent(WM_ACTIVITY_LAUNCH_TIME,info.userId, info.activityRecordIdHashCode, info.launchedActivityShortComponentName,info.windowsDrawnDelayMs);StringBuilder sb = mStringBuilder;sb.setLength(0);sb.append("Displayed ");sb.append(info.launchedActivityShortComponentName);sb.append(": ");TimeUtils.formatDuration(info.windowsDrawnDelayMs, sb);Log.i(TAG, sb.toString());
}

2. TransitionInfoSnapshot.windowsDrawnDelayMs是启动的时长。它在以下方法中被赋值：
   • ActivityMetricsLogger.notifyWindowsDrawn()
   • ➡️ TransitionInfo.calculateDelay()

//ActivityMetricsLogger.java
TransitionInfoSnapshot notifyWindowsDrawn(ActivityRecord r, long timestampNs
) {  TransitionInfo info = getActiveTransitionInfo(r);info.mWindowsDrawnDelayMs = info.calculateDelay(timestampNs);return new TransitionInfoSnapshot(info);
}
private static final class TransitionInfo {int calculateDelay(long timestampNs) {long delayNanos = timestampNs - mTransitionStartTimeNs;return (int) TimeUnit.NANOSECONDS.toMillis(delayNanos);}
}

3. timestampNs表示启动结束时间，mTransitionStartTimeNs表示启动开始时间。它们分别是在哪赋值的呢?
   mTransitionStartTimeNs启动开始时间在notifyActivityLaunching方法中被赋值。调用堆栈如下：
   • ActivityManagerService.startActivity()
   • ➡️ActivityManagerService.startActivityAsUser()
   • ➡️ActivityStarter.execute()
   • ➡️ActivityMetricsLogger.notifyActivityLaunching()
   
   ActivityMetricsLogger.notifyActivityLaunching(…)

//ActivityMetricsLogger.java
private LaunchingState notifyActivityLaunching(Intent intent,ActivityRecord caller,int callingUid
) {...long transitionStartNs = SystemClock.elapsedRealtimeNanos();LaunchingState launchingState = new LaunchingState();launchingState.mCurrentTransitionStartTimeNs = transitionStartNs;...return launchingState; 
}

启动时间记录到LaunchingState.mCurrentTransitionStartTimeNs中
ActivityStarter.execute()

//ActivityStarter.java
int execute() {try {final LaunchingState launchingState;synchronized (mService.mGlobalLock) {final ActivityRecord caller = ActivityRecord.forTokenLocked(mRequest.resultTo);launchingState = mSupervisor.getActivityMetricsLogger().notifyActivityLaunching(mRequest.intent, caller);}if (mRequest.activityInfo == null) {mRequest.resolveActivity(mSupervisor);}int res;synchronized (mService.mGlobalLock) {mSupervisor.getActivityMetricsLogger().notifyActivityLaunched(launchingState, res,mLastStartActivityRecord);return getExternalResult(mRequest.waitResult == null ? res: waitForResult(res, mLastStartActivityRecord));}} finally {onExecutionComplete();}
}

该方法作用如下：

1. 调用ActivityMetricsLogger().notifyActivityLaunching()生成LaunchingState。将启动时间记录其中
2. 执行StartActivity逻辑
3. 调用ActivityMetricsLogger().notifyActivityLaunched()把launchingState和ActivityRecord映射保存起来
   ActivityMetricsLogger.notifyActivityLaunched(…)

//ActivityMetricsLogger.java
void notifyActivityLaunched(LaunchingState launchingState,int resultCode,ActivityRecord launchedActivity) {...final TransitionInfo newInfo = TransitionInfo.create(launchedActivity, launchingState,processRunning, processSwitch, resultCode);if (newInfo == null) {abort(info, "unrecognized launch");return;}if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful");// A new launch sequence has begun. Start tracking it.mTransitionInfoList.add(newInfo);mLastTransitionInfo.put(launchedActivity, newInfo);startLaunchTrace(newInfo);if (newInfo.isInterestingToLoggerAndObserver()) {launchObserverNotifyActivityLaunched(newInfo);} else {// As abort for no process switch.launchObserverNotifyIntentFailed();}
}

该方法将根据LaunchingState和ActivityRecord生成TransitionInfo保存到mTransitionInfoList中。这样就将启动开始时间保存起来了。
ActivityMetricsLogger.notifyWindowsDrawn(…)

//ActivityMetricsLogger.java
TransitionInfoSnapshot notifyWindowsDrawn(ActivityRecord r, long timestampNs
) {  TransitionInfo info = getActiveTransitionInfo(r);info.mWindowsDrawnDelayMs = info.calculateDelay(timestampNs);return new TransitionInfoSnapshot(info);
}

notifyWindowsDraw方法正是通过查找mTransitionInfoList中对应的TransitionInfo获取到Activity的启动开始时间。
启动完成调用堆栈如下
• ActivityRecord.onFirstWindowDrawn()
• ➡️ActivityRecord.updateReportedVisibilityLocked()
• ➡️ActivityRecord.onWindowsDrawn()
• ➡️ActivityMetricsLogger.notifyWindowsDrawn()

ActivityRecord.updateReportedVisibilityLocked()

//ActivityRecord.java
void updateReportedVisibilityLocked() {...boolean nowDrawn = numInteresting > 0 && numDrawn >= numInteresting;boolean nowVisible = numInteresting > 0 && numVisible >= numInteresting && isVisible();if (nowDrawn != reportedDrawn) {onWindowsDrawn(nowDrawn, SystemClock.elapsedRealtimeNanos());reportedDrawn = nowDrawn;}...
}
void onWindowsDrawn(boolean drawn, long timestampNs) {mDrawn = drawn;if (!drawn) {return;}final TransitionInfoSnapshot info = mStackSupervisor.getActivityMetricsLogger().notifyWindowsDrawn(this, timestampNs);...
}

我们看到在updateReportedVisibilityLocked()方法中把SystemClock.elapsedRealtimeNanos()传递给onWindowsDrawn(nowDrawn, SystemClock.elapsedRealtimeNanos())

1. 准备一台root的手机(或者非Google Play版本模拟器)
2. compileSdkVersion、targetSdkVersion与模拟器版本一致(本文30)
3. notifyActivityLaunching和notifyWindowsDrawn中增加断点
4. 调试勾选Show all processes选择system_process
   
   几个重要的时间节点
5. ActivityManagerService接收到startActivity信号时间，等价于launchingState.mCurrentTransitionStartTimeNs。时间单位纳秒。
6. 进程Fork的时间，时间单位毫秒。可以通过以下方式获取：

object Processes {@JvmStaticfun readProcessForkRealtimeMillis(): Long {val myPid = android.os.Process.myPid()val ticksAtProcessStart = readProcessStartTicks(myPid)// Min API 21, use reflection before API 21.// See https://stackoverflow.com/a/42195623/703646val ticksPerSecond = Os.sysconf(OsConstants._SC_CLK_TCK)return ticksAtProcessStart * 1000 / ticksPerSecond}// Benchmarked (with Jetpack Benchmark) on Pixel 3 running// Android 10. Median time: 0.13msfun readProcessStartTicks(pid: Int): Long {val path = "/proc/$pid/stat"val stat = BufferedReader(FileReader(path)).use { reader ->reader.readLine()}val fields = stat.substringAfter(") ").split(' ')return fields[19].toLong()}
}

3. ActivityThread.handleBindApplication时设置的进程启动时间，单位毫秒。Process.getStartElapsedRealtime()。

//ActivityThread.java
private void handleBindApplication(AppBindData data) {...// Note when this process has started.Process.setStartTimes(SystemClock.elapsedRealtime(), SystemClock.uptimeMillis());...
}

4.程序代码和资源加载的时间，时间单位毫秒。Application类初始化时的时间与handleBindApplication的时间差

class MyApp extends Application {static {if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) {long loadApkAndResourceDuration = SystemClock.elapsedRealtime() - Process.getStartElapsedRealtime();}}
}

5.ContentProvider初始化时间，时间单位毫秒。 Application.onCreate() 与Application.attachBaseContext(Context context) 之间的时间差

class MyApp extends Application {long mAttachBaseContextTime = 0L;long mContentProviderDuration = 0L;@Overrideprotected void attachBaseContext(Context base) {super.attachBaseContext(base);mAttachBaseContextTime = SystemClock.elapsedRealtime();}@Overridepublic void onCreate() {super.onCreate();mContentProviderDuration = SystemClock.elapsedRealtime() - mAttachBaseContextTime;}

6. Application.onCreate()花费时间，时间单位毫秒。很简单方法开始和结束时间差。
7. 首帧绘制时间，比较复杂，使用到了com.squareup.curtains:curtains:1.0.1代码如下，firstDrawTime就是首帧的绘制时间。从ActivityThread.handleBindApplication()到首帧绘制所花费的时间：

class MyApp extends Application {@Overridepublic void onCreate() {super.onCreate();registerActivityLifecycleCallbacks(new ActivityLifecycleCallbacks() {@Overridepublic void onActivityCreated(Activity activity, Bundle savedInstanceState) {Window window = activity.getWindow();WindowsKt.onNextDraw(window, () -> {if (firstDraw) return null;firstDraw = true;handler.postAtFrontOfQueue(() -> {if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) {long firstDrawTime =  (SystemClock.elapsedRealtime() - Process.getStartElapsedRealtime()));}});return null;});}}}
}

调试launchingState.mCurrentTransitionStartTimeNs
由于ActivityMetricsLogger是运行在system_process进程中。我们无法在应用进程中获取到transitionStartTimeNs，我们可以用过Debug打印日志。我们需要将断点设置成non-suspending。如图将Suspend反勾选。选中Evaluate and log，并写入日志语句。