Add transition trace on shell side

Test: Collect trace and load in Winscope Bug: 277181336 Change-Id: I9d1cd3e49be42b7c7cadf1c810b0a10407135d70
2023-04-14 15:31:46 +00:00
parent 741ed97ad4
commit 909c8edd99
5 changed files with 338 additions and 1 deletions
--- a/core/java/com/android/internal/util/TraceBuffer.java
+++ b/core/java/com/android/internal/util/TraceBuffer.java
@@ -103,6 +103,10 @@ public class TraceBuffer<P, S extends P, T extends P> {
        this(bufferCapacity, new ProtoOutputStreamProvider(), null);
    }

+    public TraceBuffer(int bufferCapacity, Consumer<T> protoDequeuedCallback) {
+        this(bufferCapacity, new ProtoOutputStreamProvider(), protoDequeuedCallback);
+    }
+
    public TraceBuffer(int bufferCapacity, ProtoProvider protoProvider,
            Consumer<T> protoDequeuedCallback) {
        mBufferCapacity = bufferCapacity;
--- a/libs/WindowManager/Shell/Android.bp
+++ b/libs/WindowManager/Shell/Android.bp
@@ -125,6 +125,34 @@ prebuilt_etc {

 // End ProtoLog

+gensrcs {
+    name: "wm-shell-protos",
+
+    tools: [
+        "aprotoc",
+        "protoc-gen-javastream",
+        "soong_zip",
+    ],
+
+    tool_files: [
+        ":libprotobuf-internal-protos",
+    ],
+
+    cmd: "mkdir -p $(genDir)/$(in) " +
+        "&& $(location aprotoc) " +
+        "  --plugin=$(location protoc-gen-javastream) " +
+        "  --javastream_out=$(genDir)/$(in) " +
+        "  -Iexternal/protobuf/src " +
+        "  -I . " +
+        "  $(in) " +
+        "&& $(location soong_zip) -jar -o $(out) -C $(genDir)/$(in) -D $(genDir)/$(in)",
+
+    srcs: [
+        "proto/**/*.proto",
+    ],
+    output_extension: "srcjar",
+}
+
 java_library {
    name: "WindowManager-Shell-proto",

@@ -142,6 +170,7 @@ android_library {
        // TODO(b/168581922) protologtool do not support kotlin(*.kt)
        ":wm_shell-sources-kt",
        ":wm_shell-aidls",
+        ":wm-shell-protos",
    ],
    resource_dirs: [
        "res",
--- a/libs/WindowManager/Shell/proto/wm_shell_transition_trace.proto
+++ b/libs/WindowManager/Shell/proto/wm_shell_transition_trace.proto
@@ -0,0 +1,55 @@
+/*
+ * Copyright (C) 2020 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+syntax = "proto2";
+
+package com.android.wm.shell;
+
+option java_multiple_files = true;
+
+/* Represents a file full of transition entries.
+   Encoded, it should start with 0x09 0x57 0x4D 0x53 0x54 0x52 0x41 0x43 0x45 (.WMSTRACE), such
+   that it can be easily identified. */
+message WmShellTransitionTraceProto {
+    /* constant; MAGIC_NUMBER = (long) MAGIC_NUMBER_H << 32 | MagicNumber.MAGIC_NUMBER_L
+   (this is needed because enums have to be 32 bits and there's no nice way to put 64bit
+    constants into .proto files. */
+    enum MagicNumber {
+        INVALID = 0;
+        MAGIC_NUMBER_L = 0x54534D57;  /* WMST (little-endian ASCII) */
+        MAGIC_NUMBER_H = 0x45434152;  /* RACE (little-endian ASCII) */
+    }
+
+    // Must be the first field, set to value in MagicNumber
+    required fixed64 magic_number = 1;
+    repeated Transition transitions = 2;
+    repeated HandlerMapping handlerMappings = 3;
+}
+
+message Transition {
+    required int32 id = 1;
+    optional int64 dispatch_time_ns = 2;
+    optional int32 handler = 3;
+    optional int64 merge_time_ns = 4;
+    optional int64 merge_request_time_ns = 5;
+    optional int32 merged_into = 6;
+    optional int64 abort_time_ns = 7;
+}
+
+message HandlerMapping {
+    required int32 id = 1;
+    required string name = 2;
+}
--- a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Tracer.java
+++ b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Tracer.java
@@ -0,0 +1,243 @@
+/*
+ * Copyright (C) 2023 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.android.wm.shell.transition;
+
+import static android.os.Build.IS_USER;
+
+import static com.android.wm.shell.WmShellTransitionTraceProto.MAGIC_NUMBER;
+import static com.android.wm.shell.WmShellTransitionTraceProto.MAGIC_NUMBER_H;
+import static com.android.wm.shell.WmShellTransitionTraceProto.MAGIC_NUMBER_L;
+
+import android.annotation.NonNull;
+import android.annotation.Nullable;
+import android.os.SystemClock;
+import android.os.Trace;
+import android.util.Log;
+import android.util.proto.ProtoOutputStream;
+
+import com.android.internal.util.TraceBuffer;
+
+import java.io.File;
+import java.io.IOException;
+import java.io.PrintWriter;
+import java.util.HashMap;
+import java.util.Map;
+
+/**
+ * Helper class to collect and dump transition traces.
+ */
+public class Tracer {
+    private static final int ALWAYS_ON_TRACING_CAPACITY = 15 * 1024; // 15 KB
+
+    private static final long MAGIC_NUMBER_VALUE = ((long) MAGIC_NUMBER_H << 32) | MAGIC_NUMBER_L;
+
+    static final String WINSCOPE_EXT = ".winscope";
+    private static final String TRACE_FILE =
+            "/data/misc/wmtrace/shell_transition_trace" + WINSCOPE_EXT;
+
+    private final Object mEnabledLock = new Object();
+
+    private final TraceBuffer mTraceBuffer = new TraceBuffer(ALWAYS_ON_TRACING_CAPACITY,
+            (proto) -> handleOnEntryRemovedFromTrace(proto));
+    private final Map<Object, Runnable> mRemovedFromTraceCallbacks = new HashMap<>();
+
+    private final Map<Transitions.TransitionHandler, Integer> mHandlerIds = new HashMap<>();
+    private final Map<Transitions.TransitionHandler, Integer> mHandlerUseCountInTrace =
+            new HashMap<>();
+
+    /**
+     * Adds an entry in the trace to log that a transition has been dispatched to a handler.
+     *
+     * @param transitionId The id of the transition being dispatched.
+     * @param handler The handler the transition is being dispatched to.
+     */
+    public void logDispatched(int transitionId, Transitions.TransitionHandler handler) {
+        final int handlerId;
+        if (mHandlerIds.containsKey(handler)) {
+            handlerId = mHandlerIds.get(handler);
+        } else {
+            handlerId = mHandlerIds.size();
+            mHandlerIds.put(handler, handlerId);
+        }
+
+        ProtoOutputStream outputStream = new ProtoOutputStream();
+        final long protoToken =
+                outputStream.start(com.android.wm.shell.WmShellTransitionTraceProto.TRANSITIONS);
+
+        outputStream.write(com.android.wm.shell.Transition.ID, transitionId);
+        outputStream.write(com.android.wm.shell.Transition.DISPATCH_TIME_NS,
+                SystemClock.elapsedRealtimeNanos());
+        outputStream.write(com.android.wm.shell.Transition.HANDLER, handlerId);
+
+        outputStream.end(protoToken);
+
+        final int useCountAfterAdd = mHandlerUseCountInTrace.getOrDefault(handler, 0) + 1;
+        mHandlerUseCountInTrace.put(handler, useCountAfterAdd);
+
+        mRemovedFromTraceCallbacks.put(outputStream, () -> {
+            final int useCountAfterRemove = mHandlerUseCountInTrace.get(handler) - 1;
+            mHandlerUseCountInTrace.put(handler, useCountAfterRemove);
+        });
+
+        mTraceBuffer.add(outputStream);
+    }
+
+    /**
+     * Adds an entry in the trace to log that a request to merge a transition was made.
+     *
+     * @param mergeRequestedTransitionId The id of the transition we are requesting to be merged.
+     * @param playingTransitionId The id of the transition we was to merge the transition into.
+     */
+    public void logMergeRequested(int mergeRequestedTransitionId, int playingTransitionId) {
+        ProtoOutputStream outputStream = new ProtoOutputStream();
+        final long protoToken =
+                outputStream.start(com.android.wm.shell.WmShellTransitionTraceProto.TRANSITIONS);
+
+        outputStream.write(com.android.wm.shell.Transition.ID, mergeRequestedTransitionId);
+        outputStream.write(com.android.wm.shell.Transition.MERGE_REQUEST_TIME_NS,
+                SystemClock.elapsedRealtimeNanos());
+        outputStream.write(com.android.wm.shell.Transition.MERGED_INTO, playingTransitionId);
+
+        outputStream.end(protoToken);
+
+        mTraceBuffer.add(outputStream);
+    }
+
+    /**
+     * Adds an entry in the trace to log that a transition was merged by the handler.
+     *
+     * @param mergedTransitionId The id of the transition that was merged.
+     * @param playingTransitionId The id of the transition the transition was merged into.
+     */
+    public void logMerged(int mergedTransitionId, int playingTransitionId) {
+        ProtoOutputStream outputStream = new ProtoOutputStream();
+        final long protoToken =
+                outputStream.start(com.android.wm.shell.WmShellTransitionTraceProto.TRANSITIONS);
+
+        outputStream.write(com.android.wm.shell.Transition.ID, mergedTransitionId);
+        outputStream.write(
+                com.android.wm.shell.Transition.MERGE_TIME_NS, SystemClock.elapsedRealtimeNanos());
+        outputStream.write(com.android.wm.shell.Transition.MERGED_INTO, playingTransitionId);
+
+        outputStream.end(protoToken);
+
+        mTraceBuffer.add(outputStream);
+    }
+
+    /**
+     * Adds an entry in the trace to log that a transition was aborted.
+     *
+     * @param transitionId The id of the transition that was aborted.
+     */
+    public void logAborted(int transitionId) {
+        ProtoOutputStream outputStream = new ProtoOutputStream();
+        final long protoToken =
+                outputStream.start(com.android.wm.shell.WmShellTransitionTraceProto.TRANSITIONS);
+
+        outputStream.write(com.android.wm.shell.Transition.ID, transitionId);
+        outputStream.write(
+                com.android.wm.shell.Transition.ABORT_TIME_NS, SystemClock.elapsedRealtimeNanos());
+
+        outputStream.end(protoToken);
+
+        mTraceBuffer.add(outputStream);
+    }
+
+    /**
+     * Being called while taking a bugreport so that tracing files can be included in the bugreport.
+     *
+     * @param pw Print writer
+     */
+    public void saveForBugreport(@Nullable PrintWriter pw) {
+        if (IS_USER) {
+            LogAndPrintln.e(pw, "Tracing is not supported on user builds.");
+            return;
+        }
+        Trace.beginSection("TransitionTracer#saveForBugreport");
+        synchronized (mEnabledLock) {
+            final File outputFile = new File(TRACE_FILE);
+            writeTraceToFileLocked(pw, outputFile);
+        }
+        Trace.endSection();
+    }
+
+    private void writeTraceToFileLocked(@Nullable PrintWriter pw, File file) {
+        Trace.beginSection("TransitionTracer#writeTraceToFileLocked");
+        try {
+            ProtoOutputStream proto = new ProtoOutputStream();
+            proto.write(MAGIC_NUMBER, MAGIC_NUMBER_VALUE);
+            writeHandlerMappingToProto(proto);
+            int pid = android.os.Process.myPid();
+            LogAndPrintln.i(pw, "Writing file to " + file.getAbsolutePath()
+                    + " from process " + pid);
+            mTraceBuffer.writeTraceToFile(file, proto);
+        } catch (IOException e) {
+            LogAndPrintln.e(pw, "Unable to write buffer to file", e);
+        }
+        Trace.endSection();
+    }
+
+    private void writeHandlerMappingToProto(ProtoOutputStream outputStream) {
+        for (Transitions.TransitionHandler handler : mHandlerUseCountInTrace.keySet()) {
+            final int count = mHandlerUseCountInTrace.get(handler);
+            if (count > 0) {
+                final long protoToken = outputStream.start(
+                        com.android.wm.shell.WmShellTransitionTraceProto.HANDLER_MAPPINGS);
+                outputStream.write(com.android.wm.shell.HandlerMapping.ID,
+                        mHandlerIds.get(handler));
+                outputStream.write(com.android.wm.shell.HandlerMapping.NAME,
+                        handler.getClass().getName());
+                outputStream.end(protoToken);
+            }
+        }
+    }
+
+    private void handleOnEntryRemovedFromTrace(Object proto) {
+        if (mRemovedFromTraceCallbacks.containsKey(proto)) {
+            mRemovedFromTraceCallbacks.get(proto).run();
+            mRemovedFromTraceCallbacks.remove(proto);
+        }
+    }
+
+    private static class LogAndPrintln {
+        private static final String LOG_TAG = "ShellTransitionTracer";
+
+        private static void i(@Nullable PrintWriter pw, String msg) {
+            Log.i(LOG_TAG, msg);
+            if (pw != null) {
+                pw.println(msg);
+                pw.flush();
+            }
+        }
+
+        private static void e(@Nullable PrintWriter pw, String msg) {
+            Log.e(LOG_TAG, msg);
+            if (pw != null) {
+                pw.println("ERROR: " + msg);
+                pw.flush();
+            }
+        }
+
+        private static void e(@Nullable PrintWriter pw, String msg, @NonNull Exception e) {
+            Log.e(LOG_TAG, msg, e);
+            if (pw != null) {
+                pw.println("ERROR: " + msg + " ::\n " + e);
+                pw.flush();
+            }
+        }
+    }
+}
--- a/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Transitions.java
+++ b/libs/WindowManager/Shell/src/com/android/wm/shell/transition/Transitions.java
@@ -165,7 +165,7 @@ public class Transitions implements RemoteCallable<Transitions> {
    private final ShellController mShellController;
    private final ShellTransitionImpl mImpl = new ShellTransitionImpl();
    private final SleepHandler mSleepHandler = new SleepHandler();
-
+    private final Tracer mTracer = new Tracer();
    private boolean mIsRegistered = false;

    /** List of possible handlers. Ordered by specificity (eg. tapped back to front). */
@@ -783,6 +783,7 @@ public class Transitions implements RemoteCallable<Transitions> {
        ProtoLog.v(ShellProtoLogGroup.WM_SHELL_TRANSITIONS, "Transition %s ready while"
                + " %s is still animating. Notify the animating transition"
                + " in case they can be merged", ready, playing);
+        mTracer.logMergeRequested(ready.mInfo.getDebugId(), playing.mInfo.getDebugId());
        playing.mHandler.mergeAnimation(ready.mToken, ready.mInfo, ready.mStartT,
                playing.mToken, (wct, cb) -> onMerged(playing, ready));
    }
@@ -816,6 +817,7 @@ public class Transitions implements RemoteCallable<Transitions> {
        for (int i = 0; i < mObservers.size(); ++i) {
            mObservers.get(i).onTransitionMerged(merged.mToken, playing.mToken);
        }
+        mTracer.logMerged(merged.mInfo.getDebugId(), playing.mInfo.getDebugId());
        // See if we should merge another transition.
        processReadyQueue(track);
    }
@@ -842,6 +844,8 @@ public class Transitions implements RemoteCallable<Transitions> {
        // Otherwise give every other handler a chance
        active.mHandler = dispatchTransition(active.mToken, active.mInfo, active.mStartT,
                active.mFinishT, (wct, cb) -> onFinish(active, wct, cb), active.mHandler);
+
+        mTracer.logDispatched(active.mInfo.getDebugId(), active.mHandler);
    }

    /**
@@ -893,6 +897,8 @@ public class Transitions implements RemoteCallable<Transitions> {
        transition.mFinishT.apply();
        transition.mAborted = true;

+        mTracer.logAborted(transition.mInfo.getDebugId());
+
        if (transition.mHandler != null) {
            // Notifies to clean-up the aborted transition.
            transition.mHandler.onTransitionConsumed(