Merge "Disable detailed transition logs but add a summary." (decc10b7) · Commits · e / os / android_frameworks_base

core/java/com/android/internal/protolog/ProtoLogGroup.java

+3 −1

Original line number	Diff line number	Diff line
		@@ -79,7 +79,9 @@ public enum ProtoLogGroup implements IProtoLogGroup {
		Consts.TAG_WM),
		WM_DEBUG_SYNC_ENGINE(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
		Consts.TAG_WM),
		WM_DEBUG_WINDOW_TRANSITIONS(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, true,
		WM_DEBUG_WINDOW_TRANSITIONS(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
		Consts.TAG_WM),
		WM_DEBUG_WINDOW_TRANSITIONS_MIN(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, true,
		Consts.TAG_WM),
		WM_DEBUG_WINDOW_INSETS(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
		Consts.TAG_WM),

data/etc/services.core.protolog.json

+21 −0

Original line number	Diff line number	Diff line
		@@ -2599,6 +2599,12 @@
		"group": "WM_DEBUG_REMOTE_ANIMATIONS",
		"at": "com\/android\/server\/wm\/RemoteAnimationController.java"
		},
		"273212558": {
		"message": " info=%s",
		"level": "VERBOSE",
		"group": "WM_DEBUG_WINDOW_TRANSITIONS_MIN",
		"at": "com\/android\/server\/wm\/TransitionController.java"
		},
		"274773837": {
		"message": "applyAnimation: anim=%s nextAppTransition=ANIM_CLIP_REVEAL transit=%s Callers=%s",
		"level": "VERBOSE",
		@@ -3937,6 +3943,12 @@
		"group": "WM_DEBUG_STATES",
		"at": "com\/android\/server\/wm\/ActivityRecord.java"
		},
		"1621562070": {
		"message": " startWCT=%s",
		"level": "VERBOSE",
		"group": "WM_DEBUG_WINDOW_TRANSITIONS_MIN",
		"at": "com\/android\/server\/wm\/TransitionController.java"
		},
		"1628345525": {
		"message": "Now opening app %s",
		"level": "VERBOSE",
		@@ -4345,6 +4357,12 @@
		"group": "WM_DEBUG_ANIM",
		"at": "com\/android\/server\/wm\/DisplayRotation.java"
		},
		"2021079047": {
		"message": "%s",
		"level": "VERBOSE",
		"group": "WM_DEBUG_WINDOW_TRANSITIONS_MIN",
		"at": "com\/android\/server\/wm\/TransitionController.java"
		},
		"2022422429": {
		"message": "createAnimationAdapter(): container=%s",
		"level": "DEBUG",
		@@ -4551,6 +4569,9 @@
		"WM_DEBUG_WINDOW_TRANSITIONS": {
		"tag": "WindowManager"
		},
		"WM_DEBUG_WINDOW_TRANSITIONS_MIN": {
		"tag": "WindowManager"
		},
		"WM_ERROR": {
		"tag": "WindowManager"
		},

services/core/java/com/android/server/wm/Transition.java

+14 −0

Original line number	Diff line number	Diff line
		@@ -70,6 +70,7 @@ import android.os.Binder;
		import android.os.IBinder;
		import android.os.IRemoteCallback;
		import android.os.RemoteException;
		import android.os.SystemClock;
		import android.os.Trace;
		import android.util.ArrayMap;
		import android.util.ArraySet;
		@@ -211,6 +212,8 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener {
		private IContainerFreezer mContainerFreezer = null;
		private final SurfaceControl.Transaction mTmpTransaction = new SurfaceControl.Transaction();

		final TransitionController.Logger mLogger = new TransitionController.Logger();

		Transition(@TransitionType int type, @TransitionFlags int flags,
		TransitionController controller, BLASTSyncEngine syncEngine) {
		mType = type;
		@@ -219,6 +222,8 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener {
		mSyncEngine = syncEngine;
		mToken = new Token(this);

		mLogger.mCreateWallTimeMs = System.currentTimeMillis();
		mLogger.mCreateTimeNs = SystemClock.uptimeNanos();
		controller.mTransitionTracer.logState(this);
		}

		@@ -380,6 +385,8 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener {
		mState = STATE_COLLECTING;
		mSyncId = mSyncEngine.startSyncSet(this, timeoutMs, TAG, method);

		mLogger.mSyncId = mSyncId;
		mLogger.mCollectTimeNs = SystemClock.uptimeNanos();
		mController.mTransitionTracer.logState(this);
		}

		@@ -399,6 +406,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener {
		mSyncId);
		applyReady();

		mLogger.mStartTimeNs = SystemClock.uptimeNanos();
		mController.mTransitionTracer.logState(this);

		mController.updateAnimatingState(mTmpTransaction);
		@@ -608,6 +616,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener {
		ProtoLog.v(ProtoLogGroup.WM_DEBUG_WINDOW_TRANSITIONS,
		"Set transition ready=%b %d", ready, mSyncId);
		mSyncEngine.setReady(mSyncId, ready);
		if (ready) mLogger.mReadyTimeNs = SystemClock.uptimeNanos();
		}

		/**
		@@ -759,6 +768,8 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener {
		Trace.asyncTraceEnd(TRACE_TAG_WINDOW_MANAGER, TRACE_NAME_PLAY_TRANSITION,
		System.identityHashCode(this));
		}
		mLogger.mFinishTimeNs = SystemClock.uptimeNanos();
		mController.mLoggerHandler.post(mLogger::logOnFinish);
		// Close the transactions now. They were originally copied to Shell in case we needed to
		// apply them due to a remote failure. Since we don't need to apply them anymore, free them
		// immediately.
		@@ -1088,6 +1099,8 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener {
		try {
		ProtoLog.v(ProtoLogGroup.WM_DEBUG_WINDOW_TRANSITIONS,
		"Calling onTransitionReady: %s", info);
		mLogger.mSendTimeNs = SystemClock.uptimeNanos();
		mLogger.mInfo = info;
		mController.getTransitionPlayer().onTransitionReady(
		mToken, info, transaction, mFinishTransaction);
		if (Trace.isTagEnabled(TRACE_TAG_WINDOW_MANAGER)) {
		@@ -1103,6 +1116,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener {
		// No player registered, so just finish/apply immediately
		cleanUpOnFailure();
		}
		mController.mLoggerHandler.post(mLogger::logOnSend);
		mOverrideOptions = null;

		reportStartReasonsToLogger();

services/core/java/com/android/server/wm/TransitionController.java

+71 −3

Original line number	Diff line number	Diff line
		@@ -30,6 +30,7 @@ import android.annotation.Nullable;
		import android.app.ActivityManager;
		import android.app.IApplicationThread;
		import android.app.WindowConfiguration;
		import android.os.Handler;
		import android.os.IBinder;
		import android.os.IRemoteCallback;
		import android.os.RemoteException;
		@@ -38,6 +39,7 @@ import android.os.SystemProperties;
		import android.os.Trace;
		import android.util.ArrayMap;
		import android.util.Slog;
		import android.util.TimeUtils;
		import android.util.proto.ProtoOutputStream;
		import android.view.SurfaceControl;
		import android.view.WindowManager;
		@@ -46,11 +48,13 @@ import android.window.ITransitionPlayer;
		import android.window.RemoteTransition;
		import android.window.TransitionInfo;
		import android.window.TransitionRequestInfo;
		import android.window.WindowContainerTransaction;

		import com.android.internal.annotations.GuardedBy;
		import com.android.internal.annotations.VisibleForTesting;
		import com.android.internal.protolog.ProtoLogGroup;
		import com.android.internal.protolog.common.ProtoLog;
		import com.android.server.FgThread;
		import com.android.server.LocalServices;
		import com.android.server.statusbar.StatusBarManagerInternal;

		@@ -120,6 +124,8 @@ class TransitionController {

		private boolean mAnimatingState = false;

		final Handler mLoggerHandler = FgThread.getHandler();

		TransitionController(ActivityTaskManagerService atm,
		TaskSnapshotController taskSnapshotController,
		TransitionTracer transitionTracer) {
		@@ -462,9 +468,11 @@ class TransitionController {
		info = new ActivityManager.RunningTaskInfo();
		startTask.fillTaskInfo(info);
		}
		mTransitionPlayer.requestStartTransition(transition.getToken(),
		new TransitionRequestInfo(transition.mType, info, remoteTransition,
		displayChange));
		final TransitionRequestInfo request = new TransitionRequestInfo(
		transition.mType, info, remoteTransition, displayChange);
		transition.mLogger.mRequestTimeNs = SystemClock.uptimeNanos();
		transition.mLogger.mRequest = request;
		mTransitionPlayer.requestStartTransition(transition.getToken(), request);
		transition.setRemoteTransition(remoteTransition);
		} catch (RemoteException e) {
		Slog.e(TAG, "Error requesting transition", e);
		@@ -847,6 +855,66 @@ class TransitionController {
		}
		}

		/**
		* Data-class to store recorded events/info for a transition. This allows us to defer the
		* actual logging until the system isn't busy. This also records some common metrics to see
		* delays at-a-glance.
		*
		* Beside `mCreateWallTimeMs`, all times are elapsed times and will all be reported relative
		* to when the transition was created.
		*/
		static class Logger {
		long mCreateWallTimeMs;
		long mCreateTimeNs;
		long mRequestTimeNs;
		long mCollectTimeNs;
		long mStartTimeNs;
		long mReadyTimeNs;
		long mSendTimeNs;
		long mFinishTimeNs;
		TransitionRequestInfo mRequest;
		WindowContainerTransaction mStartWCT;
		int mSyncId;
		TransitionInfo mInfo;

		private String buildOnSendLog() {
		StringBuilder sb = new StringBuilder("Sent Transition #").append(mSyncId)
		.append(" createdAt=").append(TimeUtils.logTimeOfDay(mCreateWallTimeMs));
		if (mRequest != null) {
		sb.append(" via request=").append(mRequest);
		}
		return sb.toString();
		}

		void logOnSend() {
		ProtoLog.v(ProtoLogGroup.WM_DEBUG_WINDOW_TRANSITIONS_MIN, "%s", buildOnSendLog());
		ProtoLog.v(ProtoLogGroup.WM_DEBUG_WINDOW_TRANSITIONS_MIN, " startWCT=%s", mStartWCT);
		ProtoLog.v(ProtoLogGroup.WM_DEBUG_WINDOW_TRANSITIONS_MIN, " info=%s", mInfo);
		}

		private static String toMsString(long nanos) {
		return ((double) Math.round((double) nanos / 1000) / 1000) + "ms";
		}

		private String buildOnFinishLog() {
		StringBuilder sb = new StringBuilder("Finish Transition #").append(mSyncId)
		.append(": created at ").append(TimeUtils.logTimeOfDay(mCreateWallTimeMs));
		sb.append(" collect-started=").append(toMsString(mCollectTimeNs - mCreateTimeNs));
		if (mRequestTimeNs != 0) {
		sb.append(" request-sent=").append(toMsString(mRequestTimeNs - mCreateTimeNs));
		}
		sb.append(" started=").append(toMsString(mStartTimeNs - mCreateTimeNs));
		sb.append(" ready=").append(toMsString(mReadyTimeNs - mCreateTimeNs));
		sb.append(" sent=").append(toMsString(mSendTimeNs - mCreateTimeNs));
		sb.append(" finished=").append(toMsString(mFinishTimeNs - mCreateTimeNs));
		return sb.toString();
		}

		void logOnFinish() {
		ProtoLog.v(ProtoLogGroup.WM_DEBUG_WINDOW_TRANSITIONS_MIN, "%s", buildOnFinishLog());
		}
		}

		static class TransitionMetricsReporter extends ITransitionMetricsReporter.Stub {
		private final ArrayMap<IBinder, LongConsumer> mMetricConsumers = new ArrayMap<>();

services/core/java/com/android/server/wm/WindowOrganizerController.java

+1 −0

Original line number	Diff line number	Diff line
		@@ -318,6 +318,7 @@ class WindowOrganizerController extends IWindowOrganizerController.Stub
		transition = mTransitionController.createTransition(type);
		}
		transition.start();
		transition.mLogger.mStartWCT = wct;
		applyTransaction(wct, -1 /syncId/, transition, caller);
		if (needsSetReady) {
		transition.setAllReady();