1. 直观地观察应用启动时长
我们可以通过观察logcat日志查看Android应用启动耗时，过滤关键字"Displayed"：
ActivityTaskManager: Displayed com.peter.viewgrouptutorial/.activity.DashboardActivity: +797ms
启动时长(在这个例子中797ms)表示从启动App到系统认为App启动完成所花费的时间。
2. 启动时间包含哪几个阶段
从用户点击桌面图标，到Activity启动并将界面第一帧绘制出来大概会经过以下几个阶段。
- system_server展示starting window
- Zygote fork Android 进程
- ActivityThread handleBindApplication(这个阶段又细分为)
- 加载程序代码和资源
- 初始化ContentProvider
- 执行Application.onCreate()
- 启动Activity(执行 onCreate、onStart、onResume等方法)
- ViewRootImpl执行doFrame()绘制View，计算出首帧绘制时长。
流程图如下：
我们可以看出：阶段1和2都是由系统控制的。App开发者对这两个阶段的耗时能做的优化甚微。
3. 系统是如何测量启动时长的？
本文源码基于android-30
我们在cs.android.com源码阅读网站上全局搜索
- 在
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()); }
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); } }
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(); } }
该方法作用如下：
- 调用ActivityMetricsLogger().notifyActivityLaunching()生成LaunchingState。将启动时间记录其中
- 执行StartActivity逻辑
- 调用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); }
//ActivityMetricsLogger.java private TransitionInfo getActiveTransitionInfo(WindowContainer wc) { for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) { final TransitionInfo info = mTransitionInfoList.get(i); if (info.contains(wc)) { return info; } } return null;
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())
4. 调试技巧
通过断点调试记录应用冷启动记录耗时调用栈
- 准备一台root的手机(或者非Google Play版本模拟器)
- compileSdkVersion、targetSdkVersion与模拟器版本一致(本文30)
- notifyActivityLaunching和notifyWindowsDrawn中增加断点
- 调试勾选
Show all processes选择system_process
几个重要的时间节点
ActivityManagerService接收到startActivity信号时间，等价于launchingState.mCurrentTransitionStartTimeNs。时间单位纳秒。- 进程Fork的时间，时间单位毫秒。可以通过以下方式获取：
object Processes { @JvmStatic fun 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/703646 val ticksPerSecond = Os.sysconf(OsConstants._SC_CLK_TCK) return ticksAtProcessStart * 1000 / ticksPerSecond } // Benchmarked (with Jetpack Benchmark) on Pixel 3 running // Android 10. Median time: 0.13ms fun 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() } }
ActivityThread.handleBindApplication时设置的进程启动时间，单位毫秒。Process.getStartElapsedRealtime()。
//ActivityThread.java private void handleBindApplication(AppBindData data) { ... // Note when this process has started. Process.setStartTimes(SystemClock.elapsedRealtime(), SystemClock.uptimeMillis()); ... }
- 程序代码和资源加载的时间，时间单位毫秒。
Application类初始化时的时间与handleBindApplication的时间差
class MyApp extends Application { static { if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) { long loadApkAndResourceDuration = SystemClock.elapsedRealtime() - Process.getStartElapsedRealtime(); } } }
- ContentProvider初始化时间，时间单位毫秒。
Application.onCreate()与Application.attachBaseContext(Context context)之间的时间差
class MyApp extends Application { long mAttachBaseContextTime = 0L; long mContentProviderDuration = 0L; @Override protected void attachBaseContext(Context base) { super.attachBaseContext(base); mAttachBaseContextTime = SystemClock.elapsedRealtime(); } @Override public void onCreate() { super.onCreate(); mContentProviderDuration = SystemClock.elapsedRealtime() - mAttachBaseContextTime; }
Application.onCreate()花费时间，时间单位毫秒。很简单方法开始和结束时间差。
- 首帧绘制时间，比较复杂，使用到了
com.squareup.curtains:curtains:1.0.1代码如下，firstDrawTime就是首帧的绘制时间。从ActivityThread.handleBindApplication()到首帧绘制所花费的时间：
class MyApp extends Application { @Override public void onCreate() { super.onCreate(); registerActivityLifecycleCallbacks(new ActivityLifecycleCallbacks() { @Override public 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，并写入日志语句。
