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 5package org.chromium.base; 6 7import android.os.Looper; 8import android.os.MessageQueue; 9import android.os.SystemClock; 10import android.util.Log; 11import android.util.Printer; 12/** 13 * Java mirror of Chrome trace event API. See base/debug/trace_event.h. Unlike the native version, 14 * Java does not have stack objects, so a TRACE_EVENT() which does both TRACE_EVENT_BEGIN() and 15 * TRACE_EVENT_END() in ctor/dtor is not possible. 16 * It is OK to use tracing before the native library has loaded, but such traces will 17 * be ignored. (Perhaps we could devise to buffer them up in future?). 18 */ 19@JNINamespace("base::android") 20public class TraceEvent { 21 22 private static volatile boolean sEnabled = false; 23 24 private static class BasicLooperMonitor implements Printer { 25 @Override 26 public void println(final String line) { 27 if (line.startsWith(">")) { 28 beginHandling(line); 29 } else { 30 assert line.startsWith("<"); 31 endHandling(line); 32 } 33 } 34 35 void beginHandling(final String line) { 36 if (sEnabled) nativeBeginToplevel(); 37 } 38 39 void endHandling(final String line) { 40 if (sEnabled) nativeEndToplevel(); 41 } 42 } 43 44 /** 45 * A class that records, traces and logs statistics about the UI thead's Looper. 46 * The output of this class can be used in a number of interesting ways: 47 * <p> 48 * <ol><li> 49 * When using chrometrace, there will be a near-continuous line of 50 * measurements showing both event dispatches as well as idles; 51 * </li><li> 52 * Logging messages are output for events that run too long on the 53 * event dispatcher, making it easy to identify problematic areas; 54 * </li><li> 55 * Statistics are output whenever there is an idle after a non-trivial 56 * amount of activity, allowing information to be gathered about task 57 * density and execution cadence on the Looper; 58 * </li></ol> 59 * <p> 60 * The class attaches itself as an idle handler to the main Looper, and 61 * monitors the execution of events and idle notifications. Task counters 62 * accumulate between idle notifications and get reset when a new idle 63 * notification is received. 64 */ 65 private static final class IdleTracingLooperMonitor extends BasicLooperMonitor 66 implements MessageQueue.IdleHandler { 67 // Tags for dumping to logcat or TraceEvent 68 private static final String TAG = "TraceEvent.LooperMonitor"; 69 private static final String IDLE_EVENT_NAME = "Looper.queueIdle"; 70 71 // Calculation constants 72 private static final long FRAME_DURATION_MILLIS = 1000L / 60L; // 60 FPS 73 // A reasonable threshold for defining a Looper event as "long running" 74 private static final long MIN_INTERESTING_DURATION_MILLIS = 75 FRAME_DURATION_MILLIS; 76 // A reasonable threshold for a "burst" of tasks on the Looper 77 private static final long MIN_INTERESTING_BURST_DURATION_MILLIS = 78 MIN_INTERESTING_DURATION_MILLIS * 3; 79 80 // Stats tracking 81 private long mLastIdleStartedAt = 0L; 82 private long mLastWorkStartedAt = 0L; 83 private int mNumTasksSeen = 0; 84 private int mNumIdlesSeen = 0; 85 private int mNumTasksSinceLastIdle = 0; 86 87 // State 88 private boolean mIdleMonitorAttached = false; 89 90 // Called from within the begin/end methods only. 91 // This method can only execute on the looper thread, because that is 92 // the only thread that is permitted to call Looper.myqueue(). 93 private final void syncIdleMonitoring() { 94 if (sEnabled && !mIdleMonitorAttached) { 95 // approximate start time for computational purposes 96 mLastIdleStartedAt = SystemClock.elapsedRealtime(); 97 Looper.myQueue().addIdleHandler(this); 98 mIdleMonitorAttached = true; 99 Log.v(TAG, "attached idle handler"); 100 } else if (mIdleMonitorAttached && !sEnabled) { 101 Looper.myQueue().removeIdleHandler(this); 102 mIdleMonitorAttached = false; 103 Log.v(TAG, "detached idle handler"); 104 } 105 } 106 107 @Override 108 final void beginHandling(final String line) { 109 // Close-out any prior 'idle' period before starting new task. 110 if (mNumTasksSinceLastIdle == 0) { 111 TraceEvent.end(IDLE_EVENT_NAME); 112 } 113 mLastWorkStartedAt = SystemClock.elapsedRealtime(); 114 syncIdleMonitoring(); 115 super.beginHandling(line); 116 } 117 118 @Override 119 final void endHandling(final String line) { 120 final long elapsed = SystemClock.elapsedRealtime() 121 - mLastWorkStartedAt; 122 if (elapsed > MIN_INTERESTING_DURATION_MILLIS) { 123 traceAndLog(Log.WARN, "observed a task that took " 124 + elapsed + "ms: " + line); 125 } 126 super.endHandling(line); 127 syncIdleMonitoring(); 128 mNumTasksSeen++; 129 mNumTasksSinceLastIdle++; 130 } 131 132 private static void traceAndLog(int level, String message) { 133 TraceEvent.instant("TraceEvent.LooperMonitor:IdleStats", message); 134 Log.println(level, TAG, message); 135 } 136 137 @Override 138 public final boolean queueIdle() { 139 final long now = SystemClock.elapsedRealtime(); 140 if (mLastIdleStartedAt == 0) mLastIdleStartedAt = now; 141 final long elapsed = now - mLastIdleStartedAt; 142 mNumIdlesSeen++; 143 TraceEvent.begin(IDLE_EVENT_NAME, mNumTasksSinceLastIdle + " tasks since last idle."); 144 if (elapsed > MIN_INTERESTING_BURST_DURATION_MILLIS) { 145 // Dump stats 146 String statsString = mNumTasksSeen + " tasks and " 147 + mNumIdlesSeen + " idles processed so far, " 148 + mNumTasksSinceLastIdle + " tasks bursted and " 149 + elapsed + "ms elapsed since last idle"; 150 traceAndLog(Log.DEBUG, statsString); 151 } 152 mLastIdleStartedAt = now; 153 mNumTasksSinceLastIdle = 0; 154 return true; // stay installed 155 } 156 } 157 158 // Holder for monitor avoids unnecessary construction on non-debug runs 159 private static final class LooperMonitorHolder { 160 private static final BasicLooperMonitor sInstance = 161 CommandLine.getInstance().hasSwitch(BaseSwitches.ENABLE_IDLE_TRACING) ? 162 new IdleTracingLooperMonitor() : new BasicLooperMonitor(); 163 } 164 165 166 /** 167 * Register an enabled observer, such that java traces are always enabled with native. 168 */ 169 public static void registerNativeEnabledObserver() { 170 nativeRegisterEnabledObserver(); 171 } 172 173 /** 174 * Notification from native that tracing is enabled/disabled. 175 */ 176 @CalledByNative 177 public static void setEnabled(boolean enabled) { 178 sEnabled = enabled; 179 ThreadUtils.getUiThreadLooper().setMessageLogging( 180 enabled ? LooperMonitorHolder.sInstance : null); 181 } 182 183 /** 184 * Enables or disabled Android systrace path of Chrome tracing. If enabled, all Chrome 185 * traces will be also output to Android systrace. Because of the overhead of Android 186 * systrace, this is for WebView only. 187 */ 188 public static void setATraceEnabled(boolean enabled) { 189 if (sEnabled == enabled) return; 190 if (enabled) { 191 nativeStartATrace(); 192 } else { 193 nativeStopATrace(); 194 } 195 } 196 197 /** 198 * @return True if tracing is enabled, false otherwise. 199 * It is safe to call trace methods without checking if TraceEvent 200 * is enabled. 201 */ 202 public static boolean enabled() { 203 return sEnabled; 204 } 205 206 /** 207 * Triggers the 'instant' native trace event with no arguments. 208 * @param name The name of the event. 209 */ 210 public static void instant(String name) { 211 if (sEnabled) nativeInstant(name, null); 212 } 213 214 /** 215 * Triggers the 'instant' native trace event. 216 * @param name The name of the event. 217 * @param arg The arguments of the event. 218 */ 219 public static void instant(String name, String arg) { 220 if (sEnabled) nativeInstant(name, arg); 221 } 222 223 /** 224 * Convenience wrapper around the versions of startAsync() that take string parameters. 225 * @param id The id of the asynchronous event. 226 * @see #begin() 227 */ 228 public static void startAsync(long id) { 229 if (sEnabled) nativeStartAsync(getCallerName(), id, null); 230 } 231 232 /** 233 * Triggers the 'start' native trace event with no arguments. 234 * @param name The name of the event. 235 * @param id The id of the asynchronous event. 236 */ 237 public static void startAsync(String name, long id) { 238 if (sEnabled) nativeStartAsync(name, id, null); 239 } 240 241 /** 242 * Triggers the 'start' native trace event. 243 * @param name The name of the event. 244 * @param id The id of the asynchronous event. 245 * @param arg The arguments of the event. 246 */ 247 public static void startAsync(String name, long id, String arg) { 248 if (sEnabled) nativeStartAsync(name, id, arg); 249 } 250 251 /** 252 * Convenience wrapper around the versions of finishAsync() that take string parameters. 253 * @param id The id of the asynchronous event. 254 * @see #begin() 255 */ 256 public static void finishAsync(long id) { 257 if (sEnabled) nativeFinishAsync(getCallerName(), id, null); 258 } 259 260 /** 261 * Triggers the 'finish' native trace event with no arguments. 262 * @param name The name of the event. 263 * @param id The id of the asynchronous event. 264 */ 265 public static void finishAsync(String name, long id) { 266 if (sEnabled) nativeFinishAsync(name, id, null); 267 } 268 269 /** 270 * Triggers the 'finish' native trace event. 271 * @param name The name of the event. 272 * @param id The id of the asynchronous event. 273 * @param arg The arguments of the event. 274 */ 275 public static void finishAsync(String name, long id, String arg) { 276 if (sEnabled) nativeFinishAsync(name, id, arg); 277 } 278 279 /** 280 * Convenience wrapper around the versions of begin() that take string parameters. 281 * The name of the event will be derived from the class and function name that call this. 282 * IMPORTANT: if using this version, ensure end() (no parameters) is always called from the 283 * same calling context. 284 * 285 * Note that the overhead is at ms or sub-ms order. Don't use this when millisecond accuracy 286 * is desired. 287 */ 288 public static void begin() { 289 if (sEnabled) nativeBegin(getCallerName(), null); 290 } 291 292 /** 293 * Triggers the 'begin' native trace event with no arguments. 294 * @param name The name of the event. 295 */ 296 public static void begin(String name) { 297 if (sEnabled) nativeBegin(name, null); 298 } 299 300 /** 301 * Triggers the 'begin' native trace event. 302 * @param name The name of the event. 303 * @param arg The arguments of the event. 304 */ 305 public static void begin(String name, String arg) { 306 if (sEnabled) nativeBegin(name, arg); 307 } 308 309 /** 310 * Convenience wrapper around the versions of end() that take string parameters. 311 * @see #begin() 312 */ 313 public static void end() { 314 if (sEnabled) nativeEnd(getCallerName(), null); 315 } 316 317 /** 318 * Triggers the 'end' native trace event with no arguments. 319 * @param name The name of the event. 320 */ 321 public static void end(String name) { 322 if (sEnabled) nativeEnd(name, null); 323 } 324 325 /** 326 * Triggers the 'end' native trace event. 327 * @param name The name of the event. 328 * @param arg The arguments of the event. 329 */ 330 public static void end(String name, String arg) { 331 if (sEnabled) nativeEnd(name, arg); 332 } 333 334 private static String getCallerName() { 335 // This was measured to take about 1ms on Trygon device. 336 StackTraceElement[] stack = java.lang.Thread.currentThread().getStackTrace(); 337 338 // Commented out to avoid excess call overhead, but these lines can be useful to debug 339 // exactly where the TraceEvent's client is on the callstack. 340 // int index = 0; 341 // while (!stack[index].getClassName().equals(TraceEvent.class.getName())) ++index; 342 // while (stack[index].getClassName().equals(TraceEvent.class.getName())) ++index; 343 // System.logW("TraceEvent caller is at stack index " + index); 344 345 // '4' Was derived using the above commented out code snippet. 346 return stack[4].getClassName() + "." + stack[4].getMethodName(); 347 } 348 349 private static native void nativeRegisterEnabledObserver(); 350 private static native void nativeStartATrace(); 351 private static native void nativeStopATrace(); 352 private static native void nativeInstant(String name, String arg); 353 private static native void nativeBegin(String name, String arg); 354 private static native void nativeEnd(String name, String arg); 355 private static native void nativeBeginToplevel(); 356 private static native void nativeEndToplevel(); 357 private static native void nativeStartAsync(String name, long id, String arg); 358 private static native void nativeFinishAsync(String name, long id, String arg); 359} 360