1 /*
2  * Copyright (C) 2022 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.server.wm;
18 
19 import static android.os.Build.IS_USER;
20 
21 import static com.android.server.wm.shell.TransitionTraceProto.MAGIC_NUMBER;
22 import static com.android.server.wm.shell.TransitionTraceProto.MAGIC_NUMBER_H;
23 import static com.android.server.wm.shell.TransitionTraceProto.MAGIC_NUMBER_L;
24 import static com.android.server.wm.shell.TransitionTraceProto.REAL_TO_ELAPSED_TIME_OFFSET_NANOS;
25 
26 import android.annotation.NonNull;
27 import android.annotation.Nullable;
28 import android.os.SystemClock;
29 import android.os.Trace;
30 import android.util.Log;
31 import android.util.proto.ProtoOutputStream;
32 
33 import com.android.internal.util.TraceBuffer;
34 import com.android.server.wm.Transition.ChangeInfo;
35 
36 import java.io.File;
37 import java.io.IOException;
38 import java.io.PrintWriter;
39 import java.util.ArrayList;
40 import java.util.concurrent.TimeUnit;
41 
42 /**
43  * Helper class to collect and dump transition traces.
44  */
45 public class TransitionTracer {
46 
47     private static final String LOG_TAG = "TransitionTracer";
48 
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     // This will be the size the proto output streams are initialized to.
53     // Ideally this should fit most or all the proto objects we will create and be no bigger than
54     // that to ensure to don't use excessive amounts of memory.
55     private static final int CHUNK_SIZE = 64;
56 
57     static final String WINSCOPE_EXT = ".winscope";
58     private static final String TRACE_FILE =
59             "/data/misc/wmtrace/wm_transition_trace" + WINSCOPE_EXT;
60     private static final long MAGIC_NUMBER_VALUE = ((long) MAGIC_NUMBER_H << 32) | MAGIC_NUMBER_L;
61 
62     private final TraceBuffer mTraceBuffer = new TraceBuffer(ALWAYS_ON_TRACING_CAPACITY);
63 
64     private final Object mEnabledLock = new Object();
65     private volatile boolean mActiveTracingEnabled = false;
66 
67     /**
68      * Records key information about a transition that has been sent to Shell to be played.
69      * More information will be appended to the same proto object once the transition is finished or
70      * aborted.
71      * Transition information won't be added to the trace buffer until
72      * {@link #logFinishedTransition} or {@link #logAbortedTransition} is called for this
73      * transition.
74      *
75      * @param transition The transition that has been sent to Shell.
76      * @param targets Information about the target windows of the transition.
77      */
logSentTransition(Transition transition, ArrayList<ChangeInfo> targets)78     public void logSentTransition(Transition transition, ArrayList<ChangeInfo> targets) {
79         try {
80             final ProtoOutputStream outputStream = new ProtoOutputStream(CHUNK_SIZE);
81             final long protoToken = outputStream
82                     .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITIONS);
83             outputStream.write(com.android.server.wm.shell.Transition.ID, transition.getSyncId());
84             outputStream.write(com.android.server.wm.shell.Transition.CREATE_TIME_NS,
85                     transition.mLogger.mCreateTimeNs);
86             outputStream.write(com.android.server.wm.shell.Transition.SEND_TIME_NS,
87                     transition.mLogger.mSendTimeNs);
88             outputStream.write(com.android.server.wm.shell.Transition.START_TRANSACTION_ID,
89                     transition.getStartTransaction().getId());
90             outputStream.write(com.android.server.wm.shell.Transition.FINISH_TRANSACTION_ID,
91                     transition.getFinishTransaction().getId());
92             dumpTransitionTargetsToProto(outputStream, transition, targets);
93             outputStream.end(protoToken);
94 
95             mTraceBuffer.add(outputStream);
96         } catch (Exception e) {
97             // Don't let any errors in the tracing cause the transition to fail
98             Log.e(LOG_TAG, "Unexpected exception thrown while logging transitions", e);
99         }
100     }
101 
102     /**
103      * Completes the information dumped in {@link #logSentTransition} for a transition
104      * that has finished or aborted, and add the proto object to the trace buffer.
105      *
106      * @param transition The transition that has finished.
107      */
logFinishedTransition(Transition transition)108     public void logFinishedTransition(Transition transition) {
109         try {
110             final ProtoOutputStream outputStream = new ProtoOutputStream(CHUNK_SIZE);
111             final long protoToken = outputStream
112                     .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITIONS);
113             outputStream.write(com.android.server.wm.shell.Transition.ID, transition.getSyncId());
114             outputStream.write(com.android.server.wm.shell.Transition.FINISH_TIME_NS,
115                     transition.mLogger.mFinishTimeNs);
116             outputStream.end(protoToken);
117 
118             mTraceBuffer.add(outputStream);
119         } catch (Exception e) {
120             // Don't let any errors in the tracing cause the transition to fail
121             Log.e(LOG_TAG, "Unexpected exception thrown while logging transitions", e);
122         }
123     }
124 
125     /**
126      * Same as {@link #logFinishedTransition} but don't add the transition to the trace buffer
127      * unless actively tracing.
128      *
129      * @param transition The transition that has been aborted
130      */
logAbortedTransition(Transition transition)131     public void logAbortedTransition(Transition transition) {
132         try {
133             final ProtoOutputStream outputStream = new ProtoOutputStream(CHUNK_SIZE);
134             final long protoToken = outputStream
135                     .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITIONS);
136             outputStream.write(com.android.server.wm.shell.Transition.ID, transition.getSyncId());
137             outputStream.write(com.android.server.wm.shell.Transition.ABORT_TIME_NS,
138                     transition.mLogger.mAbortTimeNs);
139             outputStream.end(protoToken);
140 
141             mTraceBuffer.add(outputStream);
142         } catch (Exception e) {
143             // Don't let any errors in the tracing cause the transition to fail
144             Log.e(LOG_TAG, "Unexpected exception thrown while logging transitions", e);
145         }
146     }
147 
logRemovingStartingWindow(@onNull StartingData startingData)148     void logRemovingStartingWindow(@NonNull StartingData startingData) {
149         if (startingData.mTransitionId == 0) {
150             return;
151         }
152         try {
153             final ProtoOutputStream outputStream = new ProtoOutputStream(CHUNK_SIZE);
154             final long protoToken = outputStream
155                     .start(com.android.server.wm.shell.TransitionTraceProto.TRANSITIONS);
156             outputStream.write(com.android.server.wm.shell.Transition.ID,
157                     startingData.mTransitionId);
158             outputStream.write(
159                     com.android.server.wm.shell.Transition.STARTING_WINDOW_REMOVE_TIME_NS,
160                     SystemClock.elapsedRealtimeNanos());
161             outputStream.end(protoToken);
162 
163             mTraceBuffer.add(outputStream);
164         } catch (Exception e) {
165             Log.e(LOG_TAG, "Unexpected exception thrown while logging transitions", e);
166         }
167     }
168 
dumpTransitionTargetsToProto(ProtoOutputStream outputStream, Transition transition, ArrayList<ChangeInfo> targets)169     private void dumpTransitionTargetsToProto(ProtoOutputStream outputStream,
170             Transition transition, ArrayList<ChangeInfo> targets) {
171         Trace.beginSection("TransitionTracer#dumpTransitionTargetsToProto");
172         if (mActiveTracingEnabled) {
173             outputStream.write(com.android.server.wm.shell.Transition.ID,
174                     transition.getSyncId());
175         }
176 
177         outputStream.write(com.android.server.wm.shell.Transition.TYPE, transition.mType);
178         outputStream.write(com.android.server.wm.shell.Transition.FLAGS, transition.getFlags());
179 
180         for (int i = 0; i < targets.size(); ++i) {
181             final long changeToken = outputStream
182                     .start(com.android.server.wm.shell.Transition.TARGETS);
183 
184             final Transition.ChangeInfo target = targets.get(i);
185 
186             final int layerId;
187             if (target.mContainer.mSurfaceControl.isValid()) {
188                 layerId = target.mContainer.mSurfaceControl.getLayerId();
189             } else {
190                 layerId = -1;
191             }
192 
193             outputStream.write(com.android.server.wm.shell.Target.MODE, target.mReadyMode);
194             outputStream.write(com.android.server.wm.shell.Target.FLAGS, target.mReadyFlags);
195             outputStream.write(com.android.server.wm.shell.Target.LAYER_ID, layerId);
196 
197             if (mActiveTracingEnabled) {
198                 // What we use in the WM trace
199                 final int windowId = System.identityHashCode(target.mContainer);
200                 outputStream.write(com.android.server.wm.shell.Target.WINDOW_ID, windowId);
201             }
202 
203             outputStream.end(changeToken);
204         }
205 
206         Trace.endSection();
207     }
208 
209     /**
210      * Starts collecting transitions for the trace.
211      * If called while a trace is already running, this will reset the trace.
212      */
startTrace(@ullable PrintWriter pw)213     public void startTrace(@Nullable PrintWriter pw) {
214         if (IS_USER) {
215             LogAndPrintln.e(pw, "Tracing is not supported on user builds.");
216             return;
217         }
218         Trace.beginSection("TransitionTracer#startTrace");
219         LogAndPrintln.i(pw, "Starting shell transition trace.");
220         synchronized (mEnabledLock) {
221             mActiveTracingEnabled = true;
222             mTraceBuffer.resetBuffer();
223             mTraceBuffer.setCapacity(ACTIVE_TRACING_BUFFER_CAPACITY);
224         }
225         Trace.endSection();
226     }
227 
228     /**
229      * Stops collecting the transition trace and dump to trace to file.
230      *
231      * Dumps the trace to @link{TRACE_FILE}.
232      */
stopTrace(@ullable PrintWriter pw)233     public void stopTrace(@Nullable PrintWriter pw) {
234         stopTrace(pw, new File(TRACE_FILE));
235     }
236 
237     /**
238      * Stops collecting the transition trace and dump to trace to file.
239      * @param outputFile The file to dump the transition trace to.
240      */
stopTrace(@ullable PrintWriter pw, File outputFile)241     public void stopTrace(@Nullable PrintWriter pw, File outputFile) {
242         if (IS_USER) {
243             LogAndPrintln.e(pw, "Tracing is not supported on user builds.");
244             return;
245         }
246         Trace.beginSection("TransitionTracer#stopTrace");
247         LogAndPrintln.i(pw, "Stopping shell transition trace.");
248         synchronized (mEnabledLock) {
249             mActiveTracingEnabled = false;
250             writeTraceToFileLocked(pw, outputFile);
251             mTraceBuffer.resetBuffer();
252             mTraceBuffer.setCapacity(ALWAYS_ON_TRACING_CAPACITY);
253         }
254         Trace.endSection();
255     }
256 
257     /**
258      * Being called while taking a bugreport so that tracing files can be included in the bugreport.
259      *
260      * @param pw Print writer
261      */
saveForBugreport(@ullable PrintWriter pw)262     public void saveForBugreport(@Nullable PrintWriter pw) {
263         if (IS_USER) {
264             LogAndPrintln.e(pw, "Tracing is not supported on user builds.");
265             return;
266         }
267         Trace.beginSection("TransitionTracer#saveForBugreport");
268         synchronized (mEnabledLock) {
269             final File outputFile = new File(TRACE_FILE);
270             writeTraceToFileLocked(pw, outputFile);
271         }
272         Trace.endSection();
273     }
274 
isActiveTracingEnabled()275     boolean isActiveTracingEnabled() {
276         return mActiveTracingEnabled;
277     }
278 
writeTraceToFileLocked(@ullable PrintWriter pw, File file)279     private void writeTraceToFileLocked(@Nullable PrintWriter pw, File file) {
280         Trace.beginSection("TransitionTracer#writeTraceToFileLocked");
281         try {
282             ProtoOutputStream proto = new ProtoOutputStream(CHUNK_SIZE);
283             proto.write(MAGIC_NUMBER, MAGIC_NUMBER_VALUE);
284             long timeOffsetNs =
285                     TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis())
286                             - SystemClock.elapsedRealtimeNanos();
287             proto.write(REAL_TO_ELAPSED_TIME_OFFSET_NANOS, timeOffsetNs);
288             int pid = android.os.Process.myPid();
289             LogAndPrintln.i(pw, "Writing file to " + file.getAbsolutePath()
290                     + " from process " + pid);
291             mTraceBuffer.writeTraceToFile(file, proto);
292         } catch (IOException e) {
293             LogAndPrintln.e(pw, "Unable to write buffer to file", e);
294         }
295         Trace.endSection();
296     }
297 
298     private static class LogAndPrintln {
i(@ullable PrintWriter pw, String msg)299         private static void i(@Nullable PrintWriter pw, String msg) {
300             Log.i(LOG_TAG, msg);
301             if (pw != null) {
302                 pw.println(msg);
303                 pw.flush();
304             }
305         }
306 
e(@ullable PrintWriter pw, String msg)307         private static void e(@Nullable PrintWriter pw, String msg) {
308             Log.e(LOG_TAG, msg);
309             if (pw != null) {
310                 pw.println("ERROR: " + msg);
311                 pw.flush();
312             }
313         }
314 
e(@ullable PrintWriter pw, String msg, @NonNull Exception e)315         private static void e(@Nullable PrintWriter pw, String msg, @NonNull Exception e) {
316             Log.e(LOG_TAG, msg, e);
317             if (pw != null) {
318                 pw.println("ERROR: " + msg + " ::\n " + e);
319                 pw.flush();
320             }
321         }
322     }
323 }
324