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

Commit 3705aa41 authored by Pablo Gamito's avatar Pablo Gamito
Browse files

Update transition tracing for FaaS usecase 

For FaaS, we don't really care about all the intermediate states of a
transition we only want to get information about which window and
surfaces were part of the transition and how they should have changed.

These changes provide the data for FaaS in a format that is more
convinient for FaaS, and avoid additional processing on the FaaS side.

It also means that we can be more memory efficient when tracing the data
we need for FaaS, which allows us to enable always on tracing to provide
meaningful data about transition that FaaS can then use to run on traces
for dogfood devices.

Test: N/A
Bug: 267484886
Change-Id: I4d7aae1414e45a8170b71143e6bfa804064bbfce
parent e06b6a83

core/proto/android/server/windowmanagertransitiontrace.proto

+43 −16
Original line number Diff line number Diff line
@@ -14,7 +14,7 @@ 
 * limitations under the License.

 */



syntax = "proto3";

syntax = "proto2";



package com.android.server.wm.shell;
@@ -36,13 +36,30 @@ message TransitionTraceProto { 
    MAGIC_NUMBER_H = 0x45434152;  /* RACE (little-endian ASCII) */

  }



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

  int64 timestamp = 2; /* The timestamp of when the trace was started. */

  repeated Transition transition = 3;

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

  repeated Transition sent_transitions = 2;



  // Additional debugging info only collected and dumped when explicitly requested to trace

  repeated TransitionState transition_states = 3;

  repeated TransitionInfo transition_info = 4;

}



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;

  repeated Target targets = 6;

}



message Target {

  required int32 mode = 1;

  required int32 layer_id = 2;

  optional int32 window_id = 3;  // Not dumped in always on tracing

}



