1 /*
2  * Copyright (C) 2017 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.WindowManagerTraceFileProto.ENTRY;
22 import static com.android.server.wm.WindowManagerTraceProto.ELAPSED_REALTIME_NANOS;
23 import static com.android.server.wm.WindowManagerTraceProto.WHERE;
24 import static com.android.server.wm.WindowManagerTraceProto.WINDOW_MANAGER_SERVICE;
25 
26 import android.annotation.Nullable;
27 import android.os.ShellCommand;
28 import android.os.SystemClock;
29 import android.os.Trace;
30 import android.util.Log;
31 import android.util.proto.ProtoOutputStream;
32 import android.view.Choreographer;
33 
34 import java.io.File;
35 import java.io.IOException;
36 import java.io.PrintWriter;
37 
38 /**
39  * A class that allows window manager to dump its state continuously to a trace file, such that a
40  * time series of window manager state can be analyzed after the fact.
41  */
42 class WindowTracing {
43 
44     /**
45      * Maximum buffer size, currently defined as 512 KB
46      * Size was experimentally defined to fit between 100 to 150 elements.
47      */
48     private static final int BUFFER_CAPACITY_CRITICAL = 512 * 1024;
49     private static final int BUFFER_CAPACITY_TRIM = 2048 * 1024;
50     private static final int BUFFER_CAPACITY_ALL = 4096 * 1024;
51     private static final String TRACE_FILENAME = "/data/misc/wmtrace/wm_trace.pb";
52     private static final String TAG = "WindowTracing";
53 
54     private final WindowManagerService mService;
55     private final Choreographer mChoreographer;
56     private final WindowManagerGlobalLock mGlobalLock;
57 
58     private final Object mEnabledLock = new Object();
59     private final File mTraceFile;
60     private final WindowTraceBuffer mBuffer;
61     private final Choreographer.FrameCallback mFrameCallback = (frameTimeNanos) ->
62             log("onFrame" /* where */);
63 
64     private @WindowTraceLogLevel int mLogLevel = WindowTraceLogLevel.TRIM;
65     private boolean mLogOnFrame = false;
66     private boolean mEnabled;
67     private volatile boolean mEnabledLockFree;
68     private boolean mScheduled;
69 
createDefaultAndStartLooper(WindowManagerService service, Choreographer choreographer)70     static WindowTracing createDefaultAndStartLooper(WindowManagerService service,
71             Choreographer choreographer) {
72         File file = new File(TRACE_FILENAME);
73         return new WindowTracing(file, service, choreographer, BUFFER_CAPACITY_TRIM);
74     }
75 
WindowTracing(File file, WindowManagerService service, Choreographer choreographer, int bufferCapacity)76     private WindowTracing(File file, WindowManagerService service, Choreographer choreographer,
77             int bufferCapacity) {
78         this(file, service, choreographer, service.mGlobalLock, bufferCapacity);
79     }
80 
WindowTracing(File file, WindowManagerService service, Choreographer choreographer, WindowManagerGlobalLock globalLock, int bufferCapacity)81     WindowTracing(File file, WindowManagerService service, Choreographer choreographer,
82             WindowManagerGlobalLock globalLock, int bufferCapacity) {
83         mChoreographer = choreographer;
84         mService = service;
85         mGlobalLock = globalLock;
86         mTraceFile = file;
87         mBuffer = new WindowTraceBuffer(bufferCapacity);
88         setLogLevel(WindowTraceLogLevel.TRIM, null /* pw */);
89     }
90 
startTrace(@ullable PrintWriter pw)91     void startTrace(@Nullable PrintWriter pw) {
92         if (IS_USER) {
93             logAndPrintln(pw, "Error: Tracing is not supported on user builds.");
94             return;
95         }
96         synchronized (mEnabledLock) {
97             logAndPrintln(pw, "Start tracing to " + mTraceFile + ".");
98             mBuffer.resetBuffer();
99             mEnabled = mEnabledLockFree = true;
100         }
101         log("trace.enable");
102     }
103 
104     /**
105      * Stops the trace and write the current buffer to disk
106      * @param pw Print writer
107      */
stopTrace(@ullable PrintWriter pw)108     void stopTrace(@Nullable PrintWriter pw) {
109         stopTrace(pw, true /* writeToFile */);
110     }
111 
112     /**
113      * Stops the trace
114      * @param pw Print writer
115      * @param writeToFile If the current buffer should be written to disk or not
116      */
stopTrace(@ullable PrintWriter pw, boolean writeToFile)117     void stopTrace(@Nullable PrintWriter pw, boolean writeToFile) {
118         if (IS_USER) {
119             logAndPrintln(pw, "Error: Tracing is not supported on user builds.");
120             return;
121         }
122         synchronized (mEnabledLock) {
123             logAndPrintln(pw, "Stop tracing to " + mTraceFile + ". Waiting for traces to flush.");
124             mEnabled = mEnabledLockFree = false;
125 
126             if (mEnabled) {
127                 logAndPrintln(pw, "ERROR: tracing was re-enabled while waiting for flush.");
128                 throw new IllegalStateException("tracing enabled while waiting for flush.");
129             }
130             if (writeToFile) {
131                 writeTraceToFileLocked();
132                 logAndPrintln(pw, "Trace written to " + mTraceFile + ".");
133             }
134         }
135     }
136 
setLogLevel(@indowTraceLogLevel int logLevel, PrintWriter pw)137     private void setLogLevel(@WindowTraceLogLevel int logLevel, PrintWriter pw) {
138         logAndPrintln(pw, "Setting window tracing log level to " + logLevel);
139         mLogLevel = logLevel;
140 
141         switch (logLevel) {
142             case WindowTraceLogLevel.ALL: {
143                 setBufferCapacity(BUFFER_CAPACITY_ALL, pw);
144                 break;
145             }
146             case WindowTraceLogLevel.TRIM: {
147                 setBufferCapacity(BUFFER_CAPACITY_TRIM, pw);
148                 break;
149             }
150             case WindowTraceLogLevel.CRITICAL: {
151                 setBufferCapacity(BUFFER_CAPACITY_CRITICAL, pw);
152                 break;
153             }
154         }
155     }
156 
setLogFrequency(boolean onFrame, PrintWriter pw)157     private void setLogFrequency(boolean onFrame, PrintWriter pw) {
158         logAndPrintln(pw, "Setting window tracing log frequency to "
159                 + ((onFrame) ? "frame" : "transaction"));
160         mLogOnFrame = onFrame;
161     }
162 
setBufferCapacity(int capacity, PrintWriter pw)163     private void setBufferCapacity(int capacity, PrintWriter pw) {
164         logAndPrintln(pw, "Setting window tracing buffer capacity to " + capacity + "bytes");
165         mBuffer.setCapacity(capacity);
166     }
167 
isEnabled()168     boolean isEnabled() {
169         return mEnabledLockFree;
170     }
171 
onShellCommand(ShellCommand shell)172     int onShellCommand(ShellCommand shell) {
173         PrintWriter pw = shell.getOutPrintWriter();
174         String cmd = shell.getNextArgRequired();
175         switch (cmd) {
176             case "start":
177                 startTrace(pw);
178                 return 0;
179             case "stop":
180                 stopTrace(pw);
181                 return 0;
182             case "status":
183                 logAndPrintln(pw, getStatus());
184                 return 0;
185             case "frame":
186                 setLogFrequency(true /* onFrame */, pw);
187                 mBuffer.resetBuffer();
188                 return 0;
189             case "transaction":
190                 setLogFrequency(false /* onFrame */, pw);
191                 mBuffer.resetBuffer();
192                 return 0;
193             case "level":
194                 String logLevelStr = shell.getNextArgRequired().toLowerCase();
195                 switch (logLevelStr) {
196                     case "all": {
197                         setLogLevel(WindowTraceLogLevel.ALL, pw);
198                         break;
199                     }
200                     case "trim": {
201                         setLogLevel(WindowTraceLogLevel.TRIM, pw);
202                         break;
203                     }
204                     case "critical": {
205                         setLogLevel(WindowTraceLogLevel.CRITICAL, pw);
206                         break;
207                     }
208                     default: {
209                         setLogLevel(WindowTraceLogLevel.TRIM, pw);
210                         break;
211                     }
212                 }
213                 mBuffer.resetBuffer();
214                 return 0;
215             case "size":
216                 setBufferCapacity(Integer.parseInt(shell.getNextArgRequired()) * 1024, pw);
217                 mBuffer.resetBuffer();
218                 return 0;
219             default:
220                 pw.println("Unknown command: " + cmd);
221                 pw.println("Window manager trace options:");
222                 pw.println("  start: Start logging");
223                 pw.println("  stop: Stop logging");
224                 pw.println("  frame: Log trace once per frame");
225                 pw.println("  transaction: Log each transaction");
226                 pw.println("  size: Set the maximum log size (in KB)");
227                 pw.println("  status: Print trace status");
228                 pw.println("  level [lvl]: Set the log level between");
229                 pw.println("    lvl may be one of:");
230                 pw.println("      critical: Only visible windows with reduced information");
231                 pw.println("      trim: All windows with reduced");
232                 pw.println("      all: All window and information");
233                 return -1;
234         }
235     }
236 
getStatus()237     String getStatus() {
238         return "Status: "
239                 + ((isEnabled()) ? "Enabled" : "Disabled")
240                 + "\n"
241                 + "Log level: "
242                 + mLogLevel
243                 + "\n"
244                 + mBuffer.getStatus();
245     }
246 
247     /**
248      * If tracing is enabled, log the current state or schedule the next frame to be logged,
249      * according to {@link #mLogOnFrame}.
250      *
251      * @param where Logging point descriptor
252      */
logState(String where)253     void logState(String where) {
254         if (!isEnabled()) {
255             return;
256         }
257 
258         if (mLogOnFrame) {
259             schedule();
260         } else {
261             log(where);
262         }
263     }
264 
265     /**
266      * Schedule the log to trace the next frame
267      */
schedule()268     private void schedule() {
269         if (mScheduled) {
270             return;
271         }
272 
273         mScheduled = true;
274         mChoreographer.postFrameCallback(mFrameCallback);
275     }
276 
277     /**
278      * Write the current frame to the buffer
279      *
280      * @param where Logging point descriptor
281      */
log(String where)282     private void log(String where) {
283         Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "traceStateLocked");
284         try {
285             ProtoOutputStream os = new ProtoOutputStream();
286             long tokenOuter = os.start(ENTRY);
287             os.write(ELAPSED_REALTIME_NANOS, SystemClock.elapsedRealtimeNanos());
288             os.write(WHERE, where);
289 
290             long tokenInner = os.start(WINDOW_MANAGER_SERVICE);
291             synchronized (mGlobalLock) {
292                 Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "writeToProtoLocked");
293                 try {
294                     mService.writeToProtoLocked(os, mLogLevel);
295                 } finally {
296                     Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);
297                 }
298             }
299             os.end(tokenInner);
300             os.end(tokenOuter);
301             mBuffer.add(os);
302             mScheduled = false;
303         } catch (Exception e) {
304             Log.wtf(TAG, "Exception while tracing state", e);
305         } finally {
306             Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);
307         }
308     }
309 
310     /**
311      * Writes the trace buffer to new file for the bugreport.
312      *
313      * This method is synchronized with {@code #startTrace(PrintWriter)} and
314      * {@link #stopTrace(PrintWriter)}.
315      */
writeTraceToFile()316     void writeTraceToFile() {
317         synchronized (mEnabledLock) {
318             writeTraceToFileLocked();
319         }
320     }
321 
logAndPrintln(@ullable PrintWriter pw, String msg)322     private void logAndPrintln(@Nullable PrintWriter pw, String msg) {
323         Log.i(TAG, msg);
324         if (pw != null) {
325             pw.println(msg);
326             pw.flush();
327         }
328     }
329 
330     /**
331      * Writes the trace buffer to disk. This method has no internal synchronization and should be
332      * externally synchronized
333      */
writeTraceToFileLocked()334     private void writeTraceToFileLocked() {
335         try {
336             Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "writeTraceToFileLocked");
337             mBuffer.writeTraceToFile(mTraceFile);
338         } catch (IOException e) {
339             Log.e(TAG, "Unable to write buffer to file", e);
340         } finally {
341             Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);
342         }
343     }
344 }