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

Commit 61aaf12c authored by Pablo Gamito's avatar Pablo Gamito
Browse files

Dump finish time of transitions in transitions trace 

We were relying on using the finish transaction id to figure out when a transition ended, but that isn't reliable if the transition runner decides to merge this transition with another transition leading to a transition with a different id being applied that we cannot track. So instead we need to dump the finish time of a transition. A side effect is we will no longer dump a transition when it is sent to shell but only once it is finished or aborted.

Fixes: 269279367
Test: atest FlickerLibTest
Change-Id: Ie3e376d1a1aadfe737ee33d97d6a2496090f1404
parent 62229367

core/proto/android/server/windowmanagertransitiontrace.proto

+6 −3
Original line number Diff line number Diff line
@@ -36,8 +36,10 @@ message TransitionTraceProto { 
    MAGIC_NUMBER_H = 0x45434152;  /* RACE (little-endian ASCII) */

  }



  required fixed64 magic_number = 1;  /* Must be the first field, set to value in MagicNumber */

  repeated Transition sent_transitions = 2;

  // 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;
@@ -50,7 +52,8 @@ message Transition { 
  required uint64 finish_transaction_id = 3;

  required int64 create_time_ns = 4;

  required int64 send_time_ns = 5;

  repeated Target targets = 6;

  optional int64 finish_time_ns = 6; // consider aborted if not provided

  repeated Target targets = 7;

}



