chromium/base/TraceEvent.java

// Copyright 2014 The Chromium Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

package org.chromium.base;

import android.os.Looper;
import android.os.MessageQueue;
import android.os.SystemClock;
import android.util.Log;
import android.util.Printer;

import org.chromium.base.annotations.CalledByNative;
import org.chromium.base.annotations.JNINamespace;
import org.chromium.base.annotations.MainDex;
/**
 * Java mirror of Chrome trace event API. See base/trace_event/trace_event.h.
 *
 * To get scoped trace events, use the "try with resource" construct, for instance:
 * <pre>{@code
 * try (TraceEvent e = TraceEvent.scoped("MyTraceEvent")) {
 *   // code.
 * }
 * }</pre>
 *
 * It is OK to use tracing before the native library has loaded, in a slightly restricted fashion.
 * @see EarlyTraceEvent for details.
 */
@JNINamespace("base::android")
@MainDex
public class TraceEvent implements AutoCloseable {
    private static volatile boolean sEnabled;
    private static volatile boolean sATraceEnabled; // True when taking an Android systrace.

    private static class BasicLooperMonitor implements Printer {
        private static final String EARLY_TOPLEVEL_TASK_NAME = "Looper.dispatchMessage: ";

        @Override
        public void println(final String line) {
            if (line.startsWith(">")) {
                beginHandling(line);
            } else {
                assert line.startsWith("<");
                endHandling(line);
            }
        }

        void beginHandling(final String line) {
            // May return an out-of-date value. this is not an issue as EarlyTraceEvent#begin()
            // will filter the event in this case.
            boolean earlyTracingActive = EarlyTraceEvent.isActive();
            if (sEnabled || earlyTracingActive) {
                String target = getTarget(line);
                if (sEnabled) {
                    nativeBeginToplevel(target);
                } else if (earlyTracingActive) {
                    // Synthesize a task name instead of using a parameter, as early tracing doesn't
                    // support parameters.
                    EarlyTraceEvent.begin(EARLY_TOPLEVEL_TASK_NAME + target);
                }
            }
        }

        void endHandling(final String line) {
            if (EarlyTraceEvent.isActive()) {
                EarlyTraceEvent.end(EARLY_TOPLEVEL_TASK_NAME + getTarget(line));
            }
            if (sEnabled) nativeEndToplevel();
        }

        /**
         * Android Looper formats |line| as ">>>>> Dispatching to (TARGET) [...]" since at least
         * 2009 (Donut). Extracts the TARGET part of the message.
         */
        private static String getTarget(String logLine) {
            int start = logLine.indexOf('(', 21); // strlen(">>>>> Dispatching to ")
            int end = start == -1 ? -1 : logLine.indexOf(')', start);
            return end != -1 ? logLine.substring(start + 1, end) : "";
        }
    }

