diff options
author | TreeHugger Robot <treehugger-gerrit@google.com> | 2018-10-02 15:30:52 +0000 |
---|---|---|
committer | Android (Google) Code Review <android-gerrit@google.com> | 2018-10-02 15:30:52 +0000 |
commit | 3d82416e02df36fc83330fbf64d091163d778c1c (patch) | |
tree | 1656493300972ac29d74fe6c1aa5234c5af2af80 | |
parent | 75d2c1f13a2a452ccd8096bef591f590e84a126a (diff) | |
parent | 017cddcbcb555b8e0a7a046da08156ca5453e77e (diff) |
Merge changes from topic "am_launch_times"
* changes:
AM: Update WaitResult parsing logic in AppLaunch
AM: Use ActivityMetricsLogger to get app launch times
11 files changed, 204 insertions, 296 deletions
diff --git a/core/java/android/app/WaitResult.java b/core/java/android/app/WaitResult.java index 898d0cabee3e..5baf2e22bc31 100644 --- a/core/java/android/app/WaitResult.java +++ b/core/java/android/app/WaitResult.java @@ -28,10 +28,10 @@ import java.io.PrintWriter; * @hide */ public class WaitResult implements Parcelable { + public static final int INVALID_DELAY = -1; public int result; public boolean timeout; public ComponentName who; - public long thisTime; public long totalTime; public WaitResult() { @@ -47,7 +47,6 @@ public class WaitResult implements Parcelable { dest.writeInt(result); dest.writeInt(timeout ? 1 : 0); ComponentName.writeToParcel(who, dest); - dest.writeLong(thisTime); dest.writeLong(totalTime); } @@ -68,7 +67,6 @@ public class WaitResult implements Parcelable { result = source.readInt(); timeout = source.readInt() != 0; who = ComponentName.readFromParcel(source); - thisTime = source.readLong(); totalTime = source.readLong(); } @@ -77,7 +75,6 @@ public class WaitResult implements Parcelable { pw.println(prefix + " result=" + result); pw.println(prefix + " timeout=" + timeout); pw.println(prefix + " who=" + who); - pw.println(prefix + " thisTime=" + thisTime); pw.println(prefix + " totalTime=" + totalTime); } }
\ No newline at end of file diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java index f49c50a68674..aa14da0ad70a 100644 --- a/services/core/java/com/android/server/am/ActivityManagerService.java +++ b/services/core/java/com/android/server/am/ActivityManagerService.java @@ -4202,7 +4202,6 @@ public class ActivityManagerService extends IActivityManager.Stub private final void handleAppDiedLocked(ProcessRecord app, boolean restarting, boolean allowRestart) { int pid = app.pid; - final boolean clearLaunchStartTime = !restarting && app.removed && app.foregroundActivities; boolean kept = cleanUpApplicationRecordLocked(app, restarting, allowRestart, -1, false /*replacingPid*/); if (!kept && !restarting) { @@ -4243,18 +4242,6 @@ public class ActivityManagerService extends IActivityManager.Stub mWindowManager.continueSurfaceLayout(); } - // TODO (b/67683350) - // When an app process is removed, activities from the process may be relaunched. In the - // case of forceStopPackageLocked the activities are finished before any window is drawn, - // and the launch time is not cleared. This will be incorrectly used to calculate launch - // time for the next launched activity launched in the same windowing mode. - if (clearLaunchStartTime) { - final LaunchTimeTracker.Entry entry = mStackSupervisor - .getLaunchTimeTracker().getEntry(mStackSupervisor.getWindowingMode()); - if (entry != null) { - entry.mLaunchStartTime = 0; - } - } } private final int getLRURecordIndexForAppLocked(IApplicationThread thread) { diff --git a/services/core/java/com/android/server/am/ActivityManagerShellCommand.java b/services/core/java/com/android/server/am/ActivityManagerShellCommand.java index 4bcaf7145e60..40c555f8c2e6 100644 --- a/services/core/java/com/android/server/am/ActivityManagerShellCommand.java +++ b/services/core/java/com/android/server/am/ActivityManagerShellCommand.java @@ -568,9 +568,6 @@ final class ActivityManagerShellCommand extends ShellCommand { if (result.who != null) { pw.println("Activity: " + result.who.flattenToShortString()); } - if (result.thisTime >= 0) { - pw.println("ThisTime: " + result.thisTime); - } if (result.totalTime >= 0) { pw.println("TotalTime: " + result.totalTime); } diff --git a/services/core/java/com/android/server/am/ActivityMetricsLogger.java b/services/core/java/com/android/server/am/ActivityMetricsLogger.java index 78b42f2068ee..18cdb054e648 100644 --- a/services/core/java/com/android/server/am/ActivityMetricsLogger.java +++ b/services/core/java/com/android/server/am/ActivityMetricsLogger.java @@ -75,6 +75,7 @@ import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_T import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_METRICS; import static com.android.server.am.ActivityManagerDebugConfig.TAG_AM; import static com.android.server.am.ActivityManagerDebugConfig.TAG_WITH_CLASS_NAME; +import static com.android.server.am.EventLogTags.AM_ACTIVITY_LAUNCH_TIME; import static com.android.server.am.MemoryStatUtil.MemoryStat; import static com.android.server.am.MemoryStatUtil.readMemoryStatFromFilesystem; import static com.android.server.wm.ActivityTaskManagerInternal.APP_TRANSITION_TIMEOUT; @@ -89,10 +90,14 @@ import android.os.Handler; import android.os.Looper; import android.os.Message; import android.os.SystemClock; +import android.os.Trace; +import android.util.EventLog; +import android.util.Log; import android.util.Slog; import android.util.SparseArray; import android.util.SparseIntArray; import android.util.StatsLog; +import android.util.TimeUtils; import com.android.internal.logging.MetricsLogger; import com.android.internal.os.BackgroundThread; @@ -100,7 +105,12 @@ import com.android.internal.os.SomeArgs; import com.android.server.LocalServices; /** - * Handles logging into Tron. + * Listens to activity launches, transitions, visibility changes and window drawn callbacks to + * determine app launch times and draw delays. Source of truth for activity metrics and provides + * data for Tron, logcat, event logs and {@link android.app.WaitResult}. + * + * Tests: + * atest SystemMetricsFunctionalTests */ class ActivityMetricsLogger { @@ -115,6 +125,8 @@ class ActivityMetricsLogger { private static final int WINDOW_STATE_INVALID = -1; private static final long INVALID_START_TIME = -1; + private static final int INVALID_DELAY = -1; + private static final int INVALID_TRANSITION_TYPE = -1; private static final int MSG_CHECK_VISIBILITY = 0; @@ -143,6 +155,8 @@ class ActivityMetricsLogger { private final H mHandler; private ArtManagerInternal mArtManagerInternal; + private boolean mDrawingTraceActive; + private final StringBuilder mStringBuilder = new StringBuilder(); private final class H extends Handler { @@ -165,36 +179,56 @@ class ActivityMetricsLogger { private ActivityRecord launchedActivity; private int startResult; private boolean currentTransitionProcessRunning; + /** Elapsed time from when we launch an activity to when its windows are drawn. */ private int windowsDrawnDelayMs; - private int startingWindowDelayMs = -1; - private int bindApplicationDelayMs = -1; + private int startingWindowDelayMs = INVALID_DELAY; + private int bindApplicationDelayMs = INVALID_DELAY; private int reason = APP_TRANSITION_TIMEOUT; private boolean loggedWindowsDrawn; private boolean loggedStartingWindowDrawn; + private boolean launchTraceActive; } - private final class WindowingModeTransitionInfoSnapshot { + final class WindowingModeTransitionInfoSnapshot { final private ApplicationInfo applicationInfo; final private WindowProcessController processRecord; - final private String packageName; - final private String launchedActivityName; + final String packageName; + final String launchedActivityName; final private String launchedActivityLaunchedFromPackage; final private String launchedActivityLaunchToken; final private String launchedActivityAppRecordRequiredAbi; + final String launchedActivityShortComponentName; final private String processName; final private int reason; final private int startingWindowDelayMs; final private int bindApplicationDelayMs; - final private int windowsDrawnDelayMs; - final private int type; + final int windowsDrawnDelayMs; + final int type; + final int userId; + /** + * Elapsed time from when we launch an activity to when the app reported it was + * fully drawn. If this is not reported then the value is set to INVALID_DELAY. + */ + final int windowsFullyDrawnDelayMs; + final int activityRecordIdHashCode; private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info) { - applicationInfo = info.launchedActivity.appInfo; - packageName = info.launchedActivity.packageName; - launchedActivityName = info.launchedActivity.info.name; - launchedActivityLaunchedFromPackage = info.launchedActivity.launchedFromPackage; - launchedActivityLaunchToken = info.launchedActivity.info.launchToken; - launchedActivityAppRecordRequiredAbi = info.launchedActivity.app == null + this(info, info.launchedActivity); + } + + private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info, + ActivityRecord launchedActivity) { + this(info, launchedActivity, INVALID_DELAY); + } + + private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info, + ActivityRecord launchedActivity, int windowsFullyDrawnDelayMs) { + applicationInfo = launchedActivity.appInfo; + packageName = launchedActivity.packageName; + launchedActivityName = launchedActivity.info.name; + launchedActivityLaunchedFromPackage = launchedActivity.launchedFromPackage; + launchedActivityLaunchToken = launchedActivity.info.launchToken; + launchedActivityAppRecordRequiredAbi = launchedActivity.app == null ? null : info.launchedActivity.app.getRequiredAbi(); reason = info.reason; @@ -204,6 +238,10 @@ class ActivityMetricsLogger { type = getTransitionType(info); processRecord = findProcessForActivity(info.launchedActivity); processName = info.launchedActivity.processName; + userId = launchedActivity.userId; + launchedActivityShortComponentName = launchedActivity.shortComponentName; + activityRecordIdHashCode = System.identityHashCode(launchedActivity); + this.windowsFullyDrawnDelayMs = windowsFullyDrawnDelayMs; } } @@ -335,7 +373,7 @@ class ActivityMetricsLogger { || windowingMode == WINDOWING_MODE_UNDEFINED) && !otherWindowModesLaunching) { // Failed to launch or it was not a process switch, so we don't care about the timing. - reset(true /* abort */); + reset(true /* abort */, info); return; } else if (otherWindowModesLaunching) { // Don't log this windowing mode but continue with the other windowing modes. @@ -351,6 +389,7 @@ class ActivityMetricsLogger { mWindowingModeTransitionInfo.put(windowingMode, newInfo); mLastWindowingModeTransitionInfo.put(windowingMode, newInfo); mCurrentTransitionDeviceUptime = (int) (SystemClock.uptimeMillis() / 1000); + startTraces(newInfo); } /** @@ -364,18 +403,21 @@ class ActivityMetricsLogger { /** * Notifies the tracker that all windows of the app have been drawn. */ - void notifyWindowsDrawn(int windowingMode, long timestamp) { + WindowingModeTransitionInfoSnapshot notifyWindowsDrawn(int windowingMode, long timestamp) { if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn windowingMode=" + windowingMode); final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(windowingMode); if (info == null || info.loggedWindowsDrawn) { - return; + return null; } info.windowsDrawnDelayMs = calculateDelay(timestamp); info.loggedWindowsDrawn = true; + final WindowingModeTransitionInfoSnapshot infoSnapshot = + new WindowingModeTransitionInfoSnapshot(info); if (allWindowsDrawn() && mLoggedTransitionStarting) { - reset(false /* abort */); + reset(false /* abort */, info); } + return infoSnapshot; } /** @@ -394,7 +436,7 @@ class ActivityMetricsLogger { * Notifies the tracker that the app transition is starting. * * @param windowingModeToReason A map from windowing mode to a reason integer, which must be on - * of ActivityManagerInternal.APP_TRANSITION_* reasons. + * of ActivityTaskManagerInternal.APP_TRANSITION_* reasons. */ void notifyTransitionStarting(SparseIntArray windowingModeToReason, long timestamp) { if (!isAnyTransitionActive() || mLoggedTransitionStarting) { @@ -413,7 +455,7 @@ class ActivityMetricsLogger { info.reason = windowingModeToReason.valueAt(index); } if (allWindowsDrawn()) { - reset(false /* abort */); + reset(false /* abort */, null /* WindowingModeTransitionInfo */); } } @@ -452,8 +494,9 @@ class ActivityMetricsLogger { logAppTransitionCancel(info); mWindowingModeTransitionInfo.remove(r.getWindowingMode()); if (mWindowingModeTransitionInfo.size() == 0) { - reset(true /* abort */); + reset(true /* abort */, info); } + stopFullyDrawnTraceIfNeeded(); } } } @@ -488,19 +531,19 @@ class ActivityMetricsLogger { && mWindowingModeTransitionInfo.size() > 0; } - private void reset(boolean abort) { + private void reset(boolean abort, WindowingModeTransitionInfo info) { if (DEBUG_METRICS) Slog.i(TAG, "reset abort=" + abort); if (!abort && isAnyTransitionActive()) { logAppTransitionMultiEvents(); } + stopLaunchTrace(info); mCurrentTransitionStartTime = INVALID_START_TIME; - mCurrentTransitionDelayMs = -1; + mCurrentTransitionDelayMs = INVALID_DELAY; mLoggedTransitionStarting = false; mWindowingModeTransitionInfo.clear(); } private int calculateCurrentDelay() { - // Shouldn't take more than 25 days to launch an app, so int is fine here. return (int) (SystemClock.uptimeMillis() - mCurrentTransitionStartTime); } @@ -512,7 +555,7 @@ class ActivityMetricsLogger { private void logAppTransitionCancel(WindowingModeTransitionInfo info) { final int type = getTransitionType(info); - if (type == -1) { + if (type == INVALID_TRANSITION_TYPE) { return; } final LogMaker builder = new LogMaker(APP_TRANSITION_CANCELLED); @@ -533,7 +576,7 @@ class ActivityMetricsLogger { for (int index = mWindowingModeTransitionInfo.size() - 1; index >= 0; index--) { final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.valueAt(index); final int type = getTransitionType(info); - if (type == -1) { + if (type == INVALID_TRANSITION_TYPE) { return; } @@ -545,6 +588,7 @@ class ActivityMetricsLogger { final int currentTransitionDelayMs = mCurrentTransitionDelayMs; BackgroundThread.getHandler().post(() -> logAppTransition( currentTransitionDeviceUptime, currentTransitionDelayMs, infoSnapshot)); + BackgroundThread.getHandler().post(() -> logAppDisplayed(infoSnapshot)); info.launchedActivity.info.launchToken = null; } @@ -571,11 +615,11 @@ class ActivityMetricsLogger { currentTransitionDeviceUptime); builder.addTaggedData(APP_TRANSITION_DELAY_MS, currentTransitionDelayMs); builder.setSubtype(info.reason); - if (info.startingWindowDelayMs != -1) { + if (info.startingWindowDelayMs != INVALID_DELAY) { builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS, info.startingWindowDelayMs); } - if (info.bindApplicationDelayMs != -1) { + if (info.bindApplicationDelayMs != INVALID_DELAY) { builder.addTaggedData(APP_TRANSITION_BIND_APPLICATION_DELAY_MS, info.bindApplicationDelayMs); } @@ -612,6 +656,24 @@ class ActivityMetricsLogger { logAppStartMemoryStateCapture(info); } + private void logAppDisplayed(WindowingModeTransitionInfoSnapshot info) { + if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) { + return; + } + + EventLog.writeEvent(AM_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()); + } + private int convertAppStartTransitionType(int tronType) { if (tronType == TYPE_TRANSITION_COLD_LAUNCH) { return StatsLog.APP_START_OCCURRED__TYPE__COLD; @@ -625,11 +687,12 @@ class ActivityMetricsLogger { return StatsLog.APP_START_OCCURRED__TYPE__UNKNOWN; } - void logAppTransitionReportedDrawn(ActivityRecord r, boolean restoredFromBundle) { + WindowingModeTransitionInfoSnapshot logAppTransitionReportedDrawn(ActivityRecord r, + boolean restoredFromBundle) { final WindowingModeTransitionInfo info = mLastWindowingModeTransitionInfo.get( r.getWindowingMode()); if (info == null) { - return; + return null; } final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN); builder.setPackageName(r.packageName); @@ -652,6 +715,25 @@ class ActivityMetricsLogger { info.launchedActivity.info.name, info.currentTransitionProcessRunning, startupTimeMs); + stopFullyDrawnTraceIfNeeded(); + final WindowingModeTransitionInfoSnapshot infoSnapshot = + new WindowingModeTransitionInfoSnapshot(info, r, (int) startupTimeMs); + BackgroundThread.getHandler().post(() -> logAppFullyDrawn(infoSnapshot)); + return infoSnapshot; + } + + private void logAppFullyDrawn(WindowingModeTransitionInfoSnapshot info) { + if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) { + return; + } + + StringBuilder sb = mStringBuilder; + sb.setLength(0); + sb.append("Fully drawn "); + sb.append(info.launchedActivityShortComponentName); + sb.append(": "); + TimeUtils.formatDuration(info.windowsFullyDrawnDelayMs, sb); + Log.i(TAG, sb.toString()); } void logActivityStart(Intent intent, ProcessRecord callerApp, ActivityRecord r, @@ -753,7 +835,7 @@ class ActivityMetricsLogger { } else if (info.startResult == START_SUCCESS) { return TYPE_TRANSITION_COLD_LAUNCH; } - return -1; + return INVALID_TRANSITION_TYPE; } private void logAppStartMemoryStateCapture(WindowingModeTransitionInfoSnapshot info) { @@ -798,4 +880,46 @@ class ActivityMetricsLogger { } return mArtManagerInternal; } + + /** + * Starts traces for app launch and draw times. We stop the fully drawn trace if its already + * active since the app may not have reported fully drawn in the previous launch. + * + * See {@link android.app.Activity#reportFullyDrawn()} + * + * @param info + * */ + private void startTraces(WindowingModeTransitionInfo info) { + if (info == null) { + return; + } + stopFullyDrawnTraceIfNeeded(); + int transitionType = getTransitionType(info); + if (!info.launchTraceActive && transitionType == TYPE_TRANSITION_WARM_LAUNCH + || transitionType == TYPE_TRANSITION_COLD_LAUNCH) { + Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "launching: " + + info.launchedActivity.packageName, 0); + Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "drawing", 0); + mDrawingTraceActive = true; + info.launchTraceActive = true; + } + } + + private void stopLaunchTrace(WindowingModeTransitionInfo info) { + if (info == null) { + return; + } + if (info.launchTraceActive) { + Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, "launching: " + + info.launchedActivity.packageName, 0); + info.launchTraceActive = false; + } + } + + void stopFullyDrawnTraceIfNeeded() { + if (mDrawingTraceActive) { + Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, "drawing", 0); + mDrawingTraceActive = false; + } + } } diff --git a/services/core/java/com/android/server/am/ActivityRecord.java b/services/core/java/com/android/server/am/ActivityRecord.java index 77cfb124ec80..5853ad976bbb 100644 --- a/services/core/java/com/android/server/am/ActivityRecord.java +++ b/services/core/java/com/android/server/am/ActivityRecord.java @@ -31,6 +31,7 @@ import static android.app.ActivityOptions.ANIM_THUMBNAIL_SCALE_UP; import static android.app.ActivityTaskManager.INVALID_STACK_ID; import static android.app.AppOpsManager.MODE_ALLOWED; import static android.app.AppOpsManager.OP_PICTURE_IN_PICTURE; +import static android.app.WaitResult.INVALID_DELAY; import static android.app.WindowConfiguration.ACTIVITY_TYPE_ASSISTANT; import static android.app.WindowConfiguration.ACTIVITY_TYPE_HOME; import static android.app.WindowConfiguration.ACTIVITY_TYPE_RECENTS; @@ -80,7 +81,6 @@ import static android.content.res.Configuration.UI_MODE_TYPE_VR_HEADSET; import static android.os.Build.VERSION_CODES.HONEYCOMB; import static android.os.Build.VERSION_CODES.O; import static android.os.Process.SYSTEM_UID; -import static android.os.Trace.TRACE_TAG_ACTIVITY_MANAGER; import static android.view.WindowManagerPolicyConstants.NAV_BAR_LEFT; import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_CONFIGURATION; @@ -112,8 +112,6 @@ import static com.android.server.am.ActivityStack.LAUNCH_TICK; import static com.android.server.am.ActivityStack.LAUNCH_TICK_MSG; import static com.android.server.am.ActivityStack.PAUSE_TIMEOUT_MSG; import static com.android.server.am.ActivityStack.STOP_TIMEOUT_MSG; -import static com.android.server.am.EventLogTags.AM_ACTIVITY_FULLY_DRAWN_TIME; -import static com.android.server.am.EventLogTags.AM_ACTIVITY_LAUNCH_TIME; import static com.android.server.am.EventLogTags.AM_RELAUNCH_ACTIVITY; import static com.android.server.am.EventLogTags.AM_RELAUNCH_RESUME_ACTIVITY; import static com.android.server.am.TaskPersister.DEBUG; @@ -164,7 +162,6 @@ import android.os.PersistableBundle; import android.os.Process; import android.os.RemoteException; import android.os.SystemClock; -import android.os.Trace; import android.os.UserHandle; import android.os.storage.StorageManager; import android.service.voice.IVoiceInteractionSession; @@ -186,6 +183,7 @@ import com.android.internal.content.ReferrerIntent; import com.android.internal.util.XmlUtils; import com.android.server.AttributeCache; import com.android.server.AttributeCache.Entry; +import com.android.server.am.ActivityMetricsLogger.WindowingModeTransitionInfoSnapshot; import com.android.server.am.ActivityStack.ActivityState; import com.android.server.uri.UriPermissionOwner; import com.android.server.wm.AppWindowContainerController; @@ -266,9 +264,6 @@ final class ActivityRecord extends ConfigurationContainer implements AppWindowCo private int windowFlags; // custom window flags for preview window. private TaskRecord task; // the task this is in. private long createTime = System.currentTimeMillis(); - long displayStartTime; // when we started launching this activity - long fullyDrawnStartTime; // when we started launching this activity - private long startTime; // last time this activity was started long lastVisibleTime; // last time this activity became visible long cpuTimeAtResume; // the cpu time of host process at the time of resuming activity long pauseTime; // last time we started pausing the activity @@ -536,15 +531,6 @@ final class ActivityRecord extends ConfigurationContainer implements AppWindowCo pw.print("requestedVrComponent="); pw.println(requestedVrComponent); } - if (displayStartTime != 0 || startTime != 0) { - pw.print(prefix); pw.print("displayStartTime="); - if (displayStartTime == 0) pw.print("0"); - else TimeUtils.formatDuration(displayStartTime, now, pw); - pw.print(" startTime="); - if (startTime == 0) pw.print("0"); - else TimeUtils.formatDuration(startTime, now, pw); - pw.println(); - } final boolean waitingVisible = mStackSupervisor.mActivitiesWaitingForVisibleActivity.contains(this); if (lastVisibleTime != 0 || waitingVisible || nowVisible) { @@ -2006,79 +1992,13 @@ final class ActivityRecord extends ConfigurationContainer implements AppWindowCo } public void reportFullyDrawnLocked(boolean restoredFromBundle) { - final long curTime = SystemClock.uptimeMillis(); - if (displayStartTime != 0) { - reportLaunchTimeLocked(curTime); - } - final LaunchTimeTracker.Entry entry = mStackSupervisor.getLaunchTimeTracker().getEntry( - getWindowingMode()); - if (fullyDrawnStartTime != 0 && entry != null) { - final long thisTime = curTime - fullyDrawnStartTime; - final long totalTime = entry.mFullyDrawnStartTime != 0 - ? (curTime - entry.mFullyDrawnStartTime) : thisTime; - if (SHOW_ACTIVITY_START_TIME) { - Trace.asyncTraceEnd(TRACE_TAG_ACTIVITY_MANAGER, "drawing", 0); - EventLog.writeEvent(AM_ACTIVITY_FULLY_DRAWN_TIME, - userId, System.identityHashCode(this), shortComponentName, - thisTime, totalTime); - StringBuilder sb = service.mStringBuilder; - sb.setLength(0); - sb.append("Fully drawn "); - sb.append(shortComponentName); - sb.append(": "); - TimeUtils.formatDuration(thisTime, sb); - if (thisTime != totalTime) { - sb.append(" (total "); - TimeUtils.formatDuration(totalTime, sb); - sb.append(")"); - } - Log.i(TAG, sb.toString()); - } - if (totalTime > 0) { - //service.mUsageStatsService.noteFullyDrawnTime(realActivity, (int) totalTime); - } - entry.mFullyDrawnStartTime = 0; - } - mStackSupervisor.getActivityMetricsLogger().logAppTransitionReportedDrawn(this, - restoredFromBundle); - fullyDrawnStartTime = 0; - } - - private void reportLaunchTimeLocked(final long curTime) { - final LaunchTimeTracker.Entry entry = mStackSupervisor.getLaunchTimeTracker().getEntry( - getWindowingMode()); - if (entry == null) { - return; - } - final long thisTime = curTime - displayStartTime; - final long totalTime = entry.mLaunchStartTime != 0 - ? (curTime - entry.mLaunchStartTime) : thisTime; - if (SHOW_ACTIVITY_START_TIME) { - Trace.asyncTraceEnd(TRACE_TAG_ACTIVITY_MANAGER, "launching: " + packageName, 0); - EventLog.writeEvent(AM_ACTIVITY_LAUNCH_TIME, - userId, System.identityHashCode(this), shortComponentName, - thisTime, totalTime); - StringBuilder sb = service.mStringBuilder; - sb.setLength(0); - sb.append("Displayed "); - sb.append(shortComponentName); - sb.append(": "); - TimeUtils.formatDuration(thisTime, sb); - if (thisTime != totalTime) { - sb.append(" (total "); - TimeUtils.formatDuration(totalTime, sb); - sb.append(")"); - } - Log.i(TAG, sb.toString()); - } - mStackSupervisor.reportActivityLaunchedLocked(false, this, thisTime, totalTime); - if (totalTime > 0) { - //service.mUsageStatsService.noteLaunchTime(realActivity, (int)totalTime); + final WindowingModeTransitionInfoSnapshot info = mStackSupervisor + .getActivityMetricsLogger().logAppTransitionReportedDrawn(this, restoredFromBundle); + if (info != null) { + mStackSupervisor.reportActivityLaunchedLocked(false /* timeout */, this, + info.windowsFullyDrawnDelayMs); } - displayStartTime = 0; - entry.mLaunchStartTime = 0; } - @Override public void onStartingWindowDrawn(long timestamp) { synchronized (service.mGlobalLock) { @@ -2090,13 +2010,12 @@ final class ActivityRecord extends ConfigurationContainer implements AppWindowCo @Override public void onWindowsDrawn(long timestamp) { synchronized (service.mGlobalLock) { - mStackSupervisor.getActivityMetricsLogger().notifyWindowsDrawn(getWindowingMode(), - timestamp); - if (displayStartTime != 0) { - reportLaunchTimeLocked(timestamp); - } + final WindowingModeTransitionInfoSnapshot info = mStackSupervisor + .getActivityMetricsLogger().notifyWindowsDrawn(getWindowingMode(), timestamp); + final int windowsDrawnDelayMs = info != null ? info.windowsDrawnDelayMs : INVALID_DELAY; + mStackSupervisor.reportActivityLaunchedLocked(false /* timeout */, this, + windowsDrawnDelayMs); mStackSupervisor.sendWaitingVisibleReportLocked(this); - startTime = 0; finishLaunchTickingLocked(); if (task != null) { task.hasBeenVisible = true; diff --git a/services/core/java/com/android/server/am/ActivityStack.java b/services/core/java/com/android/server/am/ActivityStack.java index 9f59bd8db62a..29b04ccdab08 100644 --- a/services/core/java/com/android/server/am/ActivityStack.java +++ b/services/core/java/com/android/server/am/ActivityStack.java @@ -151,7 +151,6 @@ import android.view.Display; import com.android.internal.annotations.GuardedBy; import com.android.internal.annotations.VisibleForTesting; import com.android.internal.app.IVoiceInteractor; -import com.android.internal.os.BatteryStatsImpl; import com.android.internal.util.function.pooled.PooledLambda; import com.android.server.Watchdog; import com.android.server.am.ActivityManagerService.ItemMatcher; @@ -1319,16 +1318,13 @@ class ActivityStack<T extends StackWindowController> extends ConfigurationContai + " callers=" + Debug.getCallers(5)); r.setState(RESUMED, "minimalResumeActivityLocked"); r.completeResumeLocked(); - mStackSupervisor.getLaunchTimeTracker().setLaunchTime(r); if (DEBUG_SAVED_STATE) Slog.i(TAG_SAVED_STATE, "Launch completed; removing icicle of " + r.icicle); } private void clearLaunchTime(ActivityRecord r) { // Make sure that there is no activity waiting for this to launch. - if (mStackSupervisor.mWaitingActivityLaunched.isEmpty()) { - r.displayStartTime = r.fullyDrawnStartTime = 0; - } else { + if (!mStackSupervisor.mWaitingActivityLaunched.isEmpty()) { mStackSupervisor.removeTimeoutsForActivityLocked(r); mStackSupervisor.scheduleIdleTimeoutLocked(r); } @@ -1514,7 +1510,7 @@ class ActivityStack<T extends StackWindowController> extends ConfigurationContai prev.getTask().touchActiveTime(); clearLaunchTime(prev); - mStackSupervisor.getLaunchTimeTracker().stopFullyDrawnTraceIfNeeded(getWindowingMode()); + mStackSupervisor.getActivityMetricsLogger().stopFullyDrawnTraceIfNeeded(); mService.updateCpuStats(); diff --git a/services/core/java/com/android/server/am/ActivityStackSupervisor.java b/services/core/java/com/android/server/am/ActivityStackSupervisor.java index 877c8567b9d0..9688d263643c 100644 --- a/services/core/java/com/android/server/am/ActivityStackSupervisor.java +++ b/services/core/java/com/android/server/am/ActivityStackSupervisor.java @@ -25,6 +25,7 @@ import static android.app.ActivityManager.START_TASK_TO_FRONT; import static android.app.ActivityTaskManager.INVALID_STACK_ID; import static android.app.ITaskStackListener.FORCED_RESIZEABLE_REASON_SECONDARY_DISPLAY; import static android.app.ITaskStackListener.FORCED_RESIZEABLE_REASON_SPLIT_SCREEN; +import static android.app.WaitResult.INVALID_DELAY; import static android.app.WindowConfiguration.ACTIVITY_TYPE_ASSISTANT; import static android.app.WindowConfiguration.ACTIVITY_TYPE_HOME; import static android.app.WindowConfiguration.ACTIVITY_TYPE_RECENTS; @@ -450,7 +451,6 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D private boolean mTaskLayersChanged = true; private ActivityMetricsLogger mActivityMetricsLogger; - private LaunchTimeTracker mLaunchTimeTracker = new LaunchTimeTracker(); private final ArrayList<ActivityRecord> mTmpActivityList = new ArrayList<>(); @@ -646,10 +646,6 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D return mActivityMetricsLogger; } - LaunchTimeTracker getLaunchTimeTracker() { - return mLaunchTimeTracker; - } - public KeyguardController getKeyguardController() { return mKeyguardController; } @@ -1179,8 +1175,8 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D } } - void waitActivityVisible(ComponentName name, WaitResult result) { - final WaitInfo waitInfo = new WaitInfo(name, result); + void waitActivityVisible(ComponentName name, WaitResult result, long startTimeMs) { + final WaitInfo waitInfo = new WaitInfo(name, result, startTimeMs); mWaitingForActivityVisible.add(waitInfo); } @@ -1211,8 +1207,7 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D changed = true; result.timeout = false; result.who = w.getComponent(); - result.totalTime = SystemClock.uptimeMillis() - result.thisTime; - result.thisTime = result.totalTime; + result.totalTime = SystemClock.uptimeMillis() - w.getStartTime(); mWaitingForActivityVisible.remove(w); } } @@ -1251,8 +1246,7 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D } } - void reportActivityLaunchedLocked(boolean timeout, ActivityRecord r, - long thisTime, long totalTime) { + void reportActivityLaunchedLocked(boolean timeout, ActivityRecord r, long totalTime) { boolean changed = false; for (int i = mWaitingActivityLaunched.size() - 1; i >= 0; i--) { WaitResult w = mWaitingActivityLaunched.remove(i); @@ -1262,7 +1256,6 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D if (r != null) { w.who = new ComponentName(r.info.packageName, r.info.name); } - w.thisTime = thisTime; w.totalTime = totalTime; // Do not modify w.result. } @@ -1728,8 +1721,6 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D ProcessRecord app = mService.mAm.getProcessRecordLocked(r.processName, r.info.applicationInfo.uid, true); - getLaunchTimeTracker().setLaunchTime(r); - if (app != null && app.thread != null) { try { if ((r.info.flags&ActivityInfo.FLAG_MULTIPROCESS) == 0 @@ -2082,7 +2073,7 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D mHandler.removeMessages(IDLE_TIMEOUT_MSG, r); r.finishLaunchTickingLocked(); if (fromTimeout) { - reportActivityLaunchedLocked(fromTimeout, r, -1, -1); + reportActivityLaunchedLocked(fromTimeout, r, INVALID_DELAY); } // This is a hack to semi-deal with a race condition @@ -4940,10 +4931,13 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D static class WaitInfo { private final ComponentName mTargetComponent; private final WaitResult mResult; + /** Time stamp when we started to wait for {@link WaitResult}. */ + private final long mStartTimeMs; - public WaitInfo(ComponentName targetComponent, WaitResult result) { + WaitInfo(ComponentName targetComponent, WaitResult result, long startTimeMs) { this.mTargetComponent = targetComponent; this.mResult = result; + this.mStartTimeMs = startTimeMs; } public boolean matches(ComponentName targetComponent) { @@ -4954,6 +4948,10 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D return mResult; } + public long getStartTime() { + return mStartTimeMs; + } + public ComponentName getComponent() { return mTargetComponent; } diff --git a/services/core/java/com/android/server/am/ActivityStarter.java b/services/core/java/com/android/server/am/ActivityStarter.java index 890aafefdf0f..8236bd0e763e 100644 --- a/services/core/java/com/android/server/am/ActivityStarter.java +++ b/services/core/java/com/android/server/am/ActivityStarter.java @@ -1154,6 +1154,9 @@ class ActivityStarter { mService.updateConfigurationLocked(globalConfig, null, false); } + // Notify ActivityMetricsLogger that the activity has launched. ActivityMetricsLogger + // will then wait for the windows to be drawn and populate WaitResult. + mSupervisor.getActivityMetricsLogger().notifyActivityLaunched(res, outRecord[0]); if (outResult != null) { outResult.result = res; @@ -1178,7 +1181,6 @@ class ActivityStarter { outResult.timeout = false; outResult.who = r.realActivity; outResult.totalTime = 0; - outResult.thisTime = 0; break; } case START_TASK_TO_FRONT: { @@ -1188,10 +1190,9 @@ class ActivityStarter { outResult.timeout = false; outResult.who = r.realActivity; outResult.totalTime = 0; - outResult.thisTime = 0; } else { - outResult.thisTime = SystemClock.uptimeMillis(); - mSupervisor.waitActivityVisible(r.realActivity, outResult); + final long startTimeMs = SystemClock.uptimeMillis(); + mSupervisor.waitActivityVisible(r.realActivity, outResult, startTimeMs); // Note: the timeout variable is not currently not ever set. do { try { @@ -1205,7 +1206,6 @@ class ActivityStarter { } } - mSupervisor.getActivityMetricsLogger().notifyActivityLaunched(res, outRecord[0]); return res; } } diff --git a/services/core/java/com/android/server/am/EventLogTags.logtags b/services/core/java/com/android/server/am/EventLogTags.logtags index ed891dfb0e70..0ef2a0a90e13 100644 --- a/services/core/java/com/android/server/am/EventLogTags.logtags +++ b/services/core/java/com/android/server/am/EventLogTags.logtags @@ -87,9 +87,6 @@ option java_package com.android.server.am # User switched 30041 am_switch_user (id|1|5) -# Activity fully drawn time -30042 am_activity_fully_drawn_time (User|1|5),(Token|1|5),(Component Name|3),(time|2|3) - # Activity set to resumed 30043 am_set_resumed_activity (User|1|5),(Component Name|3),(Reason|3) diff --git a/services/core/java/com/android/server/am/LaunchTimeTracker.java b/services/core/java/com/android/server/am/LaunchTimeTracker.java deleted file mode 100644 index ee869691f7ca..000000000000 --- a/services/core/java/com/android/server/am/LaunchTimeTracker.java +++ /dev/null @@ -1,86 +0,0 @@ -/* - * Copyright (C) 2018 The Android Open Source Project - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License - */ - -package com.android.server.am; - -import android.app.WaitResult; -import android.os.SystemClock; -import android.os.Trace; -import android.util.SparseArray; - -/** - * Tracks launch time of apps to be reported by {@link WaitResult}. Note that this is slightly - * different from {@link ActivityMetricsLogger}, but should eventually merged with it. - */ -class LaunchTimeTracker { - - private final SparseArray<Entry> mWindowingModeLaunchTime = new SparseArray<>(); - - void setLaunchTime(ActivityRecord r) { - Entry entry = mWindowingModeLaunchTime.get(r.getWindowingMode()); - if (entry == null){ - entry = new Entry(); - mWindowingModeLaunchTime.append(r.getWindowingMode(), entry); - } - entry.setLaunchTime(r); - } - - void stopFullyDrawnTraceIfNeeded(int windowingMode) { - final Entry entry = mWindowingModeLaunchTime.get(windowingMode); - if (entry == null) { - return; - } - entry.stopFullyDrawnTraceIfNeeded(); - } - - Entry getEntry(int windowingMode) { - return mWindowingModeLaunchTime.get(windowingMode); - } - - static class Entry { - - long mLaunchStartTime; - long mFullyDrawnStartTime; - - void setLaunchTime(ActivityRecord r) { - if (r.displayStartTime == 0) { - r.fullyDrawnStartTime = r.displayStartTime = SystemClock.uptimeMillis(); - if (mLaunchStartTime == 0) { - startLaunchTraces(r.packageName); - mLaunchStartTime = mFullyDrawnStartTime = r.displayStartTime; - } - } else if (mLaunchStartTime == 0) { - startLaunchTraces(r.packageName); - mLaunchStartTime = mFullyDrawnStartTime = SystemClock.uptimeMillis(); - } - } - - private void startLaunchTraces(String packageName) { - if (mFullyDrawnStartTime != 0) { - Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, "drawing", 0); - } - Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "launching: " + packageName, 0); - Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "drawing", 0); - } - - private void stopFullyDrawnTraceIfNeeded() { - if (mFullyDrawnStartTime != 0 && mLaunchStartTime == 0) { - Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, "drawing", 0); - mFullyDrawnStartTime = 0; - } - } - } -} diff --git a/tests/AppLaunch/src/com/android/tests/applaunch/AppLaunch.java b/tests/AppLaunch/src/com/android/tests/applaunch/AppLaunch.java index 1f60b71c3c0f..976848c60dc7 100644 --- a/tests/AppLaunch/src/com/android/tests/applaunch/AppLaunch.java +++ b/tests/AppLaunch/src/com/android/tests/applaunch/AppLaunch.java @@ -106,9 +106,8 @@ public class AppLaunch extends InstrumentationTestCase { private static final String DROP_CACHE_SCRIPT = "/data/local/tmp/dropCache.sh"; private static final String APP_LAUNCH_CMD = "am start -W -n"; private static final String SUCCESS_MESSAGE = "Status: ok"; - private static final String WARNING_MESSAGE = "Warning:"; + private static final String TOTAL_TIME_MESSAGE = "TotalTime:"; private static final String COMPILE_SUCCESS = "Success"; - private static final String THIS_TIME = "ThisTime:"; private static final String LAUNCH_ITERATION = "LAUNCH_ITERATION - %d"; private static final String TRACE_ITERATION = "TRACE_ITERATION-%d"; private static final String LAUNCH_ITERATION_PREFIX = "LAUNCH_ITERATION"; @@ -814,15 +813,13 @@ public class AppLaunch extends InstrumentationTestCase { String launchTime = "-1"; String cpuCycles = "-1"; String majorFaults = "-1"; - boolean coldLaunchSuccess = false; - boolean hotLaunchSuccess = false; + boolean launchSuccess = false; try { InputStream inputStream = new FileInputStream(parcelDesc.getFileDescriptor()); /* SAMPLE OUTPUT : Cold launch Starting: Intent { cmp=com.google.android.calculator/com.android.calculator2.Calculator } Status: ok Activity: com.google.android.calculator/com.android.calculator2.Calculator - ThisTime: 357 TotalTime: 357 WaitTime: 377 Complete*/ @@ -831,7 +828,6 @@ public class AppLaunch extends InstrumentationTestCase { Warning: Activity not started, its current task has been brought to the front Status: ok Activity: com.google.android.calculator/com.android.calculator2.CalculatorGoogle - ThisTime: 60 TotalTime: 60 WaitTime: 67 Complete*/ @@ -842,54 +838,37 @@ public class AppLaunch extends InstrumentationTestCase { Total test time,1.462129,seconds,*/ BufferedReader bufferedReader = new BufferedReader(new InputStreamReader( inputStream)); - String line = null; - int lineCount = 1; + String line; mBufferedWriter.newLine(); mBufferedWriter.write(headerInfo); mBufferedWriter.newLine(); while ((line = bufferedReader.readLine()) != null) { - if (lineCount == 2 && line.startsWith(SUCCESS_MESSAGE)) { - coldLaunchSuccess = true; + mBufferedWriter.write(line); + mBufferedWriter.newLine(); + if (line.startsWith(SUCCESS_MESSAGE)) { + launchSuccess = true; } - if (lineCount == 2 && line.startsWith(WARNING_MESSAGE)) { - hotLaunchSuccess = true; + if (!launchSuccess) { + continue; } // Parse TotalTime which is the launch time - if (coldLaunchSuccess && lineCount == 5) { - String launchSplit[] = line.split(":"); - launchTime = launchSplit[1].trim(); - } - if (hotLaunchSuccess && lineCount == 6) { + if (line.startsWith(TOTAL_TIME_MESSAGE)) { String launchSplit[] = line.split(":"); launchTime = launchSplit[1].trim(); } if (mSimplePerfAppOnly) { - // Parse simpleperf output. - if ((lineCount == 9 && coldLaunchSuccess) - || (lineCount == 10 && hotLaunchSuccess)) { - if (!line.contains("cpu-cycles")) { - Log.e(TAG, "Error in simpleperf output"); - } else { - cpuCycles = line.split(",")[0].trim(); - } - } else if ((lineCount == 10 && coldLaunchSuccess) - || (lineCount == 11 && hotLaunchSuccess)) { - if (!line.contains("major-faults")) { - Log.e(TAG, "Error in simpleperf output"); - } else { - majorFaults = line.split(",")[0].trim(); - } + if (line.contains(",cpu-cycles,")) { + cpuCycles = line.split(",")[0].trim(); + } else if (line.contains(",major-faults,")) { + majorFaults = line.split(",")[0].trim(); } } - mBufferedWriter.write(line); - mBufferedWriter.newLine(); - lineCount++; } mBufferedWriter.flush(); inputStream.close(); } catch (IOException e) { - Log.w(TAG, "Error writing the launch file", e); + Log.w(TAG, "Error parsing launch time and writing to file", e); } return new AppLaunchResult(launchTime, cpuCycles, majorFaults); } |