Move fully drawn metric log out of wm lock
The method getPackageOptimizationInfo will access IO which
may spend 3~10+ms, so post the log action to the logger thread
to avoid blocking other important UI operations.
ActivityRecord#reportFullyDrawnLocked is removed because fully
drawn won't be accepted if the window is not drawn, so the
invocation reportActivityLaunched in it is a dead code.
Currently reportActivityLaunched will be called from
ActivityRecord#onWindowsDrawn.
Bug: 236677935
Test: atest ActivityMetricsLaunchObserverTests
Change-Id: Ic64b9722de4edb0a41cc7370ed0ed2f7019bbdec
diff --git a/services/core/java/com/android/server/wm/ActivityClientController.java b/services/core/java/com/android/server/wm/ActivityClientController.java
index 7386a19..3b7bf48 100644
--- a/services/core/java/com/android/server/wm/ActivityClientController.java
+++ b/services/core/java/com/android/server/wm/ActivityClientController.java
@@ -1211,7 +1211,8 @@
synchronized (mGlobalLock) {
final ActivityRecord r = ActivityRecord.isInRootTaskLocked(token);
if (r != null) {
- r.reportFullyDrawnLocked(restoredFromBundle);
+ mTaskSupervisor.getActivityMetricsLogger().notifyFullyDrawn(r,
+ restoredFromBundle);
}
}
} finally {
diff --git a/services/core/java/com/android/server/wm/ActivityMetricsLogger.java b/services/core/java/com/android/server/wm/ActivityMetricsLogger.java
index f0de1d3..e1ab291 100644
--- a/services/core/java/com/android/server/wm/ActivityMetricsLogger.java
+++ b/services/core/java/com/android/server/wm/ActivityMetricsLogger.java
@@ -454,6 +454,7 @@
final int windowsFullyDrawnDelayMs;
final int activityRecordIdHashCode;
final boolean relaunched;
+ final long timestampNs;
private TransitionInfoSnapshot(TransitionInfo info) {
this(info, info.mLastLaunchedActivity, INVALID_DELAY);
@@ -483,6 +484,7 @@
activityRecordIdHashCode = System.identityHashCode(launchedActivity);
this.windowsFullyDrawnDelayMs = windowsFullyDrawnDelayMs;
relaunched = info.mRelaunched;
+ timestampNs = info.mLaunchingState.mStartRealtimeNs;
}
@WaitResult.LaunchState int getLaunchState() {
@@ -498,6 +500,10 @@
}
}
+ boolean isIntresetedToEventLog() {
+ return type == TYPE_TRANSITION_WARM_LAUNCH || type == TYPE_TRANSITION_COLD_LAUNCH;
+ }
+
PackageOptimizationInfo getPackageOptimizationInfo(ArtManagerInternal artManagerInternal) {
return artManagerInternal == null || launchedActivityAppRecordRequiredAbi == null
? PackageOptimizationInfo.createWithNoInfo()
@@ -1022,16 +1028,17 @@
// This will avoid any races with other operations that modify the ActivityRecord.
final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info);
if (info.isInterestingToLoggerAndObserver()) {
- final long timestampNs = info.mLaunchingState.mStartRealtimeNs;
final long uptimeNs = info.mLaunchingState.mStartUptimeNs;
final int transitionDelay = info.mCurrentTransitionDelayMs;
final int processState = info.mProcessState;
final int processOomAdj = info.mProcessOomAdj;
mLoggerHandler.post(() -> logAppTransition(
- timestampNs, uptimeNs, transitionDelay, infoSnapshot, isHibernating,
+ uptimeNs, transitionDelay, infoSnapshot, isHibernating,
processState, processOomAdj));
}
- mLoggerHandler.post(() -> logAppDisplayed(infoSnapshot));
+ if (infoSnapshot.isIntresetedToEventLog()) {
+ mLoggerHandler.post(() -> logAppDisplayed(infoSnapshot));
+ }
if (info.mPendingFullyDrawn != null) {
info.mPendingFullyDrawn.run();
}
@@ -1040,7 +1047,7 @@
}
// This gets called on another thread without holding the activity manager lock.
- private void logAppTransition(long transitionStartTimeNs, long transitionDeviceUptimeNs,
+ private void logAppTransition(long transitionDeviceUptimeNs,
int currentTransitionDelayMs, TransitionInfoSnapshot info, boolean isHibernating,
int processState, int processOomAdj) {
final LogMaker builder = new LogMaker(APP_TRANSITION);
@@ -1108,7 +1115,7 @@
isIncremental,
isLoading,
info.launchedActivityName.hashCode(),
- TimeUnit.NANOSECONDS.toMillis(transitionStartTimeNs),
+ TimeUnit.NANOSECONDS.toMillis(info.timestampNs),
processState,
processOomAdj);
@@ -1132,10 +1139,6 @@
}
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);
@@ -1181,8 +1184,7 @@
}
/** @see android.app.Activity#reportFullyDrawn */
- TransitionInfoSnapshot logAppTransitionReportedDrawn(ActivityRecord r,
- boolean restoredFromBundle) {
+ TransitionInfoSnapshot notifyFullyDrawn(ActivityRecord r, boolean restoredFromBundle) {
final TransitionInfo info = mLastTransitionInfo.get(r);
if (info == null) {
return null;
@@ -1191,7 +1193,7 @@
// There are still undrawn activities, postpone reporting fully drawn until all of its
// windows are drawn. So that is closer to an usable state.
info.mPendingFullyDrawn = () -> {
- logAppTransitionReportedDrawn(r, restoredFromBundle);
+ notifyFullyDrawn(r, restoredFromBundle);
info.mPendingFullyDrawn = null;
};
return null;
@@ -1204,7 +1206,9 @@
currentTimestampNs - info.mLaunchingState.mStartUptimeNs);
final TransitionInfoSnapshot infoSnapshot =
new TransitionInfoSnapshot(info, r, (int) startupTimeMs);
- mLoggerHandler.post(() -> logAppFullyDrawn(infoSnapshot));
+ if (infoSnapshot.isIntresetedToEventLog()) {
+ mLoggerHandler.post(() -> logAppFullyDrawn(infoSnapshot));
+ }
mLastTransitionInfo.remove(r);
if (!info.isInterestingToLoggerAndObserver()) {
@@ -1216,46 +1220,8 @@
// fullfils (handling reportFullyDrawn() callbacks).
Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
"ActivityManager:ReportingFullyDrawn " + info.mLastLaunchedActivity.packageName);
-
- final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);
- builder.setPackageName(r.packageName);
- builder.addTaggedData(FIELD_CLASS_NAME, r.info.name);
- builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs);
- builder.setType(restoredFromBundle
- ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE
- : TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE);
- builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING,
- info.mProcessRunning ? 1 : 0);
- mMetricsLogger.write(builder);
- final PackageOptimizationInfo packageOptimizationInfo =
- infoSnapshot.getPackageOptimizationInfo(getArtManagerInternal());
- // Incremental info
- boolean isIncremental = false, isLoading = false;
- final String codePath = info.mLastLaunchedActivity.info.applicationInfo.getCodePath();
- if (codePath != null && IncrementalManager.isIncrementalPath(codePath)) {
- isIncremental = true;
- isLoading = isIncrementalLoading(info.mLastLaunchedActivity.packageName,
- info.mLastLaunchedActivity.mUserId);
- }
- FrameworkStatsLog.write(
- FrameworkStatsLog.APP_START_FULLY_DRAWN,
- info.mLastLaunchedActivity.info.applicationInfo.uid,
- info.mLastLaunchedActivity.packageName,
- restoredFromBundle
- ? FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITH_BUNDLE
- : FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITHOUT_BUNDLE,
- info.mLastLaunchedActivity.info.name,
- info.mProcessRunning,
- startupTimeMs,
- packageOptimizationInfo.getCompilationReason(),
- packageOptimizationInfo.getCompilationFilter(),
- info.mSourceType,
- info.mSourceEventDelayMs,
- isIncremental,
- isLoading,
- info.mLastLaunchedActivity.info.name.hashCode(),
- TimeUnit.NANOSECONDS.toMillis(info.mLaunchingState.mStartRealtimeNs));
-
+ mLoggerHandler.post(() -> logAppFullyDrawnMetrics(infoSnapshot, restoredFromBundle,
+ info.mProcessRunning));
// Ends the trace started at the beginning of this function. This is located here to allow
// the trace slice to have a noticable duration.
Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
@@ -1266,11 +1232,48 @@
return infoSnapshot;
}
- private void logAppFullyDrawn(TransitionInfoSnapshot info) {
- if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {
- return;
+ private void logAppFullyDrawnMetrics(TransitionInfoSnapshot info, boolean restoredFromBundle,
+ boolean processRunning) {
+ final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);
+ builder.setPackageName(info.packageName);
+ builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivityName);
+ builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS,
+ (long) info.windowsFullyDrawnDelayMs);
+ builder.setType(restoredFromBundle
+ ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE
+ : TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE);
+ builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING, processRunning ? 1 : 0);
+ mMetricsLogger.write(builder);
+ final PackageOptimizationInfo packageOptimizationInfo =
+ info.getPackageOptimizationInfo(getArtManagerInternal());
+ // Incremental info
+ boolean isIncremental = false, isLoading = false;
+ final String codePath = info.applicationInfo.getCodePath();
+ if (codePath != null && IncrementalManager.isIncrementalPath(codePath)) {
+ isIncremental = true;
+ isLoading = isIncrementalLoading(info.packageName, info.userId);
}
+ FrameworkStatsLog.write(
+ FrameworkStatsLog.APP_START_FULLY_DRAWN,
+ info.applicationInfo.uid,
+ info.packageName,
+ restoredFromBundle
+ ? FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITH_BUNDLE
+ : FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITHOUT_BUNDLE,
+ info.launchedActivityName,
+ processRunning,
+ info.windowsFullyDrawnDelayMs,
+ packageOptimizationInfo.getCompilationReason(),
+ packageOptimizationInfo.getCompilationFilter(),
+ info.sourceType,
+ info.sourceEventDelayMs,
+ isIncremental,
+ isLoading,
+ info.launchedActivityName.hashCode(),
+ TimeUnit.NANOSECONDS.toMillis(info.timestampNs));
+ }
+ private void logAppFullyDrawn(TransitionInfoSnapshot info) {
StringBuilder sb = mStringBuilder;
sb.setLength(0);
sb.append("Fully drawn ");
diff --git a/services/core/java/com/android/server/wm/ActivityRecord.java b/services/core/java/com/android/server/wm/ActivityRecord.java
index 2a3946f..07b87dc 100644
--- a/services/core/java/com/android/server/wm/ActivityRecord.java
+++ b/services/core/java/com/android/server/wm/ActivityRecord.java
@@ -6485,15 +6485,6 @@
}
}
- void reportFullyDrawnLocked(boolean restoredFromBundle) {
- final TransitionInfoSnapshot info = mTaskSupervisor
- .getActivityMetricsLogger().logAppTransitionReportedDrawn(this, restoredFromBundle);
- if (info != null) {
- mTaskSupervisor.reportActivityLaunched(false /* timeout */, this,
- info.windowsFullyDrawnDelayMs, info.getLaunchState());
- }
- }
-
void onFirstWindowDrawn(WindowState win) {
firstWindowDrawn = true;
// stop tracking
diff --git a/services/tests/wmtests/src/com/android/server/wm/ActivityMetricsLaunchObserverTests.java b/services/tests/wmtests/src/com/android/server/wm/ActivityMetricsLaunchObserverTests.java
index 376399a..85c4975 100644
--- a/services/tests/wmtests/src/com/android/server/wm/ActivityMetricsLaunchObserverTests.java
+++ b/services/tests/wmtests/src/com/android/server/wm/ActivityMetricsLaunchObserverTests.java
@@ -324,7 +324,7 @@
// The activity reports fully drawn before windows drawn, then the fully drawn event will
// be pending (see {@link WindowingModeTransitionInfo#pendingFullyDrawn}).
- mActivityMetricsLogger.logAppTransitionReportedDrawn(mTopActivity, false);
+ mActivityMetricsLogger.notifyFullyDrawn(mTopActivity, false /* restoredFromBundle */);
notifyTransitionStarting(mTopActivity);
// The pending fully drawn event should send when the actual windows drawn event occurs.
final ActivityMetricsLogger.TransitionInfoSnapshot info = notifyWindowsDrawn(mTopActivity);
@@ -337,7 +337,7 @@
verifyNoMoreInteractions(mLaunchObserver);
final ActivityMetricsLogger.TransitionInfoSnapshot fullyDrawnInfo = mActivityMetricsLogger
- .logAppTransitionReportedDrawn(mTopActivity, false /* restoredFromBundle */);
+ .notifyFullyDrawn(mTopActivity, false /* restoredFromBundle */);
assertWithMessage("Invisible event must be dropped").that(fullyDrawnInfo).isNull();
}