message TransitionState {

  enum State {

    COLLECTING = 0;

    PENDING = -1;
@@ -52,19 +69,29 @@ message Transition { 
    FINISHED = 4;

  }



  int32 id = 1;

  int32 transition_type = 2;

  int64 timestamp = 3;

  State state = 5;

  int32 flags = 6;

  repeated ChangeInfo change = 7;

  uint64 start_transaction_id = 8;

  uint64 finish_transaction_id = 9;

  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 {

  com.android.server.wm.IdentifierProto window_identifier = 1;

  int32 transit_mode = 2;

  bool has_changed = 3;

  int32 change_flags = 4;

  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;

}

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

+16 −6
Original line number Diff line number Diff line
@@ -225,7 +225,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { 
        mToken = new Token(this);



        mLogger.mCreateWallTimeMs = System.currentTimeMillis();

        mLogger.mCreateTimeNs = SystemClock.uptimeNanos();

        mLogger.mCreateTimeNs = SystemClock.elapsedRealtimeNanos();

        controller.mTransitionTracer.logState(this);

    }
@@ -385,6 +385,14 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { 
        return mState == STATE_STARTED;

    }



    boolean isPlaying() {

        return mState == STATE_PLAYING;

    }



    boolean isFinished() {

        return mState == STATE_FINISHED;

    }



    @VisibleForTesting

    void startCollecting(long timeoutMs) {

        startCollecting(timeoutMs, TransitionController.SYNC_METHOD);
@@ -399,7 +407,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { 
        mSyncId = mSyncEngine.startSyncSet(this, timeoutMs, TAG, method);



        mLogger.mSyncId = mSyncId;

        mLogger.mCollectTimeNs = SystemClock.uptimeNanos();

        mLogger.mCollectTimeNs = SystemClock.elapsedRealtimeNanos();

        mController.mTransitionTracer.logState(this);

    }
@@ -419,7 +427,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { 
                mSyncId);

        applyReady();



        mLogger.mStartTimeNs = SystemClock.uptimeNanos();

        mLogger.mStartTimeNs = SystemClock.elapsedRealtimeNanos();

        mController.mTransitionTracer.logState(this);



        mController.updateAnimatingState(mTmpTransaction);
@@ -629,7 +637,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();

        if (ready) mLogger.mReadyTimeNs = SystemClock.elapsedRealtimeNanos();

    }



    /**
@@ -781,7 +789,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { 
            Trace.asyncTraceEnd(TRACE_TAG_WINDOW_MANAGER, TRACE_NAME_PLAY_TRANSITION,

                    System.identityHashCode(this));

        }

        mLogger.mFinishTimeNs = SystemClock.uptimeNanos();

        mLogger.mFinishTimeNs = SystemClock.elapsedRealtimeNanos();

        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
@@ -1117,8 +1125,10 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener { 
            try {

                ProtoLog.v(ProtoLogGroup.WM_DEBUG_WINDOW_TRANSITIONS,

                        "Calling onTransitionReady: %s", info);

                mLogger.mSendTimeNs = SystemClock.uptimeNanos();

                mLogger.mSendTimeNs = SystemClock.elapsedRealtimeNanos();

                mLogger.mInfo = info;

                mController.mTransitionTracer.logSentTransition(

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

                mController.getTransitionPlayer().onTransitionReady(

                        mToken, info, transaction, mFinishTransaction);

                if (Trace.isTagEnabled(TRACE_TAG_WINDOW_MANAGER)) {

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

+1 −1
Original line number Diff line number Diff line
@@ -496,7 +496,7 @@ class TransitionController { 
            }

            final TransitionRequestInfo request = new TransitionRequestInfo(

                    transition.mType, info, remoteTransition, displayChange);

            transition.mLogger.mRequestTimeNs = SystemClock.uptimeNanos();

            transition.mLogger.mRequestTimeNs = SystemClock.elapsedRealtimeNanos();

            transition.mLogger.mRequest = request;

            mTransitionPlayer.requestStartTransition(transition.getToken(), request);

            transition.setRemoteTransition(remoteTransition);

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

+176 −58
Original line number Diff line number Diff line
@@ -21,19 +21,14 @@ 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.Transition.CHANGE;

import static com.android.server.wm.shell.Transition.FINISH_TRANSACTION_ID;

import static com.android.server.wm.shell.Transition.FLAGS;

import static com.android.server.wm.shell.Transition.ID;

import static com.android.server.wm.shell.Transition.START_TRANSACTION_ID;

import static com.android.server.wm.shell.Transition.STATE;

import static com.android.server.wm.shell.Transition.TIMESTAMP;

import static com.android.server.wm.shell.Transition.TRANSITION_TYPE;

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;

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



import android.annotation.NonNull;

import android.annotation.Nullable;
@@ -41,14 +36,15 @@ import android.os.SystemClock; 
import android.os.Trace;

import android.util.Log;

import android.util.proto.ProtoOutputStream;

import android.window.TransitionInfo;



import com.android.internal.util.TraceBuffer;

import com.android.server.wm.Transition.ChangeInfo;

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



import java.io.File;

import java.io.IOException;

import java.io.PrintWriter;

import java.util.ArrayList;



/**

 * Helper class to collect and dump transition traces.
@@ -57,10 +53,8 @@ public class TransitionTracer { 


    private static final String LOG_TAG = "TransitionTracer";



    /**

     * Maximum buffer size, currently defined as 5 MB

     */

    private static final int BUFFER_CAPACITY = 5120 * 1024; // 5 MB

    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 long MAGIC_NUMBER_VALUE = ((long) MAGIC_NUMBER_H << 32) | MAGIC_NUMBER_L;
@@ -68,28 +62,129 @@ public class TransitionTracer { 
    private final TransitionTraceBuffer mTraceBuffer = new TransitionTraceBuffer();



    private final Object mEnabledLock = new Object();

    private volatile boolean mEnabled = false;

    private volatile boolean mActiveTracingEnabled = false;



    /**

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

     * @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

     */

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

            long createTimeNs, long sendTimeNs, TransitionInfo info) {

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

        logTransitionInfo(transition, info);

    }



    private long mTraceStartTimestamp;

    /**

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

        }

        mTraceBuffer.pushTransitionState(transition);

    }



    /**

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

        }

        mTraceBuffer.pushTransitionInfo(transition, info);

    }



    private class TransitionTraceBuffer {

        private final TraceBuffer mBuffer = new TraceBuffer(BUFFER_CAPACITY);

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



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



                final Transition.ChangeInfo target = targets.get(i);



                final int mode = target.getTransitMode(target.mContainer);

                final int layerId;

                if (target.mContainer.mSurfaceControl.isValid()) {

                    layerId = target.mContainer.mSurfaceControl.getLayerId();

                } else {

                    layerId = -1;

                }



                outputStream.write(com.android.server.wm.shell.Target.MODE, mode);

                outputStream.write(com.android.server.wm.shell.Target.LAYER_ID, layerId);



                if (mActiveTracingEnabled) {

                    // What we use in the WM trace

                    final int windowId = System.identityHashCode(target.mContainer);

                    outputStream.write(com.android.server.wm.shell.Target.WINDOW_ID, windowId);

                }



                outputStream.end(changeToken);

            }



            outputStream.end(transitionToken);

            mBuffer.add(outputStream);



            Trace.endSection();

        }



        private void pushTransitionState(Transition transition) {

            Trace.beginSection("TransitionTraceBuffer#pushTransitionState");

            final ProtoOutputStream outputStream = new ProtoOutputStream();

            final long transitionEntryToken = outputStream.start(TRANSITION);



            outputStream.write(ID, transition.getSyncId());

            outputStream.write(TIMESTAMP, SystemClock.elapsedRealtimeNanos());

            outputStream.write(TRANSITION_TYPE, transition.mType);

            outputStream.write(STATE, transition.getState());

            outputStream.write(FLAGS, transition.getFlags());

            if (transition.getStartTransaction() != null) {

                outputStream.write(START_TRANSACTION_ID, transition.getStartTransaction().getId());

            }

            if (transition.getFinishTransaction() != null) {

                outputStream.write(FINISH_TRANSACTION_ID,

                        transition.getFinishTransaction().getId());

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

                writeChange(outputStream, window, changeInfo);

            }



            for (int i = 0; i < transition.mChanges.size(); ++i) {
@@ -98,29 +193,71 @@ public class TransitionTracer { 
                writeChange(outputStream, window, changeInfo);

            }



            outputStream.end(transitionEntryToken);

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

            }



            mBuffer.add(outputStream);

            outputStream.end(stateToken);



            mStateBuffer.add(outputStream);

            Trace.endSection();

        }



        private void pushTransitionInfo(Transition transition, TransitionInfo info) {

            Trace.beginSection("TransitionTraceBuffer#pushTransitionInfo");

            final ProtoOutputStream outputStream = new ProtoOutputStream();

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

                writeTransitionInfoChange(outputStream, change);

            }



            outputStream.end(transitionInfoToken);

            mTransitionInfoBuffer.add(outputStream);

            Trace.endSection();

        }



        private void writeChange(ProtoOutputStream outputStream, WindowContainer window,

                ChangeInfo changeInfo) {

            Trace.beginSection("TransitionProto#addChange");

            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(

                ProtoOutputStream outputStream,

                TransitionInfo.Change change

        ) {

            Trace.beginSection("TransitionTraceBuffer#writeTransitionInfoChange");

            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.end(changeEntryToken);

            Trace.endSection();

        }



        public void writeToFile(File file, ProtoOutputStream proto) throws IOException {

            mBuffer.writeTraceToFile(file, proto);

        }
@@ -130,19 +267,6 @@ public class TransitionTracer { 
        }

    }



    /**

     * 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 (!mEnabled) {

            return;

        }



        Log.d(LOG_TAG, "Logging state of transition " + transition);

        mTraceBuffer.pushTransitionState(transition);

    }



    /**

     * Starts collecting transitions for the trace.

     * If called while a trace is already running, this will reset the trace.
@@ -155,8 +279,8 @@ public class TransitionTracer { 
        Trace.beginSection("TransitionTracer#startTrace");

        LogAndPrintln.i(pw, "Starting shell transition trace.");

        synchronized (mEnabledLock) {

            mTraceStartTimestamp = SystemClock.elapsedRealtime();

            mEnabled = true;

            mActiveTracingEnabled = true;

            mTraceBuffer.mBuffer.setCapacity(ACTIVE_TRACING_BUFFER_CAPACITY);

            mTraceBuffer.reset();

        }

        Trace.endSection();
@@ -183,20 +307,15 @@ public class TransitionTracer { 
        Trace.beginSection("TransitionTracer#stopTrace");

        LogAndPrintln.i(pw, "Stopping shell transition trace.");

        synchronized (mEnabledLock) {

            if (!mEnabled) {

                LogAndPrintln.e(pw,

                        "Error: Tracing can't be stopped because it hasn't been started.");

                return;

            }



            mEnabled = false;

            mActiveTracingEnabled = false;

            writeTraceToFileLocked(pw, outputFile);

            mTraceBuffer.mBuffer.setCapacity(ALWAYS_ON_TRACING_CAPACITY);

        }

        Trace.endSection();

    }



    boolean isEnabled() {

        return mEnabled;

    boolean isActiveTracingEnabled() {

        return mActiveTracingEnabled;

    }



    private void writeTraceToFileLocked(@Nullable PrintWriter pw, File file) {
@@ -204,7 +323,6 @@ public class TransitionTracer { 
        try {

            ProtoOutputStream proto = new ProtoOutputStream();

            proto.write(MAGIC_NUMBER, MAGIC_NUMBER_VALUE);

            proto.write(TransitionTraceProto.TIMESTAMP, mTraceStartTimestamp);

            int pid = android.os.Process.myPid();

            LogAndPrintln.i(pw, "Writing file to " + file.getAbsolutePath()

                    + " from process " + pid);

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

+1 −1
Original line number Diff line number Diff line
@@ -6003,7 +6003,7 @@ public class WindowManagerService extends IWindowManager.Stub 


    @Override

    public boolean isTransitionTraceEnabled() {

        return mTransitionTracer.isEnabled();

        return mTransitionTracer.isActiveTracingEnabled();

    }



    @Override