services/core/java/com/android/server/wm/WindowTracing.java - platform/frameworks/base - Git at Google

 /*
  * Copyright (C) 2017 The Android Open Source Project
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
  * You may obtain a copy of the License at
  *
  *      http://www.apache.org/licenses/LICENSE-2.0
  *
  * Unless required by applicable law or agreed to in writing, software
  * distributed under the License is distributed on an "AS IS" BASIS,
  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */

 package com.android.server.wm;

 import static android.os.Build.IS_USER;

 import static com.android.server.wm.WindowManagerTraceFileProto.ENTRY;
 import static com.android.server.wm.WindowManagerTraceFileProto.MAGIC_NUMBER;
 import static com.android.server.wm.WindowManagerTraceFileProto.MAGIC_NUMBER_H;
 import static com.android.server.wm.WindowManagerTraceFileProto.MAGIC_NUMBER_L;
 import static com.android.server.wm.WindowManagerTraceProto.ELAPSED_REALTIME_NANOS;
 import static com.android.server.wm.WindowManagerTraceProto.WHERE;
 import static com.android.server.wm.WindowManagerTraceProto.WINDOW_MANAGER_SERVICE;

 import android.annotation.Nullable;
 import android.os.ShellCommand;
 import android.os.SystemClock;
 import android.os.Trace;
 import android.util.Log;
 import android.util.proto.ProtoOutputStream;
 import android.view.Choreographer;

 import com.android.server.protolog.ProtoLogImpl;
 import com.android.internal.util.TraceBuffer;

 import java.io.File;
 import java.io.IOException;
 import java.io.PrintWriter;

 /**
  * A class that allows window manager to dump its state continuously to a trace file, such that a
  * time series of window manager state can be analyzed after the fact.
  */
 class WindowTracing {

     /**
      * Maximum buffer size, currently defined as 512 KB
      * Size was experimentally defined to fit between 100 to 150 elements.
      */
     private static final int BUFFER_CAPACITY_CRITICAL = 512 * 1024;
     private static final int BUFFER_CAPACITY_TRIM = 2048 * 1024;
     private static final int BUFFER_CAPACITY_ALL = 4096 * 1024;
     private static final String TRACE_FILENAME = "/data/misc/wmtrace/wm_trace.pb";
     private static final String TAG = "WindowTracing";
     private static final long MAGIC_NUMBER_VALUE = ((long) MAGIC_NUMBER_H << 32) | MAGIC_NUMBER_L;

     private final WindowManagerService mService;
     private final Choreographer mChoreographer;
     private final WindowManagerGlobalLock mGlobalLock;

     private final Object mEnabledLock = new Object();
     private final File mTraceFile;
     private final TraceBuffer mBuffer;
     private final Choreographer.FrameCallback mFrameCallback = (frameTimeNanos) ->
             log("onFrame" /* where */);

     private @WindowTraceLogLevel int mLogLevel = WindowTraceLogLevel.TRIM;
     private boolean mLogOnFrame = false;
     private boolean mEnabled;
     private volatile boolean mEnabledLockFree;
     private boolean mScheduled;

     static WindowTracing createDefaultAndStartLooper(WindowManagerService service,
             Choreographer choreographer) {
         File file = new File(TRACE_FILENAME);
         return new WindowTracing(file, service, choreographer, BUFFER_CAPACITY_TRIM);
     }

     private WindowTracing(File file, WindowManagerService service, Choreographer choreographer,
             int bufferCapacity) {
         this(file, service, choreographer, service.mGlobalLock, bufferCapacity);
     }

     WindowTracing(File file, WindowManagerService service, Choreographer choreographer,
             WindowManagerGlobalLock globalLock, int bufferCapacity) {
         mChoreographer = choreographer;
         mService = service;
         mGlobalLock = globalLock;
         mTraceFile = file;
         mBuffer = new TraceBuffer(bufferCapacity);
         setLogLevel(WindowTraceLogLevel.TRIM, null /* pw */);
     }

     void startTrace(@Nullable PrintWriter pw) {
         if (IS_USER) {
             logAndPrintln(pw, "Error: Tracing is not supported on user builds.");
             return;
         }
         synchronized (mEnabledLock) {
             ProtoLogImpl.getSingleInstance().startProtoLog(pw);
             logAndPrintln(pw, "Start tracing to " + mTraceFile + ".");
             mBuffer.resetBuffer();
             mEnabled = mEnabledLockFree = true;
         }
         log("trace.enable");
     }

     /**
      * Stops the trace and write the current buffer to disk
      * @param pw Print writer
      */
     void stopTrace(@Nullable PrintWriter pw) {
         stopTrace(pw, true /* writeToFile */);
     }

     /**
      * Stops the trace
      * @param pw Print writer
      * @param writeToFile If the current buffer should be written to disk or not
      */
     void stopTrace(@Nullable PrintWriter pw, boolean writeToFile) {
         if (IS_USER) {
             logAndPrintln(pw, "Error: Tracing is not supported on user builds.");
             return;
         }
         synchronized (mEnabledLock) {
             logAndPrintln(pw, "Stop tracing to " + mTraceFile + ". Waiting for traces to flush.");
             mEnabled = mEnabledLockFree = false;

             if (mEnabled) {
                 logAndPrintln(pw, "ERROR: tracing was re-enabled while waiting for flush.");
                 throw new IllegalStateException("tracing enabled while waiting for flush.");
             }
             if (writeToFile) {
                 writeTraceToFileLocked();
                 logAndPrintln(pw, "Trace written to " + mTraceFile + ".");
             }
         }
         ProtoLogImpl.getSingleInstance().stopProtoLog(pw, writeToFile);
     }

     private void setLogLevel(@WindowTraceLogLevel int logLevel, PrintWriter pw) {
         logAndPrintln(pw, "Setting window tracing log level to " + logLevel);
         mLogLevel = logLevel;

         switch (logLevel) {
             case WindowTraceLogLevel.ALL: {
                 setBufferCapacity(BUFFER_CAPACITY_ALL, pw);
                 break;
             }
             case WindowTraceLogLevel.TRIM: {
                 setBufferCapacity(BUFFER_CAPACITY_TRIM, pw);
                 break;
             }
             case WindowTraceLogLevel.CRITICAL: {
                 setBufferCapacity(BUFFER_CAPACITY_CRITICAL, pw);
                 break;
             }
         }
     }

     private void setLogFrequency(boolean onFrame, PrintWriter pw) {
         logAndPrintln(pw, "Setting window tracing log frequency to "
                 + ((onFrame) ? "frame" : "transaction"));
         mLogOnFrame = onFrame;
     }

     private void setBufferCapacity(int capacity, PrintWriter pw) {
         logAndPrintln(pw, "Setting window tracing buffer capacity to " + capacity + "bytes");
         mBuffer.setCapacity(capacity);
     }

     boolean isEnabled() {
         return mEnabledLockFree;
     }

     int onShellCommand(ShellCommand shell) {
         PrintWriter pw = shell.getOutPrintWriter();
         String cmd = shell.getNextArgRequired();
         switch (cmd) {
             case "start":
                 startTrace(pw);
                 return 0;
             case "stop":
                 stopTrace(pw);
                 return 0;
             case "status":
                 logAndPrintln(pw, getStatus());
                 return 0;
             case "frame":
                 setLogFrequency(true /* onFrame */, pw);
                 mBuffer.resetBuffer();
                 return 0;
             case "transaction":
                 setLogFrequency(false /* onFrame */, pw);
                 mBuffer.resetBuffer();
                 return 0;
             case "level":
                 String logLevelStr = shell.getNextArgRequired().toLowerCase();
                 switch (logLevelStr) {
                     case "all": {
                         setLogLevel(WindowTraceLogLevel.ALL, pw);
                         break;
                     }
                     case "trim": {
                         setLogLevel(WindowTraceLogLevel.TRIM, pw);
                         break;
                     }
                     case "critical": {
                         setLogLevel(WindowTraceLogLevel.CRITICAL, pw);
                         break;
                     }
                     default: {
                         setLogLevel(WindowTraceLogLevel.TRIM, pw);
                         break;
                     }
                 }
                 mBuffer.resetBuffer();
                 return 0;
             case "size":
                 setBufferCapacity(Integer.parseInt(shell.getNextArgRequired()) * 1024, pw);
                 mBuffer.resetBuffer();
                 return 0;
             default:
                 pw.println("Unknown command: " + cmd);
                 pw.println("Window manager trace options:");
                 pw.println("  start: Start logging");
                 pw.println("  stop: Stop logging");
                 pw.println("  frame: Log trace once per frame");
                 pw.println("  transaction: Log each transaction");
                 pw.println("  size: Set the maximum log size (in KB)");
                 pw.println("  status: Print trace status");
                 pw.println("  level [lvl]: Set the log level between");
                 pw.println("    lvl may be one of:");
                 pw.println("      critical: Only visible windows with reduced information");
                 pw.println("      trim: All windows with reduced");
                 pw.println("      all: All window and information");
                 return -1;
         }
     }

     String getStatus() {
         return "Status: "
                 + ((isEnabled()) ? "Enabled" : "Disabled")
                 + "\n"
                 + "Log level: "
                 + mLogLevel
                 + "\n"
                 + mBuffer.getStatus();
     }

     /**
      * If tracing is enabled, log the current state or schedule the next frame to be logged,
      * according to {@link #mLogOnFrame}.
      *
      * @param where Logging point descriptor
      */
     void logState(String where) {
         if (!isEnabled()) {
             return;
         }

         if (mLogOnFrame) {
             schedule();
         } else {
             log(where);
         }
     }

     /**
      * Schedule the log to trace the next frame
      */
     private void schedule() {
         if (mScheduled) {
             return;
         }

         mScheduled = true;
         mChoreographer.postFrameCallback(mFrameCallback);
     }

     /**
      * Write the current frame to the buffer
      *
      * @param where Logging point descriptor
      */
     private void log(String where) {
         Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "traceStateLocked");
         try {
             ProtoOutputStream os = new ProtoOutputStream();
             long tokenOuter = os.start(ENTRY);
             os.write(ELAPSED_REALTIME_NANOS, SystemClock.elapsedRealtimeNanos());
             os.write(WHERE, where);

             long tokenInner = os.start(WINDOW_MANAGER_SERVICE);
             synchronized (mGlobalLock) {
                 Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "dumpDebugLocked");
                 try {
                     mService.dumpDebugLocked(os, mLogLevel);
                 } finally {
                     Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);
                 }
             }
             os.end(tokenInner);
             os.end(tokenOuter);
             mBuffer.add(os);
             mScheduled = false;
         } catch (Exception e) {
             Log.wtf(TAG, "Exception while tracing state", e);
         } finally {
             Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);
         }
     }

     /**
      * Writes the trace buffer to new file for the bugreport.
      *
      * This method is synchronized with {@code #startTrace(PrintWriter)} and
      * {@link #stopTrace(PrintWriter)}.
      */
     void writeTraceToFile() {
         synchronized (mEnabledLock) {
             writeTraceToFileLocked();
         }
         ProtoLogImpl.getSingleInstance().writeProtoLogToFile();
     }

     private void logAndPrintln(@Nullable PrintWriter pw, String msg) {
         Log.i(TAG, msg);
         if (pw != null) {
             pw.println(msg);
             pw.flush();
         }
     }

     /**
      * Writes the trace buffer to disk. This method has no internal synchronization and should be
      * externally synchronized
      */
     private void writeTraceToFileLocked() {
         try {
             Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "writeTraceToFileLocked");
             ProtoOutputStream proto = new ProtoOutputStream();
             proto.write(MAGIC_NUMBER, MAGIC_NUMBER_VALUE);
             mBuffer.writeTraceToFile(mTraceFile, proto);
         } catch (IOException e) {
             Log.e(TAG, "Unable to write buffer to file", e);
         } finally {
             Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);
         }
     }
 }
	/*
	* Copyright (C) 2017 The Android Open Source Project
	*
	* Licensed under the Apache License, Version 2.0 (the "License");
	* you may not use this file except in compliance with the License.
	* You may obtain a copy of the License at
	*
	* http://www.apache.org/licenses/LICENSE-2.0
	*
	* Unless required by applicable law or agreed to in writing, software
	* distributed under the License is distributed on an "AS IS" BASIS,
	* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
	* See the License for the specific language governing permissions and
	* limitations under the License.
	*/

	package com.android.server.wm;

	import static android.os.Build.IS_USER;

	import static com.android.server.wm.WindowManagerTraceFileProto.ENTRY;
	import static com.android.server.wm.WindowManagerTraceFileProto.MAGIC_NUMBER;
	import static com.android.server.wm.WindowManagerTraceFileProto.MAGIC_NUMBER_H;
	import static com.android.server.wm.WindowManagerTraceFileProto.MAGIC_NUMBER_L;
	import static com.android.server.wm.WindowManagerTraceProto.ELAPSED_REALTIME_NANOS;
	import static com.android.server.wm.WindowManagerTraceProto.WHERE;
	import static com.android.server.wm.WindowManagerTraceProto.WINDOW_MANAGER_SERVICE;

	import android.annotation.Nullable;
	import android.os.ShellCommand;
	import android.os.SystemClock;
	import android.os.Trace;
	import android.util.Log;
	import android.util.proto.ProtoOutputStream;
	import android.view.Choreographer;

	import com.android.server.protolog.ProtoLogImpl;
	import com.android.internal.util.TraceBuffer;

	import java.io.File;
	import java.io.IOException;
	import java.io.PrintWriter;

	/**
	* A class that allows window manager to dump its state continuously to a trace file, such that a
	* time series of window manager state can be analyzed after the fact.
	*/
	class WindowTracing {

	/**
	* Maximum buffer size, currently defined as 512 KB
	* Size was experimentally defined to fit between 100 to 150 elements.
	*/
	private static final int BUFFER_CAPACITY_CRITICAL = 512 * 1024;
	private static final int BUFFER_CAPACITY_TRIM = 2048 * 1024;
	private static final int BUFFER_CAPACITY_ALL = 4096 * 1024;
	private static final String TRACE_FILENAME = "/data/misc/wmtrace/wm_trace.pb";
	private static final String TAG = "WindowTracing";
	private static final long MAGIC_NUMBER_VALUE = ((long) MAGIC_NUMBER_H << 32) \| MAGIC_NUMBER_L;

	private final WindowManagerService mService;
	private final Choreographer mChoreographer;
	private final WindowManagerGlobalLock mGlobalLock;

	private final Object mEnabledLock = new Object();
	private final File mTraceFile;
	private final TraceBuffer mBuffer;
	private final Choreographer.FrameCallback mFrameCallback = (frameTimeNanos) ->
	log("onFrame" /* where */);

	private @WindowTraceLogLevel int mLogLevel = WindowTraceLogLevel.TRIM;
	private boolean mLogOnFrame = false;
	private boolean mEnabled;
	private volatile boolean mEnabledLockFree;
	private boolean mScheduled;

	static WindowTracing createDefaultAndStartLooper(WindowManagerService service,
	Choreographer choreographer) {
	File file = new File(TRACE_FILENAME);
	return new WindowTracing(file, service, choreographer, BUFFER_CAPACITY_TRIM);
	}

	private WindowTracing(File file, WindowManagerService service, Choreographer choreographer,
	int bufferCapacity) {
	this(file, service, choreographer, service.mGlobalLock, bufferCapacity);
	}

	WindowTracing(File file, WindowManagerService service, Choreographer choreographer,
	WindowManagerGlobalLock globalLock, int bufferCapacity) {
	mChoreographer = choreographer;
	mService = service;
	mGlobalLock = globalLock;
	mTraceFile = file;
	mBuffer = new TraceBuffer(bufferCapacity);
	setLogLevel(WindowTraceLogLevel.TRIM, null /* pw */);
	}

	void startTrace(@Nullable PrintWriter pw) {
	if (IS_USER) {
	logAndPrintln(pw, "Error: Tracing is not supported on user builds.");
	return;
	}
	synchronized (mEnabledLock) {
	ProtoLogImpl.getSingleInstance().startProtoLog(pw);
	logAndPrintln(pw, "Start tracing to " + mTraceFile + ".");
	mBuffer.resetBuffer();
	mEnabled = mEnabledLockFree = true;
	}
	log("trace.enable");
	}

	/**
	* Stops the trace and write the current buffer to disk
	* @param pw Print writer
	*/
	void stopTrace(@Nullable PrintWriter pw) {
	stopTrace(pw, true /* writeToFile */);
	}

	/**
	* Stops the trace
	* @param pw Print writer
	* @param writeToFile If the current buffer should be written to disk or not
	*/
	void stopTrace(@Nullable PrintWriter pw, boolean writeToFile) {
	if (IS_USER) {
	logAndPrintln(pw, "Error: Tracing is not supported on user builds.");
	return;
	}
	synchronized (mEnabledLock) {
	logAndPrintln(pw, "Stop tracing to " + mTraceFile + ". Waiting for traces to flush.");
	mEnabled = mEnabledLockFree = false;

	if (mEnabled) {
	logAndPrintln(pw, "ERROR: tracing was re-enabled while waiting for flush.");
	throw new IllegalStateException("tracing enabled while waiting for flush.");
	}
	if (writeToFile) {
	writeTraceToFileLocked();
	logAndPrintln(pw, "Trace written to " + mTraceFile + ".");
	}
	}
	ProtoLogImpl.getSingleInstance().stopProtoLog(pw, writeToFile);
	}

	private void setLogLevel(@WindowTraceLogLevel int logLevel, PrintWriter pw) {
	logAndPrintln(pw, "Setting window tracing log level to " + logLevel);
	mLogLevel = logLevel;

	switch (logLevel) {
	case WindowTraceLogLevel.ALL: {
	setBufferCapacity(BUFFER_CAPACITY_ALL, pw);
	break;
	}
	case WindowTraceLogLevel.TRIM: {
	setBufferCapacity(BUFFER_CAPACITY_TRIM, pw);
	break;
	}
	case WindowTraceLogLevel.CRITICAL: {
	setBufferCapacity(BUFFER_CAPACITY_CRITICAL, pw);
	break;
	}
	}
	}

	private void setLogFrequency(boolean onFrame, PrintWriter pw) {
	logAndPrintln(pw, "Setting window tracing log frequency to "
	+ ((onFrame) ? "frame" : "transaction"));
	mLogOnFrame = onFrame;
	}

	private void setBufferCapacity(int capacity, PrintWriter pw) {
	logAndPrintln(pw, "Setting window tracing buffer capacity to " + capacity + "bytes");
	mBuffer.setCapacity(capacity);
	}

	boolean isEnabled() {
	return mEnabledLockFree;
	}

	int onShellCommand(ShellCommand shell) {
	PrintWriter pw = shell.getOutPrintWriter();
	String cmd = shell.getNextArgRequired();
	switch (cmd) {
	case "start":
	startTrace(pw);
	return 0;
	case "stop":
	stopTrace(pw);
	return 0;
	case "status":
	logAndPrintln(pw, getStatus());
	return 0;
	case "frame":
	setLogFrequency(true /* onFrame */, pw);
	mBuffer.resetBuffer();
	return 0;
	case "transaction":
	setLogFrequency(false /* onFrame */, pw);
	mBuffer.resetBuffer();
	return 0;
	case "level":
	String logLevelStr = shell.getNextArgRequired().toLowerCase();
	switch (logLevelStr) {
	case "all": {
	setLogLevel(WindowTraceLogLevel.ALL, pw);
	break;
	}
	case "trim": {
	setLogLevel(WindowTraceLogLevel.TRIM, pw);
	break;
	}
	case "critical": {
	setLogLevel(WindowTraceLogLevel.CRITICAL, pw);
	break;
	}
	default: {
	setLogLevel(WindowTraceLogLevel.TRIM, pw);
	break;
	}
	}
	mBuffer.resetBuffer();
	return 0;
	case "size":
	setBufferCapacity(Integer.parseInt(shell.getNextArgRequired()) * 1024, pw);
	mBuffer.resetBuffer();
	return 0;
	default:
	pw.println("Unknown command: " + cmd);
	pw.println("Window manager trace options:");
	pw.println(" start: Start logging");
	pw.println(" stop: Stop logging");
	pw.println(" frame: Log trace once per frame");
	pw.println(" transaction: Log each transaction");
	pw.println(" size: Set the maximum log size (in KB)");
	pw.println(" status: Print trace status");
	pw.println(" level [lvl]: Set the log level between");
	pw.println(" lvl may be one of:");
	pw.println(" critical: Only visible windows with reduced information");
	pw.println(" trim: All windows with reduced");
	pw.println(" all: All window and information");
	return -1;
	}
	}

	String getStatus() {
	return "Status: "
	+ ((isEnabled()) ? "Enabled" : "Disabled")
	+ "\n"
	+ "Log level: "
	+ mLogLevel
	+ "\n"
	+ mBuffer.getStatus();
	}

	/**
	* If tracing is enabled, log the current state or schedule the next frame to be logged,
	* according to {@link #mLogOnFrame}.
	*
	* @param where Logging point descriptor
	*/
	void logState(String where) {
	if (!isEnabled()) {
	return;
	}

	if (mLogOnFrame) {
	schedule();
	} else {
	log(where);
	}
	}

	/**
	* Schedule the log to trace the next frame
	*/
	private void schedule() {
	if (mScheduled) {
	return;
	}

	mScheduled = true;
	mChoreographer.postFrameCallback(mFrameCallback);
	}

	/**
	* Write the current frame to the buffer
	*
	* @param where Logging point descriptor
	*/
	private void log(String where) {
	Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "traceStateLocked");
	try {
	ProtoOutputStream os = new ProtoOutputStream();
	long tokenOuter = os.start(ENTRY);
	os.write(ELAPSED_REALTIME_NANOS, SystemClock.elapsedRealtimeNanos());
	os.write(WHERE, where);

	long tokenInner = os.start(WINDOW_MANAGER_SERVICE);
	synchronized (mGlobalLock) {
	Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "dumpDebugLocked");
	try {
	mService.dumpDebugLocked(os, mLogLevel);
	} finally {
	Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);
	}
	}
	os.end(tokenInner);
	os.end(tokenOuter);
	mBuffer.add(os);
	mScheduled = false;
	} catch (Exception e) {
	Log.wtf(TAG, "Exception while tracing state", e);
	} finally {
	Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);
	}
	}

	/**
	* Writes the trace buffer to new file for the bugreport.
	*
	* This method is synchronized with {@code #startTrace(PrintWriter)} and
	* {@link #stopTrace(PrintWriter)}.
	*/
	void writeTraceToFile() {
	synchronized (mEnabledLock) {
	writeTraceToFileLocked();
	}
	ProtoLogImpl.getSingleInstance().writeProtoLogToFile();
	}

	private void logAndPrintln(@Nullable PrintWriter pw, String msg) {
	Log.i(TAG, msg);
	if (pw != null) {
	pw.println(msg);
	pw.flush();
	}
	}

	/**
	* Writes the trace buffer to disk. This method has no internal synchronization and should be
	* externally synchronized
	*/
	private void writeTraceToFileLocked() {
	try {
	Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "writeTraceToFileLocked");
	ProtoOutputStream proto = new ProtoOutputStream();
	proto.write(MAGIC_NUMBER, MAGIC_NUMBER_VALUE);
	mBuffer.writeTraceToFile(mTraceFile, proto);
	} catch (IOException e) {
	Log.e(TAG, "Unable to write buffer to file", e);
	} finally {
	Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);
	}
	}
	}