| 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.Debug; |
| 8 | import android.os.Debug.MemoryInfo; |
| 9 | import android.util.Log; |
| 10 | |
| 11 | import org.json.JSONArray; |
| 12 | import org.json.JSONException; |
| 13 | import org.json.JSONObject; |
| 14 | |
| 15 | import java.io.File; |
| 16 | import java.io.FileNotFoundException; |
| 17 | import java.io.FileOutputStream; |
| 18 | import java.io.PrintStream; |
| 19 | import java.util.LinkedList; |
| 20 | import java.util.List; |
| 21 | |
| 22 | /** |
| 23 | * PerfTraceEvent can be used like TraceEvent, but is intended for |
| 24 | * performance measurement. By limiting the types of tracing we hope |
| 25 | * to minimize impact on measurement. |
| 26 | * |
| 27 | * All PerfTraceEvent events funnel into TraceEvent. When not doing |
| 28 | * performance measurements, they act the same. However, |
| 29 | * PerfTraceEvents can be enabled even when TraceEvent is not. |
| 30 | * |
| 31 | * Unlike TraceEvent, PerfTraceEvent data is sent to the system log, |
| 32 | * not to a trace file. |
| 33 | * |
| 34 | * Performance events need to have very specific names so we find |
| 35 | * the right ones. For example, we specify the name exactly in |
| 36 | * the @TracePerf annotation. Thus, unlike TraceEvent, we do not |
| 37 | * support an implicit trace name based on the callstack. |
| 38 | */ |
| 39 | public class PerfTraceEvent { |
| 40 | private static final int MAX_NAME_LENGTH = 40; |
| 41 | private static final String MEMORY_TRACE_NAME_SUFFIX = "_BZR_PSS"; |
| 42 | private static File sOutputFile = null; |
| 43 | |
| 44 | /** The event types understood by the perf trace scripts. */ |
| 45 | private enum EventType { |
| 46 | START("S"), |
| 47 | FINISH("F"), |
| 48 | INSTANT("I"); |
| 49 | |
| 50 | // The string understood by the trace scripts. |
| 51 | private final String mTypeStr; |
| 52 | |
| 53 | EventType(String typeStr) { |
| 54 | mTypeStr = typeStr; |
| 55 | } |
| 56 | |
| 57 | @Override |
| 58 | public String toString() { |
| 59 | return mTypeStr; |
| 60 | } |
| 61 | } |
| 62 | |
| 63 | private static boolean sEnabled = false; |
| 64 | private static boolean sTrackTiming = true; |
| 65 | private static boolean sTrackMemory = false; |
| 66 | |
| 67 | // A list of performance trace event strings. |
| 68 | // Events are stored as a JSON dict much like TraceEvent. |
| 69 | // E.g. timestamp is in microseconds. |
| 70 | private static JSONArray sPerfTraceStrings; |
| 71 | |
| 72 | // A filter for performance tracing. Only events that match a |
| 73 | // string in the list are saved. Presence of a filter does not |
| 74 | // necessarily mean perf tracing is enabled. |
| 75 | private static List<String> sFilter; |
| 76 | |
| 77 | // Nanosecond start time of performance tracing. |
| 78 | private static long sBeginNanoTime; |
| 79 | |
| 80 | /** |
| 81 | * Specifies what event names will be tracked. |
| 82 | * |
| 83 | * @param strings Event names we will record. |
| 84 | */ |
| 85 | public static synchronized void setFilter(List<String> strings) { |
| 86 | sFilter = new LinkedList<String>(strings); |
| 87 | } |
| 88 | |
| 89 | /** |
| 90 | * Enable or disable perf tracing. |
| 91 | * Disabling of perf tracing will dump trace data to the system log. |
| 92 | */ |
| 93 | public static synchronized void setEnabled(boolean enabled) { |
| 94 | if (sEnabled == enabled) { |
| 95 | return; |
| 96 | } |
| 97 | if (enabled) { |
| 98 | sBeginNanoTime = System.nanoTime(); |
| 99 | sPerfTraceStrings = new JSONArray(); |
| 100 | } else { |
| 101 | dumpPerf(); |
| 102 | sPerfTraceStrings = null; |
| 103 | sFilter = null; |
| 104 | } |
| 105 | sEnabled = enabled; |
| 106 | } |
| 107 | |
| 108 | /** |
| 109 | * Enables memory tracking for all timing perf events tracked. |
| 110 | * |
| 111 | * <p> |
| 112 | * Only works when called in combination with {@link #setEnabled(boolean)}. |
| 113 | * |
| 114 | * <p> |
| 115 | * By enabling this feature, an additional perf event containing the memory usage will be |
| 116 | * logged whenever {@link #instant(String)}, {@link #begin(String)}, or {@link #end(String)} |
| 117 | * is called. |
| 118 | * |
| 119 | * @param enabled Whether to enable memory tracking for all perf events. |
| 120 | */ |
| 121 | public static synchronized void setMemoryTrackingEnabled(boolean enabled) { |
| 122 | sTrackMemory = enabled; |
| 123 | } |
| 124 | |
| 125 | /** |
| 126 | * Enables timing tracking for all perf events tracked. |
| 127 | * |
| 128 | * <p> |
| 129 | * Only works when called in combination with {@link #setEnabled(boolean)}. |
| 130 | * |
| 131 | * <p> |
| 132 | * If this feature is enabled, whenever {@link #instant(String)}, {@link #begin(String)}, |
| 133 | * or {@link #end(String)} is called the time since start of tracking will be logged. |
| 134 | * |
| 135 | * @param enabled Whether to enable timing tracking for all perf events. |
| 136 | */ |
| 137 | public static synchronized void setTimingTrackingEnabled(boolean enabled) { |
| 138 | sTrackTiming = enabled; |
| 139 | } |
| 140 | |
| 141 | /** |
| 142 | * @return True if tracing is enabled, false otherwise. |
| 143 | * It is safe to call trace methods without checking if PerfTraceEvent |
| 144 | * is enabled. |
| 145 | */ |
| 146 | public static synchronized boolean enabled() { |
| 147 | return sEnabled; |
| 148 | } |
| 149 | |
| 150 | /** |
| 151 | * Record an "instant" perf trace event. E.g. "screen update happened". |
| 152 | */ |
| 153 | public static synchronized void instant(String name) { |
| 154 | // Instant doesn't really need/take an event id, but this should be okay. |
| 155 | final long eventId = name.hashCode(); |
| 156 | TraceEvent.instant(name); |
| 157 | if (sEnabled && matchesFilter(name)) { |
| 158 | savePerfString(name, eventId, EventType.INSTANT, false); |
| 159 | } |
| 160 | } |
| 161 | |
| 162 | |
| 163 | /** |
| 164 | * Record an "begin" perf trace event. |
| 165 | * Begin trace events should have a matching end event. |
| 166 | */ |
| 167 | public static synchronized void begin(String name) { |
| 168 | final long eventId = name.hashCode(); |
| 169 | TraceEvent.startAsync(name, eventId); |
| 170 | if (sEnabled && matchesFilter(name)) { |
| 171 | // Done before calculating the starting perf data to ensure calculating the memory usage |
| 172 | // does not influence the timing data. |
| 173 | if (sTrackMemory) { |
| 174 | savePerfString(makeMemoryTraceNameFromTimingName(name), eventId, EventType.START, |
| 175 | true); |
| 176 | } |
| 177 | if (sTrackTiming) { |
| 178 | savePerfString(name, eventId, EventType.START, false); |
| 179 | } |
| 180 | } |
| 181 | } |
| 182 | |
| 183 | /** |
| 184 | * Record an "end" perf trace event, to match a begin event. The |
| 185 | * time delta between begin and end is usually interesting to |
| 186 | * graph code. |
| 187 | */ |
| 188 | public static synchronized void end(String name) { |
| 189 | final long eventId = name.hashCode(); |
| 190 | TraceEvent.finishAsync(name, eventId); |
| 191 | if (sEnabled && matchesFilter(name)) { |
| 192 | if (sTrackTiming) { |
| 193 | savePerfString(name, eventId, EventType.FINISH, false); |
| 194 | } |
| 195 | // Done after calculating the ending perf data to ensure calculating the memory usage |
| 196 | // does not influence the timing data. |
| 197 | if (sTrackMemory) { |
| 198 | savePerfString(makeMemoryTraceNameFromTimingName(name), eventId, EventType.FINISH, |
| 199 | true); |
| 200 | } |
| 201 | } |
| 202 | } |
| 203 | |
| 204 | /** |
| 205 | * Record an "begin" memory trace event. |
| 206 | * Begin trace events should have a matching end event. |
| 207 | */ |
| 208 | public static synchronized void begin(String name, MemoryInfo memoryInfo) { |
| 209 | final long eventId = name.hashCode(); |
| 210 | TraceEvent.startAsync(name, eventId); |
| 211 | if (sEnabled && matchesFilter(name)) { |
| 212 | // Done before calculating the starting perf data to ensure calculating the memory usage |
| 213 | // does not influence the timing data. |
| 214 | long timestampUs = (System.nanoTime() - sBeginNanoTime) / 1000; |
| 215 | savePerfString(makeMemoryTraceNameFromTimingName(name), eventId, EventType.START, |
| 216 | timestampUs, memoryInfo); |
| 217 | if (sTrackTiming) { |
| 218 | savePerfString(name, eventId, EventType.START, false); |
| 219 | } |
| 220 | } |
| 221 | } |
| 222 | |
| 223 | /** |
| 224 | * Record an "end" memory trace event, to match a begin event. The |
| 225 | * memory usage delta between begin and end is usually interesting to |
| 226 | * graph code. |
| 227 | */ |
| 228 | public static synchronized void end(String name, MemoryInfo memoryInfo) { |
| 229 | final long eventId = name.hashCode(); |
| 230 | TraceEvent.finishAsync(name, eventId); |
| 231 | if (sEnabled && matchesFilter(name)) { |
| 232 | if (sTrackTiming) { |
| 233 | savePerfString(name, eventId, EventType.FINISH, false); |
| 234 | } |
| 235 | // Done after calculating the instant perf data to ensure calculating the memory usage |
| 236 | // does not influence the timing data. |
| 237 | long timestampUs = (System.nanoTime() - sBeginNanoTime) / 1000; |
| 238 | savePerfString(makeMemoryTraceNameFromTimingName(name), eventId, EventType.FINISH, |
| 239 | timestampUs, memoryInfo); |
| 240 | } |
| 241 | } |
| 242 | |
| 243 | /** |
| 244 | * Determine if we are interested in this trace event. |
| 245 | * @return True if the name matches the allowed filter; else false. |
| 246 | */ |
| 247 | private static boolean matchesFilter(String name) { |
| 248 | return sFilter != null ? sFilter.contains(name) : false; |
| 249 | } |
| 250 | |
| 251 | /** |
| 252 | * Save a perf trace event as a JSON dict. The format mirrors a TraceEvent dict. |
| 253 | * |
| 254 | * @param name The trace data |
| 255 | * @param id The id of the event |
| 256 | * @param type the type of trace event (I, S, F) |
| 257 | * @param includeMemory Whether to include current browser process memory usage in the trace. |
| 258 | */ |
| 259 | private static void savePerfString(String name, long id, EventType type, |
| 260 | boolean includeMemory) { |
| 261 | long timestampUs = (System.nanoTime() - sBeginNanoTime) / 1000; |
| 262 | MemoryInfo memInfo = null; |
| 263 | if (includeMemory) { |
| 264 | memInfo = new MemoryInfo(); |
| 265 | Debug.getMemoryInfo(memInfo); |
| 266 | } |
| 267 | savePerfString(name, id, type, timestampUs, memInfo); |
| 268 | } |
| 269 | |
| 270 | /** |
| 271 | * Save a perf trace event as a JSON dict. The format mirrors a TraceEvent dict. |
| 272 | * |
| 273 | * @param name The trace data |
| 274 | * @param id The id of the event |
| 275 | * @param type the type of trace event (I, S, F) |
| 276 | * @param timestampUs The time stamp at which this event was recorded |
| 277 | * @param memoryInfo Memory details to be included in this perf string, null if |
| 278 | * no memory details are to be included. |
| 279 | */ |
| 280 | private static void savePerfString(String name, long id, EventType type, long timestampUs, |
| 281 | MemoryInfo memoryInfo) { |
| 282 | try { |
| 283 | JSONObject traceObj = new JSONObject(); |
| 284 | traceObj.put("cat", "Java"); |
| 285 | traceObj.put("ts", timestampUs); |
| 286 | traceObj.put("ph", type); |
| 287 | traceObj.put("name", name); |
| 288 | traceObj.put("id", id); |
| 289 | if (memoryInfo != null) { |
| 290 | int pss = memoryInfo.nativePss + memoryInfo.dalvikPss + memoryInfo.otherPss; |
| 291 | traceObj.put("mem", pss); |
| 292 | } |
| 293 | sPerfTraceStrings.put(traceObj); |
| 294 | } catch (JSONException e) { |
| 295 | throw new RuntimeException(e); |
| 296 | } |
| 297 | } |
| 298 | |
| 299 | /** |
| 300 | * Generating a trace name for tracking memory based on the timing name passed in. |
| 301 | * |
| 302 | * @param name The timing name to use as a base for the memory perf name. |
| 303 | * @return The memory perf name to use. |
| 304 | */ |
| 305 | public static String makeMemoryTraceNameFromTimingName(String name) { |
| 306 | return makeSafeTraceName(name, MEMORY_TRACE_NAME_SUFFIX); |
| 307 | } |
| 308 | |
| 309 | /** |
| 310 | * Builds a name to be used in the perf trace framework. The framework has length requirements |
| 311 | * for names, so this ensures the generated name does not exceed the maximum (trimming the |
| 312 | * base name if necessary). |
| 313 | * |
| 314 | * @param baseName The base name to use when generating the name. |
| 315 | * @param suffix The required suffix to be appended to the name. |
| 316 | * @return A name that is safe for the perf trace framework. |
| 317 | */ |
| 318 | public static String makeSafeTraceName(String baseName, String suffix) { |
| 319 | int suffixLength = suffix.length(); |
| 320 | |
| 321 | if (baseName.length() + suffixLength > MAX_NAME_LENGTH) { |
| 322 | baseName = baseName.substring(0, MAX_NAME_LENGTH - suffixLength); |
| 323 | } |
| 324 | return baseName + suffix; |
| 325 | } |
| 326 | |
| 327 | /** |
| 328 | * Sets a file to dump the results to. If {@code file} is {@code null}, it will be dumped |
| 329 | * to STDOUT, otherwise the JSON performance data will be appended to {@code file}. This should |
| 330 | * be called before the performance run starts. When {@link #setEnabled(boolean)} is called |
| 331 | * with {@code false}, the perf data will be dumped. |
| 332 | * |
| 333 | * @param file Which file to append the performance data to. If {@code null}, the performance |
| 334 | * data will be sent to STDOUT. |
| 335 | */ |
| 336 | public static synchronized void setOutputFile(File file) { |
| 337 | sOutputFile = file; |
| 338 | } |
| 339 | |
| 340 | /** |
| 341 | * Dump all performance data we have saved up to the log. |
| 342 | * Output as JSON for parsing convenience. |
| 343 | */ |
| 344 | private static void dumpPerf() { |
| 345 | String json = sPerfTraceStrings.toString(); |
| 346 | |
| 347 | if (sOutputFile == null) { |
| 348 | System.out.println(json); |
| 349 | } else { |
| 350 | try { |
| 351 | PrintStream stream = new PrintStream(new FileOutputStream(sOutputFile, true)); |
| 352 | try { |
| 353 | stream.print(json); |
| 354 | } finally { |
| 355 | try { |
| 356 | stream.close(); |
| 357 | } catch (Exception ex) { |
| 358 | Log.e("PerfTraceEvent", "Unable to close perf trace output file."); |
| 359 | } |
| 360 | } |
| 361 | } catch (FileNotFoundException ex) { |
| 362 | Log.e("PerfTraceEvent", "Unable to dump perf trace data to output file."); |
| 363 | } |
| 364 | } |
| 365 | } |
| 366 | } |