    /**
     * A class that records, traces and logs statistics about the UI thead's Looper.
     * The output of this class can be used in a number of interesting ways:
     * <p>
     * <ol><li>
     * When using chrometrace, there will be a near-continuous line of
     * measurements showing both event dispatches as well as idles;
     * </li><li>
     * Logging messages are output for events that run too long on the
     * event dispatcher, making it easy to identify problematic areas;
     * </li><li>
     * Statistics are output whenever there is an idle after a non-trivial
     * amount of activity, allowing information to be gathered about task
     * density and execution cadence on the Looper;
     * </li></ol>
     * <p>
     * The class attaches itself as an idle handler to the main Looper, and
     * monitors the execution of events and idle notifications. Task counters
     * accumulate between idle notifications and get reset when a new idle
     * notification is received.
     */
    private static final class IdleTracingLooperMonitor extends BasicLooperMonitor
            implements MessageQueue.IdleHandler {
        // Tags for dumping to logcat or TraceEvent
        private static final String TAG = "TraceEvent.LooperMonitor";
        private static final String IDLE_EVENT_NAME = "Looper.queueIdle";

        // Calculation constants
        private static final long FRAME_DURATION_MILLIS = 1000L / 60L; // 60 FPS
        // A reasonable threshold for defining a Looper event as "long running"
        private static final long MIN_INTERESTING_DURATION_MILLIS =
                FRAME_DURATION_MILLIS;
        // A reasonable threshold for a "burst" of tasks on the Looper
        private static final long MIN_INTERESTING_BURST_DURATION_MILLIS =
                MIN_INTERESTING_DURATION_MILLIS * 3;

        // Stats tracking
        private long mLastIdleStartedAt;
        private long mLastWorkStartedAt;
        private int mNumTasksSeen;
        private int mNumIdlesSeen;
        private int mNumTasksSinceLastIdle;

        // State
        private boolean mIdleMonitorAttached;

        // Called from within the begin/end methods only.
        // This method can only execute on the looper thread, because that is
        // the only thread that is permitted to call Looper.myqueue().
        private final void syncIdleMonitoring() {
            if (sEnabled && !mIdleMonitorAttached) {
                // approximate start time for computational purposes
                mLastIdleStartedAt = SystemClock.elapsedRealtime();
                Looper.myQueue().addIdleHandler(this);
                mIdleMonitorAttached = true;
                Log.v(TAG, "attached idle handler");
            } else if (mIdleMonitorAttached && !sEnabled) {
                Looper.myQueue().removeIdleHandler(this);
                mIdleMonitorAttached = false;
                Log.v(TAG, "detached idle handler");
            }
        }

        @Override
        final void beginHandling(final String line) {
            // Close-out any prior 'idle' period before starting new task.
            if (mNumTasksSinceLastIdle == 0) {
                TraceEvent.end(IDLE_EVENT_NAME);
            }
            mLastWorkStartedAt = SystemClock.elapsedRealtime();
            syncIdleMonitoring();
            super.beginHandling(line);
        }

        @Override
        final void endHandling(final String line) {
            final long elapsed = SystemClock.elapsedRealtime()
                    - mLastWorkStartedAt;
            if (elapsed > MIN_INTERESTING_DURATION_MILLIS) {
                traceAndLog(Log.WARN, "observed a task that took "
                        + elapsed + "ms: " + line);
            }
            super.endHandling(line);
            syncIdleMonitoring();
            mNumTasksSeen++;
            mNumTasksSinceLastIdle++;
        }

        private static void traceAndLog(int level, String message) {
            TraceEvent.instant("TraceEvent.LooperMonitor:IdleStats", message);
            Log.println(level, TAG, message);
        }

        @Override
        public final boolean queueIdle() {
            final long now =  SystemClock.elapsedRealtime();
            if (mLastIdleStartedAt == 0) mLastIdleStartedAt = now;
            final long elapsed = now - mLastIdleStartedAt;
            mNumIdlesSeen++;
            TraceEvent.begin(IDLE_EVENT_NAME, mNumTasksSinceLastIdle + " tasks since last idle.");
            if (elapsed > MIN_INTERESTING_BURST_DURATION_MILLIS) {
                // Dump stats
                String statsString = mNumTasksSeen + " tasks and "
                        + mNumIdlesSeen + " idles processed so far, "
                        + mNumTasksSinceLastIdle + " tasks bursted and "
                        + elapsed + "ms elapsed since last idle";
                traceAndLog(Log.DEBUG, statsString);
            }
            mLastIdleStartedAt = now;
            mNumTasksSinceLastIdle = 0;
            return true; // stay installed
        }
    }

    // Holder for monitor avoids unnecessary construction on non-debug runs
    private static final class LooperMonitorHolder {
        private static final BasicLooperMonitor sInstance =
                CommandLine.getInstance().hasSwitch(BaseSwitches.ENABLE_IDLE_TRACING)
                ? new IdleTracingLooperMonitor() : new BasicLooperMonitor();
    }

    private final String mName;

    /**
     * Constructor used to support the "try with resource" construct.
     */
    private TraceEvent(String name, String arg) {
        mName = name;
        begin(name, arg);
    }

    @Override
    public void close() {
        end(mName);
    }

    /**
     * Factory used to support the "try with resource" construct.
     *
     * Note that if tracing is not enabled, this will not result in allocating an object.
     *
     * @param name Trace event name.
     * @param name The arguments of the event.
     * @return a TraceEvent, or null if tracing is not enabled.
     */
    public static TraceEvent scoped(String name, String arg) {
        if (!(EarlyTraceEvent.enabled() || enabled())) return null;
        return new TraceEvent(name, arg);
    }

    /**
     * Similar to {@link #scoped(String, String arg)}, but uses null for |arg|.
     */
    public static TraceEvent scoped(String name) {
        return scoped(name, null);
    }

    /**
     * Register an enabled observer, such that java traces are always enabled with native.
     */
    public static void registerNativeEnabledObserver() {
        nativeRegisterEnabledObserver();
    }

