{@code
* try (TraceEvent e = TraceEvent.scoped("MyTraceEvent")) {
* // code.
* }
* }
*
* It is OK to use tracing before the native library has loaded, in a slightly restricted fashion.
* @see EarlyTraceEvent for details.
*/
@JNINamespace("base::android")
@MainDex
public class TraceEvent implements AutoCloseable {
private static volatile boolean sEnabled;
private static volatile boolean sATraceEnabled; // True when taking an Android systrace.
private static class BasicLooperMonitor implements Printer {
private static final String EARLY_TOPLEVEL_TASK_NAME = "Looper.dispatchMessage: ";
@Override
public void println(final String line) {
if (line.startsWith(">")) {
beginHandling(line);
} else {
assert line.startsWith("<");
endHandling(line);
}
}
void beginHandling(final String line) {
// May return an out-of-date value. this is not an issue as EarlyTraceEvent#begin()
// will filter the event in this case.
boolean earlyTracingActive = EarlyTraceEvent.isActive();
if (sEnabled || earlyTracingActive) {
String target = getTarget(line);
if (sEnabled) {
nativeBeginToplevel(target);
} else if (earlyTracingActive) {
// Synthesize a task name instead of using a parameter, as early tracing doesn't
// support parameters.
EarlyTraceEvent.begin(EARLY_TOPLEVEL_TASK_NAME + target);
}
}
}
void endHandling(final String line) {
if (EarlyTraceEvent.isActive()) {
EarlyTraceEvent.end(EARLY_TOPLEVEL_TASK_NAME + getTarget(line));
}
if (sEnabled) nativeEndToplevel();
}
/**
* Android Looper formats |line| as ">>>>> Dispatching to (TARGET) [...]" since at least
* 2009 (Donut). Extracts the TARGET part of the message.
*/
private static String getTarget(String logLine) {
int start = logLine.indexOf('(', 21); // strlen(">>>>> Dispatching to ")
int end = start == -1 ? -1 : logLine.indexOf(')', start);
return end != -1 ? logLine.substring(start + 1, end) : "";
}
}
/**
* A class that records, traces and logs statistics about the UI thead's Looper.
* The output of this class can be used in a number of interesting ways:
* *
* The class attaches itself as an idle handler to the main Looper, and * monitors the execution of events and idle notifications. Task counters * accumulate between idle notifications and get reset when a new idle * notification is received. */ private static final class IdleTracingLooperMonitor extends BasicLooperMonitor implements MessageQueue.IdleHandler { // Tags for dumping to logcat or TraceEvent private static final String TAG = "TraceEvent.LooperMonitor"; private static final String IDLE_EVENT_NAME = "Looper.queueIdle"; // Calculation constants private static final long FRAME_DURATION_MILLIS = 1000L / 60L; // 60 FPS // A reasonable threshold for defining a Looper event as "long running" private static final long MIN_INTERESTING_DURATION_MILLIS = FRAME_DURATION_MILLIS; // A reasonable threshold for a "burst" of tasks on the Looper private static final long MIN_INTERESTING_BURST_DURATION_MILLIS = MIN_INTERESTING_DURATION_MILLIS * 3; // Stats tracking private long mLastIdleStartedAt; private long mLastWorkStartedAt; private int mNumTasksSeen; private int mNumIdlesSeen; private int mNumTasksSinceLastIdle; // State private boolean mIdleMonitorAttached; // Called from within the begin/end methods only. // This method can only execute on the looper thread, because that is // the only thread that is permitted to call Looper.myqueue(). private final void syncIdleMonitoring() { if (sEnabled && !mIdleMonitorAttached) { // approximate start time for computational purposes mLastIdleStartedAt = SystemClock.elapsedRealtime(); Looper.myQueue().addIdleHandler(this); mIdleMonitorAttached = true; Log.v(TAG, "attached idle handler"); } else if (mIdleMonitorAttached && !sEnabled) { Looper.myQueue().removeIdleHandler(this); mIdleMonitorAttached = false; Log.v(TAG, "detached idle handler"); } } @Override final void beginHandling(final String line) { // Close-out any prior 'idle' period before starting new task. if (mNumTasksSinceLastIdle == 0) { TraceEvent.end(IDLE_EVENT_NAME); } mLastWorkStartedAt = SystemClock.elapsedRealtime(); syncIdleMonitoring(); super.beginHandling(line); } @Override final void endHandling(final String line) { final long elapsed = SystemClock.elapsedRealtime() - mLastWorkStartedAt; if (elapsed > MIN_INTERESTING_DURATION_MILLIS) { traceAndLog(Log.WARN, "observed a task that took " + elapsed + "ms: " + line); } super.endHandling(line); syncIdleMonitoring(); mNumTasksSeen++; mNumTasksSinceLastIdle++; } private static void traceAndLog(int level, String message) { TraceEvent.instant("TraceEvent.LooperMonitor:IdleStats", message); Log.println(level, TAG, message); } @Override public final boolean queueIdle() { final long now = SystemClock.elapsedRealtime(); if (mLastIdleStartedAt == 0) mLastIdleStartedAt = now; final long elapsed = now - mLastIdleStartedAt; mNumIdlesSeen++; TraceEvent.begin(IDLE_EVENT_NAME, mNumTasksSinceLastIdle + " tasks since last idle."); if (elapsed > MIN_INTERESTING_BURST_DURATION_MILLIS) { // Dump stats String statsString = mNumTasksSeen + " tasks and " + mNumIdlesSeen + " idles processed so far, " + mNumTasksSinceLastIdle + " tasks bursted and " + elapsed + "ms elapsed since last idle"; traceAndLog(Log.DEBUG, statsString); } mLastIdleStartedAt = now; mNumTasksSinceLastIdle = 0; return true; // stay installed } } // Holder for monitor avoids unnecessary construction on non-debug runs private static final class LooperMonitorHolder { private static final BasicLooperMonitor sInstance = CommandLine.getInstance().hasSwitch(BaseSwitches.ENABLE_IDLE_TRACING) ? new IdleTracingLooperMonitor() : new BasicLooperMonitor(); } private final String mName; /** * Constructor used to support the "try with resource" construct. */ private TraceEvent(String name, String arg) { mName = name; begin(name, arg); } @Override public void close() { end(mName); } /** * Factory used to support the "try with resource" construct. * * Note that if tracing is not enabled, this will not result in allocating an object. * * @param name Trace event name. * @param name The arguments of the event. * @return a TraceEvent, or null if tracing is not enabled. */ public static TraceEvent scoped(String name, String arg) { if (!(EarlyTraceEvent.enabled() || enabled())) return null; return new TraceEvent(name, arg); } /** * Similar to {@link #scoped(String, String arg)}, but uses null for |arg|. */ public static TraceEvent scoped(String name) { return scoped(name, null); } /** * Register an enabled observer, such that java traces are always enabled with native. */ public static void registerNativeEnabledObserver() { nativeRegisterEnabledObserver(); } /** * Notification from native that tracing is enabled/disabled. */ @CalledByNative public static void setEnabled(boolean enabled) { if (enabled) EarlyTraceEvent.disable(); // Only disable logging if Chromium enabled it originally, so as to not disrupt logging done // by other applications if (sEnabled != enabled) { sEnabled = enabled; // Android M+ systrace logs this on its own. Only log it if not writing to Android // systrace. if (sATraceEnabled) return; ThreadUtils.getUiThreadLooper().setMessageLogging( enabled ? LooperMonitorHolder.sInstance : null); } } /** * May enable early tracing depending on the environment. * * Must be called after the command-line has been read. */ public static void maybeEnableEarlyTracing() { EarlyTraceEvent.maybeEnable(); if (EarlyTraceEvent.isActive()) { ThreadUtils.getUiThreadLooper().setMessageLogging(LooperMonitorHolder.sInstance); } } /** * Enables or disabled Android systrace path of Chrome tracing. If enabled, all Chrome * traces will be also output to Android systrace. Because of the overhead of Android * systrace, this is for WebView only. */ public static void setATraceEnabled(boolean enabled) { if (sATraceEnabled == enabled) return; sATraceEnabled = enabled; if (enabled) { // Calls TraceEvent.setEnabled(true) via // TraceLog::EnabledStateObserver::OnTraceLogEnabled nativeStartATrace(); } else { // Calls TraceEvent.setEnabled(false) via // TraceLog::EnabledStateObserver::OnTraceLogDisabled nativeStopATrace(); } } /** * @return True if tracing is enabled, false otherwise. * It is safe to call trace methods without checking if TraceEvent * is enabled. */ public static boolean enabled() { return sEnabled; } /** * Triggers the 'instant' native trace event with no arguments. * @param name The name of the event. */ public static void instant(String name) { if (sEnabled) nativeInstant(name, null); } /** * Triggers the 'instant' native trace event. * @param name The name of the event. * @param arg The arguments of the event. */ public static void instant(String name, String arg) { if (sEnabled) nativeInstant(name, arg); } /** * Triggers the 'start' native trace event with no arguments. * @param name The name of the event. * @param id The id of the asynchronous event. */ public static void startAsync(String name, long id) { EarlyTraceEvent.startAsync(name, id); if (sEnabled) nativeStartAsync(name, id); } /** * Triggers the 'finish' native trace event with no arguments. * @param name The name of the event. * @param id The id of the asynchronous event. */ public static void finishAsync(String name, long id) { EarlyTraceEvent.finishAsync(name, id); if (sEnabled) nativeFinishAsync(name, id); } /** * Triggers the 'begin' native trace event with no arguments. * @param name The name of the event. */ public static void begin(String name) { begin(name, null); } /** * Triggers the 'begin' native trace event. * @param name The name of the event. * @param arg The arguments of the event. */ public static void begin(String name, String arg) { EarlyTraceEvent.begin(name); if (sEnabled) nativeBegin(name, arg); } /** * Triggers the 'end' native trace event with no arguments. * @param name The name of the event. */ public static void end(String name) { end(name, null); } /** * Triggers the 'end' native trace event. * @param name The name of the event. * @param arg The arguments of the event. */ public static void end(String name, String arg) { EarlyTraceEvent.end(name); if (sEnabled) nativeEnd(name, arg); } private static native void nativeRegisterEnabledObserver(); private static native void nativeStartATrace(); private static native void nativeStopATrace(); private static native void nativeInstant(String name, String arg); private static native void nativeBegin(String name, String arg); private static native void nativeEnd(String name, String arg); private static native void nativeBeginToplevel(String target); private static native void nativeEndToplevel(); private static native void nativeStartAsync(String name, long id); private static native void nativeFinishAsync(String name, long id); }