Merge changes from topic "update-transition-trace-dumping-structure" into udc-dev

* changes:
  Remove transition state tracing
  Update transition dumping structure
  Add real to elapsed offset to shell transition trace
  Update WM side transition trace file name

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 transitions = 2;
-  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;
 
   /* 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 int32 id = 1;
-  required uint64 start_transaction_id = 2;
+  optional uint64 start_transaction_id = 2;
-  required uint64 finish_transaction_id = 3;
+  optional uint64 finish_transaction_id = 3;
-  required int64 create_time_ns = 4;
+  optional int64 create_time_ns = 4;
-  required int64 send_time_ns = 5;
+  optional int64 send_time_ns = 5;
-  optional int64 finish_time_ns = 6; // consider aborted if not provided
+  optional int64 finish_time_ns = 6;
-  required int32 type = 7;
+  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;
-}

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 {

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

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

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)

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
+        final ProtoOutputStream outputStream = new ProtoOutputStream();
-        // is canceled
+        final long protoToken = outputStream
-        final ProtoOutputStream outputStream = transition.mLogger.mProtoOutputStream;
+                .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITIONS);
-        transition.mLogger.mProtoToken = outputStream
+        outputStream.write(com.android.server.wm.shell.Transition.ID, transition.getSyncId());
-                .start(com.android.server.wm.shell.TransitionTraceProto.FINISHED_TRANSITIONS);
+        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) {
+        final ProtoOutputStream outputStream = new ProtoOutputStream();
-            // Transition finished but never sent, so open token never added
+        final long protoToken = outputStream
-            final ProtoOutputStream outputStream = transition.mLogger.mProtoOutputStream;
+                .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITIONS);
-            transition.mLogger.mProtoToken = outputStream
+        outputStream.write(com.android.server.wm.shell.Transition.ID, transition.getSyncId());
-                    .start(com.android.server.wm.shell.TransitionTraceProto.FINISHED_TRANSITIONS);
+        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
+        mTraceBuffer.add(outputStream);
-        dumpFinishedTransitionToProto(transition.mLogger.mProtoOutputStream, transition);
-        transition.mLogger.mProtoOutputStream.end(transition.mLogger.mProtoToken);
-        mTraceBuffer.pushTransitionProto(transition.mLogger.mProtoOutputStream);
     }
 
     /**
@@ -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);
+        final long protoToken = outputStream
-        mTraceBuffer.pushTransitionState(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);
-     * 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);
     }
 
     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.resetBuffer();
-            mTraceBuffer.reset();
+            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.resetBuffer();
-            mTraceBuffer.mTransitionBuffer.setCapacity(ALWAYS_ON_TRACING_CAPACITY);
+            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);
         }