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