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.Looper;
   8 import android.os.MessageQueue;
   9 import android.os.SystemClock;
  10 import android.util.Log;
  11 import 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")
  20 public 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 }