1 /*
2  * Copyright (C) 2023 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 package com.android.wm.shell.transition;
18 
19 import static android.os.Build.IS_USER;
20 
21 import static com.android.wm.shell.nano.WmShellTransitionTraceProto.MAGIC_NUMBER_H;
22 import static com.android.wm.shell.nano.WmShellTransitionTraceProto.MAGIC_NUMBER_L;
23 
24 import android.annotation.NonNull;
25 import android.annotation.Nullable;
26 import android.os.SystemClock;
27 import android.os.Trace;
28 import android.util.Log;
29 
30 import com.android.internal.util.TraceBuffer;
31 import com.android.wm.shell.sysui.ShellCommandHandler;
32 
33 import com.google.protobuf.nano.MessageNano;
34 
35 import java.io.File;
36 import java.io.IOException;
37 import java.io.OutputStream;
38 import java.io.PrintWriter;
39 import java.util.ArrayList;
40 import java.util.HashMap;
41 import java.util.Map;
42 import java.util.Queue;
43 import java.util.concurrent.TimeUnit;
44 
45 /**
46  * Helper class to collect and dump transition traces.
47  */
48 public class Tracer implements ShellCommandHandler.ShellCommandActionHandler {
49     private static final int ALWAYS_ON_TRACING_CAPACITY = 15 * 1024; // 15 KB
50     private static final int ACTIVE_TRACING_BUFFER_CAPACITY = 5000 * 1024; // 5 MB
51 
52     private static final long MAGIC_NUMBER_VALUE = ((long) MAGIC_NUMBER_H << 32) | MAGIC_NUMBER_L;
53 
54     static final String WINSCOPE_EXT = ".winscope";
55     private static final String TRACE_FILE =
56             "/data/misc/wmtrace/shell_transition_trace" + WINSCOPE_EXT;
57 
58     private final Object mEnabledLock = new Object();
59     private boolean mActiveTracingEnabled = false;
60 
61     private final TraceBuffer.ProtoProvider mProtoProvider =
62             new TraceBuffer.ProtoProvider<MessageNano,
63                 com.android.wm.shell.nano.WmShellTransitionTraceProto,
64                 com.android.wm.shell.nano.Transition>() {
65         @Override
66         public int getItemSize(MessageNano proto) {
67             return proto.getCachedSize();
68         }
69 
70         @Override
71         public byte[] getBytes(MessageNano proto) {
72             return MessageNano.toByteArray(proto);
73         }
74 
75         @Override
76         public void write(
77                 com.android.wm.shell.nano.WmShellTransitionTraceProto encapsulatingProto,
78                 Queue<com.android.wm.shell.nano.Transition> buffer, OutputStream os)
79                         throws IOException {
80             encapsulatingProto.transitions = buffer.toArray(
81                     new com.android.wm.shell.nano.Transition[0]);
82             os.write(getBytes(encapsulatingProto));
83         }
84     };
85     private final TraceBuffer<MessageNano,
86             com.android.wm.shell.nano.WmShellTransitionTraceProto,
87             com.android.wm.shell.nano.Transition> mTraceBuffer
88                     = new TraceBuffer(ALWAYS_ON_TRACING_CAPACITY, mProtoProvider,
89                             (proto) -> handleOnEntryRemovedFromTrace(proto));
90     private final Map<Object, Runnable> mRemovedFromTraceCallbacks = new HashMap<>();
91 
92     private final Map<Transitions.TransitionHandler, Integer> mHandlerIds = new HashMap<>();
93     private final Map<Transitions.TransitionHandler, Integer> mHandlerUseCountInTrace =
94             new HashMap<>();
95 
96     /**
97      * Adds an entry in the trace to log that a transition has been dispatched to a handler.
98      *
99      * @param transitionId The id of the transition being dispatched.
100      * @param handler The handler the transition is being dispatched to.
101      */
logDispatched(int transitionId, Transitions.TransitionHandler handler)102     public void logDispatched(int transitionId, Transitions.TransitionHandler handler) {
103         final int handlerId;
104         if (mHandlerIds.containsKey(handler)) {
105             handlerId = mHandlerIds.get(handler);
106         } else {
107             // + 1 to avoid 0 ids which can be confused with missing value when dumped to proto
108             handlerId = mHandlerIds.size() + 1;
109             mHandlerIds.put(handler, handlerId);
110         }
111 
112         com.android.wm.shell.nano.Transition proto = new com.android.wm.shell.nano.Transition();
113         proto.id = transitionId;
114         proto.dispatchTimeNs = SystemClock.elapsedRealtimeNanos();
115         proto.handler = handlerId;
116 
117         final int useCountAfterAdd = mHandlerUseCountInTrace.getOrDefault(handler, 0) + 1;
118         mHandlerUseCountInTrace.put(handler, useCountAfterAdd);
119 
120         mRemovedFromTraceCallbacks.put(proto, () -> {
121             final int useCountAfterRemove = mHandlerUseCountInTrace.get(handler) - 1;
122             mHandlerUseCountInTrace.put(handler, useCountAfterRemove);
123         });
124 
125         mTraceBuffer.add(proto);
126     }
127 
128     /**
129      * Adds an entry in the trace to log that a request to merge a transition was made.
130      *
131      * @param mergeRequestedTransitionId The id of the transition we are requesting to be merged.
132      * @param playingTransitionId The id of the transition we was to merge the transition into.
133      */
logMergeRequested(int mergeRequestedTransitionId, int playingTransitionId)134     public void logMergeRequested(int mergeRequestedTransitionId, int playingTransitionId) {
135         com.android.wm.shell.nano.Transition proto = new com.android.wm.shell.nano.Transition();
136         proto.id = mergeRequestedTransitionId;
137         proto.mergeRequestTimeNs = SystemClock.elapsedRealtimeNanos();
138         proto.mergedInto = playingTransitionId;
139 
140         mTraceBuffer.add(proto);
141     }
142 
143     /**
144      * Adds an entry in the trace to log that a transition was merged by the handler.
145      *
146      * @param mergedTransitionId The id of the transition that was merged.
147      * @param playingTransitionId The id of the transition the transition was merged into.
148      */
logMerged(int mergedTransitionId, int playingTransitionId)149     public void logMerged(int mergedTransitionId, int playingTransitionId) {
150         com.android.wm.shell.nano.Transition proto = new com.android.wm.shell.nano.Transition();
151         proto.id = mergedTransitionId;
152         proto.mergeTimeNs = SystemClock.elapsedRealtimeNanos();
153         proto.mergedInto = playingTransitionId;
154 
155         mTraceBuffer.add(proto);
156     }
157 
158     /**
159      * Adds an entry in the trace to log that a transition was aborted.
160      *
161      * @param transitionId The id of the transition that was aborted.
162      */
logAborted(int transitionId)163     public void logAborted(int transitionId) {
164         com.android.wm.shell.nano.Transition proto = new com.android.wm.shell.nano.Transition();
165         proto.id = transitionId;
166         proto.abortTimeNs = SystemClock.elapsedRealtimeNanos();
167 
168         mTraceBuffer.add(proto);
169     }
170 
171     /**
172      * Starts collecting transitions for the trace.
173      * If called while a trace is already running, this will reset the trace.
174      */
startTrace(@ullable PrintWriter pw)175     public void startTrace(@Nullable PrintWriter pw) {
176         if (IS_USER) {
177             LogAndPrintln.e(pw, "Tracing is not supported on user builds.");
178             return;
179         }
180         Trace.beginSection("Tracer#startTrace");
181         LogAndPrintln.i(pw, "Starting shell transition trace.");
182         synchronized (mEnabledLock) {
183             mActiveTracingEnabled = true;
184             mTraceBuffer.resetBuffer();
185             mTraceBuffer.setCapacity(ACTIVE_TRACING_BUFFER_CAPACITY);
186         }
187         Trace.endSection();
188     }
189 
190     /**
191      * Stops collecting the transition trace and dump to trace to file.
192      *
193      * Dumps the trace to @link{TRACE_FILE}.
194      */
stopTrace(@ullable PrintWriter pw)195     public void stopTrace(@Nullable PrintWriter pw) {
196         stopTrace(pw, new File(TRACE_FILE));
197     }
198 
199     /**
200      * Stops collecting the transition trace and dump to trace to file.
201      * @param outputFile The file to dump the transition trace to.
202      */
stopTrace(@ullable PrintWriter pw, File outputFile)203     public void stopTrace(@Nullable PrintWriter pw, File outputFile) {
204         if (IS_USER) {
205             LogAndPrintln.e(pw, "Tracing is not supported on user builds.");
206             return;
207         }
208         Trace.beginSection("Tracer#stopTrace");
209         LogAndPrintln.i(pw, "Stopping shell transition trace.");
210         synchronized (mEnabledLock) {
211             mActiveTracingEnabled = false;
212             writeTraceToFileLocked(pw, outputFile);
213             mTraceBuffer.resetBuffer();
214             mTraceBuffer.setCapacity(ALWAYS_ON_TRACING_CAPACITY);
215         }
216         Trace.endSection();
217     }
218 
219     /**
220      * Being called while taking a bugreport so that tracing files can be included in the bugreport.
221      *
222      * @param pw Print writer
223      */
saveForBugreport(@ullable PrintWriter pw)224     public void saveForBugreport(@Nullable PrintWriter pw) {
225         if (IS_USER) {
226             LogAndPrintln.e(pw, "Tracing is not supported on user builds.");
227             return;
228         }
229         Trace.beginSection("TransitionTracer#saveForBugreport");
230         synchronized (mEnabledLock) {
231             final File outputFile = new File(TRACE_FILE);
232             writeTraceToFileLocked(pw, outputFile);
233         }
234         Trace.endSection();
235     }
236 
writeTraceToFileLocked(@ullable PrintWriter pw, File file)237     private void writeTraceToFileLocked(@Nullable PrintWriter pw, File file) {
238         Trace.beginSection("TransitionTracer#writeTraceToFileLocked");
239         try {
240             com.android.wm.shell.nano.WmShellTransitionTraceProto proto =
241                     new com.android.wm.shell.nano.WmShellTransitionTraceProto();
242             proto.magicNumber = MAGIC_NUMBER_VALUE;
243             writeHandlerMappingToProto(proto);
244             long timeOffsetNs =
245                     TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis())
246                             - SystemClock.elapsedRealtimeNanos();
247             proto.realToElapsedTimeOffsetNanos = timeOffsetNs;
248             int pid = android.os.Process.myPid();
249             LogAndPrintln.i(pw, "Writing file to " + file.getAbsolutePath()
250                     + " from process " + pid);
251             mTraceBuffer.writeTraceToFile(file, proto);
252         } catch (IOException e) {
253             LogAndPrintln.e(pw, "Unable to write buffer to file", e);
254         }
255         Trace.endSection();
256     }
257 
writeHandlerMappingToProto( com.android.wm.shell.nano.WmShellTransitionTraceProto proto)258     private void writeHandlerMappingToProto(
259             com.android.wm.shell.nano.WmShellTransitionTraceProto proto) {
260         ArrayList<com.android.wm.shell.nano.HandlerMapping> handlerMappings = new ArrayList<>();
261         for (Transitions.TransitionHandler handler : mHandlerUseCountInTrace.keySet()) {
262             final int count = mHandlerUseCountInTrace.get(handler);
263             if (count > 0) {
264                 com.android.wm.shell.nano.HandlerMapping mapping =
265                         new com.android.wm.shell.nano.HandlerMapping();
266                 mapping.id = mHandlerIds.get(handler);
267                 mapping.name = handler.getClass().getName();
268                 handlerMappings.add(mapping);
269             }
270         }
271         proto.handlerMappings = handlerMappings.toArray(
272                 new com.android.wm.shell.nano.HandlerMapping[0]);
273     }
274 
handleOnEntryRemovedFromTrace(Object proto)275     private void handleOnEntryRemovedFromTrace(Object proto) {
276         if (mRemovedFromTraceCallbacks.containsKey(proto)) {
277             mRemovedFromTraceCallbacks.get(proto).run();
278             mRemovedFromTraceCallbacks.remove(proto);
279         }
280     }
281 
282     @Override
onShellCommand(String[] args, PrintWriter pw)283     public boolean onShellCommand(String[] args, PrintWriter pw) {
284         switch (args[0]) {
285             case "start": {
286                 startTrace(pw);
287                 return true;
288             }
289             case "stop": {
290                 stopTrace(pw);
291                 return true;
292             }
293             case "save-for-bugreport": {
294                 saveForBugreport(pw);
295                 return true;
296             }
297             default: {
298                 pw.println("Invalid command: " + args[0]);
299                 printShellCommandHelp(pw, "");
300                 return false;
301             }
302         }
303     }
304 
305     @Override
printShellCommandHelp(PrintWriter pw, String prefix)306     public void printShellCommandHelp(PrintWriter pw, String prefix) {
307         pw.println(prefix + "start");
308         pw.println(prefix + "  Start tracing the transitions.");
309         pw.println(prefix + "stop");
310         pw.println(prefix + "  Stop tracing the transitions.");
311         pw.println(prefix + "save-for-bugreport");
312         pw.println(prefix + "  Flush in memory transition trace to file.");
313     }
314 
315     private static class LogAndPrintln {
316         private static final String LOG_TAG = "ShellTransitionTracer";
317 
i(@ullable PrintWriter pw, String msg)318         private static void i(@Nullable PrintWriter pw, String msg) {
319             Log.i(LOG_TAG, msg);
320             if (pw != null) {
321                 pw.println(msg);
322                 pw.flush();
323             }
324         }
325 
e(@ullable PrintWriter pw, String msg)326         private static void e(@Nullable PrintWriter pw, String msg) {
327             Log.e(LOG_TAG, msg);
328             if (pw != null) {
329                 pw.println("ERROR: " + msg);
330                 pw.flush();
331             }
332         }
333 
e(@ullable PrintWriter pw, String msg, @NonNull Exception e)334         private static void e(@Nullable PrintWriter pw, String msg, @NonNull Exception e) {
335             Log.e(LOG_TAG, msg, e);
336             if (pw != null) {
337                 pw.println("ERROR: " + msg + " ::\n " + e);
338                 pw.flush();
339             }
340         }
341     }
342 }
343