From a5a0576ceddd3c576f6b65bb74a208fd8d7b2957 Mon Sep 17 00:00:00 2001 From: Evan Rosky Date: Tue, 10 Jan 2023 10:55:25 -0800 Subject: [PATCH] Disable detailed transition logs but add a summary. On slow devices, logcat actually takes a lot of time, so turn it off by default. To maintain usefulness, though, add back some critical logging by recording important information during the transition and then logging a summary at critical points (startTransition and finish). Since the logging itself is deferred, we can put it on a low- priority thread so it doesn't impact latency. Bug: 260059642 Test: Run android-go latency tests and observe significant improvement Change-Id: I3621747f4d80a66953bda038dfc2c411dffa067d --- .../internal/protolog/ProtoLogGroup.java | 4 +- data/etc/services.core.protolog.json | 21 ++++++ .../com/android/server/wm/Transition.java | 14 ++++ .../server/wm/TransitionController.java | 74 ++++++++++++++++++- .../server/wm/WindowOrganizerController.java | 1 + 5 files changed, 110 insertions(+), 4 deletions(-) diff --git a/core/java/com/android/internal/protolog/ProtoLogGroup.java b/core/java/com/android/internal/protolog/ProtoLogGroup.java index 8f943ef654f92..ad1fdbae037d9 100644 --- a/core/java/com/android/internal/protolog/ProtoLogGroup.java +++ b/core/java/com/android/internal/protolog/ProtoLogGroup.java @@ -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), diff --git a/data/etc/services.core.protolog.json b/data/etc/services.core.protolog.json index bc3af1daa204c..8b7265e18d5c0 100644 --- a/data/etc/services.core.protolog.json +++ b/data/etc/services.core.protolog.json @@ -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" }, diff --git a/services/core/java/com/android/server/wm/Transition.java b/services/core/java/com/android/server/wm/Transition.java index cd23959a265e3..04ce92e703286 100644 --- a/services/core/java/com/android/server/wm/Transition.java +++ b/services/core/java/com/android/server/wm/Transition.java @@ -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. @@ -1082,6 +1093,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)) { @@ -1097,6 +1110,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { // No player registered, so just finish/apply immediately cleanUpOnFailure(); } + mController.mLoggerHandler.post(mLogger::logOnSend); mOverrideOptions = null; reportStartReasonsToLogger(); diff --git a/services/core/java/com/android/server/wm/TransitionController.java b/services/core/java/com/android/server/wm/TransitionController.java index 73cd25134bbc9..5e116baa3faec 100644 --- a/services/core/java/com/android/server/wm/TransitionController.java +++ b/services/core/java/com/android/server/wm/TransitionController.java @@ -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 mMetricConsumers = new ArrayMap<>(); diff --git a/services/core/java/com/android/server/wm/WindowOrganizerController.java b/services/core/java/com/android/server/wm/WindowOrganizerController.java index 6a1adb45ea7cb..5c68b127c45bb 100644 --- a/services/core/java/com/android/server/wm/WindowOrganizerController.java +++ b/services/core/java/com/android/server/wm/WindowOrganizerController.java @@ -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();