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系统是如何测量应用启动时间
以及应用开发者如何测量应用启动各个阶段的启动耗时
。有了这些我们能够很好的定位启动过程中的耗时以及性能瓶颈。如果你在应用启动优化有比较好的实践成果
欢迎留言讨论哟
关注同名微信公众号,好文抢先看。