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，并写入日志语句。

日志输出如下：

2021-08-08 12:55:36.295 537-579/system_process D/AppStart: 19113098274557 Intent received

5. 总结

本文主要介绍了Android系统是如何测量应用启动时间以及应用开发者如何测量应用启动各个阶段的启动耗时。有了这些我们能够很好的定位启动过程中的耗时以及性能瓶颈。如果你在应用启动优化有比较好的实践成果欢迎留言讨论哟

关注同名微信公众号，好文抢先看。搜索框传播样式-标准色版.png

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