Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Disable detailed transition logs but add a summary.

Browse Source 
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
This commit is contained in:
Evan Rosky
2023-01-10 10:55:25 -08:00
parent 0648b6f932
commit a5a0576ced
5 changed files with 110 additions and 4 deletions
Download Patch File Download Diff File Expand all files Collapse all files

4
core/java/com/android/internal/protolog/ProtoLogGroup.java
View File

@@ -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),

21
data/etc/services.core.protolog.json
View File

@@ -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"
},

14
services/core/java/com/android/server/wm/Transition.java
View File

@@ -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();

74
services/core/java/com/android/server/wm/TransitionController.java
View File

@@ -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<>();

1
services/core/java/com/android/server/wm/WindowOrganizerController.java
View File

@@ -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();