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源码阅读网站上全局搜索
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());
}
- 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);
}
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());
...
}
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;
@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，并写入日志语句。
