src/base/android/java/src/org/chromium/base/PerfTraceEvent.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.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     @VisibleForTesting
  86     public static synchronized void setFilter(List<String> strings) {
  87         sFilter = new LinkedList<String>(strings);
  88     }
  89
  90     /**
  91      * Enable or disable perf tracing.
  92      * Disabling of perf tracing will dump trace data to the system log.
  93      */
  94     @VisibleForTesting
  95     public static synchronized void setEnabled(boolean enabled) {
  96         if (sEnabled == enabled) {
  97             return;
  98         }
  99         if (enabled) {
 100             sBeginNanoTime = System.nanoTime();
 101             sPerfTraceStrings = new JSONArray();
 102         } else {
 103             dumpPerf();
 104             sPerfTraceStrings = null;
 105             sFilter = null;
 106         }
 107         sEnabled = enabled;
 108     }
 109
 110     /**
 111      * Enables memory tracking for all timing perf events tracked.
 112      *
 113      * <p>
 114      * Only works when called in combination with {@link #setEnabled(boolean)}.
 115      *
 116      * <p>
 117      * By enabling this feature, an additional perf event containing the memory usage will be
 118      * logged whenever {@link #instant(String)}, {@link #begin(String)}, or {@link #end(String)}
 119      * is called.
 120      *
 121      * @param enabled Whether to enable memory tracking for all perf events.
 122      */
 123     @VisibleForTesting
 124     public static synchronized void setMemoryTrackingEnabled(boolean enabled) {
 125         sTrackMemory = enabled;
 126     }
 127
 128     /**
 129      * Enables timing tracking for all perf events tracked.
 130      *
 131      * <p>
 132      * Only works when called in combination with {@link #setEnabled(boolean)}.
 133      *
 134      * <p>
 135      * If this feature is enabled, whenever {@link #instant(String)}, {@link #begin(String)},
 136      * or {@link #end(String)} is called the time since start of tracking will be logged.
 137      *
 138      * @param enabled Whether to enable timing tracking for all perf events.
 139      */
 140     @VisibleForTesting
 141     public static synchronized void setTimingTrackingEnabled(boolean enabled) {
 142         sTrackTiming = enabled;
 143     }
 144
 145     /**
 146      * @return True if tracing is enabled, false otherwise.
 147      * It is safe to call trace methods without checking if PerfTraceEvent
 148      * is enabled.
 149      */
 150     @VisibleForTesting
 151     public static synchronized boolean enabled() {
 152         return sEnabled;
 153     }
 154
 155     /**
 156      * Record an "instant" perf trace event.  E.g. "screen update happened".
 157      */
 158     public static synchronized void instant(String name) {
 159         // Instant doesn't really need/take an event id, but this should be okay.
 160         final long eventId = name.hashCode();
 161         TraceEvent.instant(name);
 162         if (sEnabled && matchesFilter(name)) {
 163             savePerfString(name, eventId, EventType.INSTANT, false);
 164         }
 165     }
 166
 167
 168     /**
 169      * Record an "begin" perf trace event.
 170      * Begin trace events should have a matching end event.
 171      */
 172     @VisibleForTesting
 173     public static synchronized void begin(String name) {
 174         final long eventId = name.hashCode();
 175         TraceEvent.startAsync(name, eventId);
 176         if (sEnabled && matchesFilter(name)) {
 177             // Done before calculating the starting perf data to ensure calculating the memory usage
 178             // does not influence the timing data.
 179             if (sTrackMemory) {
 180                 savePerfString(makeMemoryTraceNameFromTimingName(name), eventId, EventType.START,
 181                         true);
 182             }
 183             if (sTrackTiming) {
 184                 savePerfString(name, eventId, EventType.START, false);
 185             }
 186         }
 187     }
 188
 189     /**
 190      * Record an "end" perf trace event, to match a begin event.  The
 191      * time delta between begin and end is usually interesting to
 192      * graph code.
 193      */
 194     @VisibleForTesting
 195     public static synchronized void end(String name) {
 196         final long eventId = name.hashCode();
 197         TraceEvent.finishAsync(name, eventId);
 198         if (sEnabled && matchesFilter(name)) {
 199             if (sTrackTiming) {
 200                 savePerfString(name, eventId, EventType.FINISH, false);
 201             }
 202             // Done after calculating the ending perf data to ensure calculating the memory usage
 203             // does not influence the timing data.
 204             if (sTrackMemory) {
 205                 savePerfString(makeMemoryTraceNameFromTimingName(name), eventId, EventType.FINISH,
 206                         true);
 207             }
 208         }
 209     }
 210
 211     /**
 212      * Record an "begin" memory trace event.
 213      * Begin trace events should have a matching end event.
 214      */
 215     @VisibleForTesting
 216     public static synchronized void begin(String name, MemoryInfo memoryInfo) {
 217         final long eventId = name.hashCode();
 218         TraceEvent.startAsync(name, eventId);
 219         if (sEnabled && matchesFilter(name)) {
 220             // Done before calculating the starting perf data to ensure calculating the memory usage
 221             // does not influence the timing data.
 222             long timestampUs = (System.nanoTime() - sBeginNanoTime) / 1000;
 223             savePerfString(makeMemoryTraceNameFromTimingName(name), eventId, EventType.START,
 224                     timestampUs, memoryInfo);
 225             if (sTrackTiming) {
 226                 savePerfString(name, eventId, EventType.START, false);
 227             }
 228         }
 229     }
 230
 231     /**
 232      * Record an "end" memory trace event, to match a begin event.  The
 233      * memory usage delta between begin and end is usually interesting to
 234      * graph code.
 235      */
 236     @VisibleForTesting
 237     public static synchronized void end(String name, MemoryInfo memoryInfo) {
 238         final long eventId = name.hashCode();
 239         TraceEvent.finishAsync(name, eventId);
 240         if (sEnabled && matchesFilter(name)) {
 241             if (sTrackTiming) {
 242                 savePerfString(name, eventId, EventType.FINISH, false);
 243             }
 244             // Done after calculating the instant perf data to ensure calculating the memory usage
 245             // does not influence the timing data.
 246             long timestampUs = (System.nanoTime() - sBeginNanoTime) / 1000;
 247             savePerfString(makeMemoryTraceNameFromTimingName(name), eventId, EventType.FINISH,
 248                     timestampUs, memoryInfo);
 249         }
 250     }
 251
 252     /**
 253      * Determine if we are interested in this trace event.
 254      * @return True if the name matches the allowed filter; else false.
 255      */
 256     private static boolean matchesFilter(String name) {
 257         return sFilter != null ? sFilter.contains(name) : false;
 258     }
 259
 260     /**
 261      * Save a perf trace event as a JSON dict.  The format mirrors a TraceEvent dict.
 262      *
 263      * @param name The trace data
 264      * @param id The id of the event
 265      * @param type the type of trace event (I, S, F)
 266      * @param includeMemory Whether to include current browser process memory usage in the trace.
 267      */
 268     private static void savePerfString(String name, long id, EventType type,
 269             boolean includeMemory) {
 270         long timestampUs = (System.nanoTime() - sBeginNanoTime) / 1000;
 271         MemoryInfo memInfo = null;
 272         if (includeMemory) {
 273             memInfo = new MemoryInfo();
 274             Debug.getMemoryInfo(memInfo);
 275         }
 276         savePerfString(name, id, type, timestampUs, memInfo);
 277     }
 278
 279     /**
 280      * Save a perf trace event as a JSON dict.  The format mirrors a TraceEvent dict.
 281      *
 282      * @param name The trace data
 283      * @param id The id of the event
 284      * @param type the type of trace event (I, S, F)
 285      * @param timestampUs The time stamp at which this event was recorded
 286      * @param memoryInfo Memory details to be included in this perf string, null if
 287      *                   no memory details are to be included.
 288      */
 289     private static void savePerfString(String name, long id, EventType type, long timestampUs,
 290             MemoryInfo memoryInfo) {
 291         try {
 292             JSONObject traceObj = new JSONObject();
 293             traceObj.put("cat", "Java");
 294             traceObj.put("ts", timestampUs);
 295             traceObj.put("ph", type);
 296             traceObj.put("name", name);
 297             traceObj.put("id", id);
 298             if (memoryInfo != null) {
 299                 int pss = memoryInfo.nativePss + memoryInfo.dalvikPss + memoryInfo.otherPss;
 300                 traceObj.put("mem", pss);
 301             }
 302             sPerfTraceStrings.put(traceObj);
 303         } catch (JSONException e) {
 304             throw new RuntimeException(e);
 305         }
 306     }
 307
 308     /**
 309      * Generating a trace name for tracking memory based on the timing name passed in.
 310      *
 311      * @param name The timing name to use as a base for the memory perf name.
 312      * @return The memory perf name to use.
 313      */
 314     public static String makeMemoryTraceNameFromTimingName(String name) {
 315         return makeSafeTraceName(name, MEMORY_TRACE_NAME_SUFFIX);
 316     }
 317
 318     /**
 319      * Builds a name to be used in the perf trace framework.  The framework has length requirements
 320      * for names, so this ensures the generated name does not exceed the maximum (trimming the
 321      * base name if necessary).
 322      *
 323      * @param baseName The base name to use when generating the name.
 324      * @param suffix The required suffix to be appended to the name.
 325      * @return A name that is safe for the perf trace framework.
 326      */
 327     public static String makeSafeTraceName(String baseName, String suffix) {
 328         int suffixLength = suffix.length();
 329
 330         if (baseName.length() + suffixLength > MAX_NAME_LENGTH) {
 331             baseName = baseName.substring(0, MAX_NAME_LENGTH - suffixLength);
 332         }
 333         return baseName + suffix;
 334     }
 335
 336     /**
 337      * Sets a file to dump the results to.  If {@code file} is {@code null}, it will be dumped
 338      * to STDOUT, otherwise the JSON performance data will be appended to {@code file}.  This should
 339      * be called before the performance run starts.  When {@link #setEnabled(boolean)} is called
 340      * with {@code false}, the perf data will be dumped.
 341      *
 342      * @param file Which file to append the performance data to.  If {@code null}, the performance
 343      *             data will be sent to STDOUT.
 344      */
 345     @VisibleForTesting
 346     public static synchronized void setOutputFile(File file) {
 347         sOutputFile = file;
 348     }
 349
 350     /**
 351      * Dump all performance data we have saved up to the log.
 352      * Output as JSON for parsing convenience.
 353      */
 354     private static void dumpPerf() {
 355         String json = sPerfTraceStrings.toString();
 356
 357         if (sOutputFile == null) {
 358             System.out.println(json);
 359         } else {
 360             try {
 361                 PrintStream stream = new PrintStream(new FileOutputStream(sOutputFile, true));
 362                 try {
 363                     stream.print(json);
 364                 } finally {
 365                     try {
 366                         stream.close();
 367                     } catch (Exception ex) {
 368                         Log.e("PerfTraceEvent", "Unable to close perf trace output file.");
 369                     }
 370                 }
 371             } catch (FileNotFoundException ex) {
 372                 Log.e("PerfTraceEvent", "Unable to dump perf trace data to output file.");
 373             }
 374         }
 375     }
 376 }