Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit c8ccb5c2 authored by Pablo Gamito's avatar Pablo Gamito
Browse files

Update transition dumping structure 

- We used to keep track of the transition proto and update it as we went along the transition pipeline and would then only add it to the trace buffer when the transition finished or was aborted.
- We now dump partial transition protos as we get the information moving through the pipeline, which are then joined up together using transition id when the trace is processed.
- This way of tracing is more compatible with Perfetto tracing and simplifies any logic required to keep track of the transition protos.

Bug: 277181336
Test: Collect transition trace and load into Winscope
Change-Id: I7d0004f2f0aa233a760cfc31d1aef5dcb39b9c43
parent 541c4b60

core/proto/android/server/windowmanagertransitiontrace.proto

+11 −25
Original line number Diff line number Diff line
@@ -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 {
@@ -95,13 +91,3 @@ message ChangeInfo { 
  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;

}

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

+1 −0
Original line number Diff line number Diff line
@@ -1261,6 +1261,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

+1 −2
Original line number Diff line number Diff line
@@ -1416,12 +1416,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

+33 −119
Original line number Diff line number Diff line
@@ -54,7 +54,7 @@ public class TransitionTracer { 
            "/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;
@@ -73,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);

    }



    /**
@@ -94,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);

    }



    /**
@@ -114,11 +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);

        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.ABORT_TIME_NS,

                transition.mLogger.mAbortTimeNs);

        outputStream.end(protoToken);



        mTraceBuffer.add(outputStream);

    }



    /**
@@ -134,20 +140,6 @@ public class TransitionTracer { 
        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);

    }



    private void dumpTransitionTargetsToProto(ProtoOutputStream outputStream,

            Transition transition, ArrayList<ChangeInfo> targets) {

        Trace.beginSection("TransitionTracer#dumpTransitionTargetsToProto");
@@ -190,22 +182,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");
@@ -261,68 +237,6 @@ public class TransitionTracer { 
        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.
@@ -336,8 +250,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();

    }
@@ -365,8 +279,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();

    }
@@ -405,7 +319,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);

        }