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