diff options
6 files changed, 55 insertions, 248 deletions
diff --git a/core/proto/android/server/windowmanagertransitiontrace.proto b/core/proto/android/server/windowmanagertransitiontrace.proto index a776bd2a4330..a950a79d94fb 100644 --- a/core/proto/android/server/windowmanagertransitiontrace.proto +++ b/core/proto/android/server/windowmanagertransitiontrace.proto @@ -23,7 +23,7 @@ import "frameworks/base/core/proto/android/server/windowmanagerservice.proto"; option java_multiple_files = true; /* Represents a file full of transition entries. - Encoded, it should start with 0x09 0x54 0x52 0x4E 0x54 0x52 0x41 0x43 0x45 (TRNTRACE), such + Encoded, it should start with 0x09 0x54 0x52 0x4E 0x54 0x52 0x41 0x43 0x45 (.TRNTRACE), such that it can be easily identified. */ message TransitionTraceProto { @@ -38,28 +38,24 @@ message TransitionTraceProto { // Must be the first field, set to value in MagicNumber required fixed64 magic_number = 1; - // Transitions that don't have a finish time are considered aborted - repeated Transition finished_transitions = 2; - - // Additional debugging info only collected and dumped when explicitly requested to trace - repeated TransitionState transition_states = 3; - repeated TransitionInfo transition_info = 4; + repeated Transition transitions = 2; /* offset between real-time clock and elapsed time clock in nanoseconds. Calculated as: 1000000 * System.currentTimeMillis() - SystemClock.elapsedRealtimeNanos() */ - optional fixed64 real_to_elapsed_time_offset_nanos = 5; + optional fixed64 real_to_elapsed_time_offset_nanos = 3; } message Transition { - optional int32 id = 1; // Not dumped in always on tracing - required uint64 start_transaction_id = 2; - required uint64 finish_transaction_id = 3; - required int64 create_time_ns = 4; - required int64 send_time_ns = 5; - optional int64 finish_time_ns = 6; // consider aborted if not provided - required int32 type = 7; + required int32 id = 1; + optional uint64 start_transaction_id = 2; + optional uint64 finish_transaction_id = 3; + optional int64 create_time_ns = 4; + optional int64 send_time_ns = 5; + optional int64 finish_time_ns = 6; + optional int32 type = 7; repeated Target targets = 8; optional int32 flags = 9; + optional int64 abort_time_ns = 10; } message Target { @@ -68,40 +64,3 @@ message Target { optional int32 window_id = 3; // Not dumped in always on tracing optional int32 flags = 4; } - -message TransitionState { - enum State { - COLLECTING = 0; - PENDING = -1; - STARTED = 1; - PLAYING = 2; - ABORT = 3; - FINISHED = 4; - } - - required int64 time_ns = 1; - required int32 transition_id = 2; - required int32 transition_type = 3; - required State state = 4; - required int32 flags = 5; - repeated ChangeInfo change = 6; - repeated com.android.server.wm.IdentifierProto participants = 7; -} - -message ChangeInfo { - required com.android.server.wm.IdentifierProto window_identifier = 1; - required int32 transit_mode = 2; - required bool has_changed = 3; - required int32 change_flags = 4; - required int32 windowing_mode = 5; -} - -message TransitionInfo { - required int32 transition_id = 1; - repeated TransitionInfoChange change = 2; -} - -message TransitionInfoChange { - required int32 layer_id = 1; - required int32 mode = 2; -} diff --git a/libs/WindowManager/Shell/proto/wm_shell_transition_trace.proto b/libs/WindowManager/Shell/proto/wm_shell_transition_trace.proto index 6e0110193a05..c82a70c9a44e 100644 --- a/libs/WindowManager/Shell/proto/wm_shell_transition_trace.proto +++ b/libs/WindowManager/Shell/proto/wm_shell_transition_trace.proto @@ -37,6 +37,9 @@ message WmShellTransitionTraceProto { required fixed64 magic_number = 1; repeated Transition transitions = 2; repeated HandlerMapping handlerMappings = 3; + /* offset between real-time clock and elapsed time clock in nanoseconds. + Calculated as: 1000000 * System.currentTimeMillis() - SystemClock.elapsedRealtimeNanos() */ + optional fixed64 real_to_elapsed_time_offset_nanos = 4; } message Transition { diff --git a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Tracer.java b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Tracer.java index 0cede902f034..e27e4f990407 100644 --- a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Tracer.java +++ b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Tracer.java @@ -28,7 +28,6 @@ import android.os.Trace; import android.util.Log; import com.android.internal.util.TraceBuffer; -import com.android.wm.shell.nano.HandlerMapping; import com.android.wm.shell.sysui.ShellCommandHandler; import com.google.protobuf.nano.MessageNano; @@ -41,6 +40,7 @@ import java.util.ArrayList; import java.util.HashMap; import java.util.Map; import java.util.Queue; +import java.util.concurrent.TimeUnit; /** * Helper class to collect and dump transition traces. @@ -241,6 +241,10 @@ public class Tracer implements ShellCommandHandler.ShellCommandActionHandler { new com.android.wm.shell.nano.WmShellTransitionTraceProto(); proto.magicNumber = MAGIC_NUMBER_VALUE; writeHandlerMappingToProto(proto); + long timeOffsetNs = + TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis()) + - SystemClock.elapsedRealtimeNanos(); + proto.realToElapsedTimeOffsetNanos = timeOffsetNs; int pid = android.os.Process.myPid(); LogAndPrintln.i(pw, "Writing file to " + file.getAbsolutePath() + " from process " + pid); diff --git a/services/core/java/com/android/server/wm/Transition.java b/services/core/java/com/android/server/wm/Transition.java index 50bf38b8ce16..bfd0d96a04ab 100644 --- a/services/core/java/com/android/server/wm/Transition.java +++ b/services/core/java/com/android/server/wm/Transition.java @@ -314,7 +314,6 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { mLogger.mCreateWallTimeMs = System.currentTimeMillis(); mLogger.mCreateTimeNs = SystemClock.elapsedRealtimeNanos(); - controller.mTransitionTracer.logState(this); } @Nullable @@ -532,7 +531,6 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { mLogger.mSyncId = mSyncId; mLogger.mCollectTimeNs = SystemClock.elapsedRealtimeNanos(); - mController.mTransitionTracer.logState(this); } /** @@ -555,7 +553,6 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { applyReady(); mLogger.mStartTimeNs = SystemClock.elapsedRealtimeNanos(); - mController.mTransitionTracer.logState(this); mController.updateAnimatingState(mTmpTransaction); // merge into the next-time the global transaction is applied. This is too-early to set @@ -1232,7 +1229,6 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { validateVisibility(); mState = STATE_FINISHED; - mController.mTransitionTracer.logState(this); // Rotation change may be deferred while there is a display change transition, so check // again in case there is a new pending change. if (hasParticipatedDisplay && !mController.useShellTransitionsRotation()) { @@ -1261,6 +1257,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { } ProtoLog.v(ProtoLogGroup.WM_DEBUG_WINDOW_TRANSITIONS, "Aborting Transition: %d", mSyncId); mState = STATE_ABORT; + mLogger.mAbortTimeNs = SystemClock.elapsedRealtimeNanos(); mController.mTransitionTracer.logAbortedTransition(this); // Syncengine abort will call through to onTransactionReady() mSyncEngine.abort(mSyncId); diff --git a/services/core/java/com/android/server/wm/TransitionController.java b/services/core/java/com/android/server/wm/TransitionController.java index c9316bf6e972..b697ab158003 100644 --- a/services/core/java/com/android/server/wm/TransitionController.java +++ b/services/core/java/com/android/server/wm/TransitionController.java @@ -941,7 +941,6 @@ class TransitionController { } mPlayingTransitions.add(transition); updateRunningRemoteAnimation(transition, true /* isPlaying */); - mTransitionTracer.logState(transition); // Sync engine should become idle after this, so the idle listener will check the queue. } @@ -1122,7 +1121,6 @@ class TransitionController { mLatestOnTopTasksReported.clear(); } } - mTransitionTracer.logState(transition); // This is called during Transition.abort whose codepath will eventually check the queue // via sync-engine idle. } @@ -1416,12 +1414,11 @@ class TransitionController { long mReadyTimeNs; long mSendTimeNs; long mFinishTimeNs; + long mAbortTimeNs; TransitionRequestInfo mRequest; WindowContainerTransaction mStartWCT; int mSyncId; TransitionInfo mInfo; - ProtoOutputStream mProtoOutputStream = new ProtoOutputStream(); - long mProtoToken; private String buildOnSendLog() { StringBuilder sb = new StringBuilder("Sent Transition #").append(mSyncId) diff --git a/services/core/java/com/android/server/wm/TransitionTracer.java b/services/core/java/com/android/server/wm/TransitionTracer.java index 6aac81bc3b6c..afc14926f63c 100644 --- a/services/core/java/com/android/server/wm/TransitionTracer.java +++ b/services/core/java/com/android/server/wm/TransitionTracer.java @@ -50,10 +50,11 @@ public class TransitionTracer { private static final int ALWAYS_ON_TRACING_CAPACITY = 15 * 1024; // 15 KB private static final int ACTIVE_TRACING_BUFFER_CAPACITY = 5000 * 1024; // 5 MB static final String WINSCOPE_EXT = ".winscope"; - private static final String TRACE_FILE = "/data/misc/wmtrace/transition_trace" + WINSCOPE_EXT; + private static final String TRACE_FILE = + "/data/misc/wmtrace/wm_transition_trace" + WINSCOPE_EXT; private static final long MAGIC_NUMBER_VALUE = ((long) MAGIC_NUMBER_H << 32) | MAGIC_NUMBER_L; - private final TransitionTraceBuffer mTraceBuffer = new TransitionTraceBuffer(); + private final TraceBuffer mTraceBuffer = new TraceBuffer(ALWAYS_ON_TRACING_CAPACITY); private final Object mEnabledLock = new Object(); private volatile boolean mActiveTracingEnabled = false; @@ -72,18 +73,22 @@ public class TransitionTracer { */ public void logSentTransition(Transition transition, ArrayList<ChangeInfo> targets, TransitionInfo info) { - // Dump the info to proto that will not be available when the transition finishes or - // is canceled - final ProtoOutputStream outputStream = transition.mLogger.mProtoOutputStream; - transition.mLogger.mProtoToken = outputStream - .start(com.android.server.wm.shell.TransitionTraceProto.FINISHED_TRANSITIONS); + final ProtoOutputStream outputStream = new ProtoOutputStream(); + final long protoToken = outputStream + .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITIONS); + outputStream.write(com.android.server.wm.shell.Transition.ID, transition.getSyncId()); + outputStream.write(com.android.server.wm.shell.Transition.CREATE_TIME_NS, + transition.mLogger.mCreateTimeNs); + outputStream.write(com.android.server.wm.shell.Transition.SEND_TIME_NS, + transition.mLogger.mSendTimeNs); outputStream.write(com.android.server.wm.shell.Transition.START_TRANSACTION_ID, transition.getStartTransaction().getId()); outputStream.write(com.android.server.wm.shell.Transition.FINISH_TRANSACTION_ID, transition.getFinishTransaction().getId()); dumpTransitionTargetsToProto(outputStream, transition, targets); + outputStream.end(protoToken); - logTransitionInfo(transition, info); + mTraceBuffer.add(outputStream); } /** @@ -93,17 +98,15 @@ public class TransitionTracer { * @param transition The transition that has finished. */ public void logFinishedTransition(Transition transition) { - if (transition.mLogger.mProtoToken == 0) { - // Transition finished but never sent, so open token never added - final ProtoOutputStream outputStream = transition.mLogger.mProtoOutputStream; - transition.mLogger.mProtoToken = outputStream - .start(com.android.server.wm.shell.TransitionTraceProto.FINISHED_TRANSITIONS); - } + final ProtoOutputStream outputStream = new ProtoOutputStream(); + final long protoToken = outputStream + .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITIONS); + outputStream.write(com.android.server.wm.shell.Transition.ID, transition.getSyncId()); + outputStream.write(com.android.server.wm.shell.Transition.FINISH_TIME_NS, + transition.mLogger.mFinishTimeNs); + outputStream.end(protoToken); - // Dump the rest of the transition's info that wasn't dumped during logSentTransition - dumpFinishedTransitionToProto(transition.mLogger.mProtoOutputStream, transition); - transition.mLogger.mProtoOutputStream.end(transition.mLogger.mProtoToken); - mTraceBuffer.pushTransitionProto(transition.mLogger.mProtoOutputStream); + mTraceBuffer.add(outputStream); } /** @@ -113,38 +116,15 @@ public class TransitionTracer { * @param transition The transition that has been aborted */ public void logAbortedTransition(Transition transition) { - // We don't care about aborted transitions unless actively tracing - if (!mActiveTracingEnabled) { - return; - } - logFinishedTransition(transition); - } - - /** - * Records the current state of a transition in the transition trace (if it is running). - * @param transition the transition that we want to record the state of. - */ - public void logState(com.android.server.wm.Transition transition) { - if (!mActiveTracingEnabled) { - return; - } final ProtoOutputStream outputStream = new ProtoOutputStream(); - dumpTransitionStateToProto(outputStream, transition); - mTraceBuffer.pushTransitionState(outputStream); - } - - /** - * Records the transition info that is being sent over to Shell. - * @param transition The transition the info is associated with. - * @param info The transition info we want to log. - */ - private void logTransitionInfo(Transition transition, TransitionInfo info) { - if (!mActiveTracingEnabled) { - return; - } - final ProtoOutputStream outputStream = new ProtoOutputStream(); - dumpTransitionInfoToProto(outputStream, transition, info); - mTraceBuffer.pushTransitionInfo(outputStream); + final long protoToken = outputStream + .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITIONS); + outputStream.write(com.android.server.wm.shell.Transition.ID, transition.getSyncId()); + outputStream.write(com.android.server.wm.shell.Transition.ABORT_TIME_NS, + transition.mLogger.mAbortTimeNs); + outputStream.end(protoToken); + + mTraceBuffer.add(outputStream); } private void dumpTransitionTargetsToProto(ProtoOutputStream outputStream, @@ -189,139 +169,6 @@ public class TransitionTracer { Trace.endSection(); } - private void dumpFinishedTransitionToProto( - ProtoOutputStream outputStream, - Transition transition - ) { - Trace.beginSection("TransitionTracer#dumpFinishedTransitionToProto"); - - outputStream.write(com.android.server.wm.shell.Transition.CREATE_TIME_NS, - transition.mLogger.mCreateTimeNs); - outputStream.write(com.android.server.wm.shell.Transition.SEND_TIME_NS, - transition.mLogger.mSendTimeNs); - outputStream.write(com.android.server.wm.shell.Transition.FINISH_TIME_NS, - transition.mLogger.mFinishTimeNs); - - Trace.endSection(); - } - - private void dumpTransitionStateToProto(ProtoOutputStream outputStream, Transition transition) { - Trace.beginSection("TransitionTracer#dumpTransitionStateToProto"); - - final long stateToken = outputStream - .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITION_STATES); - - outputStream.write(com.android.server.wm.shell.TransitionState.TIME_NS, - SystemClock.elapsedRealtimeNanos()); - outputStream.write(com.android.server.wm.shell.TransitionState.TRANSITION_ID, - transition.getSyncId()); - outputStream.write(com.android.server.wm.shell.TransitionState.TRANSITION_TYPE, - transition.mType); - outputStream.write(com.android.server.wm.shell.TransitionState.STATE, - transition.getState()); - outputStream.write(com.android.server.wm.shell.TransitionState.FLAGS, - transition.getFlags()); - - for (int i = 0; i < transition.mChanges.size(); ++i) { - final WindowContainer window = transition.mChanges.keyAt(i); - final ChangeInfo changeInfo = transition.mChanges.valueAt(i); - dumpChangeInfoToProto(outputStream, window, changeInfo); - } - - for (int i = 0; i < transition.mParticipants.size(); ++i) { - final WindowContainer window = transition.mParticipants.valueAt(i); - window.writeIdentifierToProto(outputStream, - com.android.server.wm.shell.TransitionState.PARTICIPANTS); - } - - outputStream.end(stateToken); - Trace.endSection(); - } - - private void dumpChangeInfoToProto(ProtoOutputStream outputStream, WindowContainer window, - ChangeInfo changeInfo) { - Trace.beginSection("TransitionTraceBuffer#writeChange"); - final long changeEntryToken = - outputStream.start(com.android.server.wm.shell.TransitionState.CHANGE); - - final int transitMode = changeInfo.getTransitMode(window); - final boolean hasChanged = changeInfo.hasChanged(); - final int changeFlags = changeInfo.getChangeFlags(window); - final int windowingMode = changeInfo.mWindowingMode; - - outputStream.write(com.android.server.wm.shell.ChangeInfo.TRANSIT_MODE, transitMode); - outputStream.write(com.android.server.wm.shell.ChangeInfo.HAS_CHANGED, hasChanged); - outputStream.write(com.android.server.wm.shell.ChangeInfo.CHANGE_FLAGS, changeFlags); - outputStream.write(com.android.server.wm.shell.ChangeInfo.WINDOWING_MODE, windowingMode); - window.writeIdentifierToProto( - outputStream, com.android.server.wm.shell.ChangeInfo.WINDOW_IDENTIFIER); - - outputStream.end(changeEntryToken); - Trace.endSection(); - } - - private void dumpTransitionInfoToProto(ProtoOutputStream outputStream, - Transition transition, TransitionInfo info) { - Trace.beginSection("TransitionTracer#dumpTransitionInfoToProto"); - final long transitionInfoToken = outputStream - .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITION_INFO); - - outputStream.write(com.android.server.wm.shell.TransitionInfo.TRANSITION_ID, - transition.getSyncId()); - for (int i = 0; i < info.getChanges().size(); ++i) { - TransitionInfo.Change change = info.getChanges().get(i); - dumpTransitionInfoChangeToProto(outputStream, change); - } - - outputStream.end(transitionInfoToken); - Trace.endSection(); - } - - private void dumpTransitionInfoChangeToProto( - ProtoOutputStream outputStream, - TransitionInfo.Change change - ) { - Trace.beginSection("TransitionTracer#dumpTransitionInfoChangeToProto"); - final long changeEntryToken = outputStream - .start(com.android.server.wm.shell.TransitionInfo.CHANGE); - - outputStream.write(com.android.server.wm.shell.TransitionInfoChange.LAYER_ID, - change.getLeash().getLayerId()); - outputStream.write(com.android.server.wm.shell.TransitionInfoChange.MODE, change.getMode()); - - outputStream.end(changeEntryToken); - Trace.endSection(); - } - - private class TransitionTraceBuffer { - private final TraceBuffer mTransitionBuffer = new TraceBuffer(ALWAYS_ON_TRACING_CAPACITY); - private final TraceBuffer mStateBuffer = new TraceBuffer(ACTIVE_TRACING_BUFFER_CAPACITY); - private final TraceBuffer mTransitionInfoBuffer = - new TraceBuffer(ACTIVE_TRACING_BUFFER_CAPACITY); - - private void pushTransitionProto(ProtoOutputStream outputStream) { - mTransitionBuffer.add(outputStream); - } - - private void pushTransitionState(ProtoOutputStream outputStream) { - mStateBuffer.add(outputStream); - } - - private void pushTransitionInfo(ProtoOutputStream outputStream) { - mTransitionInfoBuffer.add(outputStream); - } - - public void writeToFile(File file, ProtoOutputStream proto) throws IOException { - mTransitionBuffer.writeTraceToFile(file, proto); - } - - public void reset() { - mTransitionBuffer.resetBuffer(); - mStateBuffer.resetBuffer(); - mTransitionInfoBuffer.resetBuffer(); - } - } - /** * Starts collecting transitions for the trace. * If called while a trace is already running, this will reset the trace. @@ -335,8 +182,8 @@ public class TransitionTracer { LogAndPrintln.i(pw, "Starting shell transition trace."); synchronized (mEnabledLock) { mActiveTracingEnabled = true; - mTraceBuffer.mTransitionBuffer.setCapacity(ACTIVE_TRACING_BUFFER_CAPACITY); - mTraceBuffer.reset(); + mTraceBuffer.resetBuffer(); + mTraceBuffer.setCapacity(ACTIVE_TRACING_BUFFER_CAPACITY); } Trace.endSection(); } @@ -364,8 +211,8 @@ public class TransitionTracer { synchronized (mEnabledLock) { mActiveTracingEnabled = false; writeTraceToFileLocked(pw, outputFile); - mTraceBuffer.reset(); - mTraceBuffer.mTransitionBuffer.setCapacity(ALWAYS_ON_TRACING_CAPACITY); + mTraceBuffer.resetBuffer(); + mTraceBuffer.setCapacity(ALWAYS_ON_TRACING_CAPACITY); } Trace.endSection(); } @@ -404,7 +251,7 @@ public class TransitionTracer { int pid = android.os.Process.myPid(); LogAndPrintln.i(pw, "Writing file to " + file.getAbsolutePath() + " from process " + pid); - mTraceBuffer.writeToFile(file, proto); + mTraceBuffer.writeTraceToFile(file, proto); } catch (IOException e) { LogAndPrintln.e(pw, "Unable to write buffer to file", e); } |