1 // Copyright 2014 The Chromium Authors. All rights reserved. 2 // Use of this source code is governed by a BSD-style license that can be 3 // found in the LICENSE file. 4 5 package org.chromium.base; 6 7 import android.os.Looper; 8 import android.os.MessageQueue; 9 import android.os.SystemClock; 10 import android.util.Log; 11 import android.util.Printer; 12 13 import org.chromium.base.annotations.CalledByNative; 14 import org.chromium.base.annotations.JNINamespace; 15 import org.chromium.base.annotations.MainDex; 16 /** 17 * Java mirror of Chrome trace event API. See base/trace_event/trace_event.h. Unlike the native 18 * version, Java does not have stack objects, so a TRACE_EVENT() which does both TRACE_EVENT_BEGIN() 19 * and TRACE_EVENT_END() in ctor/dtor is not possible. 20 * It is OK to use tracing before the native library has loaded, in a slightly restricted fashion. 21 * @see EarlyTraceEvent for details. 22 */ 23 @JNINamespace("base::android") 24 @MainDex 25 public class TraceEvent { 26 private static volatile boolean sEnabled; 27 private static volatile boolean sATraceEnabled; // True when taking an Android systrace. 28 29 private static class BasicLooperMonitor implements Printer { 30 @Override 31 public void println(final String line) { 32 if (line.startsWith(">")) { 33 beginHandling(line); 34 } else { 35 assert line.startsWith("<"); 36 endHandling(line); 37 } 38 } 39 40 void beginHandling(final String line) { 41 if (sEnabled) nativeBeginToplevel(); 42 } 43 44 void endHandling(final String line) { 45 if (sEnabled) nativeEndToplevel(); 46 } 47 } 48 49 /** 50 * A class that records, traces and logs statistics about the UI thead's Looper. 51 * The output of this class can be used in a number of interesting ways: 52 * <p> 53 * <ol><li> 54 * When using chrometrace, there will be a near-continuous line of 55 * measurements showing both event dispatches as well as idles; 56 * </li><li> 57 * Logging messages are output for events that run too long on the 58 * event dispatcher, making it easy to identify problematic areas; 59 * </li><li> 60 * Statistics are output whenever there is an idle after a non-trivial 61 * amount of activity, allowing information to be gathered about task 62 * density and execution cadence on the Looper; 63 * </li></ol> 64 * <p> 65 * The class attaches itself as an idle handler to the main Looper, and 66 * monitors the execution of events and idle notifications. Task counters 67 * accumulate between idle notifications and get reset when a new idle 68 * notification is received. 69 */ 70 private static final class IdleTracingLooperMonitor extends BasicLooperMonitor 71 implements MessageQueue.IdleHandler { 72 // Tags for dumping to logcat or TraceEvent 73 private static final String TAG = "TraceEvent.LooperMonitor"; 74 private static final String IDLE_EVENT_NAME = "Looper.queueIdle"; 75 76 // Calculation constants 77 private static final long FRAME_DURATION_MILLIS = 1000L / 60L; // 60 FPS 78 // A reasonable threshold for defining a Looper event as "long running" 79 private static final long MIN_INTERESTING_DURATION_MILLIS = 80 FRAME_DURATION_MILLIS; 81 // A reasonable threshold for a "burst" of tasks on the Looper 82 private static final long MIN_INTERESTING_BURST_DURATION_MILLIS = 83 MIN_INTERESTING_DURATION_MILLIS * 3; 84 85 // Stats tracking 86 private long mLastIdleStartedAt; 87 private long mLastWorkStartedAt; 88 private int mNumTasksSeen; 89 private int mNumIdlesSeen; 90 private int mNumTasksSinceLastIdle; 91 92 // State 93 private boolean mIdleMonitorAttached; 94 95 // Called from within the begin/end methods only. 96 // This method can only execute on the looper thread, because that is 97 // the only thread that is permitted to call Looper.myqueue(). 98 private final void syncIdleMonitoring() { 99 if (sEnabled && !mIdleMonitorAttached) { 100 // approximate start time for computational purposes 101 mLastIdleStartedAt = SystemClock.elapsedRealtime(); 102 Looper.myQueue().addIdleHandler(this); 103 mIdleMonitorAttached = true; 104 Log.v(TAG, "attached idle handler"); 105 } else if (mIdleMonitorAttached && !sEnabled) { 106 Looper.myQueue().removeIdleHandler(this); 107 mIdleMonitorAttached = false; 108 Log.v(TAG, "detached idle handler"); 109 } 110 } 111 112 @Override 113 final void beginHandling(final String line) { 114 // Close-out any prior 'idle' period before starting new task. 115 if (mNumTasksSinceLastIdle == 0) { 116 TraceEvent.end(IDLE_EVENT_NAME); 117 } 118 mLastWorkStartedAt = SystemClock.elapsedRealtime(); 119 syncIdleMonitoring(); 120 super.beginHandling(line); 121 } 122 123 @Override 124 final void endHandling(final String line) { 125 final long elapsed = SystemClock.elapsedRealtime() 126 - mLastWorkStartedAt; 127 if (elapsed > MIN_INTERESTING_DURATION_MILLIS) { 128 traceAndLog(Log.WARN, "observed a task that took " 129 + elapsed + "ms: " + line); 130 } 131 super.endHandling(line); 132 syncIdleMonitoring(); 133 mNumTasksSeen++; 134 mNumTasksSinceLastIdle++; 135 } 136 137 private static void traceAndLog(int level, String message) { 138 TraceEvent.instant("TraceEvent.LooperMonitor:IdleStats", message); 139 Log.println(level, TAG, message); 140 } 141 142 @Override 143 public final boolean queueIdle() { 144 final long now = SystemClock.elapsedRealtime(); 145 if (mLastIdleStartedAt == 0) mLastIdleStartedAt = now; 146 final long elapsed = now - mLastIdleStartedAt; 147 mNumIdlesSeen++; 148 TraceEvent.begin(IDLE_EVENT_NAME, mNumTasksSinceLastIdle + " tasks since last idle."); 149 if (elapsed > MIN_INTERESTING_BURST_DURATION_MILLIS) { 150 // Dump stats 151 String statsString = mNumTasksSeen + " tasks and " 152 + mNumIdlesSeen + " idles processed so far, " 153 + mNumTasksSinceLastIdle + " tasks bursted and " 154 + elapsed + "ms elapsed since last idle"; 155 traceAndLog(Log.DEBUG, statsString); 156 } 157 mLastIdleStartedAt = now; 158 mNumTasksSinceLastIdle = 0; 159 return true; // stay installed 160 } 161 } 162 163 // Holder for monitor avoids unnecessary construction on non-debug runs 164 private static final class LooperMonitorHolder { 165 private static final BasicLooperMonitor sInstance = 166 CommandLine.getInstance().hasSwitch(BaseSwitches.ENABLE_IDLE_TRACING) 167 ? new IdleTracingLooperMonitor() : new BasicLooperMonitor(); 168 } 169 170 171 /** 172 * Register an enabled observer, such that java traces are always enabled with native. 173 */ 174 public static void registerNativeEnabledObserver() { 175 nativeRegisterEnabledObserver(); 176 } 177 178 /** 179 * Notification from native that tracing is enabled/disabled. 180 */ 181 @CalledByNative 182 public static void setEnabled(boolean enabled) { 183 if (enabled) EarlyTraceEvent.disable(); 184 // Only disable logging if Chromium enabled it originally, so as to not disrupt logging done 185 // by other applications 186 if (sEnabled != enabled) { 187 sEnabled = enabled; 188 // Android M+ systrace logs this on its own. Only log it if not writing to Android 189 // systrace. 190 if (sATraceEnabled) return; 191 ThreadUtils.getUiThreadLooper().setMessageLogging( 192 enabled ? LooperMonitorHolder.sInstance : null); 193 } 194 } 195 196 /** 197 * May enable early tracing depending on the environment. 198 * 199 * Must be called after the command-line has been read. 200 */ 201 public static void maybeEnableEarlyTracing() { 202 EarlyTraceEvent.maybeEnable(); 203 } 204 205 /** 206 * Enables or disabled Android systrace path of Chrome tracing. If enabled, all Chrome 207 * traces will be also output to Android systrace. Because of the overhead of Android 208 * systrace, this is for WebView only. 209 */ 210 public static void setATraceEnabled(boolean enabled) { 211 if (sATraceEnabled == enabled) return; 212 sATraceEnabled = enabled; 213 if (enabled) { 214 // Calls TraceEvent.setEnabled(true) via 215 // TraceLog::EnabledStateObserver::OnTraceLogEnabled 216 nativeStartATrace(); 217 } else { 218 // Calls TraceEvent.setEnabled(false) via 219 // TraceLog::EnabledStateObserver::OnTraceLogDisabled 220 nativeStopATrace(); 221 } 222 } 223 224 /** 225 * @return True if tracing is enabled, false otherwise. 226 * It is safe to call trace methods without checking if TraceEvent 227 * is enabled. 228 */ 229 public static boolean enabled() { 230 return sEnabled; 231 } 232 233 /** 234 * Triggers the 'instant' native trace event with no arguments. 235 * @param name The name of the event. 236 */ 237 public static void instant(String name) { 238 if (sEnabled) nativeInstant(name, null); 239 } 240 241 /** 242 * Triggers the 'instant' native trace event. 243 * @param name The name of the event. 244 * @param arg The arguments of the event. 245 */ 246 public static void instant(String name, String arg) { 247 if (sEnabled) nativeInstant(name, arg); 248 } 249 250 /** 251 * Triggers the 'start' native trace event with no arguments. 252 * @param name The name of the event. 253 * @param id The id of the asynchronous event. 254 */ 255 public static void startAsync(String name, long id) { 256 if (sEnabled) nativeStartAsync(name, id); 257 } 258 259 /** 260 * Triggers the 'finish' native trace event with no arguments. 261 * @param name The name of the event. 262 * @param id The id of the asynchronous event. 263 */ 264 public static void finishAsync(String name, long id) { 265 if (sEnabled) nativeFinishAsync(name, id); 266 } 267 268 /** 269 * Triggers the 'begin' native trace event with no arguments. 270 * @param name The name of the event. 271 */ 272 public static void begin(String name) { 273 begin(name, null); 274 } 275 276 /** 277 * Triggers the 'begin' native trace event. 278 * @param name The name of the event. 279 * @param arg The arguments of the event. 280 */ 281 public static void begin(String name, String arg) { 282 EarlyTraceEvent.begin(name); 283 if (sEnabled) nativeBegin(name, arg); 284 } 285 286 /** 287 * Triggers the 'end' native trace event with no arguments. 288 * @param name The name of the event. 289 */ 290 public static void end(String name) { 291 end(name, null); 292 } 293 294 /** 295 * Triggers the 'end' native trace event. 296 * @param name The name of the event. 297 * @param arg The arguments of the event. 298 */ 299 public static void end(String name, String arg) { 300 EarlyTraceEvent.end(name); 301 if (sEnabled) nativeEnd(name, arg); 302 } 303 304 private static native void nativeRegisterEnabledObserver(); 305 private static native void nativeStartATrace(); 306 private static native void nativeStopATrace(); 307 private static native void nativeInstant(String name, String arg); 308 private static native void nativeBegin(String name, String arg); 309 private static native void nativeEnd(String name, String arg); 310 private static native void nativeBeginToplevel(); 311 private static native void nativeEndToplevel(); 312 private static native void nativeStartAsync(String name, long id); 313 private static native void nativeFinishAsync(String name, long id); 314 } 315