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