    /**
     * Notification from native that tracing is enabled/disabled.
     */
    @CalledByNative
    public static void setEnabled(boolean enabled) {
        if (enabled) EarlyTraceEvent.disable();
        // Only disable logging if Chromium enabled it originally, so as to not disrupt logging done
        // by other applications
        if (sEnabled != enabled) {
            sEnabled = enabled;
            // Android M+ systrace logs this on its own. Only log it if not writing to Android
            // systrace.
            if (sATraceEnabled) return;
            ThreadUtils.getUiThreadLooper().setMessageLogging(
                    enabled ? LooperMonitorHolder.sInstance : null);
        }
    }

    /**
     * May enable early tracing depending on the environment.
     *
     * Must be called after the command-line has been read.
     */
    public static void maybeEnableEarlyTracing() {
        EarlyTraceEvent.maybeEnable();
        if (EarlyTraceEvent.isActive()) {
            ThreadUtils.getUiThreadLooper().setMessageLogging(LooperMonitorHolder.sInstance);
        }
    }

    /**
     * Enables or disabled Android systrace path of Chrome tracing. If enabled, all Chrome
     * traces will be also output to Android systrace. Because of the overhead of Android
     * systrace, this is for WebView only.
     */
    public static void setATraceEnabled(boolean enabled) {
        if (sATraceEnabled == enabled) return;
        sATraceEnabled = enabled;
        if (enabled) {
            // Calls TraceEvent.setEnabled(true) via
            // TraceLog::EnabledStateObserver::OnTraceLogEnabled
            nativeStartATrace();
        } else {
            // Calls TraceEvent.setEnabled(false) via
            // TraceLog::EnabledStateObserver::OnTraceLogDisabled
            nativeStopATrace();
        }
    }

    /**
     * @return True if tracing is enabled, false otherwise.
     * It is safe to call trace methods without checking if TraceEvent
     * is enabled.
     */
    public static boolean enabled() {
        return sEnabled;
    }

    /**
     * Triggers the 'instant' native trace event with no arguments.
     * @param name The name of the event.
     */
    public static void instant(String name) {
        if (sEnabled) nativeInstant(name, null);
    }

    /**
     * Triggers the 'instant' native trace event.
     * @param name The name of the event.
     * @param arg  The arguments of the event.
     */
    public static void instant(String name, String arg) {
        if (sEnabled) nativeInstant(name, arg);
    }

    /**
     * Triggers the 'start' native trace event with no arguments.
     * @param name The name of the event.
     * @param id   The id of the asynchronous event.
     */
    public static void startAsync(String name, long id) {
        EarlyTraceEvent.startAsync(name, id);
        if (sEnabled) nativeStartAsync(name, id);
    }

    /**
     * Triggers the 'finish' native trace event with no arguments.
     * @param name The name of the event.
     * @param id   The id of the asynchronous event.
     */
    public static void finishAsync(String name, long id) {
        EarlyTraceEvent.finishAsync(name, id);
        if (sEnabled) nativeFinishAsync(name, id);
    }

    /**
     * Triggers the 'begin' native trace event with no arguments.
     * @param name The name of the event.
     */
    public static void begin(String name) {
        begin(name, null);
    }

    /**
     * Triggers the 'begin' native trace event.
     * @param name The name of the event.
     * @param arg  The arguments of the event.
     */
    public static void begin(String name, String arg) {
        EarlyTraceEvent.begin(name);
        if (sEnabled) nativeBegin(name, arg);
    }

    /**
     * Triggers the 'end' native trace event with no arguments.
     * @param name The name of the event.
     */
    public static void end(String name) {
        end(name, null);
    }

    /**
     * Triggers the 'end' native trace event.
     * @param name The name of the event.
     * @param arg  The arguments of the event.
     */
    public static void end(String name, String arg) {
        EarlyTraceEvent.end(name);
        if (sEnabled) nativeEnd(name, arg);
    }

    private static native void nativeRegisterEnabledObserver();
    private static native void nativeStartATrace();
    private static native void nativeStopATrace();
    private static native void nativeInstant(String name, String arg);
    private static native void nativeBegin(String name, String arg);
    private static native void nativeEnd(String name, String arg);
    private static native void nativeBeginToplevel(String target);
    private static native void nativeEndToplevel();
    private static native void nativeStartAsync(String name, long id);
    private static native void nativeFinishAsync(String name, long id);
}