message Target {

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

+3 −2
Original line number Diff line number Diff line
@@ -805,6 +805,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { 
        }

        mLogger.mFinishTimeNs = SystemClock.elapsedRealtimeNanos();

        mController.mLoggerHandler.post(mLogger::logOnFinish);

        mController.mTransitionTracer.logFinishedTransition(this);

        // 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.
@@ -1010,6 +1011,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { 
        }

        ProtoLog.v(ProtoLogGroup.WM_DEBUG_WINDOW_TRANSITIONS, "Aborting Transition: %d", mSyncId);

        mState = STATE_ABORT;

        mController.mTransitionTracer.logAbortedTransition(this);

        // Syncengine abort will call through to onTransactionReady()

        mSyncEngine.abort(mSyncId);

        mController.dispatchLegacyAppTransitionCancelled();
@@ -1203,8 +1205,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { 
                        "Calling onTransitionReady: %s", info);

                mLogger.mSendTimeNs = SystemClock.elapsedRealtimeNanos();

                mLogger.mInfo = info;

                mController.mTransitionTracer.logSentTransition(

                        this, mTargets, mLogger.mCreateTimeNs, mLogger.mSendTimeNs, info);

                mController.mTransitionTracer.logSentTransition(this, mTargets, info);

                mController.getTransitionPlayer().onTransitionReady(

                        mToken, info, transaction, mFinishTransaction);

                if (Trace.isTagEnabled(TRACE_TAG_WINDOW_MANAGER)) {

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

+2 −0
Original line number Diff line number Diff line
@@ -969,6 +969,8 @@ class TransitionController { 
        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

+190 −148
Original line number Diff line number Diff line
@@ -18,14 +18,6 @@ package com.android.server.wm; 


import static android.os.Build.IS_USER;



import static com.android.server.wm.shell.ChangeInfo.CHANGE_FLAGS;

import static com.android.server.wm.shell.ChangeInfo.HAS_CHANGED;

import static com.android.server.wm.shell.ChangeInfo.TRANSIT_MODE;

import static com.android.server.wm.shell.ChangeInfo.WINDOWING_MODE;

import static com.android.server.wm.shell.ChangeInfo.WINDOW_IDENTIFIER;

import static com.android.server.wm.shell.TransitionInfoChange.LAYER_ID;

import static com.android.server.wm.shell.TransitionInfoChange.MODE;

import static com.android.server.wm.shell.TransitionState.CHANGE;

import static com.android.server.wm.shell.TransitionTraceProto.MAGIC_NUMBER;

import static com.android.server.wm.shell.TransitionTraceProto.MAGIC_NUMBER_H;

import static com.android.server.wm.shell.TransitionTraceProto.MAGIC_NUMBER_L;
@@ -66,19 +58,59 @@ public class TransitionTracer { 


    /**

     * Records key information about a transition that has been sent to Shell to be played.

     * More information will be appended to the same proto object once the transition is finished or

     * aborted.

     * Transition information won't be added to the trace buffer until

     * {@link #logFinishedTransition} or {@link #logAbortedTransition} is called for this

     * transition.

     *

     * @param transition The transition that has been sent to Shell.

     * @param targets Information about the target windows of the transition.

     * @param createTimeNs System elapsed time (nanoseconds since boot including sleep time) at

 *                     which the transition to be recorded was created.

     * @param sendTimeNs System elapsed time (nanoseconds since boot including sleep time) at which

     * @param info

     * @param info The TransitionInfo send over to Shell to execute the transition.

     */

    public void logSentTransition(Transition transition, ArrayList<ChangeInfo> targets,

            long createTimeNs, long sendTimeNs, TransitionInfo info) {

        mTraceBuffer.pushSentTransition(transition, targets, createTimeNs, sendTimeNs);

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

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



        logTransitionInfo(transition, info);

    }



    /**

     * Completes the information dumped in {@link #logSentTransition} for a transition

     * that has finished or aborted, and add the proto object to the trace buffer.

     *

     * @param transition The transition that has finished.

     */

    public void logFinishedTransition(Transition transition) {

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

    }



    /**

     * Same as {@link #logFinishedTransition} but don't add the transition to the trace buffer

     * unless actively tracing.

     *

     * @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.
@@ -87,7 +119,9 @@ public class TransitionTracer { 
        if (!mActiveTracingEnabled) {

            return;

        }

        mTraceBuffer.pushTransitionState(transition);

        final ProtoOutputStream outputStream = new ProtoOutputStream();

        dumpTransitionStateToProto(outputStream, transition);

        mTraceBuffer.pushTransitionState(outputStream);

    }



    /**
@@ -99,39 +133,19 @@ public class TransitionTracer { 
        if (!mActiveTracingEnabled) {

            return;

        }

        mTraceBuffer.pushTransitionInfo(transition, info);

    }



    private class TransitionTraceBuffer {

        private final TraceBuffer mBuffer = 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);



        public void pushSentTransition(

                Transition transition,

                ArrayList<ChangeInfo> targets,

                long createTimeNs,

                long sendTimeNs

        ) {

            Trace.beginSection("TransitionTraceBuffer#pushSentTransition");

        final ProtoOutputStream outputStream = new ProtoOutputStream();

            final long transitionToken = outputStream

                    .start(com.android.server.wm.shell.TransitionTraceProto.SENT_TRANSITIONS);

        dumpTransitionInfoToProto(outputStream, transition, info);

        mTraceBuffer.pushTransitionInfo(outputStream);

    }



    private void dumpTransitionTargetsToProto(ProtoOutputStream outputStream,

            Transition transition, ArrayList<ChangeInfo> targets) {

        Trace.beginSection("TransitionTracer#dumpTransitionTargetsToProto");

        if (mActiveTracingEnabled) {

            outputStream.write(com.android.server.wm.shell.Transition.ID,

                    transition.getSyncId());

        }



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



            outputStream.write(com.android.server.wm.shell.Transition.CREATE_TIME_NS, createTimeNs);

            outputStream.write(com.android.server.wm.shell.Transition.SEND_TIME_NS, sendTimeNs);



        for (int i = 0; i < targets.size(); ++i) {

            final long changeToken = outputStream

                    .start(com.android.server.wm.shell.Transition.TARGETS);
@@ -158,15 +172,28 @@ public class TransitionTracer { 
            outputStream.end(changeToken);

        }



            outputStream.end(transitionToken);

            mBuffer.add(outputStream);

        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 pushTransitionState(Transition transition) {

            Trace.beginSection("TransitionTraceBuffer#pushTransitionState");

            final ProtoOutputStream outputStream = new ProtoOutputStream();

    private void dumpTransitionStateToProto(ProtoOutputStream outputStream, Transition transition) {

        Trace.beginSection("TransitionTracer#dumpTransitionStateToProto");



        final long stateToken = outputStream

                .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITION_STATES);
@@ -184,13 +211,7 @@ public class TransitionTracer { 
        for (int i = 0; i < transition.mChanges.size(); ++i) {

            final WindowContainer window = transition.mChanges.keyAt(i);

            final ChangeInfo changeInfo = transition.mChanges.valueAt(i);

                writeChange(outputStream, window, changeInfo);

            }



            for (int i = 0; i < transition.mChanges.size(); ++i) {

                final WindowContainer window = transition.mChanges.keyAt(i);

                final ChangeInfo changeInfo = transition.mChanges.valueAt(i);

                writeChange(outputStream, window, changeInfo);

            dumpChangeInfoToProto(outputStream, window, changeInfo);

        }



        for (int i = 0; i < transition.mParticipants.size(); ++i) {
@@ -200,14 +221,34 @@ public class TransitionTracer { 
        }



        outputStream.end(stateToken);

        Trace.endSection();

    }



            mStateBuffer.add(outputStream);

    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 pushTransitionInfo(Transition transition, TransitionInfo info) {

            Trace.beginSection("TransitionTraceBuffer#pushTransitionInfo");

            final ProtoOutputStream outputStream = new ProtoOutputStream();

    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);
@@ -215,55 +256,55 @@ public class TransitionTracer { 
                transition.getSyncId());

        for (int i = 0; i < info.getChanges().size(); ++i) {

            TransitionInfo.Change change = info.getChanges().get(i);

                writeTransitionInfoChange(outputStream, change);

            dumpTransitionInfoChangeToProto(outputStream, change);

        }



        outputStream.end(transitionInfoToken);

            mTransitionInfoBuffer.add(outputStream);

        Trace.endSection();

    }



        private void writeChange(ProtoOutputStream outputStream, WindowContainer window,

                ChangeInfo changeInfo) {

            Trace.beginSection("TransitionTraceBuffer#writeChange");

            final long changeEntryToken = outputStream.start(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(TRANSIT_MODE, transitMode);

            outputStream.write(HAS_CHANGED, hasChanged);

            outputStream.write(CHANGE_FLAGS, changeFlags);

            outputStream.write(WINDOWING_MODE, windowingMode);

            window.writeIdentifierToProto(outputStream, WINDOW_IDENTIFIER);



            outputStream.end(changeEntryToken);

            Trace.endSection();

        }



        private void writeTransitionInfoChange(

    private void dumpTransitionInfoChangeToProto(

            ProtoOutputStream outputStream,

            TransitionInfo.Change change

    ) {

            Trace.beginSection("TransitionTraceBuffer#writeTransitionInfoChange");

        Trace.beginSection("TransitionTracer#dumpTransitionInfoChangeToProto");

        final long changeEntryToken = outputStream

                .start(com.android.server.wm.shell.TransitionInfo.CHANGE);



            outputStream.write(LAYER_ID, change.getLeash().getLayerId());

            outputStream.write(MODE, change.getMode());

        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 {

            mBuffer.writeTraceToFile(file, proto);

            mTransitionBuffer.writeTraceToFile(file, proto);

        }



        public void reset() {

            mBuffer.resetBuffer();

            mTransitionBuffer.resetBuffer();

            mStateBuffer.resetBuffer();

            mTransitionInfoBuffer.resetBuffer();

        }

    }
@@ -280,7 +321,7 @@ public class TransitionTracer { 
        LogAndPrintln.i(pw, "Starting shell transition trace.");

        synchronized (mEnabledLock) {

            mActiveTracingEnabled = true;

            mTraceBuffer.mBuffer.setCapacity(ACTIVE_TRACING_BUFFER_CAPACITY);

            mTraceBuffer.mTransitionBuffer.setCapacity(ACTIVE_TRACING_BUFFER_CAPACITY);

            mTraceBuffer.reset();

        }

        Trace.endSection();
@@ -309,7 +350,8 @@ public class TransitionTracer { 
        synchronized (mEnabledLock) {

            mActiveTracingEnabled = false;

            writeTraceToFileLocked(pw, outputFile);

            mTraceBuffer.mBuffer.setCapacity(ALWAYS_ON_TRACING_CAPACITY);

            mTraceBuffer.reset();

            mTraceBuffer.mTransitionBuffer.setCapacity(ALWAYS_ON_TRACING_CAPACITY);

        }

        Trace.endSection();

    }