• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1 // Copyright 2014 The Chromium Authors
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.app.Activity;
8 import android.content.res.Resources.NotFoundException;
9 import android.os.Looper;
10 import android.os.MessageQueue;
11 import android.util.Log;
12 import android.util.Printer;
13 import android.view.View;
14 import android.view.ViewGroup;
15 
16 import androidx.annotation.VisibleForTesting;
17 
18 import org.jni_zero.CalledByNative;
19 import org.jni_zero.JNINamespace;
20 import org.jni_zero.NativeMethods;
21 
22 import org.chromium.base.task.PostTask;
23 import org.chromium.base.task.TaskTraits;
24 
25 import java.util.ArrayList;
26 
27 /**
28  * Java mirror of Chrome trace event API. See base/trace_event/trace_event.h.
29  *
30  * To get scoped trace events, use the "try with resource" construct, for instance:
31  * <pre>{@code
32  * try (TraceEvent e = TraceEvent.scoped("MyTraceEvent")) {
33  *   // code.
34  * }
35  * }</pre>
36  *
37  * The event name of the trace events must be a string literal or a |static final String| class
38  * member. Otherwise NoDynamicStringsInTraceEventCheck error will be thrown.
39  *
40  * It is OK to use tracing before the native library has loaded, in a slightly restricted fashion.
41  * @see EarlyTraceEvent for details.
42  */
43 @JNINamespace("base::android")
44 public class TraceEvent implements AutoCloseable {
45     private static volatile boolean sEnabled; // True when tracing into Chrome's tracing service.
46     private static volatile boolean sUiThreadReady;
47     private static boolean sEventNameFilteringEnabled;
48 
49     @VisibleForTesting(otherwise = VisibleForTesting.PRIVATE)
50     static class BasicLooperMonitor implements Printer {
51         @VisibleForTesting(otherwise = VisibleForTesting.PRIVATE)
52         static final String LOOPER_TASK_PREFIX = "Looper.dispatch: ";
53 
54         @VisibleForTesting(otherwise = VisibleForTesting.PRIVATE)
55         static final String FILTERED_EVENT_NAME = LOOPER_TASK_PREFIX + "EVENT_NAME_FILTERED";
56 
57         private static final int SHORTEST_LOG_PREFIX_LENGTH = "<<<<< Finished to ".length();
58         private String mCurrentTarget;
59 
60         @Override
println(final String line)61         public void println(final String line) {
62             if (line.startsWith(">")) {
63                 beginHandling(line);
64             } else {
65                 assert line.startsWith("<");
66                 endHandling(line);
67             }
68         }
69 
beginHandling(final String line)70         void beginHandling(final String line) {
71             // May return an out-of-date value. this is not an issue as EarlyTraceEvent#begin()
72             // will filter the event in this case.
73             boolean earlyTracingActive = EarlyTraceEvent.enabled();
74             if (sEnabled || earlyTracingActive) {
75                 // Note that we don't need to log ATrace events here because the
76                 // framework does that for us (M+).
77                 mCurrentTarget = getTraceEventName(line);
78                 if (sEnabled) {
79                     TraceEventJni.get().beginToplevel(mCurrentTarget);
80                 } else {
81                     EarlyTraceEvent.begin(mCurrentTarget, /* isToplevel= */ true);
82                 }
83             }
84         }
85 
endHandling(final String line)86         void endHandling(final String line) {
87             boolean earlyTracingActive = EarlyTraceEvent.enabled();
88             if ((sEnabled || earlyTracingActive) && mCurrentTarget != null) {
89                 if (sEnabled) {
90                     TraceEventJni.get().endToplevel(mCurrentTarget);
91                 } else {
92                     EarlyTraceEvent.end(mCurrentTarget, /* isToplevel= */ true);
93                 }
94             }
95             mCurrentTarget = null;
96         }
97 
98         @VisibleForTesting(otherwise = VisibleForTesting.PRIVATE)
getTraceEventName(String line)99         static String getTraceEventName(String line) {
100             if (sEventNameFilteringEnabled) {
101                 return FILTERED_EVENT_NAME;
102             }
103             return LOOPER_TASK_PREFIX + getTarget(line) + "(" + getTargetName(line) + ")";
104         }
105 
106         /**
107          * Android Looper formats |logLine| as
108          *
109          * ">>>>> Dispatching to (TARGET) {HASH_CODE} TARGET_NAME: WHAT"
110          *
111          * and
112          *
113          * "<<<<< Finished to (TARGET) {HASH_CODE} TARGET_NAME".
114          *
115          * This has been the case since at least 2009 (Donut). This function extracts the
116          * TARGET part of the message.
117          */
getTarget(String logLine)118         private static String getTarget(String logLine) {
119             int start = logLine.indexOf('(', SHORTEST_LOG_PREFIX_LENGTH);
120             int end = start == -1 ? -1 : logLine.indexOf(')', start);
121             return end != -1 ? logLine.substring(start + 1, end) : "";
122         }
123 
124         // Extracts the TARGET_NAME part of the log message (see above).
getTargetName(String logLine)125         private static String getTargetName(String logLine) {
126             int start = logLine.indexOf('}', SHORTEST_LOG_PREFIX_LENGTH);
127             int end = start == -1 ? -1 : logLine.indexOf(':', start);
128             if (end == -1) {
129                 end = logLine.length();
130             }
131             return start != -1 ? logLine.substring(start + 2, end) : "";
132         }
133     }
134 
135     /**
136      * A class that records, traces and logs statistics about the UI thead's Looper.
137      * The output of this class can be used in a number of interesting ways:
138      * <p>
139      * <ol><li>
140      * When using chrometrace, there will be a near-continuous line of
141      * measurements showing both event dispatches as well as idles;
142      * </li><li>
143      * Logging messages are output for events that run too long on the
144      * event dispatcher, making it easy to identify problematic areas;
145      * </li><li>
146      * Statistics are output whenever there is an idle after a non-trivial
147      * amount of activity, allowing information to be gathered about task
148      * density and execution cadence on the Looper;
149      * </li></ol>
150      * <p>
151      * The class attaches itself as an idle handler to the main Looper, and
152      * monitors the execution of events and idle notifications. Task counters
153      * accumulate between idle notifications and get reset when a new idle
154      * notification is received.
155      */
156     private static final class IdleTracingLooperMonitor extends BasicLooperMonitor
157             implements MessageQueue.IdleHandler {
158         // Tags for dumping to logcat or TraceEvent
159         private static final String TAG = "TraceEvt_LooperMonitor";
160         private static final String IDLE_EVENT_NAME = "Looper.queueIdle";
161 
162         // Calculation constants
163         private static final long FRAME_DURATION_MILLIS = 1000L / 60L; // 60 FPS
164         // A reasonable threshold for defining a Looper event as "long running"
165         private static final long MIN_INTERESTING_DURATION_MILLIS = FRAME_DURATION_MILLIS;
166         // A reasonable threshold for a "burst" of tasks on the Looper
167         private static final long MIN_INTERESTING_BURST_DURATION_MILLIS =
168                 MIN_INTERESTING_DURATION_MILLIS * 3;
169 
170         // Stats tracking
171         private long mLastIdleStartedAt;
172         private long mLastWorkStartedAt;
173         private int mNumTasksSeen;
174         private int mNumIdlesSeen;
175         private int mNumTasksSinceLastIdle;
176 
177         // State
178         private boolean mIdleMonitorAttached;
179 
180         // Called from within the begin/end methods only.
181         // This method can only execute on the looper thread, because that is
182         // the only thread that is permitted to call Looper.myqueue().
syncIdleMonitoring()183         private final void syncIdleMonitoring() {
184             if (sEnabled && !mIdleMonitorAttached) {
185                 // approximate start time for computational purposes
186                 mLastIdleStartedAt = TimeUtils.elapsedRealtimeMillis();
187                 Looper.myQueue().addIdleHandler(this);
188                 mIdleMonitorAttached = true;
189                 Log.v(TAG, "attached idle handler");
190             } else if (mIdleMonitorAttached && !sEnabled) {
191                 Looper.myQueue().removeIdleHandler(this);
192                 mIdleMonitorAttached = false;
193                 Log.v(TAG, "detached idle handler");
194             }
195         }
196 
197         @Override
beginHandling(final String line)198         final void beginHandling(final String line) {
199             // Close-out any prior 'idle' period before starting new task.
200             if (mNumTasksSinceLastIdle == 0) {
201                 TraceEvent.end(IDLE_EVENT_NAME);
202             }
203             mLastWorkStartedAt = TimeUtils.elapsedRealtimeMillis();
204             syncIdleMonitoring();
205             super.beginHandling(line);
206         }
207 
208         @Override
endHandling(final String line)209         final void endHandling(final String line) {
210             final long elapsed = TimeUtils.elapsedRealtimeMillis() - mLastWorkStartedAt;
211             if (elapsed > MIN_INTERESTING_DURATION_MILLIS) {
212                 traceAndLog(Log.WARN, "observed a task that took " + elapsed + "ms: " + line);
213             }
214             super.endHandling(line);
215             syncIdleMonitoring();
216             mNumTasksSeen++;
217             mNumTasksSinceLastIdle++;
218         }
219 
traceAndLog(int level, String message)220         private static void traceAndLog(int level, String message) {
221             TraceEvent.instant("TraceEvent.LooperMonitor:IdleStats", message);
222             Log.println(level, TAG, message);
223         }
224 
225         @Override
queueIdle()226         public final boolean queueIdle() {
227             final long now = TimeUtils.elapsedRealtimeMillis();
228             if (mLastIdleStartedAt == 0) mLastIdleStartedAt = now;
229             final long elapsed = now - mLastIdleStartedAt;
230             mNumIdlesSeen++;
231             TraceEvent.begin(IDLE_EVENT_NAME, mNumTasksSinceLastIdle + " tasks since last idle.");
232             if (elapsed > MIN_INTERESTING_BURST_DURATION_MILLIS) {
233                 // Dump stats
234                 String statsString =
235                         mNumTasksSeen
236                                 + " tasks and "
237                                 + mNumIdlesSeen
238                                 + " idles processed so far, "
239                                 + mNumTasksSinceLastIdle
240                                 + " tasks bursted and "
241                                 + elapsed
242                                 + "ms elapsed since last idle";
243                 traceAndLog(Log.DEBUG, statsString);
244             }
245             mLastIdleStartedAt = now;
246             mNumTasksSinceLastIdle = 0;
247             return true; // stay installed
248         }
249     }
250 
251     // Holder for monitor avoids unnecessary construction on non-debug runs
252     private static final class LooperMonitorHolder {
253         private static final BasicLooperMonitor sInstance =
254                 CommandLine.getInstance().hasSwitch(BaseSwitches.ENABLE_IDLE_TRACING)
255                         ? new IdleTracingLooperMonitor()
256                         : new BasicLooperMonitor();
257     }
258 
259     private final String mName;
260 
261     /** Constructor used to support the "try with resource" construct. */
TraceEvent(String name, String arg)262     private TraceEvent(String name, String arg) {
263         mName = name;
264         begin(name, arg);
265     }
266 
267     /** Constructor used to support the "try with resource" construct. */
TraceEvent(String name, int arg)268     private TraceEvent(String name, int arg) {
269         mName = name;
270         begin(name, arg);
271     }
272 
273     @Override
close()274     public void close() {
275         end(mName);
276     }
277 
278     /**
279      * Factory used to support the "try with resource" construct.
280      *
281      * Note that if tracing is not enabled, this will not result in allocating an object.
282      *
283      * @param name Trace event name.
284      * @param arg The arguments of the event.
285      * @return a TraceEvent, or null if tracing is not enabled.
286      */
scoped(String name, String arg)287     public static TraceEvent scoped(String name, String arg) {
288         if (!(EarlyTraceEvent.enabled() || enabled())) return null;
289         return new TraceEvent(name, arg);
290     }
291 
292     /**
293      * Factory used to support the "try with resource" construct.
294      *
295      * Note that if tracing is not enabled, this will not result in allocating an object.
296      *
297      * @param name Trace event name.
298      * @param arg An integer argument of the event.
299      * @return a TraceEvent, or null if tracing is not enabled.
300      */
scoped(String name, int arg)301     public static TraceEvent scoped(String name, int arg) {
302         if (!(EarlyTraceEvent.enabled() || enabled())) return null;
303         return new TraceEvent(name, arg);
304     }
305 
306     /** Similar to {@link #scoped(String, String arg)}, but uses null for |arg|. */
scoped(String name)307     public static TraceEvent scoped(String name) {
308         return scoped(name, null);
309     }
310 
311     /** Notification from native that tracing is enabled/disabled. */
312     @CalledByNative
setEnabled(boolean enabled)313     public static void setEnabled(boolean enabled) {
314         if (enabled) EarlyTraceEvent.disable();
315         // Only disable logging if Chromium enabled it originally, so as to not disrupt logging done
316         // by other applications
317         if (sEnabled != enabled) {
318             sEnabled = enabled;
319             ThreadUtils.getUiThreadLooper()
320                     .setMessageLogging(enabled ? LooperMonitorHolder.sInstance : null);
321         }
322         if (sUiThreadReady) {
323             ViewHierarchyDumper.updateEnabledState();
324         }
325     }
326 
327     @CalledByNative
setEventNameFilteringEnabled(boolean enabled)328     public static void setEventNameFilteringEnabled(boolean enabled) {
329         sEventNameFilteringEnabled = enabled;
330     }
331 
eventNameFilteringEnabled()332     public static boolean eventNameFilteringEnabled() {
333         return sEventNameFilteringEnabled;
334     }
335 
336     /**
337      * May enable early tracing depending on the environment.
338      *
339      * @param readCommandLine If true, also check command line flags to see
340      *                        whether tracing should be turned on.
341      */
maybeEnableEarlyTracing(boolean readCommandLine)342     public static void maybeEnableEarlyTracing(boolean readCommandLine) {
343         // Enable early trace events based on command line flags. This is only
344         // done for Chrome since WebView tracing isn't controlled with command
345         // line flags.
346         if (readCommandLine) {
347             EarlyTraceEvent.maybeEnableInBrowserProcess();
348         }
349         if (EarlyTraceEvent.enabled()) {
350             ThreadUtils.getUiThreadLooper().setMessageLogging(LooperMonitorHolder.sInstance);
351         }
352     }
353 
onNativeTracingReady()354     public static void onNativeTracingReady() {
355         TraceEventJni.get().registerEnabledObserver();
356     }
357 
358     // Called by ThreadUtils.
onUiThreadReady()359     static void onUiThreadReady() {
360         sUiThreadReady = true;
361         if (sEnabled) {
362             ViewHierarchyDumper.updateEnabledState();
363         }
364     }
365 
366     /**
367      * @return True if tracing is enabled, false otherwise.
368      * It is safe to call trace methods without checking if TraceEvent
369      * is enabled.
370      */
enabled()371     public static boolean enabled() {
372         return sEnabled;
373     }
374 
375     /**
376      * Triggers the 'instant' native trace event with no arguments.
377      * @param name The name of the event.
378      */
instant(String name)379     public static void instant(String name) {
380         if (sEnabled) TraceEventJni.get().instant(name, null);
381     }
382 
383     /**
384      * Triggers the 'instant' native trace event.
385      * @param name The name of the event.
386      * @param arg  The arguments of the event.
387      */
instant(String name, String arg)388     public static void instant(String name, String arg) {
389         if (sEnabled) TraceEventJni.get().instant(name, arg);
390     }
391 
392     /**
393      * Triggers a 'instant' native "AndroidIPC" event.
394      * @param name The name of the IPC.
395      * @param durMs The duration the IPC took in milliseconds.
396      */
instantAndroidIPC(String name, long durMs)397     public static void instantAndroidIPC(String name, long durMs) {
398         if (sEnabled) TraceEventJni.get().instantAndroidIPC(name, durMs);
399     }
400 
401     /**
402      * Triggers a 'instant' native "AndroidToolbar" event.
403      * @param blockReason the enum TopToolbarBlockCapture (-1 if not blocked).
404      * @param allowReason the enum TopToolbarAllowCapture (-1 if not allowed).
405      * @param snapshotDiff the enum ToolbarSnapshotDifference (-1 if no diff).
406      */
instantAndroidToolbar(int blockReason, int allowReason, int snapshotDiff)407     public static void instantAndroidToolbar(int blockReason, int allowReason, int snapshotDiff) {
408         if (sEnabled) {
409             TraceEventJni.get().instantAndroidToolbar(blockReason, allowReason, snapshotDiff);
410         }
411     }
412 
413     /**
414      * Records a 'WebView.Startup.CreationTime.TotalFactoryInitTime' event with the
415      * 'android_webview.timeline' category starting at `startTimeMs` with the duration of
416      * `durationMs`.
417      */
webViewStartupTotalFactoryInit(long startTimeMs, long durationMs)418     public static void webViewStartupTotalFactoryInit(long startTimeMs, long durationMs) {
419         if (sEnabled) {
420             TraceEventJni.get().webViewStartupTotalFactoryInit(startTimeMs, durationMs);
421         }
422     }
423 
424     /**
425      * Records a 'WebView.Startup.CreationTime.Stage1.FactoryInit' event with the
426      * 'android_webview.timeline' category starting at `startTimeMs` with the duration of
427      * `durationMs`.
428      */
webViewStartupStage1(long startTimeMs, long durationMs)429     public static void webViewStartupStage1(long startTimeMs, long durationMs) {
430         if (sEnabled) {
431             TraceEventJni.get().webViewStartupStage1(startTimeMs, durationMs);
432         }
433     }
434 
435     /**
436      * Records 'WebView.Startup.CreationTime.Stage2.ProviderInit.Warm' and
437      * 'WebView.Startup.CreationTime.Stage2.ProviderInit.Cold' events depending on the value of
438      * `isColdStartup` with the 'android_webview.timeline' category starting at `startTimeMs` with
439      * the duration of `durationMs`.
440      */
webViewStartupStage2( long startTimeMs, long durationMs, boolean isColdStartup)441     public static void webViewStartupStage2(
442             long startTimeMs, long durationMs, boolean isColdStartup) {
443         if (sEnabled) {
444             TraceEventJni.get().webViewStartupStage2(startTimeMs, durationMs, isColdStartup);
445         }
446     }
447 
448     /** Records 'Startup.LaunchCause' event with the 'interactions' category. */
startupLaunchCause(long activityId, int launchCause)449     public static void startupLaunchCause(long activityId, int launchCause) {
450         if (!sEnabled) return;
451         TraceEventJni.get().startupLaunchCause(activityId, launchCause);
452     }
453 
454     /** Records 'Startup.TimeToFirstVisibleContent2' event with the 'interactions' category. */
startupTimeToFirstVisibleContent2( long activityId, long startTimeMs, long durationMs)455     public static void startupTimeToFirstVisibleContent2(
456             long activityId, long startTimeMs, long durationMs) {
457         if (!sEnabled) return;
458         TraceEventJni.get().startupTimeToFirstVisibleContent2(activityId, startTimeMs, durationMs);
459     }
460 
461     /**
462      * Snapshots the view hierarchy state on the main thread and then finishes emitting a trace
463      * event on the threadpool.
464      */
snapshotViewHierarchy()465     public static void snapshotViewHierarchy() {
466         if (sEnabled && TraceEventJni.get().viewHierarchyDumpEnabled()) {
467             // Emit separate begin and end so we can set the flow id at the end.
468             TraceEvent.begin("instantAndroidViewHierarchy");
469 
470             // If we have no views don't bother to emit any TraceEvents for efficiency.
471             ArrayList<ActivityInfo> views = snapshotViewHierarchyState();
472             if (views.isEmpty()) {
473                 TraceEvent.end("instantAndroidViewHierarchy");
474                 return;
475             }
476 
477             // Use the correct snapshot object as a processed scoped flow id. This connects the
478             // mainthread work with the result emitted on the threadpool. We do this because
479             // resolving resource names can trigger exceptions (NotFoundException) which can be
480             // quite slow.
481             long flow = views.hashCode();
482 
483             PostTask.postTask(
484                     TaskTraits.BEST_EFFORT,
485                     () -> {
486                         // Actually output the dump as a trace event on a thread pool.
487                         TraceEventJni.get().initViewHierarchyDump(flow, views);
488                     });
489             TraceEvent.end("instantAndroidViewHierarchy", null, flow);
490         }
491     }
492 
493     /**
494      * Triggers the 'start' native trace event with no arguments.
495      * @param name The name of the event.
496      * @param id   The id of the asynchronous event.
497      */
startAsync(String name, long id)498     public static void startAsync(String name, long id) {
499         EarlyTraceEvent.startAsync(name, id);
500         if (sEnabled) {
501             TraceEventJni.get().startAsync(name, id);
502         }
503     }
504 
505     /**
506      * Triggers the 'finish' native trace event with no arguments.
507      * @param name The name of the event.
508      * @param id   The id of the asynchronous event.
509      */
finishAsync(String name, long id)510     public static void finishAsync(String name, long id) {
511         EarlyTraceEvent.finishAsync(name, id);
512         if (sEnabled) {
513             TraceEventJni.get().finishAsync(name, id);
514         }
515     }
516 
517     /**
518      * Triggers the 'begin' native trace event with no arguments.
519      * @param name The name of the event.
520      */
begin(String name)521     public static void begin(String name) {
522         begin(name, null);
523     }
524 
525     /**
526      * Triggers the 'begin' native trace event.
527      * @param name The name of the event.
528      * @param arg  The arguments of the event.
529      */
begin(String name, String arg)530     public static void begin(String name, String arg) {
531         EarlyTraceEvent.begin(name, /* isToplevel= */ false);
532         if (sEnabled) {
533             TraceEventJni.get().begin(name, arg);
534         }
535     }
536 
537     /**
538      * Triggers the 'begin' native trace event.
539      * @param name The name of the event.
540      * @param arg An integer argument of the event.
541      */
begin(String name, int arg)542     public static void begin(String name, int arg) {
543         EarlyTraceEvent.begin(name, /* isToplevel= */ false);
544         if (sEnabled) {
545             TraceEventJni.get().beginWithIntArg(name, arg);
546         }
547     }
548 
549     /**
550      * Triggers the 'end' native trace event with no arguments.
551      * @param name The name of the event.
552      */
end(String name)553     public static void end(String name) {
554         end(name, null);
555     }
556 
557     /**
558      * Triggers the 'end' native trace event.
559      * @param name The name of the event.
560      * @param arg  The arguments of the event.
561      */
end(String name, String arg)562     public static void end(String name, String arg) {
563         end(name, arg, 0);
564     }
565 
566     /**
567      * Triggers the 'end' native trace event.
568      * @param name The name of the event.
569      * @param arg  The arguments of the event.
570      * @param flow The flow ID to associate with this event (0 is treated as invalid).
571      */
end(String name, String arg, long flow)572     public static void end(String name, String arg, long flow) {
573         EarlyTraceEvent.end(name, /* isToplevel= */ false);
574         if (sEnabled) {
575             TraceEventJni.get().end(name, arg, flow);
576         }
577     }
578 
snapshotViewHierarchyState()579     public static ArrayList<ActivityInfo> snapshotViewHierarchyState() {
580         if (!ApplicationStatus.isInitialized()) {
581             return new ArrayList<ActivityInfo>();
582         }
583 
584         // In local testing we generally just have one activity.
585         ArrayList<ActivityInfo> views = new ArrayList<>(2);
586         for (Activity a : ApplicationStatus.getRunningActivities()) {
587             views.add(new ActivityInfo(a.getClass().getName()));
588             ViewHierarchyDumper.dumpView(
589                     views.get(views.size() - 1),
590                     /* parentId= */ 0,
591                     a.getWindow().getDecorView().getRootView());
592         }
593         return views;
594     }
595 
596     @NativeMethods
597     interface Natives {
registerEnabledObserver()598         void registerEnabledObserver();
599 
instant(String name, String arg)600         void instant(String name, String arg);
601 
begin(String name, String arg)602         void begin(String name, String arg);
603 
beginWithIntArg(String name, int arg)604         void beginWithIntArg(String name, int arg);
605 
end(String name, String arg, long flow)606         void end(String name, String arg, long flow);
607 
beginToplevel(String target)608         void beginToplevel(String target);
609 
endToplevel(String target)610         void endToplevel(String target);
611 
startAsync(String name, long id)612         void startAsync(String name, long id);
613 
finishAsync(String name, long id)614         void finishAsync(String name, long id);
615 
viewHierarchyDumpEnabled()616         boolean viewHierarchyDumpEnabled();
617 
initViewHierarchyDump(long id, Object list)618         void initViewHierarchyDump(long id, Object list);
619 
startActivityDump(String name, long dumpProtoPtr)620         long startActivityDump(String name, long dumpProtoPtr);
621 
addViewDump( int id, int parentId, boolean isShown, boolean isDirty, String className, String resourceName, long activityProtoPtr)622         void addViewDump(
623                 int id,
624                 int parentId,
625                 boolean isShown,
626                 boolean isDirty,
627                 String className,
628                 String resourceName,
629                 long activityProtoPtr);
630 
instantAndroidIPC(String name, long durMs)631         void instantAndroidIPC(String name, long durMs);
632 
instantAndroidToolbar(int blockReason, int allowReason, int snapshotDiff)633         void instantAndroidToolbar(int blockReason, int allowReason, int snapshotDiff);
634 
webViewStartupTotalFactoryInit(long startTimeMs, long durationMs)635         void webViewStartupTotalFactoryInit(long startTimeMs, long durationMs);
636 
webViewStartupStage1(long startTimeMs, long durationMs)637         void webViewStartupStage1(long startTimeMs, long durationMs);
638 
webViewStartupStage2(long startTimeMs, long durationMs, boolean isColdStartup)639         void webViewStartupStage2(long startTimeMs, long durationMs, boolean isColdStartup);
640 
startupLaunchCause(long activityId, int launchCause)641         void startupLaunchCause(long activityId, int launchCause);
642 
startupTimeToFirstVisibleContent2(long activityId, long startTimeMs, long durationMs)643         void startupTimeToFirstVisibleContent2(long activityId, long startTimeMs, long durationMs);
644     }
645 
646     /**
647      * A method to be called by native code that uses the ViewHierarchyDumper class to emit a trace
648      * event with views of all running activities of the app.
649      */
650     @CalledByNative
dumpViewHierarchy(long dumpProtoPtr, Object list)651     public static void dumpViewHierarchy(long dumpProtoPtr, Object list) {
652         if (!ApplicationStatus.isInitialized()) {
653             return;
654         }
655 
656         // Convert the Object back into the ArrayList of ActivityInfo, lifetime of this object is
657         // maintained by the Runnable that we are running in currently.
658         ArrayList<ActivityInfo> activities = (ArrayList<ActivityInfo>) list;
659 
660         for (ActivityInfo activity : activities) {
661             long activityProtoPtr =
662                     TraceEventJni.get().startActivityDump(activity.mActivityName, dumpProtoPtr);
663             for (ViewInfo view : activity.mViews) {
664                 // We need to resolve the resource, take care as NotFoundException can be common and
665                 // java exceptions aren't he fastest thing ever.
666                 String resource;
667                 try {
668                     resource =
669                             view.mRes != null
670                                     ? (view.mId == 0 || view.mId == -1
671                                             ? "__no_id__"
672                                             : view.mRes.getResourceName(view.mId))
673                                     : "__no_resources__";
674                 } catch (NotFoundException e) {
675                     resource = "__name_not_found__";
676                 }
677                 TraceEventJni.get()
678                         .addViewDump(
679                                 view.mId,
680                                 view.mParentId,
681                                 view.mIsShown,
682                                 view.mIsDirty,
683                                 view.mClassName,
684                                 resource,
685                                 activityProtoPtr);
686             }
687         }
688     }
689 
690     /**
691      * This class contains the minimum information to represent a view that the {@link
692      * #ViewHierarchyDumper} needs, so that in {@link #snapshotViewHierarchy} we can output a trace
693      * event off the main thread.
694      */
695     public static class ViewInfo {
ViewInfo( int id, int parentId, boolean isShown, boolean isDirty, String className, android.content.res.Resources res)696         public ViewInfo(
697                 int id,
698                 int parentId,
699                 boolean isShown,
700                 boolean isDirty,
701                 String className,
702                 android.content.res.Resources res) {
703             mId = id;
704             mParentId = parentId;
705             mIsShown = isShown;
706             mIsDirty = isDirty;
707             mClassName = className;
708             mRes = res;
709         }
710 
711         private int mId;
712         private int mParentId;
713         private boolean mIsShown;
714         private boolean mIsDirty;
715         private String mClassName;
716         // One can use mRes to resolve mId to a resource name.
717         private android.content.res.Resources mRes;
718     }
719 
720     /**
721      * This class contains the minimum information to represent an Activity that the {@link
722      * #ViewHierarchyDumper} needs, so that in {@link #snapshotViewHierarchy} we can output a trace
723      * event off the main thread.
724      */
725     public static class ActivityInfo {
ActivityInfo(String activityName)726         public ActivityInfo(String activityName) {
727             mActivityName = activityName;
728             // Local testing found about 115ish views in the ChromeTabbedActivity.
729             mViews = new ArrayList<ViewInfo>(125);
730         }
731 
732         public String mActivityName;
733         public ArrayList<ViewInfo> mViews;
734     }
735 
736     /**
737      * A class that periodically dumps the view hierarchy of all running activities of the app to
738      * the trace. Enabled/disabled via the disabled-by-default-android_view_hierarchy trace
739      * category.
740      *
741      * The class registers itself as an idle handler, so that it can run when there are no other
742      * tasks in the queue (but not more often than once a second). When the queue is idle,
743      * it calls the initViewHierarchyDump() native function which in turn calls the
744      * TraceEvent.dumpViewHierarchy() with a pointer to the proto buffer to fill in. The
745      * TraceEvent.dumpViewHierarchy() traverses all activities and dumps view hierarchy for every
746      * activity. Altogether, the call sequence is as follows:
747      *   ViewHierarchyDumper.queueIdle()
748      *    -> JNI#initViewHierarchyDump()
749      *        -> TraceEvent.dumpViewHierarchy()
750      *            -> JNI#startActivityDump()
751      *            -> ViewHierarchyDumper.dumpView()
752      *                -> JNI#addViewDump()
753      */
754     private static final class ViewHierarchyDumper implements MessageQueue.IdleHandler {
755         private static final String EVENT_NAME = "TraceEvent.ViewHierarchyDumper";
756         private static final long MIN_VIEW_DUMP_INTERVAL_MILLIS = 1000L;
757         private static boolean sEnabled;
758         private static ViewHierarchyDumper sInstance;
759         private long mLastDumpTs;
760 
761         @Override
queueIdle()762         public final boolean queueIdle() {
763             final long now = TimeUtils.elapsedRealtimeMillis();
764             if (mLastDumpTs == 0 || (now - mLastDumpTs) > MIN_VIEW_DUMP_INTERVAL_MILLIS) {
765                 mLastDumpTs = now;
766                 snapshotViewHierarchy();
767             }
768 
769             // Returning true to keep IdleHandler alive.
770             return true;
771         }
772 
updateEnabledState()773         public static void updateEnabledState() {
774             PostTask.runOrPostTask(
775                     TaskTraits.UI_DEFAULT,
776                     () -> {
777                         if (TraceEventJni.get().viewHierarchyDumpEnabled()) {
778                             if (sInstance == null) {
779                                 sInstance = new ViewHierarchyDumper();
780                             }
781                             enable();
782                         } else {
783                             if (sInstance != null) {
784                                 disable();
785                             }
786                         }
787                     });
788         }
789 
dumpView(ActivityInfo collection, int parentId, View v)790         private static void dumpView(ActivityInfo collection, int parentId, View v) {
791             ThreadUtils.assertOnUiThread();
792             int id = v.getId();
793             collection.mViews.add(
794                     new ViewInfo(
795                             id,
796                             parentId,
797                             v.isShown(),
798                             v.isDirty(),
799                             v.getClass().getSimpleName(),
800                             v.getResources()));
801 
802             if (v instanceof ViewGroup) {
803                 ViewGroup vg = (ViewGroup) v;
804                 for (int i = 0; i < vg.getChildCount(); i++) {
805                     dumpView(collection, id, vg.getChildAt(i));
806                 }
807             }
808         }
809 
enable()810         private static void enable() {
811             ThreadUtils.assertOnUiThread();
812             if (!sEnabled) {
813                 Looper.myQueue().addIdleHandler(sInstance);
814                 sEnabled = true;
815             }
816         }
817 
disable()818         private static void disable() {
819             ThreadUtils.assertOnUiThread();
820             if (sEnabled) {
821                 Looper.myQueue().removeIdleHandler(sInstance);
822                 sEnabled = false;
823             }
824         }
825     }
826 }
827