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