src/base/android/java/src/org/chromium/base/TraceEvent.java

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