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